contrib/llvm-project/openmp/runtime/src/kmp_stats.cpp

   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},
  29 statInfo timeStat::timerInfo[] = {
  30     KMP_FOREACH_TIMER(expandName, 0){"TIMER_LAST", 0}};
  31 const 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},
  36 kmp_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
  40 const 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.
  65 static uint32_t statsPrinted = 0;
  66
  67 // output interface
  68 static kmp_stats_output_module *__kmp_stats_global_output = NULL;
  69
  70 double 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
  78 void 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
  94 statistic &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
 127 void 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
 135 std::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
 160 int 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
 169 int 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 ?
 178 uint32_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
 193 void 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
 215 std::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
 238 void 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
 247 void 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 ************* */
 271 partitionedTimers::partitionedTimers() { timer_stack.reserve(8); }
 272
 273 // initialize the paritioned timers to an initial timer
 274 void 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.
 284 void 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
 302 void 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
 318 void 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
 340 void 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
 353 void 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).
 364 int 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
 376 void 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
 383 kmp_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 }
 396 void 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 }
 408 kmp_stats_list::iterator kmp_stats_list::begin() {
 409   kmp_stats_list::iterator it;
 410   it.ptr = this->next;
 411   return it;
 412 }
 413 kmp_stats_list::iterator kmp_stats_list::end() {
 414   kmp_stats_list::iterator it;
 415   it.ptr = this;
 416   return it;
 417 }
 418 int 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
 428 kmp_stats_list::iterator::iterator() : ptr(NULL) {}
 429 kmp_stats_list::iterator::~iterator() {}
 430 kmp_stats_list::iterator kmp_stats_list::iterator::operator++() {
 431   this->ptr = this->ptr->next;
 432   return *this;
 433 }
 434 kmp_stats_list::iterator kmp_stats_list::iterator::operator++(int dummy) {
 435   this->ptr = this->ptr->next;
 436   return *this;
 437 }
 438 kmp_stats_list::iterator kmp_stats_list::iterator::operator--() {
 439   this->ptr = this->ptr->prev;
 440   return *this;
 441 }
 442 kmp_stats_list::iterator kmp_stats_list::iterator::operator--(int dummy) {
 443   this->ptr = this->ptr->prev;
 444   return *this;
 445 }
 446 bool kmp_stats_list::iterator::operator!=(const kmp_stats_list::iterator &rhs) {
 447   return this->ptr != rhs.ptr;
 448 }
 449 bool kmp_stats_list::iterator::operator==(const kmp_stats_list::iterator &rhs) {
 450   return this->ptr == rhs.ptr;
 451 }
 452 kmp_stats_list *kmp_stats_list::iterator::operator*() const {
 453   return this->ptr;
 454 }
 455
 456 /* *************  kmp_stats_output_module functions ************** */
 457
 458 const char *kmp_stats_output_module::eventsFileName = NULL;
 459 const char *kmp_stats_output_module::plotFileName = NULL;
 460 int kmp_stats_output_module::printPerThreadFlag = 0;
 461 int kmp_stats_output_module::printPerThreadEventsFlag = 0;
 462
 463 static 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 */
 475 static 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
 494 static 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 */
 507 static 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
 547 void 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
 579 void 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
 591 void 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
 628 void 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
 651 void 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
 663 void 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
 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"