/** @file kmp_stats.cpp * Statistics gathering and processing. */ //===----------------------------------------------------------------------===// // // The LLVM Compiler Infrastructure // // This file is dual licensed under the MIT and the University of Illinois Open // Source Licenses. See LICENSE.txt for details. // //===----------------------------------------------------------------------===// #if KMP_STATS_ENABLED #include "kmp.h" #include "kmp_str.h" #include "kmp_lock.h" #include "kmp_stats.h" #include #include #include #include // for atexit #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) {0,0} }; const statInfo counter::counterInfo[] = { KMP_FOREACH_COUNTER(expandName,0) {0,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; /* ****************************************************** */ /* ************* statistic member functions ************* */ void statistic::addSample(double 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); } statistic & statistic::operator+= (const statistic & other) { 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; 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,' '); 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; } /* ********************************************************** */ /* ************* explicitTimer member functions ************* */ void explicitTimer::start(timer_e timerEnumValue) { startTime = tsc_tick_count::now(); if(timeStat::logEvent(timerEnumValue)) { __kmp_stats_thread_ptr->incrementNestValue(); } return; } void explicitTimer::stop(timer_e timerEnumValue) { if (startTime.getValue() == 0) return; tsc_tick_count finishTime = tsc_tick_count::now(); //stat->addSample ((tsc_tick_count::now() - startTime).ticks()); stat->addSample ((finishTime - startTime).ticks()); if(timeStat::logEvent(timerEnumValue)) { __kmp_stats_thread_ptr->push_event(startTime.getValue() - __kmp_stats_start_time.getValue(), finishTime.getValue() - __kmp_stats_start_time.getValue(), __kmp_stats_thread_ptr->getNestValue(), timerEnumValue); __kmp_stats_thread_ptr->decrementNestValue(); } /* We accept the risk that we drop a sample because it really did start at t==0. */ startTime = 0; return; } /* ******************************************************************* */ /* ************* 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) { kmp_stats_event* ev1 = (kmp_stats_event*)event1; kmp_stats_event* ev2 = (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::outputFileName = NULL; 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; // 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 outputFileName = statsFileName; 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(); } return; } void kmp_stats_output_module::setupEventColors() { int i; int globalColorIndex = 0; int numGlobalColors = sizeof(globalColorArray) / sizeof(rgb_color); for(i=0;igetCount() != 0) { char tag = timeStat::noUnits(timer_e(s)) ? ' ' : 'T'; fprintf (statsOut, "%-25s, %s\n", timeStat::name(timer_e(s)), stat->format(tag, true).c_str()); } } } else { // Counters for (int s = 0; sformat(' ', true).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; cgetValue(), 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 %lu %lu %1.1f rgb(%1.1f,%1.1f,%1.1f) %s\n", gtid, ev.getStart(), 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++) { for (int timer=0; timergetExplicitTimer(explicit_timer_e(timer))->stop((timer_e)timer); } } } 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;igetGtid(); // Output per thread stats if requested. if (perThreadPrintingEnabled()) { fprintf (statsOut, "Thread %d\n", t); printStats(statsOut, (*it)->getTimers(), true); 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); } for (int s = 0; sgetTimer(timer_e(s)); allStats[s] += *threadStat; } // Special handling for synthesized statistics. // These just have to be coded specially here for now. // At present we only have one: the total parallel work done in each thread. // The variance here makes it easy to see load imbalance over the whole program (though, of course, // it's possible to have a code with awful load balance in every parallel region but perfect load // balance oever the whole program.) allStats[TIMER_Total_work].addSample ((*it)->getTimer(TIMER_OMP_work)->getTotal()); // Time waiting for work (synthesized) if ((t != 0) || !timeStat::workerOnly(timer_e(TIMER_OMP_await_work))) allStats[TIMER_Total_await_work].addSample ((*it)->getTimer(TIMER_OMP_await_work)->getTotal()); // Time in explicit barriers. allStats[TIMER_Total_barrier].addSample ((*it)->getTimer(TIMER_OMP_barrier)->getTotal()); for (int c = 0; cgetCounter(counter_e(c))->getValue()); } } if (eventPrintingEnabled()) { printPloticusFile(); fclose(eventsOut); } fprintf (statsOut, "Aggregate for all threads\n"); printStats (statsOut, &allStats[0], true); fprintf (statsOut, "\n"); printStats (statsOut, &allCounters[0], false); 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(); explicitTimer * eTimers = (*it)->getExplicitTimers(); for (int t = 0; tresetEventVector(); // May need to restart the explicit timers in thread zero? } KMP_START_EXPLICIT_TIMER(OMP_serial); KMP_START_EXPLICIT_TIMER(OMP_start_end); } // 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"); return; } void __kmp_stats_init(void) { return; } } // extern "C" #endif // KMP_STATS_ENABLED