LLVM OpenMP* Runtime Library
kmp_stats.cpp
1 
5 //===----------------------------------------------------------------------===//
6 //
7 // The LLVM Compiler Infrastructure
8 //
9 // This file is dual licensed under the MIT and the University of Illinois Open
10 // Source Licenses. See LICENSE.txt for details.
11 //
12 //===----------------------------------------------------------------------===//
13 
14 #include "kmp.h"
15 #include "kmp_lock.h"
16 #include "kmp_stats.h"
17 #include "kmp_str.h"
18 
19 #include <algorithm>
20 #include <ctime>
21 #include <iomanip>
22 #include <sstream>
23 #include <stdlib.h> // for atexit
24 #include <cmath>
25 
26 #define STRINGIZE2(x) #x
27 #define STRINGIZE(x) STRINGIZE2(x)
28 
29 #define expandName(name, flags, ignore) {STRINGIZE(name), flags},
30 statInfo timeStat::timerInfo[] = {
31  KMP_FOREACH_TIMER(expandName, 0){"TIMER_LAST", 0}};
32 const statInfo counter::counterInfo[] = {
33  KMP_FOREACH_COUNTER(expandName, 0){"COUNTER_LAST", 0}};
34 #undef expandName
35 
36 #define expandName(ignore1, ignore2, ignore3) {0.0, 0.0, 0.0},
37 kmp_stats_output_module::rgb_color kmp_stats_output_module::timerColorInfo[] = {
38  KMP_FOREACH_TIMER(expandName, 0){0.0, 0.0, 0.0}};
39 #undef expandName
40 
41 const kmp_stats_output_module::rgb_color
42  kmp_stats_output_module::globalColorArray[] = {
43  {1.0, 0.0, 0.0}, // red
44  {1.0, 0.6, 0.0}, // orange
45  {1.0, 1.0, 0.0}, // yellow
46  {0.0, 1.0, 0.0}, // green
47  {0.0, 0.0, 1.0}, // blue
48  {0.6, 0.2, 0.8}, // purple
49  {1.0, 0.0, 1.0}, // magenta
50  {0.0, 0.4, 0.2}, // dark green
51  {1.0, 1.0, 0.6}, // light yellow
52  {0.6, 0.4, 0.6}, // dirty purple
53  {0.0, 1.0, 1.0}, // cyan
54  {1.0, 0.4, 0.8}, // pink
55  {0.5, 0.5, 0.5}, // grey
56  {0.8, 0.7, 0.5}, // brown
57  {0.6, 0.6, 1.0}, // light blue
58  {1.0, 0.7, 0.5}, // peach
59  {0.8, 0.5, 1.0}, // lavender
60  {0.6, 0.0, 0.0}, // dark red
61  {0.7, 0.6, 0.0}, // gold
62  {0.0, 0.0, 0.0} // black
63 };
64 
65 // Ensure that the atexit handler only runs once.
66 static uint32_t statsPrinted = 0;
67 
68 // output interface
69 static kmp_stats_output_module *__kmp_stats_global_output = NULL;
70 
71 double logHistogram::binMax[] = {
72  1.e1l, 1.e2l, 1.e3l, 1.e4l, 1.e5l, 1.e6l, 1.e7l, 1.e8l,
73  1.e9l, 1.e10l, 1.e11l, 1.e12l, 1.e13l, 1.e14l, 1.e15l, 1.e16l,
74  1.e17l, 1.e18l, 1.e19l, 1.e20l, 1.e21l, 1.e22l, 1.e23l, 1.e24l,
75  1.e25l, 1.e26l, 1.e27l, 1.e28l, 1.e29l, 1.e30l};
76 
77 /* ************* statistic member functions ************* */
78 
79 void statistic::addSample(double sample) {
80  sample -= offset;
81  KMP_DEBUG_ASSERT(std::isfinite(sample));
82 
83  double delta = sample - meanVal;
84 
85  sampleCount = sampleCount + 1;
86  meanVal = meanVal + delta / sampleCount;
87  m2 = m2 + delta * (sample - meanVal);
88 
89  minVal = std::min(minVal, sample);
90  maxVal = std::max(maxVal, sample);
91  if (collectingHist)
92  hist.addSample(sample);
93 }
94 
95 statistic &statistic::operator+=(const statistic &other) {
96  if (other.sampleCount == 0)
97  return *this;
98 
99  if (sampleCount == 0) {
100  *this = other;
101  return *this;
102  }
103 
104  uint64_t newSampleCount = sampleCount + other.sampleCount;
105  double dnsc = double(newSampleCount);
106  double dsc = double(sampleCount);
107  double dscBydnsc = dsc / dnsc;
108  double dosc = double(other.sampleCount);
109  double delta = other.meanVal - meanVal;
110 
111  // Try to order these calculations to avoid overflows. If this were Fortran,
112  // then the compiler would not be able to re-order over brackets. In C++ it
113  // may be legal to do that (we certainly hope it doesn't, and CC+ Programming
114  // Language 2nd edition suggests it shouldn't, since it says that exploitation
115  // of associativity can only be made if the operation really is associative
116  // (which floating addition isn't...)).
117  meanVal = meanVal * dscBydnsc + other.meanVal * (1 - dscBydnsc);
118  m2 = m2 + other.m2 + dscBydnsc * dosc * delta * delta;
119  minVal = std::min(minVal, other.minVal);
120  maxVal = std::max(maxVal, other.maxVal);
121  sampleCount = newSampleCount;
122  if (collectingHist)
123  hist += other.hist;
124 
125  return *this;
126 }
127 
128 void statistic::scale(double factor) {
129  minVal = minVal * factor;
130  maxVal = maxVal * factor;
131  meanVal = meanVal * factor;
132  m2 = m2 * factor * factor;
133  return;
134 }
135 
136 std::string statistic::format(char unit, bool total) const {
137  std::string result = formatSI(sampleCount, 9, ' ');
138 
139  if (sampleCount == 0) {
140  result = result + std::string(", ") + formatSI(0.0, 9, unit);
141  result = result + std::string(", ") + formatSI(0.0, 9, unit);
142  result = result + std::string(", ") + formatSI(0.0, 9, unit);
143  if (total)
144  result = result + std::string(", ") + formatSI(0.0, 9, unit);
145  result = result + std::string(", ") + formatSI(0.0, 9, unit);
146  } else {
147  result = result + std::string(", ") + formatSI(minVal, 9, unit);
148  result = result + std::string(", ") + formatSI(meanVal, 9, unit);
149  result = result + std::string(", ") + formatSI(maxVal, 9, unit);
150  if (total)
151  result =
152  result + std::string(", ") + formatSI(meanVal * sampleCount, 9, unit);
153  result = result + std::string(", ") + formatSI(getSD(), 9, unit);
154  }
155  return result;
156 }
157 
158 /* ************* histogram member functions ************* */
159 
160 // Lowest bin that has anything in it
161 int logHistogram::minBin() const {
162  for (int i = 0; i < numBins; i++) {
163  if (bins[i].count != 0)
164  return i - logOffset;
165  }
166  return -logOffset;
167 }
168 
169 // Highest bin that has anything in it
170 int logHistogram::maxBin() const {
171  for (int i = numBins - 1; i >= 0; i--) {
172  if (bins[i].count != 0)
173  return i - logOffset;
174  }
175  return -logOffset;
176 }
177 
178 // Which bin does this sample belong in ?
179 uint32_t logHistogram::findBin(double sample) {
180  double v = std::fabs(sample);
181  // Simply loop up looking which bin to put it in.
182  // According to a micro-architect this is likely to be faster than a binary
183  // search, since
184  // it will only have one branch mis-predict
185  for (int b = 0; b < numBins; b++)
186  if (binMax[b] > v)
187  return b;
188  fprintf(stderr,
189  "Trying to add a sample that is too large into a histogram\n");
190  KMP_ASSERT(0);
191  return -1;
192 }
193 
194 void logHistogram::addSample(double sample) {
195  if (sample == 0.0) {
196  zeroCount += 1;
197 #ifdef KMP_DEBUG
198  _total++;
199  check();
200 #endif
201  return;
202  }
203  KMP_DEBUG_ASSERT(std::isfinite(sample));
204  uint32_t bin = findBin(sample);
205  KMP_DEBUG_ASSERT(0 <= bin && bin < numBins);
206 
207  bins[bin].count += 1;
208  bins[bin].total += sample;
209 #ifdef KMP_DEBUG
210  _total++;
211  check();
212 #endif
213 }
214 
215 // This may not be the format we want, but it'll do for now
216 std::string logHistogram::format(char unit) const {
217  std::stringstream result;
218 
219  result << "Bin, Count, Total\n";
220  if (zeroCount) {
221  result << "0, " << formatSI(zeroCount, 9, ' ') << ", ",
222  formatSI(0.0, 9, unit);
223  if (count(minBin()) == 0)
224  return result.str();
225  result << "\n";
226  }
227  for (int i = minBin(); i <= maxBin(); i++) {
228  result << "10**" << i << "<=v<10**" << (i + 1) << ", "
229  << formatSI(count(i), 9, ' ') << ", " << formatSI(total(i), 9, unit);
230  if (i != maxBin())
231  result << "\n";
232  }
233 
234  return result.str();
235 }
236 
237 /* ************* explicitTimer member functions ************* */
238 
239 void explicitTimer::start(tsc_tick_count tick) {
240  startTime = tick;
241  totalPauseTime = 0;
242  if (timeStat::logEvent(timerEnumValue)) {
243  __kmp_stats_thread_ptr->incrementNestValue();
244  }
245  return;
246 }
247 
248 void explicitTimer::stop(tsc_tick_count tick,
249  kmp_stats_list *stats_ptr /* = nullptr */) {
250  if (startTime.getValue() == 0)
251  return;
252 
253  stat->addSample(((tick - startTime) - totalPauseTime).ticks());
254 
255  if (timeStat::logEvent(timerEnumValue)) {
256  if (!stats_ptr)
257  stats_ptr = __kmp_stats_thread_ptr;
258  stats_ptr->push_event(
259  startTime.getValue() - __kmp_stats_start_time.getValue(),
260  tick.getValue() - __kmp_stats_start_time.getValue(),
261  __kmp_stats_thread_ptr->getNestValue(), timerEnumValue);
262  stats_ptr->decrementNestValue();
263  }
264 
265  /* We accept the risk that we drop a sample because it really did start at
266  t==0. */
267  startTime = 0;
268  return;
269 }
270 
271 /* ************* partitionedTimers member functions ************* */
272 partitionedTimers::partitionedTimers() { timer_stack.reserve(8); }
273 
274 // initialize the paritioned timers to an initial timer
275 void partitionedTimers::init(explicitTimer timer) {
276  KMP_DEBUG_ASSERT(this->timer_stack.size() == 0);
277  timer_stack.push_back(timer);
278  timer_stack.back().start(tsc_tick_count::now());
279 }
280 
281 // stop/save the current timer, and start the new timer (timer_pair)
282 // There is a special condition where if the current timer is equal to
283 // the one you are trying to push, then it only manipulates the stack,
284 // and it won't stop/start the currently running timer.
285 void partitionedTimers::push(explicitTimer timer) {
286  // get the current timer
287  // pause current timer
288  // push new timer
289  // start the new timer
290  explicitTimer *current_timer, *new_timer;
291  size_t stack_size;
292  KMP_DEBUG_ASSERT(this->timer_stack.size() > 0);
293  timer_stack.push_back(timer);
294  stack_size = timer_stack.size();
295  current_timer = &(timer_stack[stack_size - 2]);
296  new_timer = &(timer_stack[stack_size - 1]);
297  tsc_tick_count tick = tsc_tick_count::now();
298  current_timer->pause(tick);
299  new_timer->start(tick);
300 }
301 
302 // stop/discard the current timer, and start the previously saved timer
303 void partitionedTimers::pop() {
304  // get the current timer
305  // stop current timer (record event/sample)
306  // pop current timer
307  // get the new current timer and resume
308  explicitTimer *old_timer, *new_timer;
309  size_t stack_size = timer_stack.size();
310  KMP_DEBUG_ASSERT(stack_size > 1);
311  old_timer = &(timer_stack[stack_size - 1]);
312  new_timer = &(timer_stack[stack_size - 2]);
313  tsc_tick_count tick = tsc_tick_count::now();
314  old_timer->stop(tick);
315  new_timer->resume(tick);
316  timer_stack.pop_back();
317 }
318 
319 void partitionedTimers::exchange(explicitTimer timer) {
320  // get the current timer
321  // stop current timer (record event/sample)
322  // push new timer
323  // start the new timer
324  explicitTimer *current_timer, *new_timer;
325  size_t stack_size;
326  KMP_DEBUG_ASSERT(this->timer_stack.size() > 0);
327  tsc_tick_count tick = tsc_tick_count::now();
328  stack_size = timer_stack.size();
329  current_timer = &(timer_stack[stack_size - 1]);
330  current_timer->stop(tick);
331  timer_stack.pop_back();
332  timer_stack.push_back(timer);
333  new_timer = &(timer_stack[stack_size - 1]);
334  new_timer->start(tick);
335 }
336 
337 // Wind up all the currently running timers.
338 // This pops off all the timers from the stack and clears the stack
339 // After this is called, init() must be run again to initialize the
340 // stack of timers
341 void partitionedTimers::windup() {
342  while (timer_stack.size() > 1) {
343  this->pop();
344  }
345  // Pop the timer from the init() call
346  if (timer_stack.size() > 0) {
347  timer_stack.back().stop(tsc_tick_count::now());
348  timer_stack.pop_back();
349  }
350 }
351 
352 /* ************* kmp_stats_event_vector member functions ************* */
353 
354 void kmp_stats_event_vector::deallocate() {
355  __kmp_free(events);
356  internal_size = 0;
357  allocated_size = 0;
358  events = NULL;
359 }
360 
361 // This function is for qsort() which requires the compare function to return
362 // either a negative number if event1 < event2, a positive number if event1 >
363 // event2 or zero if event1 == event2. This sorts by start time (lowest to
364 // highest).
365 int compare_two_events(const void *event1, const void *event2) {
366  const kmp_stats_event *ev1 = RCAST(const kmp_stats_event *, event1);
367  const kmp_stats_event *ev2 = RCAST(const kmp_stats_event *, event2);
368 
369  if (ev1->getStart() < ev2->getStart())
370  return -1;
371  else if (ev1->getStart() > ev2->getStart())
372  return 1;
373  else
374  return 0;
375 }
376 
377 void kmp_stats_event_vector::sort() {
378  qsort(events, internal_size, sizeof(kmp_stats_event), compare_two_events);
379 }
380 
381 /* ************* kmp_stats_list member functions ************* */
382 
383 // returns a pointer to newly created stats node
384 kmp_stats_list *kmp_stats_list::push_back(int gtid) {
385  kmp_stats_list *newnode =
386  (kmp_stats_list *)__kmp_allocate(sizeof(kmp_stats_list));
387  // placement new, only requires space and pointer and initializes (so
388  // __kmp_allocate instead of C++ new[] is used)
389  new (newnode) kmp_stats_list();
390  newnode->setGtid(gtid);
391  newnode->prev = this->prev;
392  newnode->next = this;
393  newnode->prev->next = newnode;
394  newnode->next->prev = newnode;
395  return newnode;
396 }
397 void kmp_stats_list::deallocate() {
398  kmp_stats_list *ptr = this->next;
399  kmp_stats_list *delptr = this->next;
400  while (ptr != this) {
401  delptr = ptr;
402  ptr = ptr->next;
403  // placement new means we have to explicitly call destructor.
404  delptr->_event_vector.deallocate();
405  delptr->~kmp_stats_list();
406  __kmp_free(delptr);
407  }
408 }
409 kmp_stats_list::iterator kmp_stats_list::begin() {
410  kmp_stats_list::iterator it;
411  it.ptr = this->next;
412  return it;
413 }
414 kmp_stats_list::iterator kmp_stats_list::end() {
415  kmp_stats_list::iterator it;
416  it.ptr = this;
417  return it;
418 }
419 int kmp_stats_list::size() {
420  int retval;
421  kmp_stats_list::iterator it;
422  for (retval = 0, it = begin(); it != end(); it++, retval++) {
423  }
424  return retval;
425 }
426 
427 /* ************* kmp_stats_list::iterator member functions ************* */
428 
429 kmp_stats_list::iterator::iterator() : ptr(NULL) {}
430 kmp_stats_list::iterator::~iterator() {}
431 kmp_stats_list::iterator kmp_stats_list::iterator::operator++() {
432  this->ptr = this->ptr->next;
433  return *this;
434 }
435 kmp_stats_list::iterator kmp_stats_list::iterator::operator++(int dummy) {
436  this->ptr = this->ptr->next;
437  return *this;
438 }
439 kmp_stats_list::iterator kmp_stats_list::iterator::operator--() {
440  this->ptr = this->ptr->prev;
441  return *this;
442 }
443 kmp_stats_list::iterator kmp_stats_list::iterator::operator--(int dummy) {
444  this->ptr = this->ptr->prev;
445  return *this;
446 }
447 bool kmp_stats_list::iterator::operator!=(const kmp_stats_list::iterator &rhs) {
448  return this->ptr != rhs.ptr;
449 }
450 bool kmp_stats_list::iterator::operator==(const kmp_stats_list::iterator &rhs) {
451  return this->ptr == rhs.ptr;
452 }
453 kmp_stats_list *kmp_stats_list::iterator::operator*() const {
454  return this->ptr;
455 }
456 
457 /* ************* kmp_stats_output_module functions ************** */
458 
459 const char *kmp_stats_output_module::eventsFileName = NULL;
460 const char *kmp_stats_output_module::plotFileName = NULL;
461 int kmp_stats_output_module::printPerThreadFlag = 0;
462 int kmp_stats_output_module::printPerThreadEventsFlag = 0;
463 
464 static char const *lastName(char *name) {
465  int l = strlen(name);
466  for (int i = l - 1; i >= 0; --i) {
467  if (name[i] == '.')
468  name[i] = '_';
469  if (name[i] == '/')
470  return name + i + 1;
471  }
472  return name;
473 }
474 
475 /* Read the name of the executable from /proc/self/cmdline */
476 static char const *getImageName(char *buffer, size_t buflen) {
477  FILE *f = fopen("/proc/self/cmdline", "r");
478  buffer[0] = char(0);
479  if (!f)
480  return buffer;
481 
482  // The file contains char(0) delimited words from the commandline.
483  // This just returns the last filename component of the first word on the
484  // line.
485  size_t n = fread(buffer, 1, buflen, f);
486  if (n == 0) {
487  fclose(f);
488  KMP_CHECK_SYSFAIL("fread", 1)
489  }
490  fclose(f);
491  buffer[buflen - 1] = char(0);
492  return lastName(buffer);
493 }
494 
495 static void getTime(char *buffer, size_t buflen, bool underscores = false) {
496  time_t timer;
497 
498  time(&timer);
499 
500  struct tm *tm_info = localtime(&timer);
501  if (underscores)
502  strftime(buffer, buflen, "%Y-%m-%d_%H%M%S", tm_info);
503  else
504  strftime(buffer, buflen, "%Y-%m-%d %H%M%S", tm_info);
505 }
506 
507 /* Generate a stats file name, expanding prototypes */
508 static std::string generateFilename(char const *prototype,
509  char const *imageName) {
510  std::string res;
511 
512  for (int i = 0; prototype[i] != char(0); i++) {
513  char ch = prototype[i];
514 
515  if (ch == '%') {
516  i++;
517  if (prototype[i] == char(0))
518  break;
519 
520  switch (prototype[i]) {
521  case 't': // Insert time and date
522  {
523  char date[26];
524  getTime(date, sizeof(date), true);
525  res += date;
526  } break;
527  case 'e': // Insert executable name
528  res += imageName;
529  break;
530  case 'p': // Insert pid
531  {
532  std::stringstream ss;
533  ss << getpid();
534  res += ss.str();
535  } break;
536  default:
537  res += prototype[i];
538  break;
539  }
540  } else
541  res += ch;
542  }
543  return res;
544 }
545 
546 // init() is called very near the beginning of execution time in the constructor
547 // of __kmp_stats_global_output
548 void kmp_stats_output_module::init() {
549 
550  fprintf(stderr, "*** Stats enabled OpenMP* runtime ***\n");
551  char *statsFileName = getenv("KMP_STATS_FILE");
552  eventsFileName = getenv("KMP_STATS_EVENTS_FILE");
553  plotFileName = getenv("KMP_STATS_PLOT_FILE");
554  char *threadStats = getenv("KMP_STATS_THREADS");
555  char *threadEvents = getenv("KMP_STATS_EVENTS");
556 
557  // set the stats output filenames based on environment variables and defaults
558  if (statsFileName) {
559  char imageName[1024];
560  // Process any escapes (e.g., %p, %e, %t) in the name
561  outputFileName = generateFilename(
562  statsFileName, getImageName(&imageName[0], sizeof(imageName)));
563  }
564  eventsFileName = eventsFileName ? eventsFileName : "events.dat";
565  plotFileName = plotFileName ? plotFileName : "events.plt";
566 
567  // set the flags based on environment variables matching: true, on, 1, .true.
568  // , .t. , yes
569  printPerThreadFlag = __kmp_str_match_true(threadStats);
570  printPerThreadEventsFlag = __kmp_str_match_true(threadEvents);
571 
572  if (printPerThreadEventsFlag) {
573  // assigns a color to each timer for printing
574  setupEventColors();
575  } else {
576  // will clear flag so that no event will be logged
577  timeStat::clearEventFlags();
578  }
579 }
580 
581 void kmp_stats_output_module::setupEventColors() {
582  int i;
583  int globalColorIndex = 0;
584  int numGlobalColors = sizeof(globalColorArray) / sizeof(rgb_color);
585  for (i = 0; i < TIMER_LAST; i++) {
586  if (timeStat::logEvent((timer_e)i)) {
587  timerColorInfo[i] = globalColorArray[globalColorIndex];
588  globalColorIndex = (globalColorIndex + 1) % numGlobalColors;
589  }
590  }
591 }
592 
593 void kmp_stats_output_module::printTimerStats(FILE *statsOut,
594  statistic const *theStats,
595  statistic const *totalStats) {
596  fprintf(statsOut,
597  "Timer, SampleCount, Min, "
598  "Mean, Max, Total, SD\n");
599  for (timer_e s = timer_e(0); s < TIMER_LAST; s = timer_e(s + 1)) {
600  statistic const *stat = &theStats[s];
601  char tag = timeStat::noUnits(s) ? ' ' : 'T';
602 
603  fprintf(statsOut, "%-35s, %s\n", timeStat::name(s),
604  stat->format(tag, true).c_str());
605  }
606  // Also print the Total_ versions of times.
607  for (timer_e s = timer_e(0); s < TIMER_LAST; s = timer_e(s + 1)) {
608  char tag = timeStat::noUnits(s) ? ' ' : 'T';
609  if (totalStats && !timeStat::noTotal(s))
610  fprintf(statsOut, "Total_%-29s, %s\n", timeStat::name(s),
611  totalStats[s].format(tag, true).c_str());
612  }
613 
614  // Print historgram of statistics
615  if (theStats[0].haveHist()) {
616  fprintf(statsOut, "\nTimer distributions\n");
617  for (int s = 0; s < TIMER_LAST; s++) {
618  statistic const *stat = &theStats[s];
619 
620  if (stat->getCount() != 0) {
621  char tag = timeStat::noUnits(timer_e(s)) ? ' ' : 'T';
622 
623  fprintf(statsOut, "%s\n", timeStat::name(timer_e(s)));
624  fprintf(statsOut, "%s\n", stat->getHist()->format(tag).c_str());
625  }
626  }
627  }
628 }
629 
630 void kmp_stats_output_module::printCounterStats(FILE *statsOut,
631  statistic const *theStats) {
632  fprintf(statsOut, "Counter, ThreadCount, Min, Mean, "
633  " Max, Total, SD\n");
634  for (int s = 0; s < COUNTER_LAST; s++) {
635  statistic const *stat = &theStats[s];
636  fprintf(statsOut, "%-25s, %s\n", counter::name(counter_e(s)),
637  stat->format(' ', true).c_str());
638  }
639  // Print histogram of counters
640  if (theStats[0].haveHist()) {
641  fprintf(statsOut, "\nCounter distributions\n");
642  for (int s = 0; s < COUNTER_LAST; s++) {
643  statistic const *stat = &theStats[s];
644 
645  if (stat->getCount() != 0) {
646  fprintf(statsOut, "%s\n", counter::name(counter_e(s)));
647  fprintf(statsOut, "%s\n", stat->getHist()->format(' ').c_str());
648  }
649  }
650  }
651 }
652 
653 void kmp_stats_output_module::printCounters(FILE *statsOut,
654  counter const *theCounters) {
655  // We print all the counters even if they are zero.
656  // That makes it easier to slice them into a spreadsheet if you need to.
657  fprintf(statsOut, "\nCounter, Count\n");
658  for (int c = 0; c < COUNTER_LAST; c++) {
659  counter const *stat = &theCounters[c];
660  fprintf(statsOut, "%-25s, %s\n", counter::name(counter_e(c)),
661  formatSI(stat->getValue(), 9, ' ').c_str());
662  }
663 }
664 
665 void kmp_stats_output_module::printEvents(FILE *eventsOut,
666  kmp_stats_event_vector *theEvents,
667  int gtid) {
668  // sort by start time before printing
669  theEvents->sort();
670  for (int i = 0; i < theEvents->size(); i++) {
671  kmp_stats_event ev = theEvents->at(i);
672  rgb_color color = getEventColor(ev.getTimerName());
673  fprintf(eventsOut, "%d %lu %lu %1.1f rgb(%1.1f,%1.1f,%1.1f) %s\n", gtid,
674  ev.getStart(), ev.getStop(), 1.2 - (ev.getNestLevel() * 0.2),
675  color.r, color.g, color.b, timeStat::name(ev.getTimerName()));
676  }
677  return;
678 }
679 
680 void 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 explcit 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 
692 void 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 
753 static 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. */
763 void 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 
789 void 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
874 extern "C" {
875 
876 void __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.
895 void __kmp_output_stats(const char *heading) {
896  __kmp_stats_global_output->outputStats(heading);
897  __kmp_reset_stats();
898 }
899 
900 void __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 
908 void __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 
915 void __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"
do not show a TOTAL_aggregation for this statistic
Definition: kmp_stats.h:51
statistic doesn&#39;t need units printed next to it
Definition: kmp_stats.h:53
#define KMP_FOREACH_COUNTER(macro, arg)
Add new counters under KMP_FOREACH_COUNTER() macro in kmp_stats.h.
Definition: kmp_stats.h:95