NCBI C++ ToolKit
perf_log.hpp
Go to the documentation of this file.

Go to the SVN repository for this file.

1 #ifndef CORELIB___PERF_LOG__HPP
2 #define CORELIB___PERF_LOG__HPP
3 
4 /* $Id: perf_log.hpp 95709 2021-12-13 15:55:26Z grichenk $
5  * ===========================================================================
6  *
7  * PUBLIC DOMAIN NOTICE
8  * National Center for Biotechnology Information
9  *
10  * This software/database is a "United States Government Work" under the
11  * terms of the United States Copyright Act. It was written as part of
12  * the author's official duties as a United States Government employee and
13  * thus cannot be copyrighted. This software/database is freely available
14  * to the public for use. The National Library of Medicine and the U.S.
15  * Government have not placed any restriction on its use or reproduction.
16  *
17  * Although all reasonable efforts have been taken to ensure the accuracy
18  * and reliability of the software and data, the NLM and the U.S.
19  * Government do not and cannot warrant the performance or results that
20  * may be obtained by using this software or data. The NLM and the U.S.
21  * Government disclaim all warranties, express or implied, including
22  * warranties of performance, merchantability or fitness for any particular
23  * purpose.
24  *
25  * Please cite the author in any work or product based on this material.
26  *
27  * ===========================================================================
28  *
29  * Author: Denis Vakatov, Vladimir Ivanov
30  *
31  *
32  */
33 
34 /// @file perf_log.hpp
35 ///
36 /// Defines NCBI C++ API for timing-and-logging, classes, and macros.
37 ///
38 
39 #include <corelib/ncbitime.hpp>
40 #include <corelib/ncbidiag.hpp>
42 
43 
44 /** @addtogroup Diagnostics
45  *
46  * @{
47  */
48 
49 
51 
52 /////////////////////////////////////////////////////////////////////////////
53 /// Forward declaration
54 
55 class CPerfLogGuard;
56 
57 
58 /////////////////////////////////////////////////////////////////////////////
59 ///
60 /// CPerfLogger --
61 ///
62 /// The CPerfLogger measure time spend somewhere, executing some operation
63 /// and put result to the performance log. Each measurement will result
64 /// in printing a one-line record to the performance log.
65 /// This class is designed to measure just one operation. Each measurement
66 /// should be finished with calling Post() or Discard() method. You can call
67 /// Start() and Suspend() methods in between as many times as you want.
68 ///
69 /// @attention
70 /// If the logging is off then neither logging nor timing will be done at all.
71 /// It will however check for incorrect usage and post errors, if any.
72 /// But if you use next construction
73 /// perf_logger.Post(...).Print(...)
74 /// that extra record will be put into the log if the logging is off.
75 /// Please use PERF_POST macro or PerfLogGuard class to avoid this.
76 /// @sa
77 /// PERF_POST, PERF_POST_DB, PerfLogGuard
78 
80 {
81 public:
82  /// If to start the timing immediately
83  enum EStart {
84  eStart, ///< Call Start() immediately after creating
85  eSuspend ///< Do not start timer (call Start() later)
86  };
87 
88  /// Constructor. Starts the timer by default.
89  CPerfLogger(EStart state = eStart);
90 
91  /// Constructor. Use start time and elapsed time values from a previous
92  /// logger to continue measuring an operation.
93  CPerfLogger(const CTime& start_time, double elapsed_time, EStart state = eStart);
94 
95  /// Constructor. Use the provided stopwatch to track time.
96  /// Start or stop the stopwatch according to the 'state'.
97  /// The same stopwatch object can be used multiple times
98  /// to accumulate total time for several operations.
99  /// @note
100  /// The stopwatch is not copied, so the original object must not be
101  /// destroyed while the logger is running.
102  /// @note
103  /// When using a user-provided stopwatch the accumulated elapsed time may be
104  /// approximate. A better approach is to initialize every new logger with the
105  /// start time and elapsed time accumulated by the previous one.
106  CPerfLogger(CStopWatch& stopwatch, EStart state = eStart);
107 
108  /// Activate and start (or, restart after Suspend()) the timer.
109  /// @note
110  /// If the timer is already running, post an error (once).
111  /// @sa Suspend
112  void Start(void);
113 
114  /// Suspend the timer.
115  /// Call Start() to continue to count time accured before.
116  /// @sa Start
117  void Suspend(void);
118 
119  /// Log the timing; stop and deactivate the timer.
120  /// @param resource
121  /// Name of the resource (must be non-empty, else throws an exception).
122  /// @param status
123  /// Status of the timed code.
124  /// @param status_msg
125  /// Verbal description of the status of the timed code.
126  /// @note
127  /// If the timer is already inactive, then post an error (once).
128  /// @note
129  /// If an external stopwatch was provided, it is stopped by this method.
130  /// @sa Discard
132  CTempString resource,
133  CTempString status_msg = CTempString());
134 
135  CDiagContext_Extra Post(int status,
136  CTempString resource,
137  CTempString status_msg = CTempString());
138 
139  /// Discard the timing results; stop and deactivate the timer.
140  void Discard(void);
141 
142  /// If the timer is still active, then post an error (once).
143  /// Usually each measurement should be finished with calling Post()
144  /// or Discard() method.
145  ~CPerfLogger();
146 
147  /// Is performance logging on, globally?
148  /// Controlled by CParam(section="Log", entry="PerfLogging", default=false)
149  static bool IsON(void);
150 
151  /// Turn performance logging on/off globally.
152  static void SetON(bool enable = true);
153 
154  /// Adjust the printed elapsed time.
155  /// @param timespan
156  /// Adjustment value, can be positive or negative. The value is
157  /// added to the actual elapsed time before logging it in Post(),
158  /// if the resuling adjusted timespan is negative, zero is logged.
159  /// Multiple adjustments are accumulated.
160  /// @note
161  /// The adjustment does not affect the actual elapsed time counted by
162  /// the stopwatch (if used), only the printed value is adjusted.
163  void Adjust(CTimeSpan timespan);
164 
165  /// Get the logger's start time.
166  const CTime& GetLoggerStartTime(void) const { return m_FirstStartTime; }
167 
168  /// Get total elapsed time (including any adjustments) in seconds.
169  double GetElapsedTime(void) const;
170 
171 private:
172  bool x_CheckValidity(const CTempString& err_msg) const;
173  friend class CPerfLogGuard;
174 
175 private:
176  CStopWatch* m_StopWatch; // Timer (internal or provided by user)
177  CStopWatch::EStart m_TimerState; // Internal timer state to save cycles
178  bool m_IsDiscarded; // TRUE if Post() or Discard() is already called
179  double m_Adjustment; // Accumulated elapsed time adjustment
180  double m_Elapsed; // Accumulated elapsed time
181  CTime m_FirstStartTime; // Time of the first start
182  CTime m_LastStartTime; // Time of the last start
183 };
184 
185 
186 /////////////////////////////////////////////////////////////////////////////
187 
188 /// Convenience macro that also saves cycles when the performance logging is
189 /// globally turned off.
190 ///
191 /// @par Usage example:
192 /// This example demonstrates logging a variety of performance statistics.
193 /// @code
194 /// CPerfLogger perf_logger;
195 /// PERF_POST(perf_logger, e200_Ok, "ApacheSlotStats",
196 /// .Print("total_slots",
197 /// NStr::NumericToString(total))
198 /// .Print("free_slots",
199 /// NStr::NumericToString(total ? total - used : 0))
200 /// .Print("used_slots",
201 /// NStr::NumericToString(total ? used : 0))
202 /// .Print("used_slots_pct",
203 /// NStr::NumericToString(total ? 100 * used / total : 0))
204 /// .Print("ratio",
205 /// NStr::DoubleToString(ratio, 2))
206 /// .Print("penalty", m_Mode == eShmem ? "N/A" :
207 /// NStr::DoubleToString(m_Penalty, 0))
208 /// .Print("error",
209 /// NStr::BoolToString(!okay)));
210 /// @endcode
211 /// @note The status must come from enum CRequestStatus::ECode (but without
212 /// the class scope, which is added by the macro).
213 #define PERF_POST(perf_logger, status, resource, args) \
214  do { if ( CPerfLogger::IsON() ) \
215  perf_logger.Post(CRequestStatus::status, resource) args; \
216  } while (false)
217 
218 
219 /// Adaptation for logging database performance.
220 ///
221 /// @par Usage example:
222 /// This example demonstrates logging the results of a stored procedure call.
223 /// @code
224 /// CPerfLogger perf_logger;
225 /// PERF_POST_DB(perf_logger, e200_Ok,
226 /// "StoredProc123", "MSSQL444")
227 /// .Print("foo", "bar"));
228 /// @endcode
229 /// @note The status must come from enum CRequestStatus::ECode (but without
230 /// the class scope, which is added by the macro).
231 ///
232 #define PERF_POST_DB(perf_logger, status, resource, server, args) \
233  do { if ( CPerfLogger::IsON() ) \
234  perf_logger.Post(CRequestStatus::status, resource) \
235  .Print("dbserver", server) args; \
236  } while (false)
237 
238 
239 
240 /////////////////////////////////////////////////////////////////////////////
241 ///
242 /// CPerfLogGuard --
243 ///
244 /// @attention
245 /// If the logging is off then neither logging nor timing will be done at all.
246 /// It will however check for incorrect usage and post errors, if any.
247 ///
248 /// If a usage error is encountered, then an error will be posted -- only
249 /// once per an error type per process.
250 
252 {
253 public:
254  /// Constructor.
255  /// @param resource
256  /// Name of the resource (must be non-empty, else throws an exception).
257  /// @param state
258  /// Whether to start the timer by default.
259  CPerfLogGuard(CTempString resource,
261 
262  /// Constructor. Use the provided start and elapsed times to initialize the logger
263  /// and continue to measure an operation.
264  /// @param resource
265  /// Name of the resource (must be non-empty, else throws an exception).
266  /// @param start_time
267  /// Start time, usually obtained from a previous logger to continue measuring an operation.
268  /// @param elapsed_time
269  /// Elapsed time in seconds obtained from a previous logger.
270  /// @param state
271  /// Whether to start the timer by default.
272  CPerfLogGuard(CTempString resource,
273  const CTime& start_time,
274  double elapsed_time,
276 
277  /// Constructor.
278  /// @param resource
279  /// Name of the resource (must be non-empty, else throws an exception).
280  /// Constructor. Use the provided stopwatch to track time.
281  /// @param stopwatch
282  /// User-provided stopwatch to use for tracking time.
283  /// The same stopwatch object can be used multiple times
284  /// to accumulate total time for several operations.
285  /// @param state
286  /// Whether to start the timer by default.
287  /// @note
288  /// The stopwatch is not copied, so the original object must not be
289  /// destroyed while the logger is running.
290  CPerfLogGuard(CTempString resource,
291  CStopWatch& stopwatch,
293 
294  /// Activate and start (or, restart after Suspend()) the timer.
295  /// @note
296  /// If the timer is already running, post an error (once).
297  /// @sa Suspend
298  void Start(void);
299 
300  /// Suspend the timer.
301  /// Call Start() to continue to count time accured before.
302  /// @sa Start
303  void Suspend(void);
304 
305  /// Add info to the resource's description
306  CPerfLogGuard& AddParameter(CTempString name, CTempString value);
307 
308  /// Write the collected resource info and timing to the log.
309  /// @param status
310  /// Status of the timed code.
311  /// @param status_msg
312  /// Verbal description of the status of the timed code.
313  /// @note
314  /// After this any action on this guard will be an error (and no-op).
315  void Post(CRequestStatus::ECode status,
316  CTempString status_msg = CTempString());
317 
318  void Post(int status,
319  CTempString status_msg = CTempString());
320 
321  /// Discard the results.
322  /// @note
323  /// After this any action on this guard will be an error (and no-op).
324  void Discard(void);
325 
326  /// If Post() or Discard() have not been called, then log the collected
327  /// info with status 500.
328  ~CPerfLogGuard();
329 
330  /// Access logger directly.
331  CPerfLogger& GetLogger(void) { return m_Logger; }
332 
333 private:
335  string m_Resource;
337 };
338 
339 
340 /* @} */
341 
342 
343 //=============================================================================
344 //
345 // Inline class methods
346 //
347 //=============================================================================
348 
349 //
350 // CPerfLogger
351 //
352 
353 inline
355 {
356  m_StopWatch = nullptr;
357  m_IsDiscarded = false;
358  m_Adjustment = 0.0;
359  m_Elapsed = 0.0;
361  if ( state == eStart ) {
362  Start();
363  }
364 }
365 
366 
367 inline
368 CPerfLogger::CPerfLogger(const CTime& start_time, double elapsed_time, EStart state)
369 {
370  m_StopWatch = nullptr;
372  m_IsDiscarded = false;
373  m_Adjustment = 0.0;
374  m_Elapsed = elapsed_time;
376  if (state == eStart) {
377  Start();
378  }
379 }
380 
381 
382 inline
384 {
385  m_StopWatch = &stopwatch;
386  m_IsDiscarded = false;
387  m_Adjustment = 0.0;
388  m_Elapsed = 0.0;
390  if ( state == eStart ) {
391  Start();
392  }
393 }
394 
395 
396 inline
398 {
399  if ( !x_CheckValidity("Start") ) {
400  return;
401  }
402  if ( m_TimerState == CStopWatch::eStart ) {
403  ERR_POST_ONCE(Error << "CPerfLogger timer is already started");
404  return;
405  }
406  if ( CPerfLogger::IsON() ) {
407  if ( m_StopWatch ) {
408  m_StopWatch->Start();
409  }
411  if ( m_FirstStartTime.IsEmpty() ) {
413  }
414  }
416 }
417 
418 
419 inline
421 {
422  if ( !x_CheckValidity("Suspend") ) {
423  return;
424  }
425  if ( CPerfLogger::IsON() ) {
426  if ( m_StopWatch ) {
427  m_StopWatch->Stop();
428  }
430  }
432 }
433 
434 
435 inline CDiagContext_Extra
437  CTempString resource,
438  CTempString status_msg)
439 {
440  return Post((int)status, resource, status_msg);
441 }
442 
443 
444 inline
446 {
447  // We don't need to "stop" CStopWatch here, it is nor actually running.
449  m_IsDiscarded = true;
450 }
451 
452 
453 inline
455 {
456  m_Adjustment += timespan.GetAsDouble();
457 }
458 
459 
460 inline
461 double CPerfLogger::GetElapsedTime(void) const
462 {
463  if ( m_StopWatch ) {
464  return m_StopWatch->Elapsed() + m_Adjustment;
465  }
466  double ret = m_Elapsed + m_Adjustment;
467  if ( m_TimerState == CStopWatch::eStart ) {
468  ret += (GetFastLocalTime() - m_LastStartTime).GetAsDouble();
469  }
470  return ret;
471 }
472 
473 
474 inline
476 {
478  ERR_POST_ONCE(Error << "CPerfLogger timer is still running");
479  }
480 }
481 
482 
483 inline
484 bool CPerfLogger::x_CheckValidity(const CTempString& err_msg) const
485 {
486  if ( m_IsDiscarded ) {
487  ERR_POST_ONCE(Error << err_msg << "() cannot be done, " \
488  "CPerfLogger is already discarded");
489  return false;
490  }
491  return true;
492 }
493 
494 
495 //
496 // CPerfLogGuard
497 //
498 
499 inline
501  : m_Logger(state), m_Resource(resource)
502 {
503  if ( resource.empty() ) {
504  NCBI_THROW(CCoreException, eInvalidArg,
505  "CPerfLogGuard:: resource name is not specified");
506  }
507 }
508 
509 
510 inline
512  const CTime& start_time,
513  double elapsed_time,
515  : m_Logger(start_time, elapsed_time, state), m_Resource(resource)
516 {
517  if ( resource.empty() ) {
518  NCBI_THROW(CCoreException, eInvalidArg,
519  "CPerfLogGuard:: resource name is not specified");
520  }
521 }
522 
523 
524 inline
526  CStopWatch& stopwatch,
528  : m_Logger(stopwatch, state), m_Resource(resource)
529 {
530  if ( resource.empty() ) {
531  NCBI_THROW(CCoreException, eInvalidArg,
532  "CPerfLogGuard:: resource name is not specified");
533  }
534 }
535 
536 
537 inline
539 {
540  try {
541  if ( !m_Logger.m_IsDiscarded ) {
543  }
544  }
545  catch (CCoreException&) {
546  }
547 }
548 
549 
550 inline
552 {
553  m_Logger.Start();
554 }
555 
556 
557 inline
559 {
560  m_Logger.Suspend();
561 }
562 
563 
564 inline
566 {
567  if ( m_Logger.m_IsDiscarded ) {
568  ERR_POST_ONCE(Error << "AddParameter() cannot be done, " \
569  "CPerfLogGuard is already discarded");
570  } else {
571  m_Parameters.push_back(SDiagMessage::TExtraArg(name, value));
572  }
573  return *this;
574 }
575 
576 
577 inline
579  CTempString status_msg)
580 {
581  return Post((int)status, status_msg);
582 }
583 
584 
585 inline
587 {
588  m_Logger.Discard();
589 }
590 
591 
592 
594 
595 
596 #endif /* CORELIB___PERF_LOG__HPP */
CCoreException –.
Definition: ncbiexpt.hpp:1476
Temporary object for holding extra message arguments.
Definition: ncbidiag.hpp:1828
CPerfLogGuard –.
Definition: perf_log.hpp:252
CPerfLogger –.
Definition: perf_log.hpp:80
CStopWatch –.
Definition: ncbitime.hpp:1937
CTempString implements a light-weight string on top of a storage buffer whose lifetime management is ...
Definition: tempstr.hpp:65
CTimeSpan.
Definition: ncbitime.hpp:1313
CTime –.
Definition: ncbitime.hpp:296
static time_t start_time
Definition: timeout.c:14
bool x_CheckValidity(const CTempString &err_msg) const
Definition: perf_log.hpp:484
CTime m_FirstStartTime
Definition: perf_log.hpp:181
void Post(CRequestStatus::ECode status, CTempString status_msg=CTempString())
Write the collected resource info and timing to the log.
Definition: perf_log.hpp:578
#define ERR_POST_ONCE(message)
Error posting only once during program execution.
Definition: ncbidiag.hpp:602
CPerfLogger m_Logger
Definition: perf_log.hpp:334
CTime m_LastStartTime
Definition: perf_log.hpp:182
EStart
If to start the timing immediately.
Definition: perf_log.hpp:83
CDiagContext_Extra Post(CRequestStatus::ECode status, CTempString resource, CTempString status_msg=CTempString())
Log the timing; stop and deactivate the timer.
Definition: perf_log.hpp:436
~CPerfLogger()
If the timer is still active, then post an error (once).
Definition: perf_log.hpp:475
double GetElapsedTime(void) const
Get total elapsed time (including any adjustments) in seconds.
Definition: perf_log.hpp:461
CPerfLogGuard(CTempString resource, CPerfLogger::EStart state=CPerfLogger::eStart)
Constructor.
Definition: perf_log.hpp:500
void Discard(void)
Discard the results.
Definition: perf_log.hpp:586
CPerfLogger & GetLogger(void)
Access logger directly.
Definition: perf_log.hpp:331
void Discard(void)
Discard the timing results; stop and deactivate the timer.
Definition: perf_log.hpp:445
double m_Elapsed
Definition: perf_log.hpp:180
SDiagMessage::TExtraArgs m_Parameters
Definition: perf_log.hpp:336
list< TExtraArg > TExtraArgs
Definition: ncbidiag.hpp:1675
const CTime & GetLoggerStartTime(void) const
Get the logger's start time.
Definition: perf_log.hpp:166
CPerfLogger(EStart state=eStart)
Constructor. Starts the timer by default.
Definition: perf_log.hpp:354
void Adjust(CTimeSpan timespan)
Adjust the printed elapsed time.
Definition: perf_log.hpp:454
pair< string, string > TExtraArg
Definition: ncbidiag.hpp:1674
static bool IsON(void)
Is performance logging on, globally? Controlled by CParam(section="Log", entry="PerfLogging",...
Definition: perf_log.cpp:58
~CPerfLogGuard()
If Post() or Discard() have not been called, then log the collected info with status 500.
Definition: perf_log.hpp:538
CStopWatch::EStart m_TimerState
Definition: perf_log.hpp:177
void Suspend(void)
Suspend the timer.
Definition: perf_log.hpp:420
string m_Resource
Definition: perf_log.hpp:335
CPerfLogGuard & AddParameter(CTempString name, CTempString value)
Add info to the resource's description.
Definition: perf_log.hpp:565
double m_Adjustment
Definition: perf_log.hpp:179
void Suspend(void)
Suspend the timer.
Definition: perf_log.hpp:558
CStopWatch * m_StopWatch
Definition: perf_log.hpp:176
bool m_IsDiscarded
Definition: perf_log.hpp:178
void Start(void)
Activate and start (or, restart after Suspend()) the timer.
Definition: perf_log.hpp:551
void Start(void)
Activate and start (or, restart after Suspend()) the timer.
Definition: perf_log.hpp:397
@ eStart
Call Start() immediately after creating.
Definition: perf_log.hpp:84
void Error(CExceptionArgs_Base &args)
Definition: ncbiexpt.hpp:1197
#define NCBI_THROW(exception_class, err_code, message)
Generic macro to throw an exception, given the exception class, error code and message string.
Definition: ncbiexpt.hpp:704
#define END_NCBI_SCOPE
End previously defined NCBI scope.
Definition: ncbistl.hpp:103
#define BEGIN_NCBI_SCOPE
Define ncbi namespace.
Definition: ncbistl.hpp:100
bool empty(void) const
Return true if the represented string is empty (i.e., the length is zero)
Definition: tempstr.hpp:334
double Elapsed(void) const
Return time elapsed since first Start() or last Restart() call (in seconds).
Definition: ncbitime.hpp:2775
void Stop(void)
Suspend the timer.
Definition: ncbitime.hpp:2792
double GetAsDouble(void) const
Return time span as number of seconds.
Definition: ncbitime.hpp:2565
bool IsEmpty(void) const
Is time object empty (date and time)?
Definition: ncbitime.hpp:2377
EStart
Defines how to create new timer.
Definition: ncbitime.hpp:1940
CTimeSpan DiffTimeSpan(const CTime &t) const
Difference in nanoseconds from specified time.
Definition: ncbitime.cpp:2305
void Start(void)
Start the timer.
Definition: ncbitime.hpp:2764
CTime GetFastLocalTime(void)
Quick and dirty getter of local time.
Definition: ncbitime.cpp:4167
@ eStart
Start timer immediately after creating.
Definition: ncbitime.hpp:1941
@ eStop
Do not start timer, just create it.
Definition: ncbitime.hpp:1942
#define NCBI_XNCBI_EXPORT
Definition: ncbi_export.h:1283
const GenericPointer< typename T::ValueType > T2 value
Definition: pointer.h:1227
Defines NCBI C++ diagnostic APIs, classes, and macros.
Defines: CTimeFormat - storage class for time format.
Defines CRequestStatus class for NCBI C++ diagnostic API.
Modified on Fri Sep 20 14:58:08 2024 by modify_doxy.py rev. 669887