blob: 3ae25d5a46f1b4d5e12704f32418093b3e4fff82 [file] [log] [blame]
Jim Cownie4cc4bb42014-10-07 16:25:50 +00001/** @file kmp_stats.cpp
2 * Statistics gathering and processing.
3 */
4
5
6//===----------------------------------------------------------------------===//
7//
8// The LLVM Compiler Infrastructure
9//
10// This file is dual licensed under the MIT and the University of Illinois Open
11// Source Licenses. See LICENSE.txt for details.
12//
13//===----------------------------------------------------------------------===//
14
Jim Cownie4cc4bb42014-10-07 16:25:50 +000015#include "kmp.h"
16#include "kmp_str.h"
17#include "kmp_lock.h"
18#include "kmp_stats.h"
19
20#include <algorithm>
21#include <sstream>
22#include <iomanip>
23#include <stdlib.h> // for atexit
Jonathan Peyton6e98d7982016-03-15 20:28:47 +000024#include <ctime>
Jim Cownie4cc4bb42014-10-07 16:25:50 +000025
26#define STRINGIZE2(x) #x
27#define STRINGIZE(x) STRINGIZE2(x)
28
29#define expandName(name,flags,ignore) {STRINGIZE(name),flags},
30statInfo timeStat::timerInfo[] = {
31 KMP_FOREACH_TIMER(expandName,0)
Jonathan Peyton5375fe82016-11-14 21:13:44 +000032 {"TIMER_LAST", 0}
Jim Cownie4cc4bb42014-10-07 16:25:50 +000033};
34const statInfo counter::counterInfo[] = {
35 KMP_FOREACH_COUNTER(expandName,0)
Jonathan Peyton5375fe82016-11-14 21:13:44 +000036 {"COUNTER_LAST", 0}
Jim Cownie4cc4bb42014-10-07 16:25:50 +000037};
38#undef expandName
39
40#define expandName(ignore1,ignore2,ignore3) {0.0,0.0,0.0},
41kmp_stats_output_module::rgb_color kmp_stats_output_module::timerColorInfo[] = {
42 KMP_FOREACH_TIMER(expandName,0)
43 {0.0,0.0,0.0}
44};
45#undef expandName
46
47const kmp_stats_output_module::rgb_color kmp_stats_output_module::globalColorArray[] = {
48 {1.0, 0.0, 0.0}, // red
49 {1.0, 0.6, 0.0}, // orange
50 {1.0, 1.0, 0.0}, // yellow
Jonathan Peyton072772b2016-04-05 18:48:48 +000051 {0.0, 1.0, 0.0}, // green
Jim Cownie4cc4bb42014-10-07 16:25:50 +000052 {0.0, 0.0, 1.0}, // blue
53 {0.6, 0.2, 0.8}, // purple
54 {1.0, 0.0, 1.0}, // magenta
55 {0.0, 0.4, 0.2}, // dark green
56 {1.0, 1.0, 0.6}, // light yellow
57 {0.6, 0.4, 0.6}, // dirty purple
58 {0.0, 1.0, 1.0}, // cyan
59 {1.0, 0.4, 0.8}, // pink
60 {0.5, 0.5, 0.5}, // grey
61 {0.8, 0.7, 0.5}, // brown
62 {0.6, 0.6, 1.0}, // light blue
63 {1.0, 0.7, 0.5}, // peach
64 {0.8, 0.5, 1.0}, // lavender
65 {0.6, 0.0, 0.0}, // dark red
66 {0.7, 0.6, 0.0}, // gold
67 {0.0, 0.0, 0.0} // black
68};
69
70// Ensure that the atexit handler only runs once.
71static uint32_t statsPrinted = 0;
72
73// output interface
Jonathan Peyton5375fe82016-11-14 21:13:44 +000074static kmp_stats_output_module* __kmp_stats_global_output = NULL;
Jim Cownie4cc4bb42014-10-07 16:25:50 +000075
76/* ****************************************************** */
77/* ************* statistic member functions ************* */
78
79void statistic::addSample(double sample)
80{
81 double delta = sample - meanVal;
82
83 sampleCount = sampleCount + 1;
84 meanVal = meanVal + delta/sampleCount;
85 m2 = m2 + delta*(sample - meanVal);
86
87 minVal = std::min(minVal, sample);
88 maxVal = std::max(maxVal, sample);
89}
90
91statistic & statistic::operator+= (const statistic & other)
92{
93 if (sampleCount == 0)
94 {
95 *this = other;
96 return *this;
97 }
98
99 uint64_t newSampleCount = sampleCount + other.sampleCount;
100 double dnsc = double(newSampleCount);
101 double dsc = double(sampleCount);
102 double dscBydnsc = dsc/dnsc;
103 double dosc = double(other.sampleCount);
104 double delta = other.meanVal - meanVal;
105
106 // Try to order these calculations to avoid overflows.
107 // If this were Fortran, then the compiler would not be able to re-order over brackets.
108 // In C++ it may be legal to do that (we certainly hope it doesn't, and CC+ Programming Language 2nd edition
109 // suggests it shouldn't, since it says that exploitation of associativity can only be made if the operation
110 // really is associative (which floating addition isn't...)).
111 meanVal = meanVal*dscBydnsc + other.meanVal*(1-dscBydnsc);
112 m2 = m2 + other.m2 + dscBydnsc*dosc*delta*delta;
113 minVal = std::min (minVal, other.minVal);
114 maxVal = std::max (maxVal, other.maxVal);
115 sampleCount = newSampleCount;
116
117
118 return *this;
119}
120
121void statistic::scale(double factor)
122{
123 minVal = minVal*factor;
124 maxVal = maxVal*factor;
125 meanVal= meanVal*factor;
126 m2 = m2*factor*factor;
127 return;
128}
129
130std::string statistic::format(char unit, bool total) const
131{
132 std::string result = formatSI(sampleCount,9,' ');
Jonathan Peyton072772b2016-04-05 18:48:48 +0000133
Jonathan Peytonc1a7c972016-03-03 21:24:13 +0000134 if (sampleCount == 0)
135 {
136 result = result + std::string(", ") + formatSI(0.0, 9, unit);
137 result = result + std::string(", ") + formatSI(0.0, 9, unit);
138 result = result + std::string(", ") + formatSI(0.0, 9, unit);
139 if (total)
140 result = result + std::string(", ") + formatSI(0.0, 9, unit);
141 result = result + std::string(", ") + formatSI(0.0, 9, unit);
142 }
143 else
144 {
145 result = result + std::string(", ") + formatSI(minVal, 9, unit);
146 result = result + std::string(", ") + formatSI(meanVal, 9, unit);
147 result = result + std::string(", ") + formatSI(maxVal, 9, unit);
148 if (total)
149 result = result + std::string(", ") + formatSI(meanVal*sampleCount, 9, unit);
150 result = result + std::string(", ") + formatSI(getSD(), 9, unit);
151 }
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000152 return result;
153}
154
155/* ********************************************************** */
156/* ************* explicitTimer member functions ************* */
157
Jonathan Peyton072772b2016-04-05 18:48:48 +0000158void explicitTimer::start(timer_e timerEnumValue) {
159 startTime = tsc_tick_count::now();
Jonathan Peyton11dc82f2016-05-05 16:15:57 +0000160 totalPauseTime = 0;
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000161 if(timeStat::logEvent(timerEnumValue)) {
162 __kmp_stats_thread_ptr->incrementNestValue();
163 }
164 return;
165}
166
Jonathan Peyton5375fe82016-11-14 21:13:44 +0000167void explicitTimer::stop(timer_e timerEnumValue, kmp_stats_list* stats_ptr /* = nullptr */) {
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000168 if (startTime.getValue() == 0)
169 return;
170
171 tsc_tick_count finishTime = tsc_tick_count::now();
172
173 //stat->addSample ((tsc_tick_count::now() - startTime).ticks());
Jonathan Peyton11dc82f2016-05-05 16:15:57 +0000174 stat->addSample(((finishTime - startTime) - totalPauseTime).ticks());
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000175
176 if(timeStat::logEvent(timerEnumValue)) {
Jonathan Peyton5375fe82016-11-14 21:13:44 +0000177 if(!stats_ptr)
178 stats_ptr = __kmp_stats_thread_ptr;
179 stats_ptr->push_event(startTime.getValue() - __kmp_stats_start_time.getValue(), finishTime.getValue() - __kmp_stats_start_time.getValue(), __kmp_stats_thread_ptr->getNestValue(), timerEnumValue);
180 stats_ptr->decrementNestValue();
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000181 }
182
183 /* We accept the risk that we drop a sample because it really did start at t==0. */
Jonathan Peyton072772b2016-04-05 18:48:48 +0000184 startTime = 0;
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000185 return;
186}
187
Jonathan Peyton11dc82f2016-05-05 16:15:57 +0000188/* ************************************************************** */
189/* ************* partitionedTimers member functions ************* */
190partitionedTimers::partitionedTimers() {
191 timer_stack.reserve(8);
192}
193
194// add a timer to this collection of partitioned timers.
195void partitionedTimers::add_timer(explicit_timer_e timer_index, explicitTimer* timer_pointer) {
196 KMP_DEBUG_ASSERT((int)timer_index < (int)EXPLICIT_TIMER_LAST+1);
197 timers[timer_index] = timer_pointer;
198}
199
200// initialize the paritioned timers to an initial timer
201void partitionedTimers::init(timerPair init_timer_pair) {
202 KMP_DEBUG_ASSERT(this->timer_stack.size() == 0);
203 timer_stack.push_back(init_timer_pair);
204 timers[init_timer_pair.get_index()]->start(init_timer_pair.get_timer());
205}
206
207// stop/save the current timer, and start the new timer (timer_pair)
208// There is a special condition where if the current timer is equal to
209// the one you are trying to push, then it only manipulates the stack,
210// and it won't stop/start the currently running timer.
211void partitionedTimers::push(timerPair timer_pair) {
212 // get the current timer
213 // stop current timer
214 // push new timer
215 // start the new timer
216 KMP_DEBUG_ASSERT(this->timer_stack.size() > 0);
217 timerPair current_timer = timer_stack.back();
218 timer_stack.push_back(timer_pair);
219 if(current_timer != timer_pair) {
220 timers[current_timer.get_index()]->pause();
221 timers[timer_pair.get_index()]->start(timer_pair.get_timer());
222 }
223}
224
225// stop/discard the current timer, and start the previously saved timer
226void partitionedTimers::pop() {
227 // get the current timer
228 // stop current timer
229 // pop current timer
230 // get the new current timer and start it back up
231 KMP_DEBUG_ASSERT(this->timer_stack.size() > 1);
232 timerPair current_timer = timer_stack.back();
233 timer_stack.pop_back();
234 timerPair new_timer = timer_stack.back();
235 if(current_timer != new_timer) {
236 timers[current_timer.get_index()]->stop(current_timer.get_timer());
237 timers[new_timer.get_index()]->resume();
238 }
239}
240
241// Wind up all the currently running timers.
242// This pops off all the timers from the stack and clears the stack
243// After this is called, init() must be run again to initialize the
244// stack of timers
245void partitionedTimers::windup() {
246 while(timer_stack.size() > 1) {
247 this->pop();
248 }
249 if(timer_stack.size() > 0) {
250 timerPair last_timer = timer_stack.back();
251 timer_stack.pop_back();
252 timers[last_timer.get_index()]->stop(last_timer.get_timer());
253 }
254}
255
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000256/* ******************************************************************* */
257/* ************* kmp_stats_event_vector member functions ************* */
258
259void kmp_stats_event_vector::deallocate() {
260 __kmp_free(events);
261 internal_size = 0;
262 allocated_size = 0;
263 events = NULL;
264}
265
266// This function is for qsort() which requires the compare function to return
267// either a negative number if event1 < event2, a positive number if event1 > event2
Jonathan Peyton072772b2016-04-05 18:48:48 +0000268// or zero if event1 == event2.
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000269// This sorts by start time (lowest to highest).
270int compare_two_events(const void* event1, const void* event2) {
271 kmp_stats_event* ev1 = (kmp_stats_event*)event1;
272 kmp_stats_event* ev2 = (kmp_stats_event*)event2;
273
274 if(ev1->getStart() < ev2->getStart()) return -1;
275 else if(ev1->getStart() > ev2->getStart()) return 1;
276 else return 0;
277}
278
279void kmp_stats_event_vector::sort() {
280 qsort(events, internal_size, sizeof(kmp_stats_event), compare_two_events);
281}
282
283/* *********************************************************** */
284/* ************* kmp_stats_list member functions ************* */
285
286// returns a pointer to newly created stats node
Jonathan Peyton072772b2016-04-05 18:48:48 +0000287kmp_stats_list* kmp_stats_list::push_back(int gtid) {
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000288 kmp_stats_list* newnode = (kmp_stats_list*)__kmp_allocate(sizeof(kmp_stats_list));
289 // placement new, only requires space and pointer and initializes (so __kmp_allocate instead of C++ new[] is used)
290 new (newnode) kmp_stats_list();
291 newnode->setGtid(gtid);
292 newnode->prev = this->prev;
293 newnode->next = this;
294 newnode->prev->next = newnode;
295 newnode->next->prev = newnode;
296 return newnode;
297}
298void kmp_stats_list::deallocate() {
299 kmp_stats_list* ptr = this->next;
300 kmp_stats_list* delptr = this->next;
301 while(ptr != this) {
302 delptr = ptr;
303 ptr=ptr->next;
304 // placement new means we have to explicitly call destructor.
305 delptr->_event_vector.deallocate();
306 delptr->~kmp_stats_list();
307 __kmp_free(delptr);
308 }
309}
310kmp_stats_list::iterator kmp_stats_list::begin() {
311 kmp_stats_list::iterator it;
312 it.ptr = this->next;
313 return it;
314}
315kmp_stats_list::iterator kmp_stats_list::end() {
316 kmp_stats_list::iterator it;
317 it.ptr = this;
318 return it;
319}
320int kmp_stats_list::size() {
321 int retval;
322 kmp_stats_list::iterator it;
323 for(retval=0, it=begin(); it!=end(); it++, retval++) {}
324 return retval;
325}
326
327/* ********************************************************************* */
328/* ************* kmp_stats_list::iterator member functions ************* */
329
Jonathan Peyton072772b2016-04-05 18:48:48 +0000330kmp_stats_list::iterator::iterator() : ptr(NULL) {}
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000331kmp_stats_list::iterator::~iterator() {}
332kmp_stats_list::iterator kmp_stats_list::iterator::operator++() {
333 this->ptr = this->ptr->next;
334 return *this;
335}
336kmp_stats_list::iterator kmp_stats_list::iterator::operator++(int dummy) {
337 this->ptr = this->ptr->next;
338 return *this;
339}
340kmp_stats_list::iterator kmp_stats_list::iterator::operator--() {
341 this->ptr = this->ptr->prev;
342 return *this;
343}
344kmp_stats_list::iterator kmp_stats_list::iterator::operator--(int dummy) {
345 this->ptr = this->ptr->prev;
346 return *this;
347}
348bool kmp_stats_list::iterator::operator!=(const kmp_stats_list::iterator & rhs) {
Jonathan Peyton072772b2016-04-05 18:48:48 +0000349 return this->ptr!=rhs.ptr;
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000350}
351bool kmp_stats_list::iterator::operator==(const kmp_stats_list::iterator & rhs) {
Jonathan Peyton072772b2016-04-05 18:48:48 +0000352 return this->ptr==rhs.ptr;
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000353}
354kmp_stats_list* kmp_stats_list::iterator::operator*() const {
355 return this->ptr;
356}
357
358/* *************************************************************** */
359/* ************* kmp_stats_output_module functions ************** */
360
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000361const char* kmp_stats_output_module::eventsFileName = NULL;
362const char* kmp_stats_output_module::plotFileName = NULL;
363int kmp_stats_output_module::printPerThreadFlag = 0;
364int kmp_stats_output_module::printPerThreadEventsFlag = 0;
365
366// init() is called very near the beginning of execution time in the constructor of __kmp_stats_global_output
Jonathan Peyton072772b2016-04-05 18:48:48 +0000367void kmp_stats_output_module::init()
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000368{
369 char * statsFileName = getenv("KMP_STATS_FILE");
370 eventsFileName = getenv("KMP_STATS_EVENTS_FILE");
371 plotFileName = getenv("KMP_STATS_PLOT_FILE");
372 char * threadStats = getenv("KMP_STATS_THREADS");
373 char * threadEvents = getenv("KMP_STATS_EVENTS");
374
375 // set the stats output filenames based on environment variables and defaults
Jonathan Peyton98b76f62016-06-21 15:20:33 +0000376 if(statsFileName) {
377 // append the process id to the output filename
378 // events.csv --> events-pid.csv
379 size_t index;
380 std::string baseFileName, pid, suffix;
381 std::stringstream ss;
382 outputFileName = std::string(statsFileName);
383 index = outputFileName.find_last_of('.');
384 if(index == std::string::npos) {
385 baseFileName = outputFileName;
386 } else {
387 baseFileName = outputFileName.substr(0, index);
388 suffix = outputFileName.substr(index);
389 }
390 ss << getpid();
391 pid = ss.str();
392 outputFileName = baseFileName + "-" + pid + suffix;
393 }
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000394 eventsFileName = eventsFileName ? eventsFileName : "events.dat";
395 plotFileName = plotFileName ? plotFileName : "events.plt";
396
397 // set the flags based on environment variables matching: true, on, 1, .true. , .t. , yes
398 printPerThreadFlag = __kmp_str_match_true(threadStats);
399 printPerThreadEventsFlag = __kmp_str_match_true(threadEvents);
400
401 if(printPerThreadEventsFlag) {
402 // assigns a color to each timer for printing
403 setupEventColors();
404 } else {
405 // will clear flag so that no event will be logged
406 timeStat::clearEventFlags();
407 }
408
409 return;
410}
411
412void kmp_stats_output_module::setupEventColors() {
413 int i;
414 int globalColorIndex = 0;
415 int numGlobalColors = sizeof(globalColorArray) / sizeof(rgb_color);
416 for(i=0;i<TIMER_LAST;i++) {
417 if(timeStat::logEvent((timer_e)i)) {
418 timerColorInfo[i] = globalColorArray[globalColorIndex];
419 globalColorIndex = (globalColorIndex+1)%numGlobalColors;
420 }
421 }
422 return;
423}
424
Jonathan Peytone2554af2016-03-11 20:20:49 +0000425void kmp_stats_output_module::printTimerStats(FILE *statsOut, statistic const * theStats, statistic const * totalStats)
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000426{
Jonathan Peytone2554af2016-03-11 20:20:49 +0000427 fprintf (statsOut, "Timer, SampleCount, Min, Mean, Max, Total, SD\n");
Jonathan Peyton6e98d7982016-03-15 20:28:47 +0000428 for (timer_e s = timer_e(0); s<TIMER_LAST; s = timer_e(s+1)) {
Jonathan Peytone2554af2016-03-11 20:20:49 +0000429 statistic const * stat = &theStats[s];
Jonathan Peyton6e98d7982016-03-15 20:28:47 +0000430 char tag = timeStat::noUnits(s) ? ' ' : 'T';
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000431
Jonathan Peyton6e98d7982016-03-15 20:28:47 +0000432 fprintf (statsOut, "%-28s, %s\n", timeStat::name(s), stat->format(tag, true).c_str());
Jonathan Peyton53eca522016-04-18 17:24:20 +0000433 }
434 // Also print the Total_ versions of times.
435 for (timer_e s = timer_e(0); s<TIMER_LAST; s = timer_e(s+1)) {
436 char tag = timeStat::noUnits(s) ? ' ' : 'T';
Jonathan Peyton6e98d7982016-03-15 20:28:47 +0000437 if (totalStats && !timeStat::noTotal(s))
438 fprintf(statsOut, "Total_%-22s, %s\n", timeStat::name(s), totalStats[s].format(tag, true).c_str());
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000439 }
Jonathan Peytone2554af2016-03-11 20:20:49 +0000440}
441
442void kmp_stats_output_module::printCounterStats(FILE *statsOut, statistic const * theStats)
443{
444 fprintf (statsOut, "Counter, ThreadCount, Min, Mean, Max, Total, SD\n");
445 for (int s = 0; s<COUNTER_LAST; s++) {
446 statistic const * stat = &theStats[s];
447 fprintf (statsOut, "%-25s, %s\n", counter::name(counter_e(s)), stat->format(' ', true).c_str());
448 }
449}
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000450
451void kmp_stats_output_module::printCounters(FILE * statsOut, counter const * theCounters)
452{
453 // We print all the counters even if they are zero.
454 // That makes it easier to slice them into a spreadsheet if you need to.
455 fprintf (statsOut, "\nCounter, Count\n");
456 for (int c = 0; c<COUNTER_LAST; c++) {
457 counter const * stat = &theCounters[c];
458 fprintf (statsOut, "%-25s, %s\n", counter::name(counter_e(c)), formatSI(stat->getValue(), 9, ' ').c_str());
459 }
460}
461
462void kmp_stats_output_module::printEvents(FILE* eventsOut, kmp_stats_event_vector* theEvents, int gtid) {
463 // sort by start time before printing
464 theEvents->sort();
465 for (int i = 0; i < theEvents->size(); i++) {
466 kmp_stats_event ev = theEvents->at(i);
467 rgb_color color = getEventColor(ev.getTimerName());
Jonathan Peyton072772b2016-04-05 18:48:48 +0000468 fprintf(eventsOut, "%d %lu %lu %1.1f rgb(%1.1f,%1.1f,%1.1f) %s\n",
469 gtid,
470 ev.getStart(),
471 ev.getStop(),
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000472 1.2 - (ev.getNestLevel() * 0.2),
473 color.r, color.g, color.b,
474 timeStat::name(ev.getTimerName())
475 );
476 }
477 return;
478}
479
480void kmp_stats_output_module::windupExplicitTimers()
481{
Jonathan Peyton072772b2016-04-05 18:48:48 +0000482 // Wind up any explicit timers. We assume that it's fair at this point to just walk all the explcit timers in all threads
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000483 // and say "it's over".
484 // If the timer wasn't running, this won't record anything anyway.
485 kmp_stats_list::iterator it;
Jonathan Peyton5375fe82016-11-14 21:13:44 +0000486 for(it = __kmp_stats_list->begin(); it != __kmp_stats_list->end(); it++) {
Jonathan Peyton11dc82f2016-05-05 16:15:57 +0000487 kmp_stats_list* ptr = *it;
488 ptr->getPartitionedTimers()->windup();
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000489 for (int timer=0; timer<EXPLICIT_TIMER_LAST; timer++) {
Jonathan Peyton5375fe82016-11-14 21:13:44 +0000490 ptr->getExplicitTimer(explicit_timer_e(timer))->stop((timer_e)timer, ptr);
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000491 }
492 }
493}
494
495void kmp_stats_output_module::printPloticusFile() {
496 int i;
Jonathan Peyton5375fe82016-11-14 21:13:44 +0000497 int size = __kmp_stats_list->size();
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000498 FILE* plotOut = fopen(plotFileName, "w+");
499
500 fprintf(plotOut, "#proc page\n"
501 " pagesize: 15 10\n"
502 " scale: 1.0\n\n");
503
504 fprintf(plotOut, "#proc getdata\n"
Jonathan Peyton072772b2016-04-05 18:48:48 +0000505 " file: %s\n\n",
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000506 eventsFileName);
507
508 fprintf(plotOut, "#proc areadef\n"
509 " title: OpenMP Sampling Timeline\n"
510 " titledetails: align=center size=16\n"
511 " rectangle: 1 1 13 9\n"
512 " xautorange: datafield=2,3\n"
Jonathan Peyton072772b2016-04-05 18:48:48 +0000513 " yautorange: -1 %d\n\n",
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000514 size);
515
516 fprintf(plotOut, "#proc xaxis\n"
517 " stubs: inc\n"
518 " stubdetails: size=12\n"
519 " label: Time (ticks)\n"
520 " labeldetails: size=14\n\n");
521
522 fprintf(plotOut, "#proc yaxis\n"
523 " stubs: inc 1\n"
524 " stubrange: 0 %d\n"
525 " stubdetails: size=12\n"
526 " label: Thread #\n"
Jonathan Peyton072772b2016-04-05 18:48:48 +0000527 " labeldetails: size=14\n\n",
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000528 size-1);
529
530 fprintf(plotOut, "#proc bars\n"
531 " exactcolorfield: 5\n"
532 " axis: x\n"
533 " locfield: 1\n"
534 " segmentfields: 2 3\n"
535 " barwidthfield: 4\n\n");
536
537 // create legend entries corresponding to the timer color
538 for(i=0;i<TIMER_LAST;i++) {
539 if(timeStat::logEvent((timer_e)i)) {
540 rgb_color c = getEventColor((timer_e)i);
541 fprintf(plotOut, "#proc legendentry\n"
542 " sampletype: color\n"
543 " label: %s\n"
544 " details: rgb(%1.1f,%1.1f,%1.1f)\n\n",
545 timeStat::name((timer_e)i),
546 c.r, c.g, c.b);
547
548 }
549 }
550
551 fprintf(plotOut, "#proc legend\n"
552 " format: down\n"
553 " location: max max\n\n");
554 fclose(plotOut);
555 return;
556}
557
Jonathan Peyton6e98d7982016-03-15 20:28:47 +0000558/*
559 * Print some useful information about
560 * * the date and time this experiment ran.
561 * * the machine on which it ran.
562 * We output all of this as stylised comments, though we may decide to parse some of it.
563 */
564void kmp_stats_output_module::printHeaderInfo(FILE * statsOut)
565{
566 std::time_t now = std::time(0);
567 char buffer[40];
568 char hostName[80];
569
570 std::strftime(&buffer[0], sizeof(buffer), "%c", std::localtime(&now));
571 fprintf (statsOut, "# Time of run: %s\n", &buffer[0]);
572 if (gethostname(&hostName[0], sizeof(hostName)) == 0)
573 fprintf (statsOut,"# Hostname: %s\n", &hostName[0]);
574#if KMP_ARCH_X86 || KMP_ARCH_X86_64
575 fprintf (statsOut, "# CPU: %s\n", &__kmp_cpuinfo.name[0]);
576 fprintf (statsOut, "# Family: %d, Model: %d, Stepping: %d\n", __kmp_cpuinfo.family, __kmp_cpuinfo.model, __kmp_cpuinfo.stepping);
Jonathan Peyton20c1e4e2016-03-15 20:55:32 +0000577 if (__kmp_cpuinfo.frequency == 0)
578 fprintf (statsOut, "# Nominal frequency: Unknown\n");
579 else
580 fprintf (statsOut, "# Nominal frequency: %sz\n", formatSI(double(__kmp_cpuinfo.frequency),9,'H').c_str());
Jonathan Peyton6e98d7982016-03-15 20:28:47 +0000581#endif
582}
583
Jonathan Peyton072772b2016-04-05 18:48:48 +0000584void kmp_stats_output_module::outputStats(const char* heading)
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000585{
Jonathan Peyton6e98d7982016-03-15 20:28:47 +0000586 // Stop all the explicit timers in all threads
587 // Do this before declaring the local statistics because thay have constructors so will take time to create.
588 windupExplicitTimers();
589
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000590 statistic allStats[TIMER_LAST];
Jonathan Peytone2554af2016-03-11 20:20:49 +0000591 statistic totalStats[TIMER_LAST]; /* Synthesized, cross threads versions of normal timer stats */
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000592 statistic allCounters[COUNTER_LAST];
593
Jonathan Peyton98b76f62016-06-21 15:20:33 +0000594 FILE * statsOut = !outputFileName.empty() ? fopen (outputFileName.c_str(), "a+") : stderr;
Jonathan Peyton6e98d7982016-03-15 20:28:47 +0000595 if (!statsOut)
596 statsOut = stderr;
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000597
598 FILE * eventsOut;
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000599 if (eventPrintingEnabled()) {
600 eventsOut = fopen(eventsFileName, "w+");
601 }
602
Jonathan Peyton6e98d7982016-03-15 20:28:47 +0000603 printHeaderInfo (statsOut);
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000604 fprintf(statsOut, "%s\n",heading);
605 // Accumulate across threads.
606 kmp_stats_list::iterator it;
Jonathan Peyton5375fe82016-11-14 21:13:44 +0000607 for (it = __kmp_stats_list->begin(); it != __kmp_stats_list->end(); it++) {
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000608 int t = (*it)->getGtid();
609 // Output per thread stats if requested.
Jonathan Peyton6e98d7982016-03-15 20:28:47 +0000610 if (printPerThreadFlag) {
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000611 fprintf (statsOut, "Thread %d\n", t);
Jonathan Peyton6e98d7982016-03-15 20:28:47 +0000612 printTimerStats (statsOut, (*it)->getTimers(), 0);
613 printCounters (statsOut, (*it)->getCounters());
614 fprintf (statsOut,"\n");
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000615 }
616 // Output per thread events if requested.
617 if (eventPrintingEnabled()) {
618 kmp_stats_event_vector events = (*it)->getEventVector();
619 printEvents(eventsOut, &events, t);
620 }
621
Jonathan Peytone2554af2016-03-11 20:20:49 +0000622 // Accumulate timers.
Jonathan Peyton6e98d7982016-03-15 20:28:47 +0000623 for (timer_e s = timer_e(0); s<TIMER_LAST; s = timer_e(s+1)) {
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000624 // See if we should ignore this timer when aggregating
Jonathan Peyton6e98d7982016-03-15 20:28:47 +0000625 if ((timeStat::masterOnly(s) && (t != 0)) || // Timer is only valid on the master and this thread is a worker
626 (timeStat::workerOnly(s) && (t == 0)) // Timer is only valid on a worker and this thread is the master
Jonathan Peyton072772b2016-04-05 18:48:48 +0000627 )
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000628 {
629 continue;
630 }
631
Jonathan Peyton6e98d7982016-03-15 20:28:47 +0000632 statistic * threadStat = (*it)->getTimer(s);
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000633 allStats[s] += *threadStat;
Jonathan Peytone2554af2016-03-11 20:20:49 +0000634
Jonathan Peyton6e98d7982016-03-15 20:28:47 +0000635 // Add Total stats for timers that are valid in more than one thread
636 if (!timeStat::noTotal(s))
Jonathan Peytone2554af2016-03-11 20:20:49 +0000637 totalStats[s].addSample(threadStat->getTotal());
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000638 }
639
Jonathan Peytone2554af2016-03-11 20:20:49 +0000640 // Accumulate counters.
Jonathan Peyton6e98d7982016-03-15 20:28:47 +0000641 for (counter_e c = counter_e(0); c<COUNTER_LAST; c = counter_e(c+1)) {
642 if (counter::masterOnly(c) && t != 0)
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000643 continue;
Jonathan Peyton6e98d7982016-03-15 20:28:47 +0000644 allCounters[c].addSample ((*it)->getCounter(c)->getValue());
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000645 }
646 }
647
648 if (eventPrintingEnabled()) {
649 printPloticusFile();
650 fclose(eventsOut);
651 }
652
653 fprintf (statsOut, "Aggregate for all threads\n");
Jonathan Peytone2554af2016-03-11 20:20:49 +0000654 printTimerStats (statsOut, &allStats[0], &totalStats[0]);
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000655 fprintf (statsOut, "\n");
Jonathan Peytone2554af2016-03-11 20:20:49 +0000656 printCounterStats (statsOut, &allCounters[0]);
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000657
658 if (statsOut != stderr)
659 fclose(statsOut);
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000660}
661
662/* ************************************************** */
663/* ************* exported C functions ************** */
664
665// no name mangling for these functions, we want the c files to be able to get at these functions
666extern "C" {
667
668void __kmp_reset_stats()
669{
670 kmp_stats_list::iterator it;
Jonathan Peyton5375fe82016-11-14 21:13:44 +0000671 for(it = __kmp_stats_list->begin(); it != __kmp_stats_list->end(); it++) {
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000672 timeStat * timers = (*it)->getTimers();
673 counter * counters = (*it)->getCounters();
674 explicitTimer * eTimers = (*it)->getExplicitTimers();
675
676 for (int t = 0; t<TIMER_LAST; t++)
677 timers[t].reset();
678
679 for (int c = 0; c<COUNTER_LAST; c++)
680 counters[c].reset();
681
682 for (int t=0; t<EXPLICIT_TIMER_LAST; t++)
683 eTimers[t].reset();
684
685 // reset the event vector so all previous events are "erased"
686 (*it)->resetEventVector();
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000687 }
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000688}
689
690// This function will reset all stats and stop all threads' explicit timers if they haven't been stopped already.
691void __kmp_output_stats(const char * heading)
692{
Jonathan Peyton5375fe82016-11-14 21:13:44 +0000693 __kmp_stats_global_output->outputStats(heading);
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000694 __kmp_reset_stats();
695}
696
697void __kmp_accumulate_stats_at_exit(void)
698{
699 // Only do this once.
700 if (KMP_XCHG_FIXED32(&statsPrinted, 1) != 0)
701 return;
702
703 __kmp_output_stats("Statistics on exit");
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000704}
705
Jonathan Peyton072772b2016-04-05 18:48:48 +0000706void __kmp_stats_init(void)
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000707{
Jonathan Peyton5375fe82016-11-14 21:13:44 +0000708 __kmp_init_tas_lock( & __kmp_stats_lock );
709 __kmp_stats_start_time = tsc_tick_count::now();
710 __kmp_stats_global_output = new kmp_stats_output_module();
711 __kmp_stats_list = new kmp_stats_list();
712}
713
714void __kmp_stats_fini(void)
715{
716 __kmp_accumulate_stats_at_exit();
717 __kmp_stats_list->deallocate();
718 delete __kmp_stats_global_output;
719 delete __kmp_stats_list;
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000720}
721
Jonathan Peyton072772b2016-04-05 18:48:48 +0000722} // extern "C"
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000723