41 #include "BESStopWatch.h"
50 #define TIMING_LOG(x) MR_LOG(TIMING_LOG_KEY, x)
52 #define MODULE TIMING_LOG_KEY
53 #define prolog string("BESStopWatch::").append(__func__).append("() - ")
55 namespace bes_timing {
69 return start(name, MISSING_LOG_PARAM) ;
87 if(!get_time_of_day(d_start_usage)){
93 if( gettimeofday(&d_start_usage, NULL) != 0 )
96 char *c_err = strerror( myerrno ) ;
97 string errno_msg = ((c_err != 0) ? c_err :
"unknown error");
100 std::stringstream msg;
101 msg <<
"[" << BESDebug::GetPidStr() <<
"][" << d_log_name <<
"][" << d_req_id <<
"][ERROR]";
102 msg <<
"["<< d_timer_name <<
"]";
103 msg <<
"[" << prolog <<
"gettimeofday() failed. Message: " << errno_msg <<
"]" << endl;
106 std::stringstream msg;
107 msg << prolog <<
"gettimeofday() failed. Message: " << errno_msg << endl;
108 ERROR_LOG(msg.str());
122 std::stringstream msg;
123 if(BESLog::TheLog()->is_verbose()){
124 msg <<
"start_us" << BESLog::mark << get_start_us() << BESLog::mark;
125 msg << (d_req_id.empty()?
"-":d_req_id) << BESLog::mark;
126 msg << d_timer_name << endl;
127 TIMING_LOG(msg.str());
130 msg << get_debug_log_line_prefix();
131 msg <<
"[" << d_log_name <<
"]";
132 msg <<
"[STARTED][" << get_start_us() <<
" us]";
133 msg <<
"[" << d_req_id <<
"]";
134 msg <<
"[" << d_timer_name <<
"]" << endl;
145 bool BESStopWatch::get_time_of_day(
struct timeval &time_val)
148 if( gettimeofday(&time_val, NULL) != 0 )
151 char *c_err = strerror(myerrno);
152 string errno_msg = (c_err != 0) ? c_err :
"unknown error";
153 std::stringstream msg;
154 msg << prolog <<
"ERROR The gettimeofday() function failed. errno_msg: " << errno_msg << endl;
158 ERROR_LOG(msg.str());
178 if(!get_time_of_day(d_stop_usage)){
184 if( gettimeofday(&d_stop_usage, NULL) != 0 )
187 char *c_err = strerror(myerrno);
188 string errno_msg = (c_err != 0) ? c_err :
"unknown error";
191 std::stringstream msg;
192 msg <<
"[" << BESDebug::GetPidStr() <<
"][" << d_log_name <<
"]";
193 msg <<
"[" << d_req_id <<
"][ERROR][" << d_timer_name <<
"][" << errno_msg <<
"]" << endl;
197 std::stringstream msg;
198 msg <<
"[" << BESDebug::GetPidStr() <<
"][" << d_log_name <<
"][" << d_req_id <<
"][ERROR]";
199 msg <<
"["<< d_timer_name <<
"]";
200 msg <<
"[" << prolog <<
"gettimeofday() failed. errno_msg: " << errno_msg <<
"]" << endl;
203 std::stringstream msg;
204 msg << prolog <<
"gettimeofday() failed. errno_msg: " << errno_msg << endl;
205 ERROR_LOG(msg.str());
214 std::stringstream msg;
215 msg << get_debug_log_line_prefix();
216 msg <<
"[" << d_log_name <<
"]";
217 msg <<
"[ELAPSED][" << get_elapsed_us() <<
" us]";
218 msg <<
"[STARTED][" << get_start_us() <<
" us]";
219 msg <<
"[STOPPED][" << get_stop_us() <<
" us]";
220 msg <<
"[" << (d_req_id.empty()?
"-":d_req_id) <<
"]";
221 msg <<
"[" << d_timer_name <<
"]";
224 std::stringstream msg;
225 msg <<
"elapsed_us" << BESLog::mark << get_elapsed_us() << BESLog::mark;
226 msg <<
"start_us" << BESLog::mark << get_start_us() << BESLog::mark;
227 msg <<
"stop_us" << BESLog::mark << get_stop_us() << BESLog::mark;
228 msg << (d_req_id.empty()?
"-":d_req_id) << BESLog::mark;
229 msg << d_timer_name << endl;
230 TIMING_LOG(msg.str());
240 unsigned long int BESStopWatch::get_elapsed_us()
242 return get_stop_us() - get_start_us();
245 unsigned long int BESStopWatch::get_start_us()
247 return d_start_usage.tv_sec*1000*1000 + d_start_usage.tv_usec;
250 unsigned long int BESStopWatch::get_stop_us()
252 return d_stop_usage.tv_sec*1000*1000 + d_stop_usage.tv_usec;
265 BESStopWatch::timeval_subtract()
272 if( d_stop_usage.tv_usec < d_start_usage.tv_usec )
274 int nsec = (d_start_usage.tv_usec - d_stop_usage.tv_usec) / 1000000 + 1 ;
275 d_start_usage.tv_usec -= 1000000 * nsec ;
276 d_start_usage.tv_sec += nsec ;
278 if( d_stop_usage.tv_usec - d_start_usage.tv_usec > 1000000 )
280 int nsec = (d_start_usage.tv_usec - d_stop_usage.tv_usec) / 1000000 ;
281 d_start_usage.tv_usec += 1000000 * nsec ;
282 d_start_usage.tv_sec -= nsec ;
287 d_result.tv_sec = d_stop_usage.tv_sec - d_start_usage.tv_sec ;
288 d_result.tv_usec = d_stop_usage.tv_usec - d_start_usage.tv_usec ;
291 return !(d_stop_usage.tv_sec < d_start_usage.tv_sec) ;
308 if( getrusage( RUSAGE_SELF, &_start_usage ) != 0 )
310 int myerrno = errno ;
311 char *c_err = strerror( myerrno ) ;
312 string err =
"getrusage failed in start: " ;
313 err += (c_err != 0) ? c_err :
"unknown error";
321 err +=
"unknown error" ;
324 std::stringstream msg;
325 msg <<
"[" << BESDebug::GetPidStr() <<
"]["<< d_log_name <<
"][" << d_req_id <<
"]";
326 msg <<
"[ERROR][" << d_timer_name <<
"][" << err <<
"]" << endl;
336 struct timeval &
start = _start_usage.ru_utime ;
337 double starttime =
start.tv_sec*1000.0 +
start.tv_usec/1000.0;
339 std::stringstream msg;
340 msg <<
"[" << BESDebug::GetPidStr() <<
"]["<< d_log_name <<
"][" << d_req_id <<
"]";
341 msg <<
"[STARTED][" << starttime <<
" ms]["<< d_timer_name <<
"]" << endl;
367 if (getrusage(RUSAGE_SELF, &_stop_usage) != 0) {
369 char *c_err = strerror(myerrno);
370 string err =
"getrusage failed in stop: ";
371 err += (c_err != 0) ? c_err :
"unknown error";
379 err +=
"unknown error" ;
382 std::stringstream msg;
383 msg <<
"[" << BESDebug::GetPidStr() <<
"][" << d_log_name <<
"]";
384 msg <<
"[" << d_req_id <<
"][ERROR][" << d_timer_name <<
"][" << err <<
"]" << endl;
394 bool success = timeval_subtract();
397 std::stringstream msg;
398 msg <<
"[" << BESDebug::GetPidStr() <<
"][" << d_log_name <<
"]";
399 msg <<
"[" << d_req_id <<
"][ERROR][" << d_timer_name <<
"][Failed to get timing.]" << endl;
412 struct timeval &stop = _stop_usage.ru_utime;
413 double stoptime = stop.tv_sec * 1000.0 + stop.tv_usec / 1000.0;
414 double elapsed = _result.tv_sec * 1000.0 + _result.tv_usec / 1000.0;
416 std::stringstream msg;
417 msg <<
"[" << BESDebug::GetPidStr() <<
"][" << d_log_name <<
"]";
418 msg <<
"[" << d_req_id <<
"][STOPPED][" << stoptime <<
" ms]";
419 msg <<
"[" << d_timer_name <<
"][ELAPSED][" << elapsed <<
" ms]" << endl;
430 BESStopWatch::timeval_subtract()
432 struct timeval &
start = _start_usage.ru_utime ;
433 struct timeval &stop = _stop_usage.ru_utime ;
436 if( stop.tv_usec <
start.tv_usec )
438 int nsec = (
start.tv_usec - stop.tv_usec) / 1000000 + 1 ;
439 start.tv_usec -= 1000000 * nsec ;
440 start.tv_sec += nsec ;
442 if( stop.tv_usec -
start.tv_usec > 1000000 )
444 int nsec = (
start.tv_usec - stop.tv_usec) / 1000000 ;
445 start.tv_usec += 1000000 * nsec ;
446 start.tv_sec -= nsec ;
451 _result.tv_sec = stop.tv_sec -
start.tv_sec ;
452 _result.tv_usec = stop.tv_usec -
start.tv_usec ;
455 return !(stop.tv_sec <
start.tv_sec) ;
468 strm << BESIndent::LMarg <<
"BESStopWatch::dump - ("
469 << (
void *)
this <<
")" << endl ;
static std::ostream * GetStrm()
return the debug stream
virtual bool start(std::string name)
virtual void dump(std::ostream &strm) const
dumps information about this object