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 433