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("() - ")
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;
145bool 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::unique_lock<std::mutex> lck (bes_debug_log_mutex);
215 std::stringstream msg;
216 msg << get_debug_log_line_prefix();
217 msg <<
"[" << d_log_name <<
"]";
218 msg <<
"[ELAPSED][" << get_elapsed_us() <<
" us]";
219 msg <<
"[STARTED][" << get_start_us() <<
" us]";
220 msg <<
"[STOPPED][" << get_stop_us() <<
" us]";
221 msg <<
"[" << (d_req_id.empty()?
"-":d_req_id) <<
"]";
222 msg <<
"[" << d_timer_name <<
"]";
225 std::stringstream msg;
226 msg <<
"elapsed_us" << BESLog::mark << get_elapsed_us() << BESLog::mark;
227 msg <<
"start_us" << BESLog::mark << get_start_us() << BESLog::mark;
228 msg <<
"stop_us" << BESLog::mark << get_stop_us() << BESLog::mark;
229 msg << (d_req_id.empty()?
"-":d_req_id) << BESLog::mark;
230 msg << d_timer_name << endl;
231 TIMING_LOG(msg.str());
241unsigned long int BESStopWatch::get_elapsed_us()
243 return get_stop_us() - get_start_us();
246unsigned long int BESStopWatch::get_start_us()
248 return d_start_usage.tv_sec*1000*1000 + d_start_usage.tv_usec;
251unsigned long int BESStopWatch::get_stop_us()
253 return d_stop_usage.tv_sec*1000*1000 + d_stop_usage.tv_usec;
266BESStopWatch::timeval_subtract()
273 if( d_stop_usage.tv_usec < d_start_usage.tv_usec )
275 int nsec = (d_start_usage.tv_usec - d_stop_usage.tv_usec) / 1000000 + 1 ;
276 d_start_usage.tv_usec -= 1000000 * nsec ;
277 d_start_usage.tv_sec += nsec ;
279 if( d_stop_usage.tv_usec - d_start_usage.tv_usec > 1000000 )
281 int nsec = (d_start_usage.tv_usec - d_stop_usage.tv_usec) / 1000000 ;
282 d_start_usage.tv_usec += 1000000 * nsec ;
283 d_start_usage.tv_sec -= nsec ;
288 d_result.tv_sec = d_stop_usage.tv_sec - d_start_usage.tv_sec ;
289 d_result.tv_usec = d_stop_usage.tv_usec - d_start_usage.tv_usec ;
292 return !(d_stop_usage.tv_sec < d_start_usage.tv_sec) ;
309 if( getrusage( RUSAGE_SELF, &_start_usage ) != 0 )
311 int myerrno = errno ;
312 char *c_err = strerror( myerrno ) ;
313 string err =
"getrusage failed in start: " ;
314 err += (c_err != 0) ? c_err :
"unknown error";
322 err +=
"unknown error" ;
325 std::stringstream msg;
326 msg <<
"[" << BESDebug::GetPidStr() <<
"]["<< d_log_name <<
"][" << d_req_id <<
"]";
327 msg <<
"[ERROR][" << d_timer_name <<
"][" << err <<
"]" << endl;
337 struct timeval &
start = _start_usage.ru_utime ;
338 double starttime =
start.tv_sec*1000.0 +
start.tv_usec/1000.0;
340 std::stringstream msg;
341 msg <<
"[" << BESDebug::GetPidStr() <<
"]["<< d_log_name <<
"][" << d_req_id <<
"]";
342 msg <<
"[STARTED][" << starttime <<
" ms]["<< d_timer_name <<
"]" << endl;
368 if (getrusage(RUSAGE_SELF, &_stop_usage) != 0) {
370 char *c_err = strerror(myerrno);
371 string err =
"getrusage failed in stop: ";
372 err += (c_err != 0) ? c_err :
"unknown error";
380 err +=
"unknown error" ;
383 std::stringstream msg;
384 msg <<
"[" << BESDebug::GetPidStr() <<
"][" << d_log_name <<
"]";
385 msg <<
"[" << d_req_id <<
"][ERROR][" << d_timer_name <<
"][" << err <<
"]" << endl;
395 bool success = timeval_subtract();
398 std::stringstream msg;
399 msg <<
"[" << BESDebug::GetPidStr() <<
"][" << d_log_name <<
"]";
400 msg <<
"[" << d_req_id <<
"][ERROR][" << d_timer_name <<
"][Failed to get timing.]" << endl;
413 struct timeval &stop = _stop_usage.ru_utime;
414 double stoptime = stop.tv_sec * 1000.0 + stop.tv_usec / 1000.0;
415 double elapsed = _result.tv_sec * 1000.0 + _result.tv_usec / 1000.0;
417 std::stringstream msg;
418 msg <<
"[" << BESDebug::GetPidStr() <<
"][" << d_log_name <<
"]";
419 msg <<
"[" << d_req_id <<
"][STOPPED][" << stoptime <<
" ms]";
420 msg <<
"[" << d_timer_name <<
"][ELAPSED][" << elapsed <<
" ms]" << endl;
431BESStopWatch::timeval_subtract()
433 struct timeval &
start = _start_usage.ru_utime ;
434 struct timeval &stop = _stop_usage.ru_utime ;
437 if( stop.tv_usec <
start.tv_usec )
439 int nsec = (
start.tv_usec - stop.tv_usec) / 1000000 + 1 ;
440 start.tv_usec -= 1000000 * nsec ;
441 start.tv_sec += nsec ;
443 if( stop.tv_usec -
start.tv_usec > 1000000 )
445 int nsec = (
start.tv_usec - stop.tv_usec) / 1000000 ;
446 start.tv_usec += 1000000 * nsec ;
447 start.tv_sec -= nsec ;
452 _result.tv_sec = stop.tv_sec -
start.tv_sec ;
453 _result.tv_usec = stop.tv_usec -
start.tv_usec ;
456 return !(stop.tv_sec <
start.tv_sec) ;
470 strm << BESIndent::LMarg <<
"BESStopWatch::dump - ("
471 << (
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