• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
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 
addSample(double sample)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 
operator +=(const statistic & other)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 
scale(double factor)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 
format(char unit,bool total) const135 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
minBin() const160 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
maxBin() const169 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 ?
findBin(double sample)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 
addSample(double sample)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
format(char unit) const215 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 
start(tsc_tick_count tick)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 
stop(tsc_tick_count tick,kmp_stats_list * stats_ptr)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 ************* */
partitionedTimers()271 partitionedTimers::partitionedTimers() { timer_stack.reserve(8); }
272 
273 // initialize the partitioned timers to an initial timer
init(explicitTimer 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.
push(explicitTimer 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
pop()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 
exchange(explicitTimer timer)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
windup()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 
deallocate()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).
compare_two_events(const void * event1,const void * event2)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 
sort()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
push_back(int gtid)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 }
deallocate()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 }
begin()408 kmp_stats_list::iterator kmp_stats_list::begin() {
409   kmp_stats_list::iterator it;
410   it.ptr = this->next;
411   return it;
412 }
end()413 kmp_stats_list::iterator kmp_stats_list::end() {
414   kmp_stats_list::iterator it;
415   it.ptr = this;
416   return it;
417 }
size()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 
iterator()428 kmp_stats_list::iterator::iterator() : ptr(NULL) {}
~iterator()429 kmp_stats_list::iterator::~iterator() {}
operator ++()430 kmp_stats_list::iterator kmp_stats_list::iterator::operator++() {
431   this->ptr = this->ptr->next;
432   return *this;
433 }
operator ++(int dummy)434 kmp_stats_list::iterator kmp_stats_list::iterator::operator++(int dummy) {
435   this->ptr = this->ptr->next;
436   return *this;
437 }
operator --()438 kmp_stats_list::iterator kmp_stats_list::iterator::operator--() {
439   this->ptr = this->ptr->prev;
440   return *this;
441 }
operator --(int dummy)442 kmp_stats_list::iterator kmp_stats_list::iterator::operator--(int dummy) {
443   this->ptr = this->ptr->prev;
444   return *this;
445 }
operator !=(const kmp_stats_list::iterator & rhs)446 bool kmp_stats_list::iterator::operator!=(const kmp_stats_list::iterator &rhs) {
447   return this->ptr != rhs.ptr;
448 }
operator ==(const kmp_stats_list::iterator & rhs)449 bool kmp_stats_list::iterator::operator==(const kmp_stats_list::iterator &rhs) {
450   return this->ptr == rhs.ptr;
451 }
operator *() const452 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 
lastName(char * name)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 */
getImageName(char * buffer,size_t buflen)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 
getTime(char * buffer,size_t buflen,bool underscores=false)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 */
generateFilename(char const * prototype,char const * imageName)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
init()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 
setupEventColors()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 
printTimerStats(FILE * statsOut,statistic const * theStats,statistic const * totalStats)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 histogram 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 
printCounterStats(FILE * statsOut,statistic const * theStats)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 
printCounters(FILE * statsOut,counter const * theCounters)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 
printEvents(FILE * eventsOut,kmp_stats_event_vector * theEvents,int gtid)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 
windupExplicitTimers()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 explicit 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 
printPloticusFile()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 
outputEnvVariable(FILE * statsOut,char const * name)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. */
printHeaderInfo(FILE * statsOut)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 
outputStats(const char * heading)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 
__kmp_reset_stats()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.
__kmp_output_stats(const char * heading)895 void __kmp_output_stats(const char *heading) {
896   __kmp_stats_global_output->outputStats(heading);
897   __kmp_reset_stats();
898 }
899 
__kmp_accumulate_stats_at_exit(void)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 
__kmp_stats_init(void)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 
__kmp_stats_fini(void)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"
923