bes  Updated for version 3.20.10
BESStopWatch.cc
1 // BESStopWatch.cc
2 
3 // This file is part of bes, A C++ back-end server implementation framework
4 // for the OPeNDAP Data Access Protocol.
5 
6 // Copyright (c) 2004-2009 University Corporation for Atmospheric Research
7 // Author: Patrick West <pwest@ucar.edu> and Jose Garcia <jgarcia@ucar.edu>
8 //
9 // This library is free software; you can redistribute it and/or
10 // modify it under the terms of the GNU Lesser General Public
11 // License as published by the Free Software Foundation; either
12 // version 2.1 of the License, or (at your option) any later version.
13 //
14 // This library is distributed in the hope that it will be useful,
15 // but WITHOUT ANY WARRANTY; without even the implied warranty of
16 // MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
17 // Lesser General Public License for more details.
18 //
19 // You should have received a copy of the GNU Lesser General Public
20 // License along with this library; if not, write to the Free Software
21 // Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA
22 //
23 // You can contact University Corporation for Atmospheric Research at
24 // 3080 Center Green Drive, Boulder, CO 80301
25 
26 // (c) COPYRIGHT University Corporation for Atmospheric Research 2004-2005
27 // Please read the full copyright statement in the file COPYRIGHT_UCAR.
28 //
29 // Authors:
30 // ndp Nathan Potter <ndp@opendap.org>
31 // pwest Patrick West <pwest@ucar.edu>
32 // jgarcia Jose Garcia <jgarcia@ucar.edu>
33 #include "config.h"
34 
35 #include <cerrno>
36 #include <string>
37 #include <iostream>
38 #include <cstring>
39 #include <sstream>
40 
41 #include "BESStopWatch.h"
42 #include "BESDebug.h"
43 #include "BESLog.h"
44 
45 using std::string ;
46 using std::endl;
47 using std::ostream;
48 
49 
50 #define TIMING_LOG(x) MR_LOG(TIMING_LOG_KEY, x)
51 
52 #define MODULE TIMING_LOG_KEY
53 #define prolog string("BESStopWatch::").append(__func__).append("() - ")
54 
55 namespace bes_timing {
56 BESStopWatch *elapsedTimeToReadStart=0;
57 BESStopWatch *elapsedTimeToTransmitStart=0;
58 }
59 
66 bool
67 BESStopWatch::start(string name)
68 {
69  return start(name, MISSING_LOG_PARAM) ;
70 }
71 
80 bool
81 BESStopWatch::start(string name, string reqID)
82 {
83  d_timer_name = name;
84  d_req_id = reqID;
85  // get timing for current usage
86 
87  if(!get_time_of_day(d_start_usage)){
88  d_started = false;
89  return d_started;
90  }
91 
92 #if 0
93  if( gettimeofday(&d_start_usage, NULL) != 0 )
94  {
95  int myerrno = errno ;
96  char *c_err = strerror( myerrno ) ;
97  string errno_msg = ((c_err != 0) ? c_err : "unknown error");
98 
99  if(BESDebug::GetStrm()){
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;
104  *(BESDebug::GetStrm()) << msg.str();
105  }
106  std::stringstream msg;
107  msg << prolog << "gettimeofday() failed. Message: " << errno_msg << endl;
108  ERROR_LOG(msg.str());
109  d_started = false ;
110  }
111  else
112  {
113  }
114 #endif
115  d_started = true ;
116  // Convert to milliseconds. Multiply seconds by 1000, divide micro seconds by 1000
117  // double starttime = d_start_usage.tv_sec*1000.0 + d_start_usage.tv_usec/1000.0;
118 
119  // Convert to microseconds
120  //unsigned long int start_time_us = d_start_usage.tv_sec*1000*1000 + d_start_usage.tv_usec;
121 
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());
128  }
129  if ( BESDebug::GetStrm()) {
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;
135  *(BESDebug::GetStrm()) << msg.str();
136  }
137 
138  // }
139  // either we started the stop watch, or failed to start it. Either way,
140  // no timings are available, so set stopped to false.
141  d_stopped = false ;
142  return d_started ;
143 }
144 
145 bool BESStopWatch::get_time_of_day(struct timeval &time_val)
146 {
147  bool retval = true;
148  if( gettimeofday(&time_val, NULL) != 0 )
149  {
150  int myerrno = errno;
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;
155  if ( BESDebug::GetStrm()) {
156  *(BESDebug::GetStrm()) << get_debug_log_line_prefix() << msg.str();
157  }
158  ERROR_LOG(msg.str());
159  retval = false;
160  }
161  return retval;
162 
163 }
164 
173 {
174  // if we have started, then stop and update the log.
175  if (d_started) {
176  // get timing for current usage
177 
178  if(!get_time_of_day(d_stop_usage)){
179  d_started = false;
180  d_stopped = false;
181  return;
182  }
183 #if 0
184  if( gettimeofday(&d_stop_usage, NULL) != 0 )
185  {
186  int myerrno = errno;
187  char *c_err = strerror(myerrno);
188  string errno_msg = (c_err != 0) ? c_err : "unknown error";
189 
190 #if 0
191  std::stringstream msg;
192  msg << "[" << BESDebug::GetPidStr() << "][" << d_log_name << "]";
193  msg << "[" << d_req_id << "][ERROR][" << d_timer_name << "][" << errno_msg << "]" << endl;
194 #endif
195 
196  if (BESDebug::GetStrm()){
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;
201  *(BESDebug::GetStrm()) << msg.str();
202  }
203  std::stringstream msg;
204  msg << prolog << "gettimeofday() failed. errno_msg: " << errno_msg << endl;
205  ERROR_LOG(msg.str());
206 
207  d_started = false;
208  d_stopped = false;
209  }
210  else {
211 #endif
212  d_stopped = true;
213  if (BESDebug::GetStrm()) {
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 << "]";
223  *(BESDebug::GetStrm()) << msg.str() << endl;
224  }
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());
232 
233  //}
234  }
235 }
241 unsigned long int BESStopWatch::get_elapsed_us()
242 {
243  return get_stop_us() - get_start_us();
244 }
245 
246 unsigned long int BESStopWatch::get_start_us()
247 {
248  return d_start_usage.tv_sec*1000*1000 + d_start_usage.tv_usec;
249 }
250 
251 unsigned long int BESStopWatch::get_stop_us()
252 {
253  return d_stop_usage.tv_sec*1000*1000 + d_stop_usage.tv_usec;
254 }
255 
256 
257 #if 0
265 bool
266 BESStopWatch::timeval_subtract()
267 {
268  // struct
269  // time_t tv_sec seconds
270  // suseconds_t tv_usec microseconds
271 
272  /* Perform the carry for the later subtraction by updating y. */
273  if( d_stop_usage.tv_usec < d_start_usage.tv_usec )
274  {
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 ;
278  }
279  if( d_stop_usage.tv_usec - d_start_usage.tv_usec > 1000000 )
280  {
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 ;
284  }
285 
286  /* Compute the time remaining to wait.
287  tv_usec is certainly positive. */
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 ;
290 
291  /* Return 1 if result is negative. */
292  return !(d_stop_usage.tv_sec < d_start_usage.tv_sec) ;
293 }
294 
303 bool
304 BESStopWatch::start(string name, string reqID)
305 {
306  d_timer_name = name;
307  d_req_id = reqID;
308  // get timing for current usage
309  if( getrusage( RUSAGE_SELF, &_start_usage ) != 0 )
310  {
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";
315 #if 0
316  if( c_err )
317  {
318  err += c_err ;
319  }
320  else
321  {
322  err += "unknown error" ;
323  }
324 #endif
325  std::stringstream msg;
326  msg << "[" << BESDebug::GetPidStr() << "]["<< d_log_name << "][" << d_req_id << "]";
327  msg << "[ERROR][" << d_timer_name << "][" << err << "]" << endl;
328 
329  if(!BESLog::TheLog()->is_verbose() && BESDebug::GetStrm())
330  *(BESDebug::GetStrm()) << msg.str();
331  VERBOSE(msg.str());
332  d_started = false ;
333  }
334  else
335  {
336  d_started = true ;
337  struct timeval &start = _start_usage.ru_utime ;
338  double starttime = start.tv_sec*1000.0 + start.tv_usec/1000.0;
339 
340  std::stringstream msg;
341  msg << "[" << BESDebug::GetPidStr() << "]["<< d_log_name << "][" << d_req_id << "]";
342  msg << "[STARTED][" << starttime << " ms]["<< d_timer_name << "]" << endl;
343  if(!BESLog::TheLog()->is_verbose() && BESDebug::GetStrm())
344  *(BESDebug::GetStrm()) << msg.str();
345  VERBOSE(msg.str());
346  }
347 
348  // either we started the stop watch, or failed to start it. Either way,
349  // no timings are available, so set stopped to false.
350  d_stopped = false ;
351 
352 
353  return d_started ;
354 }
355 
364 {
365  // if we have started, then stop and update the log.
366  if (d_started) {
367  // get timing for current usage
368  if (getrusage(RUSAGE_SELF, &_stop_usage) != 0) {
369  int myerrno = errno;
370  char *c_err = strerror(myerrno);
371  string err = "getrusage failed in stop: ";
372  err += (c_err != 0) ? c_err : "unknown error";
373 #if 0
374  if( c_err )
375  {
376  err += c_err ;
377  }
378  else
379  {
380  err += "unknown error" ;
381  }
382 #endif
383  std::stringstream msg;
384  msg << "[" << BESDebug::GetPidStr() << "][" << d_log_name << "]";
385  msg << "[" << d_req_id << "][ERROR][" << d_timer_name << "][" << err << "]" << endl;
386  if (!BESLog::TheLog()->is_verbose() && BESDebug::GetStrm())
387  *(BESDebug::GetStrm()) << msg.str();
388  VERBOSE(msg.str());
389 
390  d_started = false;
391  d_stopped = false;
392  } else {
393  // get the difference between the _start_usage and the
394  // _stop_usage and save the difference in _result.
395  bool success = timeval_subtract();
396  if (!success)
397  {
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;
401 
402  if (!BESLog::TheLog()->is_verbose() && BESDebug::GetStrm())
403  *(BESDebug::GetStrm()) << msg.str();
404  VERBOSE(msg.str());
405 
406  d_started = false;
407  d_stopped = false;
408  }
409  else
410  {
411  d_stopped = true;
412 
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;
416 
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;
421 
422  if (!BESLog::TheLog()->is_verbose() && BESDebug::GetStrm())
423  *(BESDebug::GetStrm()) << msg.str();
424  VERBOSE(msg.str() );
425  }
426  }
427  }
428 }
429 
430 bool
431 BESStopWatch::timeval_subtract()
432 {
433  struct timeval &start = _start_usage.ru_utime ;
434  struct timeval &stop = _stop_usage.ru_utime ;
435 
436  /* Perform the carry for the later subtraction by updating y. */
437  if( stop.tv_usec < start.tv_usec )
438  {
439  int nsec = (start.tv_usec - stop.tv_usec) / 1000000 + 1 ;
440  start.tv_usec -= 1000000 * nsec ;
441  start.tv_sec += nsec ;
442  }
443  if( stop.tv_usec - start.tv_usec > 1000000 )
444  {
445  int nsec = (start.tv_usec - stop.tv_usec) / 1000000 ;
446  start.tv_usec += 1000000 * nsec ;
447  start.tv_sec -= nsec ;
448  }
449 
450  /* Compute the time remaining to wait.
451  tv_usec is certainly positive. */
452  _result.tv_sec = stop.tv_sec - start.tv_sec ;
453  _result.tv_usec = stop.tv_usec - start.tv_usec ;
454 
455  /* Return 1 if result is negative. */
456  return !(stop.tv_sec < start.tv_sec) ;
457 }
458 
459 #endif
466 void
467 BESStopWatch::dump( ostream &strm ) const
468 {
469  strm << BESIndent::LMarg << "BESStopWatch::dump - ("
470  << (void *)this << ")" << endl ;
471 }
472 
473 
474 
475 
476 
static std::ostream * GetStrm()
return the debug stream
Definition: BESDebug.h:187
virtual bool start(std::string name)
Definition: BESStopWatch.cc:67
virtual void dump(std::ostream &strm) const
dumps information about this object
virtual ~BESStopWatch()