bes Updated for version 3.20.13
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
45using std::string ;
46using std::endl;
47using 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
55namespace bes_timing {
56BESStopWatch *elapsedTimeToReadStart=0;
57BESStopWatch *elapsedTimeToTransmitStart=0;
58}
59
66bool
68{
69 return start(name, MISSING_LOG_PARAM) ;
70}
71
80bool
81BESStopWatch::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
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
145bool 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}
241unsigned long int BESStopWatch::get_elapsed_us()
242{
243 return get_stop_us() - get_start_us();
244}
245
246unsigned long int BESStopWatch::get_start_us()
247{
248 return d_start_usage.tv_sec*1000*1000 + d_start_usage.tv_usec;
249}
250
251unsigned 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
265bool
266BESStopWatch::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
303bool
304BESStopWatch::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
430bool
431BESStopWatch::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
460
467void
468BESStopWatch::dump( ostream &strm ) const
469{
470 strm << BESIndent::LMarg << "BESStopWatch::dump - ("
471 << (void *)this << ")" << endl ;
472}
473
474
475
476
477
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()