kmp_stats.cpp revision 360784
1/** @file kmp_stats.cpp
2 * Statistics gathering and processing.
3 */
4
5//===----------------------------------------------------------------------===//
6//
7// Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
8// See https://llvm.org/LICENSE.txt for license information.
9// SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
10//
11//===----------------------------------------------------------------------===//
12
13#include "kmp.h"
14#include "kmp_lock.h"
15#include "kmp_stats.h"
16#include "kmp_str.h"
17
18#include <algorithm>
19#include <ctime>
20#include <iomanip>
21#include <sstream>
22#include <stdlib.h> // for atexit
23#include <cmath>
24
25#define STRINGIZE2(x) #x
26#define STRINGIZE(x) STRINGIZE2(x)
27
28#define expandName(name, flags, ignore) {STRINGIZE(name), flags},
29statInfo timeStat::timerInfo[] = {
30    KMP_FOREACH_TIMER(expandName, 0){"TIMER_LAST", 0}};
31const statInfo counter::counterInfo[] = {
32    KMP_FOREACH_COUNTER(expandName, 0){"COUNTER_LAST", 0}};
33#undef expandName
34
35#define expandName(ignore1, ignore2, ignore3) {0.0, 0.0, 0.0},
36kmp_stats_output_module::rgb_color kmp_stats_output_module::timerColorInfo[] = {
37    KMP_FOREACH_TIMER(expandName, 0){0.0, 0.0, 0.0}};
38#undef expandName
39
40const kmp_stats_output_module::rgb_color
41    kmp_stats_output_module::globalColorArray[] = {
42        {1.0, 0.0, 0.0}, // red
43        {1.0, 0.6, 0.0}, // orange
44        {1.0, 1.0, 0.0}, // yellow
45        {0.0, 1.0, 0.0}, // green
46        {0.0, 0.0, 1.0}, // blue
47        {0.6, 0.2, 0.8}, // purple
48        {1.0, 0.0, 1.0}, // magenta
49        {0.0, 0.4, 0.2}, // dark green
50        {1.0, 1.0, 0.6}, // light yellow
51        {0.6, 0.4, 0.6}, // dirty purple
52        {0.0, 1.0, 1.0}, // cyan
53        {1.0, 0.4, 0.8}, // pink
54        {0.5, 0.5, 0.5}, // grey
55        {0.8, 0.7, 0.5}, // brown
56        {0.6, 0.6, 1.0}, // light blue
57        {1.0, 0.7, 0.5}, // peach
58        {0.8, 0.5, 1.0}, // lavender
59        {0.6, 0.0, 0.0}, // dark red
60        {0.7, 0.6, 0.0}, // gold
61        {0.0, 0.0, 0.0} // black
62};
63
64// Ensure that the atexit handler only runs once.
65static uint32_t statsPrinted = 0;
66
67// output interface
68static kmp_stats_output_module *__kmp_stats_global_output = NULL;
69
70double logHistogram::binMax[] = {
71    1.e1l,  1.e2l,  1.e3l,  1.e4l,  1.e5l,  1.e6l,  1.e7l,  1.e8l,
72    1.e9l,  1.e10l, 1.e11l, 1.e12l, 1.e13l, 1.e14l, 1.e15l, 1.e16l,
73    1.e17l, 1.e18l, 1.e19l, 1.e20l, 1.e21l, 1.e22l, 1.e23l, 1.e24l,
74    1.e25l, 1.e26l, 1.e27l, 1.e28l, 1.e29l, 1.e30l};
75
76/* ************* statistic member functions ************* */
77
78void statistic::addSample(double sample) {
79  sample -= offset;
80  KMP_DEBUG_ASSERT(std::isfinite(sample));
81
82  double delta = sample - meanVal;
83
84  sampleCount = sampleCount + 1;
85  meanVal = meanVal + delta / sampleCount;
86  m2 = m2 + delta * (sample - meanVal);
87
88  minVal = std::min(minVal, sample);
89  maxVal = std::max(maxVal, sample);
90  if (collectingHist)
91    hist.addSample(sample);
92}
93
94statistic &statistic::operator+=(const statistic &other) {
95  if (other.sampleCount == 0)
96    return *this;
97
98  if (sampleCount == 0) {
99    *this = other;
100    return *this;
101  }
102
103  uint64_t newSampleCount = sampleCount + other.sampleCount;
104  double dnsc = double(newSampleCount);
105  double dsc = double(sampleCount);
106  double dscBydnsc = dsc / dnsc;
107  double dosc = double(other.sampleCount);
108  double delta = other.meanVal - meanVal;
109
110  // Try to order these calculations to avoid overflows. If this were Fortran,
111  // then the compiler would not be able to re-order over brackets. In C++ it
112  // may be legal to do that (we certainly hope it doesn't, and CC+ Programming
113  // Language 2nd edition suggests it shouldn't, since it says that exploitation
114  // of associativity can only be made if the operation really is associative
115  // (which floating addition isn't...)).
116  meanVal = meanVal * dscBydnsc + other.meanVal * (1 - dscBydnsc);
117  m2 = m2 + other.m2 + dscBydnsc * dosc * delta * delta;
118  minVal = std::min(minVal, other.minVal);
119  maxVal = std::max(maxVal, other.maxVal);
120  sampleCount = newSampleCount;
121  if (collectingHist)
122    hist += other.hist;
123
124  return *this;
125}
126
127void statistic::scale(double factor) {
128  minVal = minVal * factor;
129  maxVal = maxVal * factor;
130  meanVal = meanVal * factor;
131  m2 = m2 * factor * factor;
132  return;
133}
134
135std::string statistic::format(char unit, bool total) const {
136  std::string result = formatSI(sampleCount, 9, ' ');
137
138  if (sampleCount == 0) {
139    result = result + std::string(", ") + formatSI(0.0, 9, unit);
140    result = result + std::string(", ") + formatSI(0.0, 9, unit);
141    result = result + std::string(", ") + formatSI(0.0, 9, unit);
142    if (total)
143      result = result + std::string(", ") + formatSI(0.0, 9, unit);
144    result = result + std::string(", ") + formatSI(0.0, 9, unit);
145  } else {
146    result = result + std::string(", ") + formatSI(minVal, 9, unit);
147    result = result + std::string(", ") + formatSI(meanVal, 9, unit);
148    result = result + std::string(", ") + formatSI(maxVal, 9, unit);
149    if (total)
150      result =
151          result + std::string(", ") + formatSI(meanVal * sampleCount, 9, unit);
152    result = result + std::string(", ") + formatSI(getSD(), 9, unit);
153  }
154  return result;
155}
156
157/* ************* histogram member functions ************* */
158
159// Lowest bin that has anything in it
160int logHistogram::minBin() const {
161  for (int i = 0; i < numBins; i++) {
162    if (bins[i].count != 0)
163      return i - logOffset;
164  }
165  return -logOffset;
166}
167
168// Highest bin that has anything in it
169int logHistogram::maxBin() const {
170  for (int i = numBins - 1; i >= 0; i--) {
171    if (bins[i].count != 0)
172      return i - logOffset;
173  }
174  return -logOffset;
175}
176
177// Which bin does this sample belong in ?
178uint32_t logHistogram::findBin(double sample) {
179  double v = std::fabs(sample);
180  // Simply loop up looking which bin to put it in.
181  // According to a micro-architect this is likely to be faster than a binary
182  // search, since
183  // it will only have one branch mis-predict
184  for (int b = 0; b < numBins; b++)
185    if (binMax[b] > v)
186      return b;
187  fprintf(stderr,
188          "Trying to add a sample that is too large into a histogram\n");
189  KMP_ASSERT(0);
190  return -1;
191}
192
193void logHistogram::addSample(double sample) {
194  if (sample == 0.0) {
195    zeroCount += 1;
196#ifdef KMP_DEBUG
197    _total++;
198    check();
199#endif
200    return;
201  }
202  KMP_DEBUG_ASSERT(std::isfinite(sample));
203  uint32_t bin = findBin(sample);
204  KMP_DEBUG_ASSERT(0 <= bin && bin < numBins);
205
206  bins[bin].count += 1;
207  bins[bin].total += sample;
208#ifdef KMP_DEBUG
209  _total++;
210  check();
211#endif
212}
213
214// This may not be the format we want, but it'll do for now
215std::string logHistogram::format(char unit) const {
216  std::stringstream result;
217
218  result << "Bin,                Count,     Total\n";
219  if (zeroCount) {
220    result << "0,              " << formatSI(zeroCount, 9, ' ') << ", ",
221        formatSI(0.0, 9, unit);
222    if (count(minBin()) == 0)
223      return result.str();
224    result << "\n";
225  }
226  for (int i = minBin(); i <= maxBin(); i++) {
227    result << "10**" << i << "<=v<10**" << (i + 1) << ", "
228           << formatSI(count(i), 9, ' ') << ", " << formatSI(total(i), 9, unit);
229    if (i != maxBin())
230      result << "\n";
231  }
232
233  return result.str();
234}
235
236/* ************* explicitTimer member functions ************* */
237
238void explicitTimer::start(tsc_tick_count tick) {
239  startTime = tick;
240  totalPauseTime = 0;
241  if (timeStat::logEvent(timerEnumValue)) {
242    __kmp_stats_thread_ptr->incrementNestValue();
243  }
244  return;
245}
246
247void explicitTimer::stop(tsc_tick_count tick,
248                         kmp_stats_list *stats_ptr /* = nullptr */) {
249  if (startTime.getValue() == 0)
250    return;
251
252  stat->addSample(((tick - startTime) - totalPauseTime).ticks());
253
254  if (timeStat::logEvent(timerEnumValue)) {
255    if (!stats_ptr)
256      stats_ptr = __kmp_stats_thread_ptr;
257    stats_ptr->push_event(
258        startTime.getValue() - __kmp_stats_start_time.getValue(),
259        tick.getValue() - __kmp_stats_start_time.getValue(),
260        __kmp_stats_thread_ptr->getNestValue(), timerEnumValue);
261    stats_ptr->decrementNestValue();
262  }
263
264  /* We accept the risk that we drop a sample because it really did start at
265     t==0. */
266  startTime = 0;
267  return;
268}
269
270/* ************* partitionedTimers member functions ************* */
271partitionedTimers::partitionedTimers() { timer_stack.reserve(8); }
272
273// initialize the paritioned timers to an initial timer
274void partitionedTimers::init(explicitTimer timer) {
275  KMP_DEBUG_ASSERT(this->timer_stack.size() == 0);
276  timer_stack.push_back(timer);
277  timer_stack.back().start(tsc_tick_count::now());
278}
279
280// stop/save the current timer, and start the new timer (timer_pair)
281// There is a special condition where if the current timer is equal to
282// the one you are trying to push, then it only manipulates the stack,
283// and it won't stop/start the currently running timer.
284void partitionedTimers::push(explicitTimer timer) {
285  // get the current timer
286  // pause current timer
287  // push new timer
288  // start the new timer
289  explicitTimer *current_timer, *new_timer;
290  size_t stack_size;
291  KMP_DEBUG_ASSERT(this->timer_stack.size() > 0);
292  timer_stack.push_back(timer);
293  stack_size = timer_stack.size();
294  current_timer = &(timer_stack[stack_size - 2]);
295  new_timer = &(timer_stack[stack_size - 1]);
296  tsc_tick_count tick = tsc_tick_count::now();
297  current_timer->pause(tick);
298  new_timer->start(tick);
299}
300
301// stop/discard the current timer, and start the previously saved timer
302void partitionedTimers::pop() {
303  // get the current timer
304  // stop current timer (record event/sample)
305  // pop current timer
306  // get the new current timer and resume
307  explicitTimer *old_timer, *new_timer;
308  size_t stack_size = timer_stack.size();
309  KMP_DEBUG_ASSERT(stack_size > 1);
310  old_timer = &(timer_stack[stack_size - 1]);
311  new_timer = &(timer_stack[stack_size - 2]);
312  tsc_tick_count tick = tsc_tick_count::now();
313  old_timer->stop(tick);
314  new_timer->resume(tick);
315  timer_stack.pop_back();
316}
317
318void partitionedTimers::exchange(explicitTimer timer) {
319  // get the current timer
320  // stop current timer (record event/sample)
321  // push new timer
322  // start the new timer
323  explicitTimer *current_timer, *new_timer;
324  size_t stack_size;
325  KMP_DEBUG_ASSERT(this->timer_stack.size() > 0);
326  tsc_tick_count tick = tsc_tick_count::now();
327  stack_size = timer_stack.size();
328  current_timer = &(timer_stack[stack_size - 1]);
329  current_timer->stop(tick);
330  timer_stack.pop_back();
331  timer_stack.push_back(timer);
332  new_timer = &(timer_stack[stack_size - 1]);
333  new_timer->start(tick);
334}
335
336// Wind up all the currently running timers.
337// This pops off all the timers from the stack and clears the stack
338// After this is called, init() must be run again to initialize the
339// stack of timers
340void partitionedTimers::windup() {
341  while (timer_stack.size() > 1) {
342    this->pop();
343  }
344  // Pop the timer from the init() call
345  if (timer_stack.size() > 0) {
346    timer_stack.back().stop(tsc_tick_count::now());
347    timer_stack.pop_back();
348  }
349}
350
351/* ************* kmp_stats_event_vector member functions ************* */
352
353void kmp_stats_event_vector::deallocate() {
354  __kmp_free(events);
355  internal_size = 0;
356  allocated_size = 0;
357  events = NULL;
358}
359
360// This function is for qsort() which requires the compare function to return
361// either a negative number if event1 < event2, a positive number if event1 >
362// event2 or zero if event1 == event2. This sorts by start time (lowest to
363// highest).
364int compare_two_events(const void *event1, const void *event2) {
365  const kmp_stats_event *ev1 = RCAST(const kmp_stats_event *, event1);
366  const kmp_stats_event *ev2 = RCAST(const kmp_stats_event *, event2);
367
368  if (ev1->getStart() < ev2->getStart())
369    return -1;
370  else if (ev1->getStart() > ev2->getStart())
371    return 1;
372  else
373    return 0;
374}
375
376void kmp_stats_event_vector::sort() {
377  qsort(events, internal_size, sizeof(kmp_stats_event), compare_two_events);
378}
379
380/* ************* kmp_stats_list member functions ************* */
381
382// returns a pointer to newly created stats node
383kmp_stats_list *kmp_stats_list::push_back(int gtid) {
384  kmp_stats_list *newnode =
385      (kmp_stats_list *)__kmp_allocate(sizeof(kmp_stats_list));
386  // placement new, only requires space and pointer and initializes (so
387  // __kmp_allocate instead of C++ new[] is used)
388  new (newnode) kmp_stats_list();
389  newnode->setGtid(gtid);
390  newnode->prev = this->prev;
391  newnode->next = this;
392  newnode->prev->next = newnode;
393  newnode->next->prev = newnode;
394  return newnode;
395}
396void kmp_stats_list::deallocate() {
397  kmp_stats_list *ptr = this->next;
398  kmp_stats_list *delptr = this->next;
399  while (ptr != this) {
400    delptr = ptr;
401    ptr = ptr->next;
402    // placement new means we have to explicitly call destructor.
403    delptr->_event_vector.deallocate();
404    delptr->~kmp_stats_list();
405    __kmp_free(delptr);
406  }
407}
408kmp_stats_list::iterator kmp_stats_list::begin() {
409  kmp_stats_list::iterator it;
410  it.ptr = this->next;
411  return it;
412}
413kmp_stats_list::iterator kmp_stats_list::end() {
414  kmp_stats_list::iterator it;
415  it.ptr = this;
416  return it;
417}
418int kmp_stats_list::size() {
419  int retval;
420  kmp_stats_list::iterator it;
421  for (retval = 0, it = begin(); it != end(); it++, retval++) {
422  }
423  return retval;
424}
425
426/* ************* kmp_stats_list::iterator member functions ************* */
427
428kmp_stats_list::iterator::iterator() : ptr(NULL) {}
429kmp_stats_list::iterator::~iterator() {}
430kmp_stats_list::iterator kmp_stats_list::iterator::operator++() {
431  this->ptr = this->ptr->next;
432  return *this;
433}
434kmp_stats_list::iterator kmp_stats_list::iterator::operator++(int dummy) {
435  this->ptr = this->ptr->next;
436  return *this;
437}
438kmp_stats_list::iterator kmp_stats_list::iterator::operator--() {
439  this->ptr = this->ptr->prev;
440  return *this;
441}
442kmp_stats_list::iterator kmp_stats_list::iterator::operator--(int dummy) {
443  this->ptr = this->ptr->prev;
444  return *this;
445}
446bool kmp_stats_list::iterator::operator!=(const kmp_stats_list::iterator &rhs) {
447  return this->ptr != rhs.ptr;
448}
449bool kmp_stats_list::iterator::operator==(const kmp_stats_list::iterator &rhs) {
450  return this->ptr == rhs.ptr;
451}
452kmp_stats_list *kmp_stats_list::iterator::operator*() const {
453  return this->ptr;
454}
455
456/* *************  kmp_stats_output_module functions ************** */
457
458const char *kmp_stats_output_module::eventsFileName = NULL;
459const char *kmp_stats_output_module::plotFileName = NULL;
460int kmp_stats_output_module::printPerThreadFlag = 0;
461int kmp_stats_output_module::printPerThreadEventsFlag = 0;
462
463static char const *lastName(char *name) {
464  int l = strlen(name);
465  for (int i = l - 1; i >= 0; --i) {
466    if (name[i] == '.')
467      name[i] = '_';
468    if (name[i] == '/')
469      return name + i + 1;
470  }
471  return name;
472}
473
474/* Read the name of the executable from /proc/self/cmdline */
475static char const *getImageName(char *buffer, size_t buflen) {
476  FILE *f = fopen("/proc/self/cmdline", "r");
477  buffer[0] = char(0);
478  if (!f)
479    return buffer;
480
481  // The file contains char(0) delimited words from the commandline.
482  // This just returns the last filename component of the first word on the
483  // line.
484  size_t n = fread(buffer, 1, buflen, f);
485  if (n == 0) {
486    fclose(f);
487    KMP_CHECK_SYSFAIL("fread", 1)
488  }
489  fclose(f);
490  buffer[buflen - 1] = char(0);
491  return lastName(buffer);
492}
493
494static void getTime(char *buffer, size_t buflen, bool underscores = false) {
495  time_t timer;
496
497  time(&timer);
498
499  struct tm *tm_info = localtime(&timer);
500  if (underscores)
501    strftime(buffer, buflen, "%Y-%m-%d_%H%M%S", tm_info);
502  else
503    strftime(buffer, buflen, "%Y-%m-%d %H%M%S", tm_info);
504}
505
506/* Generate a stats file name, expanding prototypes */
507static std::string generateFilename(char const *prototype,
508                                    char const *imageName) {
509  std::string res;
510
511  for (int i = 0; prototype[i] != char(0); i++) {
512    char ch = prototype[i];
513
514    if (ch == '%') {
515      i++;
516      if (prototype[i] == char(0))
517        break;
518
519      switch (prototype[i]) {
520      case 't': // Insert time and date
521      {
522        char date[26];
523        getTime(date, sizeof(date), true);
524        res += date;
525      } break;
526      case 'e': // Insert executable name
527        res += imageName;
528        break;
529      case 'p': // Insert pid
530      {
531        std::stringstream ss;
532        ss << getpid();
533        res += ss.str();
534      } break;
535      default:
536        res += prototype[i];
537        break;
538      }
539    } else
540      res += ch;
541  }
542  return res;
543}
544
545// init() is called very near the beginning of execution time in the constructor
546// of __kmp_stats_global_output
547void kmp_stats_output_module::init() {
548
549  char *statsFileName = getenv("KMP_STATS_FILE");
550  eventsFileName = getenv("KMP_STATS_EVENTS_FILE");
551  plotFileName = getenv("KMP_STATS_PLOT_FILE");
552  char *threadStats = getenv("KMP_STATS_THREADS");
553  char *threadEvents = getenv("KMP_STATS_EVENTS");
554
555  // set the stats output filenames based on environment variables and defaults
556  if (statsFileName) {
557    char imageName[1024];
558    // Process any escapes (e.g., %p, %e, %t) in the name
559    outputFileName = generateFilename(
560        statsFileName, getImageName(&imageName[0], sizeof(imageName)));
561  }
562  eventsFileName = eventsFileName ? eventsFileName : "events.dat";
563  plotFileName = plotFileName ? plotFileName : "events.plt";
564
565  // set the flags based on environment variables matching: true, on, 1, .true.
566  // , .t. , yes
567  printPerThreadFlag = __kmp_str_match_true(threadStats);
568  printPerThreadEventsFlag = __kmp_str_match_true(threadEvents);
569
570  if (printPerThreadEventsFlag) {
571    // assigns a color to each timer for printing
572    setupEventColors();
573  } else {
574    // will clear flag so that no event will be logged
575    timeStat::clearEventFlags();
576  }
577}
578
579void kmp_stats_output_module::setupEventColors() {
580  int i;
581  int globalColorIndex = 0;
582  int numGlobalColors = sizeof(globalColorArray) / sizeof(rgb_color);
583  for (i = 0; i < TIMER_LAST; i++) {
584    if (timeStat::logEvent((timer_e)i)) {
585      timerColorInfo[i] = globalColorArray[globalColorIndex];
586      globalColorIndex = (globalColorIndex + 1) % numGlobalColors;
587    }
588  }
589}
590
591void kmp_stats_output_module::printTimerStats(FILE *statsOut,
592                                              statistic const *theStats,
593                                              statistic const *totalStats) {
594  fprintf(statsOut,
595          "Timer,                             SampleCount,    Min,      "
596          "Mean,       Max,     Total,        SD\n");
597  for (timer_e s = timer_e(0); s < TIMER_LAST; s = timer_e(s + 1)) {
598    statistic const *stat = &theStats[s];
599    char tag = timeStat::noUnits(s) ? ' ' : 'T';
600
601    fprintf(statsOut, "%-35s, %s\n", timeStat::name(s),
602            stat->format(tag, true).c_str());
603  }
604  // Also print the Total_ versions of times.
605  for (timer_e s = timer_e(0); s < TIMER_LAST; s = timer_e(s + 1)) {
606    char tag = timeStat::noUnits(s) ? ' ' : 'T';
607    if (totalStats && !timeStat::noTotal(s))
608      fprintf(statsOut, "Total_%-29s, %s\n", timeStat::name(s),
609              totalStats[s].format(tag, true).c_str());
610  }
611
612  // Print historgram of statistics
613  if (theStats[0].haveHist()) {
614    fprintf(statsOut, "\nTimer distributions\n");
615    for (int s = 0; s < TIMER_LAST; s++) {
616      statistic const *stat = &theStats[s];
617
618      if (stat->getCount() != 0) {
619        char tag = timeStat::noUnits(timer_e(s)) ? ' ' : 'T';
620
621        fprintf(statsOut, "%s\n", timeStat::name(timer_e(s)));
622        fprintf(statsOut, "%s\n", stat->getHist()->format(tag).c_str());
623      }
624    }
625  }
626}
627
628void kmp_stats_output_module::printCounterStats(FILE *statsOut,
629                                                statistic const *theStats) {
630  fprintf(statsOut, "Counter,                 ThreadCount,    Min,      Mean,  "
631                    "     Max,     Total,        SD\n");
632  for (int s = 0; s < COUNTER_LAST; s++) {
633    statistic const *stat = &theStats[s];
634    fprintf(statsOut, "%-25s, %s\n", counter::name(counter_e(s)),
635            stat->format(' ', true).c_str());
636  }
637  // Print histogram of counters
638  if (theStats[0].haveHist()) {
639    fprintf(statsOut, "\nCounter distributions\n");
640    for (int s = 0; s < COUNTER_LAST; s++) {
641      statistic const *stat = &theStats[s];
642
643      if (stat->getCount() != 0) {
644        fprintf(statsOut, "%s\n", counter::name(counter_e(s)));
645        fprintf(statsOut, "%s\n", stat->getHist()->format(' ').c_str());
646      }
647    }
648  }
649}
650
651void kmp_stats_output_module::printCounters(FILE *statsOut,
652                                            counter const *theCounters) {
653  // We print all the counters even if they are zero.
654  // That makes it easier to slice them into a spreadsheet if you need to.
655  fprintf(statsOut, "\nCounter,                    Count\n");
656  for (int c = 0; c < COUNTER_LAST; c++) {
657    counter const *stat = &theCounters[c];
658    fprintf(statsOut, "%-25s, %s\n", counter::name(counter_e(c)),
659            formatSI(stat->getValue(), 9, ' ').c_str());
660  }
661}
662
663void kmp_stats_output_module::printEvents(FILE *eventsOut,
664                                          kmp_stats_event_vector *theEvents,
665                                          int gtid) {
666  // sort by start time before printing
667  theEvents->sort();
668  for (int i = 0; i < theEvents->size(); i++) {
669    kmp_stats_event ev = theEvents->at(i);
670    rgb_color color = getEventColor(ev.getTimerName());
671    fprintf(eventsOut, "%d %llu %llu %1.1f rgb(%1.1f,%1.1f,%1.1f) %s\n", gtid,
672            static_cast<unsigned long long>(ev.getStart()),
673            static_cast<unsigned long long>(ev.getStop()),
674            1.2 - (ev.getNestLevel() * 0.2), color.r, color.g, color.b,
675            timeStat::name(ev.getTimerName()));
676  }
677  return;
678}
679
680void kmp_stats_output_module::windupExplicitTimers() {
681  // Wind up any explicit timers. We assume that it's fair at this point to just
682  // walk all the explicit timers in all threads and say "it's over".
683  // If the timer wasn't running, this won't record anything anyway.
684  kmp_stats_list::iterator it;
685  for (it = __kmp_stats_list->begin(); it != __kmp_stats_list->end(); it++) {
686    kmp_stats_list *ptr = *it;
687    ptr->getPartitionedTimers()->windup();
688    ptr->endLife();
689  }
690}
691
692void kmp_stats_output_module::printPloticusFile() {
693  int i;
694  int size = __kmp_stats_list->size();
695  FILE *plotOut = fopen(plotFileName, "w+");
696
697  fprintf(plotOut, "#proc page\n"
698                   "   pagesize: 15 10\n"
699                   "   scale: 1.0\n\n");
700
701  fprintf(plotOut, "#proc getdata\n"
702                   "   file: %s\n\n",
703          eventsFileName);
704
705  fprintf(plotOut, "#proc areadef\n"
706                   "   title: OpenMP Sampling Timeline\n"
707                   "   titledetails: align=center size=16\n"
708                   "   rectangle: 1 1 13 9\n"
709                   "   xautorange: datafield=2,3\n"
710                   "   yautorange: -1 %d\n\n",
711          size);
712
713  fprintf(plotOut, "#proc xaxis\n"
714                   "   stubs: inc\n"
715                   "   stubdetails: size=12\n"
716                   "   label: Time (ticks)\n"
717                   "   labeldetails: size=14\n\n");
718
719  fprintf(plotOut, "#proc yaxis\n"
720                   "   stubs: inc 1\n"
721                   "   stubrange: 0 %d\n"
722                   "   stubdetails: size=12\n"
723                   "   label: Thread #\n"
724                   "   labeldetails: size=14\n\n",
725          size - 1);
726
727  fprintf(plotOut, "#proc bars\n"
728                   "   exactcolorfield: 5\n"
729                   "   axis: x\n"
730                   "   locfield: 1\n"
731                   "   segmentfields: 2 3\n"
732                   "   barwidthfield: 4\n\n");
733
734  // create legend entries corresponding to the timer color
735  for (i = 0; i < TIMER_LAST; i++) {
736    if (timeStat::logEvent((timer_e)i)) {
737      rgb_color c = getEventColor((timer_e)i);
738      fprintf(plotOut, "#proc legendentry\n"
739                       "   sampletype: color\n"
740                       "   label: %s\n"
741                       "   details: rgb(%1.1f,%1.1f,%1.1f)\n\n",
742              timeStat::name((timer_e)i), c.r, c.g, c.b);
743    }
744  }
745
746  fprintf(plotOut, "#proc legend\n"
747                   "   format: down\n"
748                   "   location: max max\n\n");
749  fclose(plotOut);
750  return;
751}
752
753static void outputEnvVariable(FILE *statsOut, char const *name) {
754  char const *value = getenv(name);
755  fprintf(statsOut, "# %s = %s\n", name, value ? value : "*unspecified*");
756}
757
758/* Print some useful information about
759   * the date and time this experiment ran.
760   * the machine on which it ran.
761   We output all of this as stylised comments, though we may decide to parse
762   some of it. */
763void kmp_stats_output_module::printHeaderInfo(FILE *statsOut) {
764  std::time_t now = std::time(0);
765  char buffer[40];
766  char hostName[80];
767
768  std::strftime(&buffer[0], sizeof(buffer), "%c", std::localtime(&now));
769  fprintf(statsOut, "# Time of run: %s\n", &buffer[0]);
770  if (gethostname(&hostName[0], sizeof(hostName)) == 0)
771    fprintf(statsOut, "# Hostname: %s\n", &hostName[0]);
772#if KMP_ARCH_X86 || KMP_ARCH_X86_64
773  fprintf(statsOut, "# CPU:  %s\n", &__kmp_cpuinfo.name[0]);
774  fprintf(statsOut, "# Family: %d, Model: %d, Stepping: %d\n",
775          __kmp_cpuinfo.family, __kmp_cpuinfo.model, __kmp_cpuinfo.stepping);
776  if (__kmp_cpuinfo.frequency == 0)
777    fprintf(statsOut, "# Nominal frequency: Unknown\n");
778  else
779    fprintf(statsOut, "# Nominal frequency: %sz\n",
780            formatSI(double(__kmp_cpuinfo.frequency), 9, 'H').c_str());
781  outputEnvVariable(statsOut, "KMP_HW_SUBSET");
782  outputEnvVariable(statsOut, "KMP_AFFINITY");
783  outputEnvVariable(statsOut, "KMP_BLOCKTIME");
784  outputEnvVariable(statsOut, "KMP_LIBRARY");
785  fprintf(statsOut, "# Production runtime built " __DATE__ " " __TIME__ "\n");
786#endif
787}
788
789void kmp_stats_output_module::outputStats(const char *heading) {
790  // Stop all the explicit timers in all threads
791  // Do this before declaring the local statistics because thay have
792  // constructors so will take time to create.
793  windupExplicitTimers();
794
795  statistic allStats[TIMER_LAST];
796  statistic totalStats[TIMER_LAST]; /* Synthesized, cross threads versions of
797                                       normal timer stats */
798  statistic allCounters[COUNTER_LAST];
799
800  FILE *statsOut =
801      !outputFileName.empty() ? fopen(outputFileName.c_str(), "a+") : stderr;
802  if (!statsOut)
803    statsOut = stderr;
804
805  FILE *eventsOut;
806  if (eventPrintingEnabled()) {
807    eventsOut = fopen(eventsFileName, "w+");
808  }
809
810  printHeaderInfo(statsOut);
811  fprintf(statsOut, "%s\n", heading);
812  // Accumulate across threads.
813  kmp_stats_list::iterator it;
814  for (it = __kmp_stats_list->begin(); it != __kmp_stats_list->end(); it++) {
815    int t = (*it)->getGtid();
816    // Output per thread stats if requested.
817    if (printPerThreadFlag) {
818      fprintf(statsOut, "Thread %d\n", t);
819      printTimerStats(statsOut, (*it)->getTimers(), 0);
820      printCounters(statsOut, (*it)->getCounters());
821      fprintf(statsOut, "\n");
822    }
823    // Output per thread events if requested.
824    if (eventPrintingEnabled()) {
825      kmp_stats_event_vector events = (*it)->getEventVector();
826      printEvents(eventsOut, &events, t);
827    }
828
829    // Accumulate timers.
830    for (timer_e s = timer_e(0); s < TIMER_LAST; s = timer_e(s + 1)) {
831      // See if we should ignore this timer when aggregating
832      if ((timeStat::masterOnly(s) && (t != 0)) || // Timer only valid on master
833          // and this thread is worker
834          (timeStat::workerOnly(s) && (t == 0)) // Timer only valid on worker
835          // and this thread is the master
836          ) {
837        continue;
838      }
839
840      statistic *threadStat = (*it)->getTimer(s);
841      allStats[s] += *threadStat;
842
843      // Add Total stats for timers that are valid in more than one thread
844      if (!timeStat::noTotal(s))
845        totalStats[s].addSample(threadStat->getTotal());
846    }
847
848    // Accumulate counters.
849    for (counter_e c = counter_e(0); c < COUNTER_LAST; c = counter_e(c + 1)) {
850      if (counter::masterOnly(c) && t != 0)
851        continue;
852      allCounters[c].addSample((*it)->getCounter(c)->getValue());
853    }
854  }
855
856  if (eventPrintingEnabled()) {
857    printPloticusFile();
858    fclose(eventsOut);
859  }
860
861  fprintf(statsOut, "Aggregate for all threads\n");
862  printTimerStats(statsOut, &allStats[0], &totalStats[0]);
863  fprintf(statsOut, "\n");
864  printCounterStats(statsOut, &allCounters[0]);
865
866  if (statsOut != stderr)
867    fclose(statsOut);
868}
869
870/* *************  exported C functions ************** */
871
872// no name mangling for these functions, we want the c files to be able to get
873// at these functions
874extern "C" {
875
876void __kmp_reset_stats() {
877  kmp_stats_list::iterator it;
878  for (it = __kmp_stats_list->begin(); it != __kmp_stats_list->end(); it++) {
879    timeStat *timers = (*it)->getTimers();
880    counter *counters = (*it)->getCounters();
881
882    for (int t = 0; t < TIMER_LAST; t++)
883      timers[t].reset();
884
885    for (int c = 0; c < COUNTER_LAST; c++)
886      counters[c].reset();
887
888    // reset the event vector so all previous events are "erased"
889    (*it)->resetEventVector();
890  }
891}
892
893// This function will reset all stats and stop all threads' explicit timers if
894// they haven't been stopped already.
895void __kmp_output_stats(const char *heading) {
896  __kmp_stats_global_output->outputStats(heading);
897  __kmp_reset_stats();
898}
899
900void __kmp_accumulate_stats_at_exit(void) {
901  // Only do this once.
902  if (KMP_XCHG_FIXED32(&statsPrinted, 1) != 0)
903    return;
904
905  __kmp_output_stats("Statistics on exit");
906}
907
908void __kmp_stats_init(void) {
909  __kmp_init_tas_lock(&__kmp_stats_lock);
910  __kmp_stats_start_time = tsc_tick_count::now();
911  __kmp_stats_global_output = new kmp_stats_output_module();
912  __kmp_stats_list = new kmp_stats_list();
913}
914
915void __kmp_stats_fini(void) {
916  __kmp_accumulate_stats_at_exit();
917  __kmp_stats_list->deallocate();
918  delete __kmp_stats_global_output;
919  delete __kmp_stats_list;
920}
921
922} // extern "C"
923