Profiling.h
1 /*
2  * Medical Image Registration ToolKit (MIRTK)
3  *
4  * Copyright 2013-2015 Imperial College London
5  * Copyright 2013-2015 Andreas Schuh
6  *
7  * Licensed under the Apache License, Version 2.0 (the "License");
8  * you may not use this file except in compliance with the License.
9  * You may obtain a copy of the License at
10  *
11  * http://www.apache.org/licenses/LICENSE-2.0
12  *
13  * Unless required by applicable law or agreed to in writing, software
14  * distributed under the License is distributed on an "AS IS" BASIS,
15  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
16  * See the License for the specific language governing permissions and
17  * limitations under the License.
18  */
19 
20 #ifndef MIRTK_Profiling_H
21 #define MIRTK_Profiling_H
22 
23 #include "mirtk/CommonExport.h"
24 
25 #include "mirtk/Stream.h"
26 #include "mirtk/String.h"
27 
28 #include <ctime>
29 #ifdef HAVE_TBB
30 // TBB includes windows header which defines min/max macros otherwise
31 # ifndef NOMINMAX
32 # define NOMINMAX
33 # define MIRTK_UNDEF_NOMINMAX
34 # endif
35 # include <tbb/tick_count.h>
36 # ifdef MIRTK_UNDEF_NOMINMAX
37 # undef MIRTK_UNDEF_NOMINMAX
38 # undef NOMINMAX
39 # endif
40 #endif
41 
42 
43 namespace mirtk {
44 
45 
46 // -----------------------------------------------------------------------------
47 enum TimeUnit
48 {
49  TIME_IN_DEFAULT_UNIT,
50  TIME_IN_MILLISECONDS,
51  TIME_IN_SECONDS
52 };
53 
54 enum TimeFormat
55 {
56  TIME_FORMAT_UNITS, ///< Print elapsed time using time units
57  TIME_FORMAT_HHMMSS, ///< Print elapsed time with format "HH:MM:SS"
58  TIME_FORMAT_H_MIN_SEC, ///< Print elapsed time with format "[H h] [M min] [S sec]"
59  TIME_FORMAT_MIN_SEC ///< Print elapsed time with format "[M min] [S sec]"
60 };
61 
62 // =============================================================================
63 // Global profiling options
64 // =============================================================================
65 
66 /// Enable/disable profiling of execution time.
67 ///
68 /// Should be set in the main function before any processing starts, e.g.,
69 /// depending on a command-line flag (for example -v -verbose).
70 /// If less or equal to zero, no timing measurements are printed to screen.
71 /// Otherwise, whether a timing measure is output or not depends on the
72 /// set debugging level.
73 MIRTK_Common_EXPORT extern int debug_time;
74 
75 /// Time unit to use for output of time measurements.
76 MIRTK_Common_EXPORT extern TimeUnit debug_time_unit;
77 
78 // =============================================================================
79 // Command help
80 // =============================================================================
81 
82 /// Check if given option is a profiling option
83 bool IsProfilingOption(const char *);
84 
85 /// Parse profiling option
86 void ParseProfilingOption(int &, int &, char *[]);
87 
88 /// Print profiling command-line options
89 void PrintProfilingOptions(ostream &);
90 
91 // =============================================================================
92 // CPU Profiling
93 // =============================================================================
94 
95 /// Print elapsed time for profiled section
96 void PrintElapsedTime(const char *, double, TimeUnit = TIME_IN_SECONDS);
97 
98 /// Convert elapsed time given in the specified units to string of given format
99 ///
100 /// \param[in] t Elapsed time in specified \p units.
101 /// \param[in] units Units of time measurement.
102 /// \param[in] fmt Time string format.
103 /// \param[in] w Width of time field when \p fmt is not TIME_FORMAT_HHMMSS.
104 /// \param[in] c Character used to fill time field.
105 /// \param[in] left Whether to print time value left justified.
106 string ElapsedTimeToString(double t, TimeUnit units = TIME_IN_SECONDS,
107  TimeFormat fmt = TIME_FORMAT_HHMMSS,
108  int w = 0, char c = ' ', bool left = false);
109 
110 // -----------------------------------------------------------------------------
111 /// Start measurement of execution time of current code block
112 ///
113 /// @code
114 /// {
115 /// MIRTK_START_TIMING();
116 /// // do some work here
117 /// MIRTK_END_TIMING("example section");
118 /// }
119 /// @endcode
120 ///
121 /// @sa MIRTK_END_TIMING
122 #ifdef MIRTK_WITH_PROFILING
123 # ifdef HAVE_TBB
124 # define MIRTK_START_TIMING() tbb::tick_count t_start = tbb::tick_count::now()
125 # else
126 # define MIRTK_START_TIMING() clock_t t_start = clock()
127 # endif
128 #else
129 # define MIRTK_START_TIMING() do {} while (false)
130 #endif
131 
132 // -----------------------------------------------------------------------------
133 /// Reset measurement of starting execution time of current code block
134 ///
135 /// @code
136 /// {
137 /// MIRTK_START_TIMING();
138 /// // do some work here
139 /// MIRTK_END_TIMING("first part");
140 /// MIRTK_RESET_TIMING();
141 /// // do some work here
142 /// MIRTK_END_TIMING("second part");
143 /// }
144 /// @endcode
145 ///
146 /// @sa MIRTK_END_TIMING
147 #ifdef MIRTK_WITH_PROFILING
148 # ifdef HAVE_TBB
149 # define MIRTK_RESET_TIMING() t_start = tbb::tick_count::now()
150 # else
151 # define MIRTK_RESET_TIMING() t_start = clock()
152 # endif
153 #else
154 # define MIRTK_RESET_TIMING() do {} while (false)
155 #endif
156 
157 // -----------------------------------------------------------------------------
158 /// End measurement of execution time of current code block.
159 ///
160 /// @code
161 /// {
162 /// MIRTK_START_TIMING();
163 /// // do some work here
164 /// MIRTK_END_TIMING("example section");
165 /// }
166 /// @endcode
167 ///
168 /// @note Whether or not the execution time is actually being measured and
169 /// printed to screen is decided at compile time depending on the
170 /// MIRTK_WITH_PROFILING flag.
171 ///
172 /// @sa MIRTK_START_TIMING
173 #ifdef MIRTK_WITH_PROFILING
174 # ifdef HAVE_TBB
175 # define MIRTK_END_TIMING(section) \
176  do { \
177  ostringstream oss; \
178  oss << section; \
179  PrintElapsedTime(oss.str().c_str(), \
180  (tbb::tick_count::now() - t_start).seconds()); \
181  } while (false)
182 # else
183 # define MIRTK_END_TIMING(section) \
184  do { \
185  ostringstream oss; \
186  oss << section; \
187  PrintElapsedTime(oss.str().c_str(), \
188  static_cast<double>(clock() - t_start) \
189  / static_cast<double>(CLOCKS_PER_SEC)); \
190  } while (false)
191 # endif
192 #else
193 # define MIRTK_END_TIMING(section) do {} while (false)
194 #endif
195 
196 // -----------------------------------------------------------------------------
197 /// End measurement of execution time of current code block.
198 ///
199 /// In the following example, the timing measurement are only printed if
200 /// the global execution time debugging level is greater or equal the
201 /// specified debugging level. Hence, if debug_time is 1, only the time of
202 /// the following example section is printed. If debug_time is greater than 1,
203 /// also the times needed for each execution of inner block are printed together
204 /// with the summarizing total execution time of the example section. Otherwise,
205 /// if debug_time is less than 1, no time measurements are printed at all.
206 /// @code
207 /// {
208 /// MIRTK_START_TIMING();
209 /// // do some work here
210 /// {
211 /// MIRTK_START_TIMING();
212 /// // do some part of the work here
213 /// MIRTK_DEBUG_TIMING(2, "example part");
214 /// }
215 /// // possibly combine results and maybe do some clean up work here
216 /// MIRTK_DEBUG_TIMING(1, "example section");
217 /// }
218 /// @endcode
219 ///
220 /// @note Whether or not the execution time is actually being measured and
221 /// printed to screen is decided at runtime depending on the global
222 /// variable debug_time.
223 ///
224 /// @sa MIRTK_START_TIMING
225 #ifdef MIRTK_WITH_PROFILING
226 # ifdef HAVE_TBB
227 # define MIRTK_DEBUG_TIMING(level, section) \
228  do { \
229  if (debug_time >= level) { \
230  ostringstream oss; \
231  oss << section; \
232  PrintElapsedTime(oss.str().c_str(), \
233  (tbb::tick_count::now() - t_start).seconds()); \
234  } \
235  } while (false)
236 # else
237 # define MIRTK_DEBUG_TIMING(level, section) \
238  do { \
239  if (debug_time >= level) { \
240  ostringstream oss; \
241  oss << section; \
242  PrintElapsedTime(oss.str().c_str(), \
243  static_cast<double>(clock() - t_start) \
244  / static_cast<double>(CLOCKS_PER_SEC)); \
245  } \
246  } while (false)
247 # endif
248 #else
249 # define MIRTK_DEBUG_TIMING(level, section) do {} while (false)
250 #endif
251 
252 // =============================================================================
253 // GPU Profiling
254 // =============================================================================
255 
256 // -----------------------------------------------------------------------------
257 /// Start measurement of execution time of current code block.
258 ///
259 /// @code
260 /// {
261 /// MIRTKCU_START_TIMING();
262 /// // launch CUDA kernel here
263 /// MIRTKCU_END_TIMING("example section");
264 /// }
265 /// @endcode
266 ///
267 /// @sa IRTKCU_END_TIMING
268 #ifdef MIRTK_WITH_PROFILING
269 # define MIRTKCU_START_TIMING() \
270  cudaEvent_t e_start, e_stop; \
271  CudaSafeCall( cudaEventCreate(&e_start) ); \
272  CudaSafeCall( cudaEventCreate(&e_stop) ); \
273  CudaSafeCall( cudaEventRecord(e_start, 0) )
274 #else
275 # define MIRTKCU_START_TIMING() do {} while (false)
276 #endif
277 
278 // -----------------------------------------------------------------------------
279 /// Reset measurement of starting execution time of current code block
280 ///
281 /// @code
282 /// {
283 /// MIRTKCU_START_TIMING();
284 /// // do some work here
285 /// MIRTKCU_END_TIMING("first part");
286 /// MIRTKCU_RESET_TIMING();
287 /// // do some work here
288 /// MIRTKCU_END_TIMING("second part");
289 /// }
290 /// @endcode
291 ///
292 /// @sa MIRTKCU_END_TIMING
293 #ifdef MIRTK_WITH_PROFILING
294 # define MIRTKCU_RESET_TIMING() CudaSafeCall( cudaEventRecord(e_start, 0) )
295 #else
296 # define MIRTKCU_RESET_TIMING() do {} while (false)
297 #endif
298 
299 // -----------------------------------------------------------------------------
300 /// Print interim measurement of execution time of current code block.
301 ///
302 /// @code
303 /// {
304 /// MIRTKCU_START_TIMING();
305 /// // launch CUDA kernel here
306 /// MIRTKCU_INTERIM_TIMING("example kernel");
307 /// CudaSafeCall( cudaDeviceSynchronize() );
308 /// MIRTKCU_END_TIMING("example section");
309 /// }
310 /// @endcode
311 ///
312 /// @note Whether or not the execution time is actually being measured and
313 /// printed to screen is decided at compile time depending on the
314 /// MIRTK_WITH_PROFILING flag.
315 ///
316 /// @sa MIRTKCU_START_TIMING
317 #ifdef MIRTK_WITH_PROFILING
318 # define MIRTKCU_INTERIM_TIMING(section) \
319  do { \
320  float t_elapsed; \
321  CudaSafeCall( cudaEventRecord(e_stop, 0) ); \
322  CudaSafeCall( cudaEventSynchronize(e_stop) ); \
323  CudaSafeCall( cudaEventElapsedTime(&t_elapsed, e_start, e_stop) ); \
324  ostringstream oss; \
325  oss << section << " [interim]"; \
326  PrintElapsedTime(oss.str().c_str(), t_elapsed, TIME_IN_MILLISECONDS); \
327  } while (false)
328 #else
329 # define MIRTKCU_INTERIM_TIMING(section) do {} while (false)
330 #endif
331 
332 // -----------------------------------------------------------------------------
333 /// End measurement of execution time of current code block.
334 ///
335 /// @code
336 /// {
337 /// MIRTKCU_START_TIMING();
338 /// // launch CUDA kernel here
339 /// MIRTKCU_END_TIMING("example section");
340 /// }
341 /// @endcode
342 ///
343 /// @note Whether or not the execution time is actually being measured and
344 /// printed to screen is decided at compile time depending on the
345 /// MIRTK_WITH_PROFILING flag.
346 ///
347 /// @sa MIRTKCU_START_TIMING
348 #ifdef MIRTK_WITH_PROFILING
349 # define MIRTKCU_END_TIMING(section) \
350  do { \
351  float t_elapsed; \
352  CudaSafeCall( cudaEventRecord(e_stop, 0) ); \
353  CudaSafeCall( cudaEventSynchronize(e_stop) ); \
354  CudaSafeCall( cudaEventElapsedTime(&t_elapsed, e_start, e_stop) ); \
355  CudaSafeCall( cudaEventDestroy(e_start) ); \
356  CudaSafeCall( cudaEventDestroy(e_stop) ); \
357  ostringstream oss; \
358  oss << section << " [GPU]"; \
359  PrintElapsedTime(oss.str().c_str(), t_elapsed, TIME_IN_MILLISECONDS); \
360  } while (false)
361 #else
362 # define MIRTKCU_END_TIMING(section) do {} while (false)
363 #endif
364 
365 // -----------------------------------------------------------------------------
366 /// Print interim measurement of execution time of current code block.
367 ///
368 /// In the following example, the timing measurement are only printed if
369 /// the global execution time debugging level is greater or equal the
370 /// specified debugging level. Hence, if debug_time is 1, only the time of
371 /// the following example section is printed. If debug_time is greater than 1,
372 /// also the times needed for each execution of inner block are printed together
373 /// with the summarizing total execution time of the example section. Otherwise,
374 /// if debug_time is less than 1, no time measurements are printed at all.
375 /// @code
376 /// {
377 /// MIRTKCU_START_TIMING();
378 /// // launch CUDA kernel here
379 /// MIRTKCU_DEBUG_INTERIM_TIMING(1, "kernel name");
380 /// }
381 /// @endcode
382 ///
383 /// @note Whether or not the execution time is actually being measured and
384 /// printed to screen is decided at runtime depending on the global
385 /// variable debug_time.
386 ///
387 /// @sa MIRTKCU_START_TIMING
388 #ifdef MIRTK_WITH_PROFILING
389 # define MIRTKCU_DEBUG_INTERIM_TIMING(level, section) \
390  if (debug_time >= level) IRTKCU_INTERIM_TIMING(section)
391 #else
392 # define MIRTKCU_DEBUG_INTERIM_TIMING(level, section) do {} while (false)
393 #endif
394 
395 // ---------------------------------------------------------------------------
396 /// End measurement of execution time of current code block.
397 ///
398 /// In the following example, the timing measurement are only printed if
399 /// the global execution time debugging level is greater or equal the
400 /// specified debugging level. Hence, if debug_time is 1, only the time of
401 /// the following example section is printed. If debug_time is greater than 1,
402 /// also the times needed for each execution of inner block are printed together
403 /// with the summarizing total execution time of the example section. Otherwise,
404 /// if debug_time is less than 1, no time measurements are printed at all.
405 /// @code
406 /// {
407 /// MIRTKCU_START_TIMING();
408 /// // launch CUDA kernel here
409 /// MIRTKCU_DEBUG_TIMING(1, "kernel name");
410 /// }
411 /// @endcode
412 ///
413 /// @note Whether or not the execution time is actually being measured and
414 /// printed to screen is decided at runtime depending on the global
415 /// variable debug_time.
416 ///
417 /// @sa MIRTKCU_START_TIMING
418 #ifdef MIRTK_WITH_PROFILING
419 # define MIRTKCU_DEBUG_TIMING(level, section) \
420  if (debug_time >= level) MIRTKCU_END_TIMING(section); \
421  else do { \
422  CudaSafeCall( cudaEventDestroy(e_start) ); \
423  CudaSafeCall( cudaEventDestroy(e_stop) ); \
424  } while (false)
425 #else
426 # define MIRTKCU_DEBUG_TIMING(level, section) do {} while (false)
427 #endif
428 
429 
430 } // namespace mirtk
431 
432 #endif // MIRTK_Profiling_H
mirtk::PrintElapsedTime
void PrintElapsedTime(const char *, double, TimeUnit=TIME_IN_SECONDS)
Print elapsed time for profiled section.
mirtk::ElapsedTimeToString
string ElapsedTimeToString(double t, TimeUnit units=TIME_IN_SECONDS, TimeFormat fmt=TIME_FORMAT_HHMMSS, int w=0, char c=' ', bool left=false)
mirtk::debug_time
MIRTK_Common_EXPORT int debug_time
mirtk::TIME_FORMAT_H_MIN_SEC
Print elapsed time with format "[H h] [M min] [S sec]".
Definition: Profiling.h:58
mirtk::IsProfilingOption
bool IsProfilingOption(const char *)
Check if given option is a profiling option.
mirtk::debug_time_unit
MIRTK_Common_EXPORT TimeUnit debug_time_unit
Time unit to use for output of time measurements.
mirtk::ParseProfilingOption
void ParseProfilingOption(int &, int &, char *[])
Parse profiling option.
mirtk::TIME_FORMAT_UNITS
Print elapsed time using time units.
Definition: Profiling.h:56
mirtk::TIME_FORMAT_HHMMSS
Print elapsed time with format "HH:MM:SS".
Definition: Profiling.h:57
mirtk
Definition: IOConfig.h:41
mirtk::PrintProfilingOptions
void PrintProfilingOptions(ostream &)
Print profiling command-line options.
mirtk::TimeFormat
TimeFormat
Definition: Profiling.h:54
mirtk::TIME_FORMAT_MIN_SEC
Print elapsed time with format "[M min] [S sec]".
Definition: Profiling.h:59
© 2013-2018 Imperial College London, Andreas Schuh.