/** @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 #include #include #include #include // for atexit #include #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}; /* ************* 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(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; b++) if (binMax[b] > v) return b; fprintf(stderr, "Trying to add a sample that is too large into a histogram\n"); KMP_ASSERT(0); return -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<10**" << (i + 1) << ", " << 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 paritioned 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 = 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 historgram 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(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(ev.getStart()), static_cast(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 explcit 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(); FILE *plotOut = fopen(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"); fclose(plotOut); 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]; FILE *statsOut = !outputFileName.empty() ? fopen(outputFileName.c_str(), "a+") : stderr; if (!statsOut) statsOut = stderr; FILE *eventsOut; if (eventPrintingEnabled()) { eventsOut = fopen(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 master // and this thread is worker (timeStat::workerOnly(s) && (t == 0)) // Timer only valid on worker // and this thread is the master ) { 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((*it)->getCounter(c)->getValue()); } } if (eventPrintingEnabled()) { printPloticusFile(); fclose(eventsOut); } fprintf(statsOut, "Aggregate for all threads\n"); printTimerStats(statsOut, &allStats[0], &totalStats[0]); fprintf(statsOut, "\n"); printCounterStats(statsOut, &allCounters[0]); if (statsOut != stderr) fclose(statsOut); } /* ************* 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"