runtime/src/kmp_stats.cpp

/** @file kmp_stats.cpp
 * Statistics gathering and processing.
 */

//===----------------------------------------------------------------------===//
//
// Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
// See https://llvm.org/LICENSE.txt for license information.
// SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
//
//===----------------------------------------------------------------------===//

#include "kmp.h"
#include "kmp_lock.h"
#include "kmp_stats.h"
#include "kmp_str.h"

#include <algorithm>
#include <ctime>
#include <iomanip>
#include <sstream>
#include <stdlib.h> // for atexit
#include <cmath>

#define STRINGIZE2(x) #x
#define STRINGIZE(x) STRINGIZE2(x)

#define expandName(name, flags, ignore) {STRINGIZE(name), flags},
statInfo timeStat::timerInfo[] = {
    KMP_FOREACH_TIMER(expandName, 0){"TIMER_LAST", 0}};
const statInfo counter::counterInfo[] = {
    KMP_FOREACH_COUNTER(expandName, 0){"COUNTER_LAST", 0}};
#undef expandName

#define expandName(ignore1, ignore2, ignore3) {0.0, 0.0, 0.0},
kmp_stats_output_module::rgb_color kmp_stats_output_module::timerColorInfo[] = {
    KMP_FOREACH_TIMER(expandName, 0){0.0, 0.0, 0.0}};
#undef expandName

const kmp_stats_output_module::rgb_color
    kmp_stats_output_module::globalColorArray[] = {
        {1.0, 0.0, 0.0}, // red
        {1.0, 0.6, 0.0}, // orange
        {1.0, 1.0, 0.0}, // yellow
        {0.0, 1.0, 0.0}, // green
        {0.0, 0.0, 1.0}, // blue
        {0.6, 0.2, 0.8}, // purple
        {1.0, 0.0, 1.0}, // magenta
        {0.0, 0.4, 0.2}, // dark green
        {1.0, 1.0, 0.6}, // light yellow
        {0.6, 0.4, 0.6}, // dirty purple
        {0.0, 1.0, 1.0}, // cyan
        {1.0, 0.4, 0.8}, // pink
        {0.5, 0.5, 0.5}, // grey
        {0.8, 0.7, 0.5}, // brown
        {0.6, 0.6, 1.0}, // light blue
        {1.0, 0.7, 0.5}, // peach
        {0.8, 0.5, 1.0}, // lavender
        {0.6, 0.0, 0.0}, // dark red
        {0.7, 0.6, 0.0}, // gold
        {0.0, 0.0, 0.0} // black
};

// Ensure that the atexit handler only runs once.
static uint32_t statsPrinted = 0;

// output interface
static kmp_stats_output_module *__kmp_stats_global_output = NULL;

double logHistogram::binMax[] = {1.e1l, 1.e2l, 1.e3l, 1.e4l, 1.e5l, 1.e6l,
                                 1.e7l, 1.e8l, 1.e9l, 1.e10l, 1.e11l, 1.e12l,
                                 1.e13l, 1.e14l, 1.e15l, 1.e16l, 1.e17l, 1.e18l,
                                 1.e19l, 1.e20l, 1.e21l, 1.e22l, 1.e23l, 1.e24l,
                                 1.e25l, 1.e26l, 1.e27l, 1.e28l, 1.e29l, 1.e30l,
                                 // Always have infinity be the last value
                                 std::numeric_limits<double>::infinity()};

/* ************* statistic member functions ************* */

void statistic::addSample(double sample) {
  sample -= offset;
  KMP_DEBUG_ASSERT(std::isfinite(sample));

  double delta = sample - meanVal;

  sampleCount = sampleCount + 1;
  meanVal = meanVal + delta / sampleCount;
  m2 = m2 + delta * (sample - meanVal);

  minVal = std::min(minVal, sample);
  maxVal = std::max(maxVal, sample);
  if (collectingHist)
    hist.addSample(sample);
}

statistic &statistic::operator+=(const statistic &other) {
  if (other.sampleCount == 0)
    return *this;

  if (sampleCount == 0) {
    *this = other;
    return *this;
  }

  uint64_t newSampleCount = sampleCount + other.sampleCount;
  double dnsc = double(newSampleCount);
  double dsc = double(sampleCount);
  double dscBydnsc = dsc / dnsc;
  double dosc = double(other.sampleCount);
  double delta = other.meanVal - meanVal;

  // Try to order these calculations to avoid overflows. If this were Fortran,
  // then the compiler would not be able to re-order over brackets. In C++ it
  // may be legal to do that (we certainly hope it doesn't, and CC+ Programming
  // Language 2nd edition suggests it shouldn't, since it says that exploitation
  // of associativity can only be made if the operation really is associative
  // (which floating addition isn't...)).
  meanVal = meanVal * dscBydnsc + other.meanVal * (1 - dscBydnsc);
  m2 = m2 + other.m2 + dscBydnsc * dosc * delta * delta;
  minVal = std::min(minVal, other.minVal);
  maxVal = std::max(maxVal, other.maxVal);
  sampleCount = newSampleCount;
  if (collectingHist)
    hist += other.hist;

  return *this;
}

void statistic::scale(double factor) {
  minVal = minVal * factor;
  maxVal = maxVal * factor;
  meanVal = meanVal * factor;
  m2 = m2 * factor * factor;
  return;
}

std::string statistic::format(char unit, bool total) const {
  std::string result = formatSI((double)sampleCount, 9, ' ');

  if (sampleCount == 0) {
    result = result + std::string(", ") + formatSI(0.0, 9, unit);
    result = result + std::string(", ") + formatSI(0.0, 9, unit);
    result = result + std::string(", ") + formatSI(0.0, 9, unit);
    if (total)
      result = result + std::string(", ") + formatSI(0.0, 9, unit);
    result = result + std::string(", ") + formatSI(0.0, 9, unit);
  } else {
    result = result + std::string(", ") + formatSI(minVal, 9, unit);
    result = result + std::string(", ") + formatSI(meanVal, 9, unit);
    result = result + std::string(", ") + formatSI(maxVal, 9, unit);
    if (total)
      result =
          result + std::string(", ") + formatSI(meanVal * sampleCount, 9, unit);
    result = result + std::string(", ") + formatSI(getSD(), 9, unit);
  }
  return result;
}

/* ************* histogram member functions ************* */

// Lowest bin that has anything in it
int logHistogram::minBin() const {
  for (int i = 0; i < numBins; i++) {
    if (bins[i].count != 0)
      return i - logOffset;
  }
  return -logOffset;
}

// Highest bin that has anything in it
int logHistogram::maxBin() const {
  for (int i = numBins - 1; i >= 0; i--) {
    if (bins[i].count != 0)
      return i - logOffset;
  }
  return -logOffset;
}

// Which bin does this sample belong in ?
uint32_t logHistogram::findBin(double sample) {
  double v = std::fabs(sample);
  // Simply loop up looking which bin to put it in.
  // According to a micro-architect this is likely to be faster than a binary
  // search, since
  // it will only have one branch mis-predict
  for (int b = 0; b < numBins - 1; b++)
    if (binMax[b] > v)
      return b;
  return numBins - 1;
}

void logHistogram::addSample(double sample) {
  if (sample == 0.0) {
    zeroCount += 1;
#ifdef KMP_DEBUG
    _total++;
    check();
#endif
    return;
  }
  KMP_DEBUG_ASSERT(std::isfinite(sample));
  uint32_t bin = findBin(sample);
  KMP_DEBUG_ASSERT(0 <= bin && bin < numBins);

  bins[bin].count += 1;
  bins[bin].total += sample;
#ifdef KMP_DEBUG
  _total++;
  check();
#endif
}

// This may not be the format we want, but it'll do for now
std::string logHistogram::format(char unit) const {
  std::stringstream result;

  result << "Bin,                Count,     Total\n";
  if (zeroCount) {
    result << "0,              " << formatSI(zeroCount, 9, ' ') << ", ",
        formatSI(0.0, 9, unit);
    if (count(minBin()) == 0)
      return result.str();
    result << "\n";
  }
  for (int i = minBin(); i <= maxBin(); i++) {
    result << "10**" << i << "<=v<";
    if (i + 1 == numBins - 1)
      result << "infinity, ";
    else
      result << "10**" << (i + 1) << ", ";
    result << formatSI(count(i), 9, ' ') << ", " << formatSI(total(i), 9, unit);
    if (i != maxBin())
      result << "\n";
  }

  return result.str();
}

/* ************* explicitTimer member functions ************* */

void explicitTimer::start(tsc_tick_count tick) {
  startTime = tick;
  totalPauseTime = 0;
  if (timeStat::logEvent(timerEnumValue)) {
    __kmp_stats_thread_ptr->incrementNestValue();
  }
  return;
}

void explicitTimer::stop(tsc_tick_count tick,
                         kmp_stats_list *stats_ptr /* = nullptr */) {
  if (startTime.getValue() == 0)
    return;

  stat->addSample(((tick - startTime) - totalPauseTime).ticks());

  if (timeStat::logEvent(timerEnumValue)) {
    if (!stats_ptr)
      stats_ptr = __kmp_stats_thread_ptr;
    stats_ptr->push_event(
        startTime.getValue() - __kmp_stats_start_time.getValue(),
        tick.getValue() - __kmp_stats_start_time.getValue(),
        __kmp_stats_thread_ptr->getNestValue(), timerEnumValue);
    stats_ptr->decrementNestValue();
  }

  /* We accept the risk that we drop a sample because it really did start at
     t==0. */
  startTime = 0;
  return;
}

/* ************* partitionedTimers member functions ************* */
partitionedTimers::partitionedTimers() { timer_stack.reserve(8); }

// initialize the partitioned timers to an initial timer
void partitionedTimers::init(explicitTimer timer) {
  KMP_DEBUG_ASSERT(this->timer_stack.size() == 0);
  timer_stack.push_back(timer);
  timer_stack.back().start(tsc_tick_count::now());
}

// stop/save the current timer, and start the new timer (timer_pair)
// There is a special condition where if the current timer is equal to
// the one you are trying to push, then it only manipulates the stack,
// and it won't stop/start the currently running timer.
void partitionedTimers::push(explicitTimer timer) {
  // get the current timer
  // pause current timer
  // push new timer
  // start the new timer
  explicitTimer *current_timer, *new_timer;
  size_t stack_size;
  KMP_DEBUG_ASSERT(this->timer_stack.size() > 0);
  timer_stack.push_back(timer);
  stack_size = timer_stack.size();
  current_timer = &(timer_stack[stack_size - 2]);
  new_timer = &(timer_stack[stack_size - 1]);
  tsc_tick_count tick = tsc_tick_count::now();
  current_timer->pause(tick);
  new_timer->start(tick);
}

// stop/discard the current timer, and start the previously saved timer
void partitionedTimers::pop() {
  // get the current timer
  // stop current timer (record event/sample)
  // pop current timer
  // get the new current timer and resume
  explicitTimer *old_timer, *new_timer;
  size_t stack_size = timer_stack.size();
  KMP_DEBUG_ASSERT(stack_size > 1);
  old_timer = &(timer_stack[stack_size - 1]);
  new_timer = &(timer_stack[stack_size - 2]);
  tsc_tick_count tick = tsc_tick_count::now();
  old_timer->stop(tick);
  new_timer->resume(tick);
  timer_stack.pop_back();
}

void partitionedTimers::exchange(explicitTimer timer) {
  // get the current timer
  // stop current timer (record event/sample)
  // push new timer
  // start the new timer
  explicitTimer *current_timer, *new_timer;
  size_t stack_size;
  KMP_DEBUG_ASSERT(this->timer_stack.size() > 0);
  tsc_tick_count tick = tsc_tick_count::now();
  stack_size = timer_stack.size();
  current_timer = &(timer_stack[stack_size - 1]);
  current_timer->stop(tick);
  timer_stack.pop_back();
  timer_stack.push_back(timer);
  new_timer = &(timer_stack[stack_size - 1]);
  new_timer->start(tick);
}

// Wind up all the currently running timers.
// This pops off all the timers from the stack and clears the stack
// After this is called, init() must be run again to initialize the
// stack of timers
void partitionedTimers::windup() {
  while (timer_stack.size() > 1) {
    this->pop();
  }
  // Pop the timer from the init() call
  if (timer_stack.size() > 0) {
    timer_stack.back().stop(tsc_tick_count::now());
    timer_stack.pop_back();
  }
}

/* ************* kmp_stats_event_vector member functions ************* */

void kmp_stats_event_vector::deallocate() {
  __kmp_free(events);
  internal_size = 0;
  allocated_size = 0;
  events = NULL;
}

// This function is for qsort() which requires the compare function to return
// either a negative number if event1 < event2, a positive number if event1 >
// event2 or zero if event1 == event2. This sorts by start time (lowest to
// highest).
int compare_two_events(const void *event1, const void *event2) {
  const kmp_stats_event *ev1 = RCAST(const kmp_stats_event *, event1);
  const kmp_stats_event *ev2 = RCAST(const kmp_stats_event *, event2);

  if (ev1->getStart() < ev2->getStart())
    return -1;
  else if (ev1->getStart() > ev2->getStart())
    return 1;
  else
    return 0;
}

void kmp_stats_event_vector::sort() {
  qsort(events, internal_size, sizeof(kmp_stats_event), compare_two_events);
}

/* ************* kmp_stats_list member functions ************* */

// returns a pointer to newly created stats node
kmp_stats_list *kmp_stats_list::push_back(int gtid) {
  kmp_stats_list *newnode =
      (kmp_stats_list *)__kmp_allocate(sizeof(kmp_stats_list));
  // placement new, only requires space and pointer and initializes (so
  // __kmp_allocate instead of C++ new[] is used)
  new (newnode) kmp_stats_list();
  newnode->setGtid(gtid);
  newnode->prev = this->prev;
  newnode->next = this;
  newnode->prev->next = newnode;
  newnode->next->prev = newnode;
  return newnode;
}
void kmp_stats_list::deallocate() {
  kmp_stats_list *ptr = this->next;
  kmp_stats_list *delptr = this->next;
  while (ptr != this) {
    delptr = ptr;
    ptr = ptr->next;
    // placement new means we have to explicitly call destructor.
    delptr->_event_vector.deallocate();
    delptr->~kmp_stats_list();
    __kmp_free(delptr);
  }
}
kmp_stats_list::iterator kmp_stats_list::begin() {
  kmp_stats_list::iterator it;
  it.ptr = this->next;
  return it;
}
kmp_stats_list::iterator kmp_stats_list::end() {
  kmp_stats_list::iterator it;
  it.ptr = this;
  return it;
}
int kmp_stats_list::size() {
  int retval;
  kmp_stats_list::iterator it;
  for (retval = 0, it = begin(); it != end(); it++, retval++) {
  }
  return retval;
}

/* ************* kmp_stats_list::iterator member functions ************* */

kmp_stats_list::iterator::iterator() : ptr(NULL) {}
kmp_stats_list::iterator::~iterator() {}
kmp_stats_list::iterator kmp_stats_list::iterator::operator++() {
  this->ptr = this->ptr->next;
  return *this;
}
kmp_stats_list::iterator kmp_stats_list::iterator::operator++(int dummy) {
  this->ptr = this->ptr->next;
  return *this;
}
kmp_stats_list::iterator kmp_stats_list::iterator::operator--() {
  this->ptr = this->ptr->prev;
  return *this;
}
kmp_stats_list::iterator kmp_stats_list::iterator::operator--(int dummy) {
  this->ptr = this->ptr->prev;
  return *this;
}
bool kmp_stats_list::iterator::operator!=(const kmp_stats_list::iterator &rhs) {
  return this->ptr != rhs.ptr;
}
bool kmp_stats_list::iterator::operator==(const kmp_stats_list::iterator &rhs) {
  return this->ptr == rhs.ptr;
}
kmp_stats_list *kmp_stats_list::iterator::operator*() const {
  return this->ptr;
}

/* *************  kmp_stats_output_module functions ************** */

const char *kmp_stats_output_module::eventsFileName = NULL;
const char *kmp_stats_output_module::plotFileName = NULL;
int kmp_stats_output_module::printPerThreadFlag = 0;
int kmp_stats_output_module::printPerThreadEventsFlag = 0;

static char const *lastName(char *name) {
  int l = (int)strlen(name);
  for (int i = l - 1; i >= 0; --i) {
    if (name[i] == '.')
      name[i] = '_';
    if (name[i] == '/')
      return name + i + 1;
  }
  return name;
}

/* Read the name of the executable from /proc/self/cmdline */
static char const *getImageName(char *buffer, size_t buflen) {
  FILE *f = fopen("/proc/self/cmdline", "r");
  buffer[0] = char(0);
  if (!f)
    return buffer;

  // The file contains char(0) delimited words from the commandline.
  // This just returns the last filename component of the first word on the
  // line.
  size_t n = fread(buffer, 1, buflen, f);
  if (n == 0) {
    fclose(f);
    KMP_CHECK_SYSFAIL("fread", 1)
  }
  fclose(f);
  buffer[buflen - 1] = char(0);
  return lastName(buffer);
}

static void getTime(char *buffer, size_t buflen, bool underscores = false) {
  time_t timer;

  time(&timer);

  struct tm *tm_info = localtime(&timer);
  if (underscores)
    strftime(buffer, buflen, "%Y-%m-%d_%H%M%S", tm_info);
  else
    strftime(buffer, buflen, "%Y-%m-%d %H%M%S", tm_info);
}

/* Generate a stats file name, expanding prototypes */
static std::string generateFilename(char const *prototype,
                                    char const *imageName) {
  std::string res;

  for (int i = 0; prototype[i] != char(0); i++) {
    char ch = prototype[i];

    if (ch == '%') {
      i++;
      if (prototype[i] == char(0))
        break;

      switch (prototype[i]) {
      case 't': // Insert time and date
      {
        char date[26];
        getTime(date, sizeof(date), true);
        res += date;
      } break;
      case 'e': // Insert executable name
        res += imageName;
        break;
      case 'p': // Insert pid
      {
        std::stringstream ss;
        ss << getpid();
        res += ss.str();
      } break;
      default:
        res += prototype[i];
        break;
      }
    } else
      res += ch;
  }
  return res;
}

// init() is called very near the beginning of execution time in the constructor
// of __kmp_stats_global_output
void kmp_stats_output_module::init() {

  char *statsFileName = getenv("KMP_STATS_FILE");
  eventsFileName = getenv("KMP_STATS_EVENTS_FILE");
  plotFileName = getenv("KMP_STATS_PLOT_FILE");
  char *threadStats = getenv("KMP_STATS_THREADS");
  char *threadEvents = getenv("KMP_STATS_EVENTS");

  // set the stats output filenames based on environment variables and defaults
  if (statsFileName) {
    char imageName[1024];
    // Process any escapes (e.g., %p, %e, %t) in the name
    outputFileName = generateFilename(
        statsFileName, getImageName(&imageName[0], sizeof(imageName)));
  }
  eventsFileName = eventsFileName ? eventsFileName : "events.dat";
  plotFileName = plotFileName ? plotFileName : "events.plt";

  // set the flags based on environment variables matching: true, on, 1, .true.
  // , .t. , yes
  printPerThreadFlag = __kmp_str_match_true(threadStats);
  printPerThreadEventsFlag = __kmp_str_match_true(threadEvents);

  if (printPerThreadEventsFlag) {
    // assigns a color to each timer for printing
    setupEventColors();
  } else {
    // will clear flag so that no event will be logged
    timeStat::clearEventFlags();
  }
}

void kmp_stats_output_module::setupEventColors() {
  int i;
  int globalColorIndex = 0;
  int numGlobalColors = sizeof(globalColorArray) / sizeof(rgb_color);
  for (i = 0; i < TIMER_LAST; i++) {
    if (timeStat::logEvent((timer_e)i)) {
      timerColorInfo[i] = globalColorArray[globalColorIndex];
      globalColorIndex = (globalColorIndex + 1) % numGlobalColors;
    }
  }
}

void kmp_stats_output_module::printTimerStats(FILE *statsOut,
                                              statistic const *theStats,
                                              statistic const *totalStats) {
  fprintf(statsOut,
          "Timer,                             SampleCount,    Min,      "
          "Mean,       Max,     Total,        SD\n");
  for (timer_e s = timer_e(0); s < TIMER_LAST; s = timer_e(s + 1)) {
    statistic const *stat = &theStats[s];
    char tag = timeStat::noUnits(s) ? ' ' : 'T';

    fprintf(statsOut, "%-35s, %s\n", timeStat::name(s),
            stat->format(tag, true).c_str());
  }
  // Also print the Total_ versions of times.
  for (timer_e s = timer_e(0); s < TIMER_LAST; s = timer_e(s + 1)) {
    char tag = timeStat::noUnits(s) ? ' ' : 'T';
    if (totalStats && !timeStat::noTotal(s))
      fprintf(statsOut, "Total_%-29s, %s\n", timeStat::name(s),
              totalStats[s].format(tag, true).c_str());
  }

  // Print histogram of statistics
  if (theStats[0].haveHist()) {
    fprintf(statsOut, "\nTimer distributions\n");
    for (int s = 0; s < TIMER_LAST; s++) {
      statistic const *stat = &theStats[s];

      if (stat->getCount() != 0) {
        char tag = timeStat::noUnits(timer_e(s)) ? ' ' : 'T';

        fprintf(statsOut, "%s\n", timeStat::name(timer_e(s)));
        fprintf(statsOut, "%s\n", stat->getHist()->format(tag).c_str());
      }
    }
  }
}

void kmp_stats_output_module::printCounterStats(FILE *statsOut,
                                                statistic const *theStats) {
  fprintf(statsOut, "Counter,                 ThreadCount,    Min,      Mean,  "
                    "     Max,     Total,        SD\n");
  for (int s = 0; s < COUNTER_LAST; s++) {
    statistic const *stat = &theStats[s];
    fprintf(statsOut, "%-25s, %s\n", counter::name(counter_e(s)),
            stat->format(' ', true).c_str());
  }
  // Print histogram of counters
  if (theStats[0].haveHist()) {
    fprintf(statsOut, "\nCounter distributions\n");
    for (int s = 0; s < COUNTER_LAST; s++) {
      statistic const *stat = &theStats[s];

      if (stat->getCount() != 0) {
        fprintf(statsOut, "%s\n", counter::name(counter_e(s)));
        fprintf(statsOut, "%s\n", stat->getHist()->format(' ').c_str());
      }
    }
  }
}

void kmp_stats_output_module::printCounters(FILE *statsOut,
                                            counter const *theCounters) {
  // We print all the counters even if they are zero.
  // That makes it easier to slice them into a spreadsheet if you need to.
  fprintf(statsOut, "\nCounter,                    Count\n");
  for (int c = 0; c < COUNTER_LAST; c++) {
    counter const *stat = &theCounters[c];
    fprintf(statsOut, "%-25s, %s\n", counter::name(counter_e(c)),
            formatSI((double)stat->getValue(), 9, ' ').c_str());
  }
}

void kmp_stats_output_module::printEvents(FILE *eventsOut,
                                          kmp_stats_event_vector *theEvents,
                                          int gtid) {
  // sort by start time before printing
  theEvents->sort();
  for (int i = 0; i < theEvents->size(); i++) {
    kmp_stats_event ev = theEvents->at(i);
    rgb_color color = getEventColor(ev.getTimerName());
    fprintf(eventsOut, "%d %llu %llu %1.1f rgb(%1.1f,%1.1f,%1.1f) %s\n", gtid,
            static_cast<unsigned long long>(ev.getStart()),
            static_cast<unsigned long long>(ev.getStop()),
            1.2 - (ev.getNestLevel() * 0.2), color.r, color.g, color.b,
            timeStat::name(ev.getTimerName()));
  }
  return;
}

void kmp_stats_output_module::windupExplicitTimers() {
  // Wind up any explicit timers. We assume that it's fair at this point to just
  // walk all the explicit timers in all threads and say "it's over".
  // If the timer wasn't running, this won't record anything anyway.
  kmp_stats_list::iterator it;
  for (it = __kmp_stats_list->begin(); it != __kmp_stats_list->end(); it++) {
    kmp_stats_list *ptr = *it;
    ptr->getPartitionedTimers()->windup();
    ptr->endLife();
  }
}

void kmp_stats_output_module::printPloticusFile() {
  int i;
  int size = __kmp_stats_list->size();
  kmp_safe_raii_file_t plotOut(plotFileName, "w+");
  fprintf(plotOut, "#proc page\n"
                   "   pagesize: 15 10\n"
                   "   scale: 1.0\n\n");

  fprintf(plotOut,
          "#proc getdata\n"
          "   file: %s\n\n",
          eventsFileName);

  fprintf(plotOut,
          "#proc areadef\n"
          "   title: OpenMP Sampling Timeline\n"
          "   titledetails: align=center size=16\n"
          "   rectangle: 1 1 13 9\n"
          "   xautorange: datafield=2,3\n"
          "   yautorange: -1 %d\n\n",
          size);

  fprintf(plotOut, "#proc xaxis\n"
                   "   stubs: inc\n"
                   "   stubdetails: size=12\n"
                   "   label: Time (ticks)\n"
                   "   labeldetails: size=14\n\n");

  fprintf(plotOut,
          "#proc yaxis\n"
          "   stubs: inc 1\n"
          "   stubrange: 0 %d\n"
          "   stubdetails: size=12\n"
          "   label: Thread #\n"
          "   labeldetails: size=14\n\n",
          size - 1);

  fprintf(plotOut, "#proc bars\n"
                   "   exactcolorfield: 5\n"
                   "   axis: x\n"
                   "   locfield: 1\n"
                   "   segmentfields: 2 3\n"
                   "   barwidthfield: 4\n\n");

  // create legend entries corresponding to the timer color
  for (i = 0; i < TIMER_LAST; i++) {
    if (timeStat::logEvent((timer_e)i)) {
      rgb_color c = getEventColor((timer_e)i);
      fprintf(plotOut,
              "#proc legendentry\n"
              "   sampletype: color\n"
              "   label: %s\n"
              "   details: rgb(%1.1f,%1.1f,%1.1f)\n\n",
              timeStat::name((timer_e)i), c.r, c.g, c.b);
    }
  }

  fprintf(plotOut, "#proc legend\n"
                   "   format: down\n"
                   "   location: max max\n\n");
  return;
}

static void outputEnvVariable(FILE *statsOut, char const *name) {
  char const *value = getenv(name);
  fprintf(statsOut, "# %s = %s\n", name, value ? value : "*unspecified*");
}

/* Print some useful information about
   * the date and time this experiment ran.
   * the machine on which it ran.
   We output all of this as stylised comments, though we may decide to parse
   some of it. */
void kmp_stats_output_module::printHeaderInfo(FILE *statsOut) {
  std::time_t now = std::time(0);
  char buffer[40];
  char hostName[80];

  std::strftime(&buffer[0], sizeof(buffer), "%c", std::localtime(&now));
  fprintf(statsOut, "# Time of run: %s\n", &buffer[0]);
  if (gethostname(&hostName[0], sizeof(hostName)) == 0)
    fprintf(statsOut, "# Hostname: %s\n", &hostName[0]);
#if KMP_ARCH_X86 || KMP_ARCH_X86_64
  fprintf(statsOut, "# CPU:  %s\n", &__kmp_cpuinfo.name[0]);
  fprintf(statsOut, "# Family: %d, Model: %d, Stepping: %d\n",
          __kmp_cpuinfo.family, __kmp_cpuinfo.model, __kmp_cpuinfo.stepping);
  if (__kmp_cpuinfo.frequency == 0)
    fprintf(statsOut, "# Nominal frequency: Unknown\n");
  else
    fprintf(statsOut, "# Nominal frequency: %sz\n",
            formatSI(double(__kmp_cpuinfo.frequency), 9, 'H').c_str());
  outputEnvVariable(statsOut, "KMP_HW_SUBSET");
  outputEnvVariable(statsOut, "KMP_AFFINITY");
  outputEnvVariable(statsOut, "KMP_BLOCKTIME");
  outputEnvVariable(statsOut, "KMP_LIBRARY");
  fprintf(statsOut, "# Production runtime built " __DATE__ " " __TIME__ "\n");
#endif
}

void kmp_stats_output_module::outputStats(const char *heading) {
  // Stop all the explicit timers in all threads
  // Do this before declaring the local statistics because thay have
  // constructors so will take time to create.
  windupExplicitTimers();

  statistic allStats[TIMER_LAST];
  statistic totalStats[TIMER_LAST]; /* Synthesized, cross threads versions of
                                       normal timer stats */
  statistic allCounters[COUNTER_LAST];

  kmp_safe_raii_file_t statsOut;
  if (!outputFileName.empty()) {
    statsOut.open(outputFileName.c_str(), "a+");
  } else {
    statsOut.set_stderr();
  }

  kmp_safe_raii_file_t eventsOut;
  if (eventPrintingEnabled()) {
    eventsOut.open(eventsFileName, "w+");
  }

  printHeaderInfo(statsOut);
  fprintf(statsOut, "%s\n", heading);
  // Accumulate across threads.
  kmp_stats_list::iterator it;
  for (it = __kmp_stats_list->begin(); it != __kmp_stats_list->end(); it++) {
    int t = (*it)->getGtid();
    // Output per thread stats if requested.
    if (printPerThreadFlag) {
      fprintf(statsOut, "Thread %d\n", t);
      printTimerStats(statsOut, (*it)->getTimers(), 0);
      printCounters(statsOut, (*it)->getCounters());
      fprintf(statsOut, "\n");
    }
    // Output per thread events if requested.
    if (eventPrintingEnabled()) {
      kmp_stats_event_vector events = (*it)->getEventVector();
      printEvents(eventsOut, &events, t);
    }

    // Accumulate timers.
    for (timer_e s = timer_e(0); s < TIMER_LAST; s = timer_e(s + 1)) {
      // See if we should ignore this timer when aggregating
      if ((timeStat::masterOnly(s) && (t != 0)) || // Timer only valid on
          // primary thread and this thread is worker
          (timeStat::workerOnly(s) && (t == 0)) // Timer only valid on worker
          // and this thread is the primary thread
          ) {
        continue;
      }

      statistic *threadStat = (*it)->getTimer(s);
      allStats[s] += *threadStat;

      // Add Total stats for timers that are valid in more than one thread
      if (!timeStat::noTotal(s))
        totalStats[s].addSample(threadStat->getTotal());
    }

    // Accumulate counters.
    for (counter_e c = counter_e(0); c < COUNTER_LAST; c = counter_e(c + 1)) {
      if (counter::masterOnly(c) && t != 0)
        continue;
      allCounters[c].addSample((double)(*it)->getCounter(c)->getValue());
    }
  }

  if (eventPrintingEnabled()) {
    printPloticusFile();
  }

  fprintf(statsOut, "Aggregate for all threads\n");
  printTimerStats(statsOut, &allStats[0], &totalStats[0]);
  fprintf(statsOut, "\n");
  printCounterStats(statsOut, &allCounters[0]);
}

/* *************  exported C functions ************** */

// no name mangling for these functions, we want the c files to be able to get
// at these functions
extern "C" {

void __kmp_reset_stats() {
  kmp_stats_list::iterator it;
  for (it = __kmp_stats_list->begin(); it != __kmp_stats_list->end(); it++) {
    timeStat *timers = (*it)->getTimers();
    counter *counters = (*it)->getCounters();

    for (int t = 0; t < TIMER_LAST; t++)
      timers[t].reset();

    for (int c = 0; c < COUNTER_LAST; c++)
      counters[c].reset();

    // reset the event vector so all previous events are "erased"
    (*it)->resetEventVector();
  }
}

// This function will reset all stats and stop all threads' explicit timers if
// they haven't been stopped already.
void __kmp_output_stats(const char *heading) {
  __kmp_stats_global_output->outputStats(heading);
  __kmp_reset_stats();
}

void __kmp_accumulate_stats_at_exit(void) {
  // Only do this once.
  if (KMP_XCHG_FIXED32(&statsPrinted, 1) != 0)
    return;

  __kmp_output_stats("Statistics on exit");
}

void __kmp_stats_init(void) {
  __kmp_init_tas_lock(&__kmp_stats_lock);
  __kmp_stats_start_time = tsc_tick_count::now();
  __kmp_stats_global_output = new kmp_stats_output_module();
  __kmp_stats_list = new kmp_stats_list();
}

void __kmp_stats_fini(void) {
  __kmp_accumulate_stats_at_exit();
  __kmp_stats_list->deallocate();
  delete __kmp_stats_global_output;
  delete __kmp_stats_list;
}

} // extern "C"