blob: aeea4de1fc21bfc932e2934b035111a024cffa85 [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
Jonathan Peyton30419822017-05-12 18:01:32 +000015
Jim Cownie4cc4bb42014-10-07 16:25:50 +000016#include "kmp.h"
Jim Cownie4cc4bb42014-10-07 16:25:50 +000017#include "kmp_lock.h"
18#include "kmp_stats.h"
Jonathan Peyton30419822017-05-12 18:01:32 +000019#include "kmp_str.h"
Jim Cownie4cc4bb42014-10-07 16:25:50 +000020
21#include <algorithm>
Jonathan Peyton6e98d7982016-03-15 20:28:47 +000022#include <ctime>
Jonathan Peyton30419822017-05-12 18:01:32 +000023#include <iomanip>
24#include <sstream>
25#include <stdlib.h> // for atexit
Jim Cownie4cc4bb42014-10-07 16:25:50 +000026
27#define STRINGIZE2(x) #x
28#define STRINGIZE(x) STRINGIZE2(x)
29
Jonathan Peyton30419822017-05-12 18:01:32 +000030#define expandName(name, flags, ignore) {STRINGIZE(name), flags},
Jim Cownie4cc4bb42014-10-07 16:25:50 +000031statInfo timeStat::timerInfo[] = {
Jonathan Peyton30419822017-05-12 18:01:32 +000032 KMP_FOREACH_TIMER(expandName, 0){"TIMER_LAST", 0}};
Jim Cownie4cc4bb42014-10-07 16:25:50 +000033const statInfo counter::counterInfo[] = {
Jonathan Peyton30419822017-05-12 18:01:32 +000034 KMP_FOREACH_COUNTER(expandName, 0){"COUNTER_LAST", 0}};
Jim Cownie4cc4bb42014-10-07 16:25:50 +000035#undef expandName
36
Jonathan Peyton30419822017-05-12 18:01:32 +000037#define expandName(ignore1, ignore2, ignore3) {0.0, 0.0, 0.0},
Jim Cownie4cc4bb42014-10-07 16:25:50 +000038kmp_stats_output_module::rgb_color kmp_stats_output_module::timerColorInfo[] = {
Jonathan Peyton30419822017-05-12 18:01:32 +000039 KMP_FOREACH_TIMER(expandName, 0){0.0, 0.0, 0.0}};
Jim Cownie4cc4bb42014-10-07 16:25:50 +000040#undef expandName
41
Jonathan Peyton30419822017-05-12 18:01:32 +000042const kmp_stats_output_module::rgb_color
43 kmp_stats_output_module::globalColorArray[] = {
44 {1.0, 0.0, 0.0}, // red
45 {1.0, 0.6, 0.0}, // orange
46 {1.0, 1.0, 0.0}, // yellow
47 {0.0, 1.0, 0.0}, // green
48 {0.0, 0.0, 1.0}, // blue
49 {0.6, 0.2, 0.8}, // purple
50 {1.0, 0.0, 1.0}, // magenta
51 {0.0, 0.4, 0.2}, // dark green
52 {1.0, 1.0, 0.6}, // light yellow
53 {0.6, 0.4, 0.6}, // dirty purple
54 {0.0, 1.0, 1.0}, // cyan
55 {1.0, 0.4, 0.8}, // pink
56 {0.5, 0.5, 0.5}, // grey
57 {0.8, 0.7, 0.5}, // brown
58 {0.6, 0.6, 1.0}, // light blue
59 {1.0, 0.7, 0.5}, // peach
60 {0.8, 0.5, 1.0}, // lavender
61 {0.6, 0.0, 0.0}, // dark red
62 {0.7, 0.6, 0.0}, // gold
63 {0.0, 0.0, 0.0} // black
Jim Cownie4cc4bb42014-10-07 16:25:50 +000064};
65
66// Ensure that the atexit handler only runs once.
67static uint32_t statsPrinted = 0;
68
69// output interface
Jonathan Peyton30419822017-05-12 18:01:32 +000070static kmp_stats_output_module *__kmp_stats_global_output = NULL;
Jim Cownie4cc4bb42014-10-07 16:25:50 +000071
Jim Cownie4cc4bb42014-10-07 16:25:50 +000072/* ************* statistic member functions ************* */
73
Jonathan Peyton30419822017-05-12 18:01:32 +000074void statistic::addSample(double sample) {
75 double delta = sample - meanVal;
Jim Cownie4cc4bb42014-10-07 16:25:50 +000076
Jonathan Peyton30419822017-05-12 18:01:32 +000077 sampleCount = sampleCount + 1;
78 meanVal = meanVal + delta / sampleCount;
79 m2 = m2 + delta * (sample - meanVal);
Jim Cownie4cc4bb42014-10-07 16:25:50 +000080
Jonathan Peyton30419822017-05-12 18:01:32 +000081 minVal = std::min(minVal, sample);
82 maxVal = std::max(maxVal, sample);
Jim Cownie4cc4bb42014-10-07 16:25:50 +000083}
84
Jonathan Peyton30419822017-05-12 18:01:32 +000085statistic &statistic::operator+=(const statistic &other) {
86 if (sampleCount == 0) {
87 *this = other;
Jim Cownie4cc4bb42014-10-07 16:25:50 +000088 return *this;
Jonathan Peyton30419822017-05-12 18:01:32 +000089 }
90
91 uint64_t newSampleCount = sampleCount + other.sampleCount;
92 double dnsc = double(newSampleCount);
93 double dsc = double(sampleCount);
94 double dscBydnsc = dsc / dnsc;
95 double dosc = double(other.sampleCount);
96 double delta = other.meanVal - meanVal;
97
98 // Try to order these calculations to avoid overflows. If this were Fortran,
99 // then the compiler would not be able to re-order over brackets. In C++ it
100 // may be legal to do that (we certainly hope it doesn't, and CC+ Programming
101 // Language 2nd edition suggests it shouldn't, since it says that exploitation
102 // of associativity can only be made if the operation really is associative
103 // (which floating addition isn't...)).
104 meanVal = meanVal * dscBydnsc + other.meanVal * (1 - dscBydnsc);
105 m2 = m2 + other.m2 + dscBydnsc * dosc * delta * delta;
106 minVal = std::min(minVal, other.minVal);
107 maxVal = std::max(maxVal, other.maxVal);
108 sampleCount = newSampleCount;
109
110 return *this;
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000111}
112
Jonathan Peyton30419822017-05-12 18:01:32 +0000113void statistic::scale(double factor) {
114 minVal = minVal * factor;
115 maxVal = maxVal * factor;
116 meanVal = meanVal * factor;
117 m2 = m2 * factor * factor;
118 return;
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000119}
120
Jonathan Peyton30419822017-05-12 18:01:32 +0000121std::string statistic::format(char unit, bool total) const {
122 std::string result = formatSI(sampleCount, 9, ' ');
Jonathan Peyton072772b2016-04-05 18:48:48 +0000123
Jonathan Peyton30419822017-05-12 18:01:32 +0000124 if (sampleCount == 0) {
125 result = result + std::string(", ") + formatSI(0.0, 9, unit);
126 result = result + std::string(", ") + formatSI(0.0, 9, unit);
127 result = result + std::string(", ") + formatSI(0.0, 9, unit);
128 if (total)
129 result = result + std::string(", ") + formatSI(0.0, 9, unit);
130 result = result + std::string(", ") + formatSI(0.0, 9, unit);
131 } else {
132 result = result + std::string(", ") + formatSI(minVal, 9, unit);
133 result = result + std::string(", ") + formatSI(meanVal, 9, unit);
134 result = result + std::string(", ") + formatSI(maxVal, 9, unit);
135 if (total)
136 result =
137 result + std::string(", ") + formatSI(meanVal * sampleCount, 9, unit);
138 result = result + std::string(", ") + formatSI(getSD(), 9, unit);
139 }
140 return result;
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000141}
142
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000143/* ************* explicitTimer member functions ************* */
144
Jonathan Peyton072772b2016-04-05 18:48:48 +0000145void explicitTimer::start(timer_e timerEnumValue) {
Jonathan Peyton30419822017-05-12 18:01:32 +0000146 startTime = tsc_tick_count::now();
147 totalPauseTime = 0;
148 if (timeStat::logEvent(timerEnumValue)) {
149 __kmp_stats_thread_ptr->incrementNestValue();
150 }
151 return;
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000152}
153
Jonathan Peyton30419822017-05-12 18:01:32 +0000154void explicitTimer::stop(timer_e timerEnumValue,
155 kmp_stats_list *stats_ptr /* = nullptr */) {
156 if (startTime.getValue() == 0)
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000157 return;
Jonathan Peyton30419822017-05-12 18:01:32 +0000158
159 tsc_tick_count finishTime = tsc_tick_count::now();
160
161 // stat->addSample ((tsc_tick_count::now() - startTime).ticks());
162 stat->addSample(((finishTime - startTime) - totalPauseTime).ticks());
163
164 if (timeStat::logEvent(timerEnumValue)) {
165 if (!stats_ptr)
166 stats_ptr = __kmp_stats_thread_ptr;
167 stats_ptr->push_event(
168 startTime.getValue() - __kmp_stats_start_time.getValue(),
169 finishTime.getValue() - __kmp_stats_start_time.getValue(),
170 __kmp_stats_thread_ptr->getNestValue(), timerEnumValue);
171 stats_ptr->decrementNestValue();
172 }
173
174 /* We accept the risk that we drop a sample because it really did start at
175 t==0. */
176 startTime = 0;
177 return;
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000178}
179
Jonathan Peyton11dc82f2016-05-05 16:15:57 +0000180/* ************* partitionedTimers member functions ************* */
Jonathan Peyton30419822017-05-12 18:01:32 +0000181partitionedTimers::partitionedTimers() { timer_stack.reserve(8); }
Jonathan Peyton11dc82f2016-05-05 16:15:57 +0000182
183// add a timer to this collection of partitioned timers.
Jonathan Peyton30419822017-05-12 18:01:32 +0000184void partitionedTimers::add_timer(explicit_timer_e timer_index,
185 explicitTimer *timer_pointer) {
186 KMP_DEBUG_ASSERT((int)timer_index < (int)EXPLICIT_TIMER_LAST + 1);
187 timers[timer_index] = timer_pointer;
Jonathan Peyton11dc82f2016-05-05 16:15:57 +0000188}
189
190// initialize the paritioned timers to an initial timer
191void partitionedTimers::init(timerPair init_timer_pair) {
Jonathan Peyton30419822017-05-12 18:01:32 +0000192 KMP_DEBUG_ASSERT(this->timer_stack.size() == 0);
193 timer_stack.push_back(init_timer_pair);
194 timers[init_timer_pair.get_index()]->start(init_timer_pair.get_timer());
Jonathan Peyton11dc82f2016-05-05 16:15:57 +0000195}
196
197// stop/save the current timer, and start the new timer (timer_pair)
198// There is a special condition where if the current timer is equal to
199// the one you are trying to push, then it only manipulates the stack,
200// and it won't stop/start the currently running timer.
201void partitionedTimers::push(timerPair timer_pair) {
Jonathan Peyton30419822017-05-12 18:01:32 +0000202 // get the current timer
203 // stop current timer
204 // push new timer
205 // start the new timer
206 KMP_DEBUG_ASSERT(this->timer_stack.size() > 0);
207 timerPair current_timer = timer_stack.back();
208 timer_stack.push_back(timer_pair);
209 if (current_timer != timer_pair) {
210 timers[current_timer.get_index()]->pause();
211 timers[timer_pair.get_index()]->start(timer_pair.get_timer());
212 }
Jonathan Peyton11dc82f2016-05-05 16:15:57 +0000213}
214
215// stop/discard the current timer, and start the previously saved timer
216void partitionedTimers::pop() {
Jonathan Peyton30419822017-05-12 18:01:32 +0000217 // get the current timer
218 // stop current timer
219 // pop current timer
220 // get the new current timer and start it back up
221 KMP_DEBUG_ASSERT(this->timer_stack.size() > 1);
222 timerPair current_timer = timer_stack.back();
223 timer_stack.pop_back();
224 timerPair new_timer = timer_stack.back();
225 if (current_timer != new_timer) {
226 timers[current_timer.get_index()]->stop(current_timer.get_timer());
227 timers[new_timer.get_index()]->resume();
228 }
Jonathan Peyton11dc82f2016-05-05 16:15:57 +0000229}
230
231// Wind up all the currently running timers.
232// This pops off all the timers from the stack and clears the stack
233// After this is called, init() must be run again to initialize the
234// stack of timers
235void partitionedTimers::windup() {
Jonathan Peyton30419822017-05-12 18:01:32 +0000236 while (timer_stack.size() > 1) {
237 this->pop();
238 }
239 if (timer_stack.size() > 0) {
240 timerPair last_timer = timer_stack.back();
241 timer_stack.pop_back();
242 timers[last_timer.get_index()]->stop(last_timer.get_timer());
243 }
Jonathan Peyton11dc82f2016-05-05 16:15:57 +0000244}
245
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000246/* ************* kmp_stats_event_vector member functions ************* */
247
248void kmp_stats_event_vector::deallocate() {
Jonathan Peyton30419822017-05-12 18:01:32 +0000249 __kmp_free(events);
250 internal_size = 0;
251 allocated_size = 0;
252 events = NULL;
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000253}
254
255// This function is for qsort() which requires the compare function to return
Jonathan Peyton30419822017-05-12 18:01:32 +0000256// either a negative number if event1 < event2, a positive number if event1 >
257// event2 or zero if event1 == event2. This sorts by start time (lowest to
258// highest).
259int compare_two_events(const void *event1, const void *event2) {
260 kmp_stats_event *ev1 = (kmp_stats_event *)event1;
261 kmp_stats_event *ev2 = (kmp_stats_event *)event2;
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000262
Jonathan Peyton30419822017-05-12 18:01:32 +0000263 if (ev1->getStart() < ev2->getStart())
264 return -1;
265 else if (ev1->getStart() > ev2->getStart())
266 return 1;
267 else
268 return 0;
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000269}
270
271void kmp_stats_event_vector::sort() {
Jonathan Peyton30419822017-05-12 18:01:32 +0000272 qsort(events, internal_size, sizeof(kmp_stats_event), compare_two_events);
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000273}
274
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000275/* ************* kmp_stats_list member functions ************* */
276
277// returns a pointer to newly created stats node
Jonathan Peyton30419822017-05-12 18:01:32 +0000278kmp_stats_list *kmp_stats_list::push_back(int gtid) {
279 kmp_stats_list *newnode =
280 (kmp_stats_list *)__kmp_allocate(sizeof(kmp_stats_list));
281 // placement new, only requires space and pointer and initializes (so
282 // __kmp_allocate instead of C++ new[] is used)
283 new (newnode) kmp_stats_list();
284 newnode->setGtid(gtid);
285 newnode->prev = this->prev;
286 newnode->next = this;
287 newnode->prev->next = newnode;
288 newnode->next->prev = newnode;
289 return newnode;
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000290}
291void kmp_stats_list::deallocate() {
Jonathan Peyton30419822017-05-12 18:01:32 +0000292 kmp_stats_list *ptr = this->next;
293 kmp_stats_list *delptr = this->next;
294 while (ptr != this) {
295 delptr = ptr;
296 ptr = ptr->next;
297 // placement new means we have to explicitly call destructor.
298 delptr->_event_vector.deallocate();
299 delptr->~kmp_stats_list();
300 __kmp_free(delptr);
301 }
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000302}
303kmp_stats_list::iterator kmp_stats_list::begin() {
Jonathan Peyton30419822017-05-12 18:01:32 +0000304 kmp_stats_list::iterator it;
305 it.ptr = this->next;
306 return it;
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000307}
308kmp_stats_list::iterator kmp_stats_list::end() {
Jonathan Peyton30419822017-05-12 18:01:32 +0000309 kmp_stats_list::iterator it;
310 it.ptr = this;
311 return it;
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000312}
313int kmp_stats_list::size() {
Jonathan Peyton30419822017-05-12 18:01:32 +0000314 int retval;
315 kmp_stats_list::iterator it;
316 for (retval = 0, it = begin(); it != end(); it++, retval++) {
317 }
318 return retval;
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000319}
320
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000321/* ************* kmp_stats_list::iterator member functions ************* */
322
Jonathan Peyton072772b2016-04-05 18:48:48 +0000323kmp_stats_list::iterator::iterator() : ptr(NULL) {}
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000324kmp_stats_list::iterator::~iterator() {}
325kmp_stats_list::iterator kmp_stats_list::iterator::operator++() {
Jonathan Peyton30419822017-05-12 18:01:32 +0000326 this->ptr = this->ptr->next;
327 return *this;
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000328}
329kmp_stats_list::iterator kmp_stats_list::iterator::operator++(int dummy) {
Jonathan Peyton30419822017-05-12 18:01:32 +0000330 this->ptr = this->ptr->next;
331 return *this;
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000332}
333kmp_stats_list::iterator kmp_stats_list::iterator::operator--() {
Jonathan Peyton30419822017-05-12 18:01:32 +0000334 this->ptr = this->ptr->prev;
335 return *this;
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000336}
337kmp_stats_list::iterator kmp_stats_list::iterator::operator--(int dummy) {
Jonathan Peyton30419822017-05-12 18:01:32 +0000338 this->ptr = this->ptr->prev;
339 return *this;
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000340}
Jonathan Peyton30419822017-05-12 18:01:32 +0000341bool kmp_stats_list::iterator::operator!=(const kmp_stats_list::iterator &rhs) {
342 return this->ptr != rhs.ptr;
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000343}
Jonathan Peyton30419822017-05-12 18:01:32 +0000344bool kmp_stats_list::iterator::operator==(const kmp_stats_list::iterator &rhs) {
345 return this->ptr == rhs.ptr;
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000346}
Jonathan Peyton30419822017-05-12 18:01:32 +0000347kmp_stats_list *kmp_stats_list::iterator::operator*() const {
348 return this->ptr;
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000349}
350
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000351/* ************* kmp_stats_output_module functions ************** */
352
Jonathan Peyton30419822017-05-12 18:01:32 +0000353const char *kmp_stats_output_module::eventsFileName = NULL;
354const char *kmp_stats_output_module::plotFileName = NULL;
355int kmp_stats_output_module::printPerThreadFlag = 0;
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000356int kmp_stats_output_module::printPerThreadEventsFlag = 0;
357
Jonathan Peyton30419822017-05-12 18:01:32 +0000358// init() is called very near the beginning of execution time in the constructor
359// of __kmp_stats_global_output
360void kmp_stats_output_module::init() {
361 char *statsFileName = getenv("KMP_STATS_FILE");
362 eventsFileName = getenv("KMP_STATS_EVENTS_FILE");
363 plotFileName = getenv("KMP_STATS_PLOT_FILE");
364 char *threadStats = getenv("KMP_STATS_THREADS");
365 char *threadEvents = getenv("KMP_STATS_EVENTS");
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000366
Jonathan Peyton30419822017-05-12 18:01:32 +0000367 // set the stats output filenames based on environment variables and defaults
368 if (statsFileName) {
369 // append the process id to the output filename
370 // events.csv --> events-pid.csv
371 size_t index;
372 std::string baseFileName, pid, suffix;
373 std::stringstream ss;
374 outputFileName = std::string(statsFileName);
375 index = outputFileName.find_last_of('.');
376 if (index == std::string::npos) {
377 baseFileName = outputFileName;
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000378 } else {
Jonathan Peyton30419822017-05-12 18:01:32 +0000379 baseFileName = outputFileName.substr(0, index);
380 suffix = outputFileName.substr(index);
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000381 }
Jonathan Peyton30419822017-05-12 18:01:32 +0000382 ss << getpid();
383 pid = ss.str();
384 outputFileName = baseFileName + "-" + pid + suffix;
385 }
386 eventsFileName = eventsFileName ? eventsFileName : "events.dat";
387 plotFileName = plotFileName ? plotFileName : "events.plt";
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000388
Jonathan Peyton30419822017-05-12 18:01:32 +0000389 // set the flags based on environment variables matching: true, on, 1, .true.
390 // , .t. , yes
391 printPerThreadFlag = __kmp_str_match_true(threadStats);
392 printPerThreadEventsFlag = __kmp_str_match_true(threadEvents);
393
394 if (printPerThreadEventsFlag) {
395 // assigns a color to each timer for printing
396 setupEventColors();
397 } else {
398 // will clear flag so that no event will be logged
399 timeStat::clearEventFlags();
400 }
401
402 return;
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000403}
404
405void kmp_stats_output_module::setupEventColors() {
Jonathan Peyton30419822017-05-12 18:01:32 +0000406 int i;
407 int globalColorIndex = 0;
408 int numGlobalColors = sizeof(globalColorArray) / sizeof(rgb_color);
409 for (i = 0; i < TIMER_LAST; i++) {
410 if (timeStat::logEvent((timer_e)i)) {
411 timerColorInfo[i] = globalColorArray[globalColorIndex];
412 globalColorIndex = (globalColorIndex + 1) % numGlobalColors;
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000413 }
Jonathan Peyton30419822017-05-12 18:01:32 +0000414 }
415 return;
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000416}
417
Jonathan Peyton30419822017-05-12 18:01:32 +0000418void kmp_stats_output_module::printTimerStats(FILE *statsOut,
419 statistic const *theStats,
420 statistic const *totalStats) {
421 fprintf(statsOut, "Timer, SampleCount, Min, "
422 "Mean, Max, Total, SD\n");
423 for (timer_e s = timer_e(0); s < TIMER_LAST; s = timer_e(s + 1)) {
424 statistic const *stat = &theStats[s];
425 char tag = timeStat::noUnits(s) ? ' ' : 'T';
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000426
Jonathan Peyton30419822017-05-12 18:01:32 +0000427 fprintf(statsOut, "%-28s, %s\n", timeStat::name(s),
428 stat->format(tag, true).c_str());
429 }
430 // Also print the Total_ versions of times.
431 for (timer_e s = timer_e(0); s < TIMER_LAST; s = timer_e(s + 1)) {
432 char tag = timeStat::noUnits(s) ? ' ' : 'T';
433 if (totalStats && !timeStat::noTotal(s))
434 fprintf(statsOut, "Total_%-22s, %s\n", timeStat::name(s),
435 totalStats[s].format(tag, true).c_str());
436 }
Jonathan Peytone2554af2016-03-11 20:20:49 +0000437}
438
Jonathan Peyton30419822017-05-12 18:01:32 +0000439void kmp_stats_output_module::printCounterStats(FILE *statsOut,
440 statistic const *theStats) {
441 fprintf(statsOut, "Counter, ThreadCount, Min, Mean, "
442 " Max, Total, SD\n");
443 for (int s = 0; s < COUNTER_LAST; s++) {
444 statistic const *stat = &theStats[s];
445 fprintf(statsOut, "%-25s, %s\n", counter::name(counter_e(s)),
446 stat->format(' ', true).c_str());
447 }
Jonathan Peytone2554af2016-03-11 20:20:49 +0000448}
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000449
Jonathan Peyton30419822017-05-12 18:01:32 +0000450void kmp_stats_output_module::printCounters(FILE *statsOut,
451 counter const *theCounters) {
452 // We print all the counters even if they are zero.
453 // That makes it easier to slice them into a spreadsheet if you need to.
454 fprintf(statsOut, "\nCounter, Count\n");
455 for (int c = 0; c < COUNTER_LAST; c++) {
456 counter const *stat = &theCounters[c];
457 fprintf(statsOut, "%-25s, %s\n", counter::name(counter_e(c)),
458 formatSI(stat->getValue(), 9, ' ').c_str());
459 }
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000460}
461
Jonathan Peyton30419822017-05-12 18:01:32 +0000462void kmp_stats_output_module::printEvents(FILE *eventsOut,
463 kmp_stats_event_vector *theEvents,
464 int gtid) {
465 // sort by start time before printing
466 theEvents->sort();
467 for (int i = 0; i < theEvents->size(); i++) {
468 kmp_stats_event ev = theEvents->at(i);
469 rgb_color color = getEventColor(ev.getTimerName());
470 fprintf(eventsOut, "%d %lu %lu %1.1f rgb(%1.1f,%1.1f,%1.1f) %s\n", gtid,
471 ev.getStart(), ev.getStop(), 1.2 - (ev.getNestLevel() * 0.2),
472 color.r, color.g, color.b, timeStat::name(ev.getTimerName()));
473 }
474 return;
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000475}
476
Jonathan Peyton30419822017-05-12 18:01:32 +0000477void kmp_stats_output_module::windupExplicitTimers() {
478 // Wind up any explicit timers. We assume that it's fair at this point to just
479 // walk all the explcit timers in all threads and say "it's over".
480 // If the timer wasn't running, this won't record anything anyway.
481 kmp_stats_list::iterator it;
482 for (it = __kmp_stats_list->begin(); it != __kmp_stats_list->end(); it++) {
483 kmp_stats_list *ptr = *it;
484 ptr->getPartitionedTimers()->windup();
485 for (int timer = 0; timer < EXPLICIT_TIMER_LAST; timer++) {
486 ptr->getExplicitTimer(explicit_timer_e(timer))->stop((timer_e)timer, ptr);
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000487 }
Jonathan Peyton30419822017-05-12 18:01:32 +0000488 }
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000489}
490
491void kmp_stats_output_module::printPloticusFile() {
Jonathan Peyton30419822017-05-12 18:01:32 +0000492 int i;
493 int size = __kmp_stats_list->size();
494 FILE *plotOut = fopen(plotFileName, "w+");
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000495
Jonathan Peyton30419822017-05-12 18:01:32 +0000496 fprintf(plotOut, "#proc page\n"
497 " pagesize: 15 10\n"
498 " scale: 1.0\n\n");
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000499
Jonathan Peyton30419822017-05-12 18:01:32 +0000500 fprintf(plotOut, "#proc getdata\n"
501 " file: %s\n\n",
502 eventsFileName);
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000503
Jonathan Peyton30419822017-05-12 18:01:32 +0000504 fprintf(plotOut, "#proc areadef\n"
505 " title: OpenMP Sampling Timeline\n"
506 " titledetails: align=center size=16\n"
507 " rectangle: 1 1 13 9\n"
508 " xautorange: datafield=2,3\n"
509 " yautorange: -1 %d\n\n",
510 size);
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000511
Jonathan Peyton30419822017-05-12 18:01:32 +0000512 fprintf(plotOut, "#proc xaxis\n"
513 " stubs: inc\n"
514 " stubdetails: size=12\n"
515 " label: Time (ticks)\n"
516 " labeldetails: size=14\n\n");
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000517
Jonathan Peyton30419822017-05-12 18:01:32 +0000518 fprintf(plotOut, "#proc yaxis\n"
519 " stubs: inc 1\n"
520 " stubrange: 0 %d\n"
521 " stubdetails: size=12\n"
522 " label: Thread #\n"
523 " labeldetails: size=14\n\n",
524 size - 1);
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000525
Jonathan Peyton30419822017-05-12 18:01:32 +0000526 fprintf(plotOut, "#proc bars\n"
527 " exactcolorfield: 5\n"
528 " axis: x\n"
529 " locfield: 1\n"
530 " segmentfields: 2 3\n"
531 " barwidthfield: 4\n\n");
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000532
Jonathan Peyton30419822017-05-12 18:01:32 +0000533 // create legend entries corresponding to the timer color
534 for (i = 0; i < TIMER_LAST; i++) {
535 if (timeStat::logEvent((timer_e)i)) {
536 rgb_color c = getEventColor((timer_e)i);
537 fprintf(plotOut, "#proc legendentry\n"
538 " sampletype: color\n"
539 " label: %s\n"
540 " details: rgb(%1.1f,%1.1f,%1.1f)\n\n",
541 timeStat::name((timer_e)i), c.r, c.g, c.b);
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000542 }
Jonathan Peyton30419822017-05-12 18:01:32 +0000543 }
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000544
Jonathan Peyton30419822017-05-12 18:01:32 +0000545 fprintf(plotOut, "#proc legend\n"
546 " format: down\n"
547 " location: max max\n\n");
548 fclose(plotOut);
549 return;
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000550}
551
Jonathan Peyton30419822017-05-12 18:01:32 +0000552/* Print some useful information about
553 * the date and time this experiment ran.
554 * the machine on which it ran.
555 We output all of this as stylised comments, though we may decide to parse
556 some of it. */
557void kmp_stats_output_module::printHeaderInfo(FILE *statsOut) {
558 std::time_t now = std::time(0);
559 char buffer[40];
560 char hostName[80];
Jonathan Peyton6e98d7982016-03-15 20:28:47 +0000561
Jonathan Peyton30419822017-05-12 18:01:32 +0000562 std::strftime(&buffer[0], sizeof(buffer), "%c", std::localtime(&now));
563 fprintf(statsOut, "# Time of run: %s\n", &buffer[0]);
564 if (gethostname(&hostName[0], sizeof(hostName)) == 0)
565 fprintf(statsOut, "# Hostname: %s\n", &hostName[0]);
Jonathan Peyton6e98d7982016-03-15 20:28:47 +0000566#if KMP_ARCH_X86 || KMP_ARCH_X86_64
Jonathan Peyton30419822017-05-12 18:01:32 +0000567 fprintf(statsOut, "# CPU: %s\n", &__kmp_cpuinfo.name[0]);
568 fprintf(statsOut, "# Family: %d, Model: %d, Stepping: %d\n",
569 __kmp_cpuinfo.family, __kmp_cpuinfo.model, __kmp_cpuinfo.stepping);
570 if (__kmp_cpuinfo.frequency == 0)
571 fprintf(statsOut, "# Nominal frequency: Unknown\n");
572 else
573 fprintf(statsOut, "# Nominal frequency: %sz\n",
574 formatSI(double(__kmp_cpuinfo.frequency), 9, 'H').c_str());
Jonathan Peyton6e98d7982016-03-15 20:28:47 +0000575#endif
576}
577
Jonathan Peyton30419822017-05-12 18:01:32 +0000578void kmp_stats_output_module::outputStats(const char *heading) {
579 // Stop all the explicit timers in all threads
580 // Do this before declaring the local statistics because thay have
581 // constructors so will take time to create.
582 windupExplicitTimers();
Jonathan Peyton6e98d7982016-03-15 20:28:47 +0000583
Jonathan Peyton30419822017-05-12 18:01:32 +0000584 statistic allStats[TIMER_LAST];
585 statistic totalStats[TIMER_LAST]; /* Synthesized, cross threads versions of
586 normal timer stats */
587 statistic allCounters[COUNTER_LAST];
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000588
Jonathan Peyton30419822017-05-12 18:01:32 +0000589 FILE *statsOut =
590 !outputFileName.empty() ? fopen(outputFileName.c_str(), "a+") : stderr;
591 if (!statsOut)
592 statsOut = stderr;
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000593
Jonathan Peyton30419822017-05-12 18:01:32 +0000594 FILE *eventsOut;
595 if (eventPrintingEnabled()) {
596 eventsOut = fopen(eventsFileName, "w+");
597 }
598
599 printHeaderInfo(statsOut);
600 fprintf(statsOut, "%s\n", heading);
601 // Accumulate across threads.
602 kmp_stats_list::iterator it;
603 for (it = __kmp_stats_list->begin(); it != __kmp_stats_list->end(); it++) {
604 int t = (*it)->getGtid();
605 // Output per thread stats if requested.
606 if (printPerThreadFlag) {
607 fprintf(statsOut, "Thread %d\n", t);
608 printTimerStats(statsOut, (*it)->getTimers(), 0);
609 printCounters(statsOut, (*it)->getCounters());
610 fprintf(statsOut, "\n");
611 }
612 // Output per thread events if requested.
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000613 if (eventPrintingEnabled()) {
Jonathan Peyton30419822017-05-12 18:01:32 +0000614 kmp_stats_event_vector events = (*it)->getEventVector();
615 printEvents(eventsOut, &events, t);
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000616 }
617
Jonathan Peyton30419822017-05-12 18:01:32 +0000618 // Accumulate timers.
619 for (timer_e s = timer_e(0); s < TIMER_LAST; s = timer_e(s + 1)) {
620 // See if we should ignore this timer when aggregating
621 if ((timeStat::masterOnly(s) && (t != 0)) || // Timer only valid on master
622 // and this thread is worker
623 (timeStat::workerOnly(s) && (t == 0)) // Timer only valid on worker
624 // and this thread is the master
625 ) {
626 continue;
627 }
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000628
Jonathan Peyton30419822017-05-12 18:01:32 +0000629 statistic *threadStat = (*it)->getTimer(s);
630 allStats[s] += *threadStat;
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000631
Jonathan Peyton30419822017-05-12 18:01:32 +0000632 // Add Total stats for timers that are valid in more than one thread
633 if (!timeStat::noTotal(s))
634 totalStats[s].addSample(threadStat->getTotal());
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000635 }
636
Jonathan Peyton30419822017-05-12 18:01:32 +0000637 // Accumulate counters.
638 for (counter_e c = counter_e(0); c < COUNTER_LAST; c = counter_e(c + 1)) {
639 if (counter::masterOnly(c) && t != 0)
640 continue;
641 allCounters[c].addSample((*it)->getCounter(c)->getValue());
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000642 }
Jonathan Peyton30419822017-05-12 18:01:32 +0000643 }
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000644
Jonathan Peyton30419822017-05-12 18:01:32 +0000645 if (eventPrintingEnabled()) {
646 printPloticusFile();
647 fclose(eventsOut);
648 }
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000649
Jonathan Peyton30419822017-05-12 18:01:32 +0000650 fprintf(statsOut, "Aggregate for all threads\n");
651 printTimerStats(statsOut, &allStats[0], &totalStats[0]);
652 fprintf(statsOut, "\n");
653 printCounterStats(statsOut, &allCounters[0]);
654
655 if (statsOut != stderr)
656 fclose(statsOut);
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000657}
658
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000659/* ************* exported C functions ************** */
660
Jonathan Peyton30419822017-05-12 18:01:32 +0000661// no name mangling for these functions, we want the c files to be able to get
662// at these functions
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000663extern "C" {
664
Jonathan Peyton30419822017-05-12 18:01:32 +0000665void __kmp_reset_stats() {
666 kmp_stats_list::iterator it;
667 for (it = __kmp_stats_list->begin(); it != __kmp_stats_list->end(); it++) {
668 timeStat *timers = (*it)->getTimers();
669 counter *counters = (*it)->getCounters();
670 explicitTimer *eTimers = (*it)->getExplicitTimers();
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000671
Jonathan Peyton30419822017-05-12 18:01:32 +0000672 for (int t = 0; t < TIMER_LAST; t++)
673 timers[t].reset();
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000674
Jonathan Peyton30419822017-05-12 18:01:32 +0000675 for (int c = 0; c < COUNTER_LAST; c++)
676 counters[c].reset();
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000677
Jonathan Peyton30419822017-05-12 18:01:32 +0000678 for (int t = 0; t < EXPLICIT_TIMER_LAST; t++)
679 eTimers[t].reset();
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000680
Jonathan Peyton30419822017-05-12 18:01:32 +0000681 // reset the event vector so all previous events are "erased"
682 (*it)->resetEventVector();
683 }
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000684}
685
Jonathan Peyton30419822017-05-12 18:01:32 +0000686// This function will reset all stats and stop all threads' explicit timers if
687// they haven't been stopped already.
688void __kmp_output_stats(const char *heading) {
689 __kmp_stats_global_output->outputStats(heading);
690 __kmp_reset_stats();
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000691}
692
Jonathan Peyton30419822017-05-12 18:01:32 +0000693void __kmp_accumulate_stats_at_exit(void) {
694 // Only do this once.
695 if (KMP_XCHG_FIXED32(&statsPrinted, 1) != 0)
696 return;
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000697
Jonathan Peyton30419822017-05-12 18:01:32 +0000698 __kmp_output_stats("Statistics on exit");
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000699}
700
Jonathan Peyton30419822017-05-12 18:01:32 +0000701void __kmp_stats_init(void) {
702 __kmp_init_tas_lock(&__kmp_stats_lock);
703 __kmp_stats_start_time = tsc_tick_count::now();
704 __kmp_stats_global_output = new kmp_stats_output_module();
705 __kmp_stats_list = new kmp_stats_list();
Jonathan Peyton5375fe82016-11-14 21:13:44 +0000706}
707
Jonathan Peyton30419822017-05-12 18:01:32 +0000708void __kmp_stats_fini(void) {
709 __kmp_accumulate_stats_at_exit();
710 __kmp_stats_list->deallocate();
711 delete __kmp_stats_global_output;
712 delete __kmp_stats_list;
Jim Cownie4cc4bb42014-10-07 16:25:50 +0000713}
714
Jonathan Peyton072772b2016-04-05 18:48:48 +0000715} // extern "C"