timer.cpp 14.8 KB
Newer Older
1
// Copyright 2017-2021, Schlumberger
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
//
// Licensed under the Apache License, Version 2.0 (the "License");
// you may not use this file except in compliance with the License.
// You may obtain a copy of the License at
//
//      http://www.apache.org/licenses/LICENSE-2.0
//
// Unless required by applicable law or agreed to in writing, software
// distributed under the License is distributed on an "AS IS" BASIS,
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
// See the License for the specific language governing permissions and
// limitations under the License.

#include "timer.h"

#ifdef _WIN32
#include <Windows.h>
#endif

#include <sstream>
#include <stdarg.h>
#include <errno.h>
#ifndef _WIN32
#include <sys/time.h>
#endif

#include <stdlib.h>
#include <stdio.h>
#include <string.h>
#ifndef _WIN32
#include <unistd.h>
#endif

#include <atomic>
36
#include <omp.h>
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115

namespace {
  int sprintf_s(char *buffer, int size, const char *format, ...)
  {
    if (size <= 0) {
      errno = EINVAL;
      return -1;
    }
    va_list ap;
    va_start(ap, format);
    int n = vsnprintf(buffer, size, format, ap);
    va_end(ap);
    if (n < 0 || n >= size) {
      buffer[0] = '\0'; // error or overflow. Don't write anything at all.
      errno = EINVAL;
      return -1;
    }
    return n; // Number of characters written, excluding terminatung null.
  }
}

namespace InternalZGY {
#if 0
}
#endif

/**
 * High resolution timer for performance measurement.
 *
 * The timer starts running as soon as it is constructed,
 * but for added accuracy it is recommended to invoke start() explicity.
 * The previous start time is then ignored.
 *
 * After calling stop(), the formatted elapsed time is available in getValue().
 * start() and stop() may be called multiple times to accumulate statistics.
 * In this case, it might be useful to pass a "skip" argument to the constructor
 * telling it that the first N laps are not representative and should be ignored.
 *
 * The resolution and accuracy for timing short duration calls is approx.
 * +/- 1 microsecond. Note that the class tries to adjust for the overhead
 * of calling the Windows performance timer.  This is done heuristically,
 * so if you time something that takes just a few nanoseconds to execute then
 * the result could end up negative.
 *
 * Applications may use Timer directly, but the higher level NamedTimer
 * will often be more convenient. The following examples show the use:
 *
 * \code
 * // One-shot timer:
 *    static bool enable = Timer.getNumericEnv("SALMON_TIMERS")>0;
 *    Timer t(enable);
 *    DoTheWork();
 *    t.Stop();
 *    printf("It took %s\n", t.getValue());
 *
 * //Statistics timer:
 *    static Timer t(enable);
 *    DoTheWork();
 *    t.Stop();
 *    if (last_call)
 *      printf("It took %s\n", t.getValue());
 * \endcode
 *
 * The first example is often too noisy, and there is no way for the
 * user to configure the timer to only print statistics.
 * The second approach may be tricky because it is not always obvious
 * when to print the gathered statistics. The higher level NamedTimer
 * and TimerPool solves these problems.
 */


/**
 * Create a new Timer instance, optionally giving it a name.
 * Optionally pass enabled=false to create a low overhead stub.
 * Optionally pass an initial count not to be included in statistics.
 * Once the instance is created the enabled state cannot be changed.
 */
Timer::Timer(bool enabled, const char* name, int skip, bool startrunning)
  : enabled_(enabled), skip_(skip), frequency_(1), overhead_(0),
116
    laps_(0), last_(0), total_(0), adjusted_(0), begin_(0), end_(0), running_(false), verbose_(enabled ? 1 : 0)
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
{
  name_[0] = '\0';
  buff_[0] = '\0';
  if (enabled_) {
    if (name != 0) {
#ifdef _WIN32
      strncpy_s(name_, name, sizeof(name_) - 1);
#else
      strncpy(name_, name, sizeof(name_)-1);
#endif
      name_[sizeof(name_)-1] = '\0';
    }
    frequency_ = getNativeFrequency();
    frequency_ = getNativeFrequency();
    if (frequency_ == 0) frequency_ = 1; // prevent divide-by-zero

    // Start and stop a couple of times to remove artifacts from JITting and cache
    start();
    stop();
    start();
    stop();
    start();
    stop();

    // The time for the last lap should be 0, but will probably be a small
    // number of microseconds representing the overhead of these calls.
    // Fudge subsequent numbers by 90% of this amount.
    overhead_ += (last_ * 9) / 10;

    // Reset the counters again, and then start them for real.
    // If the application does a start also, this first one is ignored.
    doReset();
    if (startrunning)
      doStart();
  }
}


long long
Timer::getNativeTime() {
#ifdef _WIN32
  LARGE_INTEGER now;
  QueryPerformanceCounter(&now);
  return now.QuadPart;
#else
  struct timeval tv;
  gettimeofday(&tv, NULL);
  return (long long)tv.tv_sec * 1000000 + tv.tv_usec;
#endif
}


long long
Timer::getNativeFrequency() {
#ifdef _WIN32
  LARGE_INTEGER freq;
  QueryPerformanceFrequency(&freq);
  return freq.QuadPart;
#else
  return 1000000;
#endif
}


/**
 * Start the timer. If already running, discard the previous start time.
 */
void
Timer::doStart()
{
  if (enabled_) {
                running_ = true;
                begin_ = getNativeTime();
  }
}


/**
 * Stop the timer. Add the elapsed time to the accumulated result.
 */
void
Timer::doStop()
{
  if (enabled_) {
    end_ = getNativeTime();
    if (running_) {
      last_ = end_ - begin_ - overhead_;
204
      if (laps_ >= skip_) {
205
        total_ += last_;
206
207
        adjusted_ += last_ / omp_get_num_threads();
      }
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
      ++laps_;
      running_ = false;
    }
  }
}


/**
 * Reset all counters, as if the timer instance was deleted and re-created.
 * The timer will be in a stopped state after this.
 */
void
Timer::doReset()
{
  last_    = 0;
  total_   = 0;
224
  adjusted_= 0;
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
  laps_    = 0;
  running_ = false;
}


/**
 * Show the elapsed time and lap count as a human readable string. The
 * function only uses public information, so callers need not use this
 * method if they don't like the particular formatting being done.
 *
 * The result of getValue() points to a class member that is
 * overwritten at each call. So this method is definitely not thread
 * safe. But safe to call in two different instances at the same time.
 * The result from getValue_s() is thread safe because caller supplies
 * the buffer,
 *
 * By default the result is shown in a "reasonable" unit. us, ms, s,
 * etc. depending on the elapsed time. This can be confusing if
 * printing a list of timers wanting to quickly see where the time is
 * being spent. Pass msonly=true for those cases.
 *
 * \param details If true, include the timer name.
 * \param msonly If true, always show result in milliseconds.
 */
const char*
Timer::getValue(bool details, bool msonly)
{
  if (!enabled_)
    return "";
  getValue_s(buff_, sizeof(buff_),
255
             getName(), getCount(), getTotal(), getAdjusted(), getRunning(),
256
257
258
259
260
261
262
263
264
             details, msonly);
  return buff_;
}


/**
 * \copydoc Timer::getValue
 */
void
265
Timer::getValue_s(char *result, int buffer_size, const char *name, int count, double total, double adjusted, bool running, bool details, bool msonly)
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
{
  result[0] = '\0';

  if (details) {
    int n = sprintf_s(result, buffer_size, "Time for %-16s: ", name[0] ? name : "(anonymous)");
    if (n > 0 && n < buffer_size) {
      buffer_size -= n;
      result += n;
    }
  }

  if (count == 0)
    sprintf_s(result, buffer_size, "No calls logged");
  else if (msonly)
    sprintf_s(result, buffer_size, "%9.1lf ms", total * 1000.0);
  else if (total < 0.00999)
    sprintf_s(result, buffer_size, "%6.1lf us", total * 1000000.0);
  else if (total < 9.99)
    sprintf_s(result, buffer_size, "%6.1lf ms", total * 1000.0);
  else
    sprintf_s(result, buffer_size, "%6.1lf s ", total * 1.0);

  if (count > 1)
    sprintf_s(result+strlen(result), buffer_size-strlen(result), " in %d calls", count);

291
292
293
294
295
296
297
298
299
300
301
  if (adjusted != total && adjusted != 0) {
    if (msonly)
      sprintf_s(result+strlen(result), buffer_size-strlen(result), " adjusted %9.1lf ms", adjusted * 1000.0);
    else if (total < 0.00999)
      sprintf_s(result+strlen(result), buffer_size-strlen(result), " adjusted %6.1lf us", adjusted * 1000000.0);
    else if (total < 9.99)
      sprintf_s(result+strlen(result), buffer_size-strlen(result), " adjusted %6.1lf ms", adjusted * 1000.0);
    else
      sprintf_s(result+strlen(result), buffer_size-strlen(result), " adjusted %6.1lf s ", adjusted * 1.0);
  }

302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
  //if (getSkip() != 0)
  //  sprintf_s(result+strlen(result), buffer_size-strlen(result), " (first %d not counted)", getSkip());

  if (running)
    sprintf_s(result+strlen(result), buffer_size-strlen(result), " STILL RUNNING (forgot to Stop?)");

  if (details)
    sprintf_s(result+strlen(result), buffer_size-strlen(result), "\n");
}

/*=========================================================================*/
/*===   PrintingTimer   ===================================================*/
/*=========================================================================*/

PrintingTimer::PrintingTimer(const char *name, int level, bool startrunning)
  : Timer(true, name, 0, startrunning), level_(level)
{
}

PrintingTimer::~PrintingTimer()
{
  print();
}

void
PrintingTimer::print()
{
  if (getRunning())
    stop();
Paal Kvamme's avatar
Paal Kvamme committed
331
332
333
334
  // Most code will use one of the fancier timers that can redirect
  // output to a file or possibly interface with a proper logger.
  // What you see here is a bulletproof variant for ad-hoc debugging,
  // unit tests, etc. made to work also in a static destructor.
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
  if (getCount() != 0) {
    const char *msg = getValue(true, true);
    fwrite(msg, 1, strlen(msg), stderr);
  }
  reset();
}

/*=========================================================================*/
/*   RawPrintingTimer   ===================================================*/
/*=========================================================================*/

RawPrintingTimer::RawPrintingTimer(const char *name, int level)
  : Timer(true, name), level_(level)
{
}

RawPrintingTimer::~RawPrintingTimer()
{
  print();
}

void
RawPrintingTimer::print()
{
  if (getRunning())
    stop();
  if (getCount() != 0) {
    const char *msg = getValue(true, true);
    fwrite(msg, 1, strlen(msg), stderr);
  }
  reset();
}

/*=========================================================================*/
/*   SimpleTimer   ========================================================*/
/*=========================================================================*/

// Inline code only

/*=========================================================================*/
/*   SummaryTimer   =======================================================*/
/*=========================================================================*/

378
379
380
381
382
383
384
385
/*
 * \details Thread safety:
 * Modification other than the statistics may lead to a data race.
 * Planned usage is that most information will be only set in create.
 * Updating statistics, as is done in SummaryTimer::add() is thread
 * safe. Note in particular the buff_ member which is not safe and
 * which causes SummaryTimer::getValue() to not be threads safe.
 */
386
387
388
389
390
391
class SummaryTimer::Impl
{
public:
  long long frequency_;
  std::atomic<int> count_;
  std::atomic<long long> total_;
392
  std::atomic<long long> adjusted_;
393
394
395
396
  std::atomic<long long> last_;
  char name_[256];    // Optional name of this timer
  char buff_[256];    // Returned from getValue().
  explicit Impl(const char *name)
397
    : frequency_(1000*1000), count_(0), total_(0), adjusted_(0), last_(0)
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
414
415
416
417
418
419
420
421
422
423
424
425
426
427
428
429
430
431
432
433
434
435
436
437
438
439
440
441
442
  {
    name_[0] = '\0';
    buff_[0] = '\0';
    if (name != 0) {
#ifdef _WIN32
      strncpy_s(name_, name, sizeof(name_) - 1);
#else
      strncpy(name_, name, sizeof(name_)-1);
#endif
      name_[sizeof(name_)-1] = '\0';
    }
  }
};

SummaryTimer::SummaryTimer(const char *name)
  : pimpl_(new Impl(name))
{
}

SummaryTimer::~SummaryTimer()
{
  delete pimpl_;
  pimpl_ =  nullptr;
}

double
SummaryTimer::getFrequency() const
{
  // Reason the cast is safe: Even if there is a loss of precision,
  // this would only cause a slightly less precise measurement.
  return static_cast<double>(pimpl_->frequency_);
}

int
SummaryTimer::getCount() const
{
  return pimpl_->count_.load();
}

double
SummaryTimer::getTotal() const
{
  return static_cast<double>(pimpl_->total_.load()) / pimpl_->frequency_;
}

443
444
445
446
447
448
double
SummaryTimer::getAdjusted() const
{
  return static_cast<double>(pimpl_->adjusted_.load()) / pimpl_->frequency_;
}

449
450
451
452
453
454
455
456
457
458
459
460
461
462
463
464
double
SummaryTimer::getLast() const
{
  return static_cast<double>(pimpl_->last_.load())  / pimpl_->frequency_;
}

const char*
SummaryTimer::getName() const
{
  return pimpl_->name_;
}

const char*
SummaryTimer::getValue(bool details, bool msonly) const
{
  Timer::getValue_s(pimpl_->buff_, sizeof(pimpl_->buff_),
465
                    getName(), getCount(), getTotal(), getAdjusted(), false,
466
467
468
469
                    details, msonly);
  return pimpl_->buff_;
}

470
471
472
const char*
SummaryTimer::getCSV() const
{
473
474
475
476
477
478
479
  // Avoid odd characters in name to make it easier for spreadsheets.
  char *safename = new char[strlen(getName())+1];
  char *dst = safename;
  const char *src = getName(); // Instance member, remains valid long enough.
  for (; *src; ++src, ++dst)
    *dst = isalnum(*src) ? *src : '_';
  *dst = '\0';
480
481
  sprintf_s(pimpl_->buff_, sizeof(pimpl_->buff_),
            "TIMER,\"%s\",%d,%.3lf,%.3lf\n",
482
            safename, getCount(), getTotal(), getAdjusted());
483
  delete[] safename;
484
485
486
  return pimpl_->buff_;
}

487
488
489
490
491
492
493
494
495
/**
 * \brief Clear all counters.
 * \details The timer name is unchanged.
 */
void
SummaryTimer::reset()
{
  pimpl_->count_ = 0;
  pimpl_->total_ = 0;
496
  pimpl_->adjusted_  = 0;
497
498
499
500
501
502
503
504
505
  pimpl_->last_  = 0;
}

/**
 * \brief Add the contents of the specified Timer to our summary.
 * \details The information to add is passed as discrete arguments,
 * so it is possible to e.g. add an managed timer to an umanaged one.
 */
void
506
SummaryTimer::add(int count, double total, double adjusted, double last)
507
508
509
{
  pimpl_->count_.fetch_add(count);
  pimpl_->total_.fetch_add((long long)(total * pimpl_->frequency_));
510
  pimpl_->adjusted_.fetch_add((long long)(adjusted * pimpl_->frequency_));
511
512
513
514
515
516
517
518
519
520
521
  pimpl_->last_.store((long long)(last * pimpl_->frequency_));
}

/**
 * \brief Add the contents of the specified Timer to our summary.
 * \details The caller is responsible for stopping the timer first.
 */
void
SummaryTimer::add(const Timer& t)
{
  if (t.getEnabled()) {
522
    add(t.getCount(), t.getTotal(), t.getAdjusted(), t.getLast());
523
524
525
526
527
528
529
  }
}

/*=========================================================================*/
/*   SummaryPrintingTimer   ===============================================*/
/*=========================================================================*/

530
SummaryPrintingTimer::SummaryPrintingTimer(const char *name, bool csv)
531
  : SummaryTimer(name)
532
  , csv_(csv)
533
534
535
536
537
538
539
540
541
542
543
544
{
}

SummaryPrintingTimer::~SummaryPrintingTimer()
{
  print();
}

void
SummaryPrintingTimer::print()
{
  if (getCount() != 0) {
545
    const char *msg = csv_ ? getCSV() : getValue(true, true);
546
547
548
549
550
551
    fwrite(msg, 1, strlen(msg), stderr);
  }
  reset();
}

} // end namespace