bes  Updated for version 3.20.8
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::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 << "]";
222  *(BESDebug::GetStrm()) << msg.str() << endl;
223  }
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());
231 
232  //}
233  }
234 }
240 unsigned long int BESStopWatch::get_elapsed_us()
241 {
242  return get_stop_us() - get_start_us();
243 }
244 
245 unsigned long int BESStopWatch::get_start_us()
246 {
247  return d_start_usage.tv_sec*1000*1000 + d_start_usage.tv_usec;
248 }
249 
250 unsigned long int BESStopWatch::get_stop_us()
251 {
252  return d_stop_usage.tv_sec*1000*1000 + d_stop_usage.tv_usec;
253 }
254 
255 
256 #if 0
264 bool
265 BESStopWatch::timeval_subtract()
266 {
267  // struct
268  // time_t tv_sec seconds
269  // suseconds_t tv_usec microseconds
270 
271  /* Perform the carry for the later subtraction by updating y. */
272  if( d_stop_usage.tv_usec < d_start_usage.tv_usec )
273  {
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 ;
277  }
278  if( d_stop_usage.tv_usec - d_start_usage.tv_usec > 1000000 )
279  {
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 ;
283  }
284 
285  /* Compute the time remaining to wait.
286  tv_usec is certainly positive. */
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 ;
289 
290  /* Return 1 if result is negative. */
291  return !(d_stop_usage.tv_sec < d_start_usage.tv_sec) ;
292 }
293 
302 bool
303 BESStopWatch::start(string name, string reqID)
304 {
305  d_timer_name = name;
306  d_req_id = reqID;
307  // get timing for current usage
308  if( getrusage( RUSAGE_SELF, &_start_usage ) != 0 )
309  {
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";
314 #if 0
315  if( c_err )
316  {
317  err += c_err ;
318  }
319  else
320  {
321  err += "unknown error" ;
322  }
323 #endif
324  std::stringstream msg;
325  msg << "[" << BESDebug::GetPidStr() << "]["<< d_log_name << "][" << d_req_id << "]";
326  msg << "[ERROR][" << d_timer_name << "][" << err << "]" << endl;
327 
328  if(!BESLog::TheLog()->is_verbose() && BESDebug::GetStrm())
329  *(BESDebug::GetStrm()) << msg.str();
330  VERBOSE(msg.str());
331  d_started = false ;
332  }
333  else
334  {
335  d_started = true ;
336  struct timeval &start = _start_usage.ru_utime ;
337  double starttime = start.tv_sec*1000.0 + start.tv_usec/1000.0;
338 
339  std::stringstream msg;
340  msg << "[" << BESDebug::GetPidStr() << "]["<< d_log_name << "][" << d_req_id << "]";
341  msg << "[STARTED][" << starttime << " ms]["<< d_timer_name << "]" << endl;
342  if(!BESLog::TheLog()->is_verbose() && BESDebug::GetStrm())
343  *(BESDebug::GetStrm()) << msg.str();
344  VERBOSE(msg.str());
345  }
346 
347  // either we started the stop watch, or failed to start it. Either way,
348  // no timings are available, so set stopped to false.
349  d_stopped = false ;
350 
351 
352  return d_started ;
353 }
354 
363 {
364  // if we have started, then stop and update the log.
365  if (d_started) {
366  // get timing for current usage
367  if (getrusage(RUSAGE_SELF, &_stop_usage) != 0) {
368  int myerrno = errno;
369  char *c_err = strerror(myerrno);
370  string err = "getrusage failed in stop: ";
371  err += (c_err != 0) ? c_err : "unknown error";
372 #if 0
373  if( c_err )
374  {
375  err += c_err ;
376  }
377  else
378  {
379  err += "unknown error" ;
380  }
381 #endif
382  std::stringstream msg;
383  msg << "[" << BESDebug::GetPidStr() << "][" << d_log_name << "]";
384  msg << "[" << d_req_id << "][ERROR][" << d_timer_name << "][" << err << "]" << endl;
385  if (!BESLog::TheLog()->is_verbose() && BESDebug::GetStrm())
386  *(BESDebug::GetStrm()) << msg.str();
387  VERBOSE(msg.str());
388 
389  d_started = false;
390  d_stopped = false;
391  } else {
392  // get the difference between the _start_usage and the
393  // _stop_usage and save the difference in _result.
394  bool success = timeval_subtract();
395  if (!success)
396  {
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;
400 
401  if (!BESLog::TheLog()->is_verbose() && BESDebug::GetStrm())
402  *(BESDebug::GetStrm()) << msg.str();
403  VERBOSE(msg.str());
404 
405  d_started = false;
406  d_stopped = false;
407  }
408  else
409  {
410  d_stopped = true;
411 
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;
415 
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;
420 
421  if (!BESLog::TheLog()->is_verbose() && BESDebug::GetStrm())
422  *(BESDebug::GetStrm()) << msg.str();
423  VERBOSE(msg.str() );
424  }
425  }
426  }
427 }
428 
429 bool
430 BESStopWatch::timeval_subtract()
431 {
432  struct timeval &start = _start_usage.ru_utime ;
433  struct timeval &stop = _stop_usage.ru_utime ;
434 
435  /* Perform the carry for the later subtraction by updating y. */
436  if( stop.tv_usec < start.tv_usec )
437  {
438  int nsec = (start.tv_usec - stop.tv_usec) / 1000000 + 1 ;
439  start.tv_usec -= 1000000 * nsec ;
440  start.tv_sec += nsec ;
441  }
442  if( stop.tv_usec - start.tv_usec > 1000000 )
443  {
444  int nsec = (start.tv_usec - stop.tv_usec) / 1000000 ;
445  start.tv_usec += 1000000 * nsec ;
446  start.tv_sec -= nsec ;
447  }
448 
449  /* Compute the time remaining to wait.
450  tv_usec is certainly positive. */
451  _result.tv_sec = stop.tv_sec - start.tv_sec ;
452  _result.tv_usec = stop.tv_usec - start.tv_usec ;
453 
454  /* Return 1 if result is negative. */
455  return !(stop.tv_sec < start.tv_sec) ;
456 }
457 
458 #endif
465 void
466 BESStopWatch::dump( ostream &strm ) const
467 {
468  strm << BESIndent::LMarg << "BESStopWatch::dump - ("
469  << (void *)this << ")" << endl ;
470 }
471 
472 
473 
474 
475 
static std::ostream * GetStrm()
return the debug stream
Definition: BESDebug.h:179
virtual bool start(std::string name)
Definition: BESStopWatch.cc:67
virtual void dump(std::ostream &strm) const
dumps information about this object
virtual ~BESStopWatch()