3535
3636#include < atomic>
3737#include < ctime>
38+ #include < fstream>
3839
3940#ifndef _WIN32
4041#include < unistd.h>
@@ -263,19 +264,21 @@ int32_t GPUReconstructionCPU::RunChains()
263264 }
264265 double kernelTotal = 0 ;
265266 std::vector<double > kernelStepTimes (gpudatatypes::N_RECO_STEPS, 0 .);
267+ std::ofstream timingCSVFile;
268+ if (!GetProcessingSettings ().timingCSV .empty ()) {
269+ timingCSVFile.open (GetProcessingSettings ().timingCSV , std::ios::binary | std::ofstream::app);
270+ if (mNEventsProcessed == 1 ) timingCSVFile << " name,time,count,type\n " ;
271+ if (!timingCSVFile.is_open ()) GPUError (" Could not open timing CSV file '%s' for writing" , GetProcessingSettings ().timingCSV .c_str ());
272+ }
266273
267274 if (GetProcessingSettings ().debugLevel >= 1 ) {
268275 for (uint32_t i = 0 ; i < mTimers .size (); i++) {
269276 double time = 0 ;
270- if (mTimers [i] == nullptr ) {
271- continue ;
272- }
277+ if (mTimers [i] == nullptr ) continue ;
273278 for (int32_t j = 0 ; j < mTimers [i]->num ; j++) {
274279 HighResTimer& timer = mTimers [i]->timer [j];
275280 time += timer.GetElapsedTime ();
276- if (GetProcessingSettings ().resetTimers ) {
277- timer.Reset ();
278- }
281+ if (GetProcessingSettings ().resetTimers ) timer.Reset ();
279282 }
280283
281284 uint32_t type = mTimers [i]->type ;
@@ -288,7 +291,9 @@ int32_t GPUReconstructionCPU::RunChains()
288291 if (mTimers [i]->memSize && mStatNEvents && time != 0 .) {
289292 snprintf (bandwidth, 256 , " (%8.3f GB/s - %'14zu bytes - %'14zu per call)" , mTimers [i]->memSize / time * 1e-9 , mTimers [i]->memSize / mStatNEvents , mTimers [i]->memSize / mStatNEvents / mTimers [i]->count );
290293 }
291- printf (" Execution Time: Task (%c %8ux): %50s Time: %'10.0f us%s\n " , type == 0 ? ' K' : ' C' , mTimers [i]->count , mTimers [i]->name .c_str (), time * 1000000 / mStatNEvents , bandwidth);
294+ double elapsedTime_ms = time * 1000000 / mStatNEvents ;
295+ printf (" Execution Time: Task (%c %8ux): %50s Time: %'10.0f us%s\n " , type == 0 ? ' K' : ' C' , mTimers [i]->count , mTimers [i]->name .c_str (), elapsedTime_ms, bandwidth);
296+ if (timingCSVFile.is_open ()) timingCSVFile << mTimers [i]->name << " ," << elapsedTime_ms << " ," << mTimers [i]->count << " ,Task\n " ;
292297 if (GetProcessingSettings ().resetTimers ) {
293298 mTimers [i]->count = 0 ;
294299 mTimers [i]->memSize = 0 ;
@@ -298,8 +303,10 @@ int32_t GPUReconstructionCPU::RunChains()
298303 if (GetProcessingSettings ().recoTaskTiming ) {
299304 for (int32_t i = 0 ; i < gpudatatypes::N_RECO_STEPS; i++) {
300305 if (kernelStepTimes[i] != 0 . || mTimersRecoSteps [i].timerTotal .GetElapsedTime () != 0 .) {
306+ double elapsedTime_ms = kernelStepTimes[i] * 1000000 / mStatNEvents ;
301307 printf (" Execution Time: Step : %11s %38s Time: %'10.0f us %64s ( Total Time : %'14.0f us, CPU Time : %'14.0f us, %'7.2fx )\n " , " Tasks" ,
302- gpudatatypes::RECO_STEP_NAMES[i], kernelStepTimes[i] * 1000000 / mStatNEvents , " " , mTimersRecoSteps [i].timerTotal .GetElapsedTime () * 1000000 / mStatNEvents , mTimersRecoSteps [i].timerCPU * 1000000 / mStatNEvents , mTimersRecoSteps [i].timerCPU / mTimersRecoSteps [i].timerTotal .GetElapsedTime ());
308+ gpudatatypes::RECO_STEP_NAMES[i], elapsedTime_ms, " " , mTimersRecoSteps [i].timerTotal .GetElapsedTime () * 1000000 / mStatNEvents , mTimersRecoSteps [i].timerCPU * 1000000 / mStatNEvents , mTimersRecoSteps [i].timerCPU / mTimersRecoSteps [i].timerTotal .GetElapsedTime ());
309+ if (timingCSVFile.is_open ()) timingCSVFile << gpudatatypes::RECO_STEP_NAMES[i] << " ," << elapsedTime_ms << " ,1,Step\n " ;
303310 }
304311 if (mTimersRecoSteps [i].bytesToGPU ) {
305312 printf (" Execution Time: Step (D %8ux): %11s %38s Time: %'10.0f us (%8.3f GB/s - %'14zu bytes - %'14zu per call)\n " , mTimersRecoSteps [i].countToGPU , " DMA to GPU" , gpudatatypes::RECO_STEP_NAMES[i], mTimersRecoSteps [i].timerToGPU .GetElapsedTime () * 1000000 / mStatNEvents ,
@@ -320,17 +327,22 @@ int32_t GPUReconstructionCPU::RunChains()
320327 }
321328 }
322329 for (int32_t i = 0 ; i < gpudatatypes::N_GENERAL_STEPS; i++) {
323- if (mTimersGeneralSteps [i].GetElapsedTime () != 0 .) {
324- printf (" Execution Time: General Step : %50s Time: %'10.0f us\n " , gpudatatypes::GENERAL_STEP_NAMES[i], mTimersGeneralSteps [i].GetElapsedTime () * 1000000 / mStatNEvents );
330+ double elapsedTime_ms = mTimersGeneralSteps [i].GetElapsedTime () * 1000000 / mStatNEvents ;
331+ if (elapsedTime_ms != 0 .) {
332+ printf (" Execution Time: General Step : %50s Time: %'10.0f us\n " , gpudatatypes::GENERAL_STEP_NAMES[i], elapsedTime_ms);
333+ if (timingCSVFile.is_open ()) timingCSVFile << gpudatatypes::GENERAL_STEP_NAMES[i] << " ," << elapsedTime_ms << " ,1,Step\n " ;
325334 }
326335 }
327336 if (GetProcessingSettings ().debugLevel >= 1 ) {
328337 mStatKernelTime = kernelTotal * 1000000 / mStatNEvents ;
329338 printf (" Execution Time: Total : %50s Time: %'10.0f us%s\n " , " Total Kernel" , mStatKernelTime , nEventReport.c_str ());
339+ if (timingCSVFile.is_open ()) timingCSVFile << " Total Kernel" << " ," << mStatKernelTime << " ,1,Total\n " ;
330340 }
331341 printf (" Execution Time: Total : %50s Time: %'10.0f us ( CPU Time : %'10.0f us, %7.2fx ) %s\n " , " Total Wall" , mStatWallTime , mStatCPUTime * 1000000 / mStatNEvents , mStatCPUTime / mTimerTotal .GetElapsedTime (), nEventReport.c_str ());
342+ if (timingCSVFile.is_open ()) timingCSVFile << " Total Wall" << " ," << mStatWallTime << " ,1,Total\n " ;
332343 } else if (GetProcessingSettings ().debugLevel >= 0 ) {
333344 GPUInfo (" Total Wall Time: %10.0f us%s" , mStatWallTime , nEventReport.c_str ());
345+ if (timingCSVFile.is_open ()) timingCSVFile << " Total Wall" << " ," << mStatWallTime << " ,1,Total\n " ;
334346 }
335347 if (GetProcessingSettings ().resetTimers ) {
336348 mStatNEvents = 0 ;
0 commit comments