openmp/runtime/src/kmp_stats.cpp

/** @file kmp_stats.cpp
 * Statistics gathering and processing.
 */


//===----------------------------------------------------------------------===//
//
//                     The LLVM Compiler Infrastructure
//
// This file is dual licensed under the MIT and the University of Illinois Open
// Source Licenses. See LICENSE.txt for details.
//
//===----------------------------------------------------------------------===//


#if KMP_STATS_ENABLED

#include "kmp.h"
#include "kmp_str.h"
#include "kmp_lock.h"
#include "kmp_stats.h"

#include <algorithm>
#include <sstream>
#include <iomanip>
#include <stdlib.h>                             // for atexit

#define STRINGIZE2(x) #x
#define STRINGIZE(x) STRINGIZE2(x)

#define expandName(name,flags,ignore)  {STRINGIZE(name),flags},
statInfo timeStat::timerInfo[] = {
    KMP_FOREACH_TIMER(expandName,0)
    {0,0}
};
const statInfo counter::counterInfo[] = {
    KMP_FOREACH_COUNTER(expandName,0)
    {0,0}
};
#undef expandName

#define expandName(ignore1,ignore2,ignore3)  {0.0,0.0,0.0},
kmp_stats_output_module::rgb_color kmp_stats_output_module::timerColorInfo[] = {
    KMP_FOREACH_TIMER(expandName,0)
    {0.0,0.0,0.0}
};
#undef expandName

const kmp_stats_output_module::rgb_color kmp_stats_output_module::globalColorArray[] = {
    {1.0, 0.0, 0.0}, // red
    {1.0, 0.6, 0.0}, // orange
    {1.0, 1.0, 0.0}, // yellow
    {0.0, 1.0, 0.0}, // green 
    {0.0, 0.0, 1.0}, // blue
    {0.6, 0.2, 0.8}, // purple
    {1.0, 0.0, 1.0}, // magenta
    {0.0, 0.4, 0.2}, // dark green
    {1.0, 1.0, 0.6}, // light yellow
    {0.6, 0.4, 0.6}, // dirty purple
    {0.0, 1.0, 1.0}, // cyan
    {1.0, 0.4, 0.8}, // pink
    {0.5, 0.5, 0.5}, // grey
    {0.8, 0.7, 0.5}, // brown
    {0.6, 0.6, 1.0}, // light blue
    {1.0, 0.7, 0.5}, // peach
    {0.8, 0.5, 1.0}, // lavender
    {0.6, 0.0, 0.0}, // dark red
    {0.7, 0.6, 0.0}, // gold
    {0.0, 0.0, 0.0}  // black
};

// Ensure that the atexit handler only runs once.
static uint32_t statsPrinted = 0;

// output interface
static kmp_stats_output_module __kmp_stats_global_output;

/* ****************************************************** */
/* ************* statistic member functions ************* */

void statistic::addSample(double sample)
{
    double delta = sample - meanVal;

    sampleCount = sampleCount + 1;
    meanVal     = meanVal + delta/sampleCount;
    m2          = m2 + delta*(sample - meanVal);

    minVal = std::min(minVal, sample);
    maxVal = std::max(maxVal, sample);
}

statistic & statistic::operator+= (const statistic & other)
{
    if (sampleCount == 0)
    {
        *this = other;
        return *this;
    }

    uint64_t newSampleCount = sampleCount + other.sampleCount;
    double dnsc  = double(newSampleCount);
    double dsc   = double(sampleCount);
    double dscBydnsc = dsc/dnsc;
    double dosc  = double(other.sampleCount);
    double delta = other.meanVal - meanVal;

    // Try to order these calculations to avoid overflows.
    // If this were Fortran, then the compiler would not be able to re-order over brackets.
    // In C++ it may be legal to do that (we certainly hope it doesn't, and CC+ Programming Language 2nd edition
    // suggests it shouldn't, since it says that exploitation of associativity can only be made if the operation
    // really is associative (which floating addition isn't...)).
    meanVal     = meanVal*dscBydnsc + other.meanVal*(1-dscBydnsc);
    m2          = m2 + other.m2 + dscBydnsc*dosc*delta*delta;
    minVal      = std::min (minVal, other.minVal);
    maxVal      = std::max (maxVal, other.maxVal);
    sampleCount = newSampleCount;


    return *this;
}

void statistic::scale(double factor)
{
    minVal = minVal*factor;
    maxVal = maxVal*factor;
    meanVal= meanVal*factor;
    m2     = m2*factor*factor;
    return;
}

std::string statistic::format(char unit, bool total) const
{
    std::string result = formatSI(sampleCount,9,' ');

    result = result + std::string(", ") + formatSI(minVal,  9, unit);
    result = result + std::string(", ") + formatSI(meanVal, 9, unit);
    result = result + std::string(", ") + formatSI(maxVal,  9, unit);
    if (total)
        result = result + std::string(", ") + formatSI(meanVal*sampleCount, 9, unit);
    result = result + std::string(", ") + formatSI(getSD(), 9, unit);

    return result;
}

/* ********************************************************** */
/* ************* explicitTimer member functions ************* */

void explicitTimer::start(timer_e timerEnumValue) { 
    startTime = tsc_tick_count::now(); 
    if(timeStat::logEvent(timerEnumValue)) {
        __kmp_stats_thread_ptr->incrementNestValue();
    }
    return;
}

void explicitTimer::stop(timer_e timerEnumValue) {
    if (startTime.getValue() == 0)
        return;

    tsc_tick_count finishTime = tsc_tick_count::now();

    //stat->addSample ((tsc_tick_count::now() - startTime).ticks());
    stat->addSample ((finishTime - startTime).ticks());

    if(timeStat::logEvent(timerEnumValue)) {
        __kmp_stats_thread_ptr->push_event(startTime.getValue() - __kmp_stats_start_time.getValue(), finishTime.getValue() - __kmp_stats_start_time.getValue(), __kmp_stats_thread_ptr->getNestValue(), timerEnumValue); 
        __kmp_stats_thread_ptr->decrementNestValue();
    }

    /* We accept the risk that we drop a sample because it really did start at t==0. */
    startTime = 0; 
    return;
}

/* ******************************************************************* */
/* ************* kmp_stats_event_vector member functions ************* */

void kmp_stats_event_vector::deallocate() {
    __kmp_free(events);
    internal_size = 0;
    allocated_size = 0;
    events = NULL;
}

// This function is for qsort() which requires the compare function to return
// either a negative number if event1 < event2, a positive number if event1 > event2
// or zero if event1 == event2.  
// This sorts by start time (lowest to highest).
int compare_two_events(const void* event1, const void* event2) {
    kmp_stats_event* ev1 = (kmp_stats_event*)event1;
    kmp_stats_event* ev2 = (kmp_stats_event*)event2;

    if(ev1->getStart() < ev2->getStart()) return -1;
    else if(ev1->getStart() > ev2->getStart()) return 1;
    else return 0;
}

void kmp_stats_event_vector::sort() {
    qsort(events, internal_size, sizeof(kmp_stats_event), compare_two_events);
}

/* *********************************************************** */
/* ************* kmp_stats_list member functions ************* */

// returns a pointer to newly created stats node
kmp_stats_list* kmp_stats_list::push_back(int gtid) { 
    kmp_stats_list* newnode = (kmp_stats_list*)__kmp_allocate(sizeof(kmp_stats_list));
    // placement new, only requires space and pointer and initializes (so __kmp_allocate instead of C++ new[] is used)
    new (newnode) kmp_stats_list();
    newnode->setGtid(gtid);
    newnode->prev = this->prev;
    newnode->next = this;
    newnode->prev->next = newnode;
    newnode->next->prev = newnode;
    return newnode;
}
void kmp_stats_list::deallocate() {
    kmp_stats_list* ptr = this->next;
    kmp_stats_list* delptr = this->next;
    while(ptr != this) {
        delptr = ptr;
        ptr=ptr->next;
        // placement new means we have to explicitly call destructor.
        delptr->_event_vector.deallocate();
        delptr->~kmp_stats_list();
        __kmp_free(delptr);
    }
}
kmp_stats_list::iterator kmp_stats_list::begin() {
    kmp_stats_list::iterator it;
    it.ptr = this->next;
    return it;
}
kmp_stats_list::iterator kmp_stats_list::end() {
    kmp_stats_list::iterator it;
    it.ptr = this;
    return it;
}
int kmp_stats_list::size() {
    int retval;
    kmp_stats_list::iterator it;
    for(retval=0, it=begin(); it!=end(); it++, retval++) {}
    return retval;
}

/* ********************************************************************* */
/* ************* kmp_stats_list::iterator member functions ************* */

kmp_stats_list::iterator::iterator() : ptr(NULL) {} 
kmp_stats_list::iterator::~iterator() {}
kmp_stats_list::iterator kmp_stats_list::iterator::operator++() {
    this->ptr = this->ptr->next;
    return *this;
}
kmp_stats_list::iterator kmp_stats_list::iterator::operator++(int dummy) {
    this->ptr = this->ptr->next;
    return *this;
}
kmp_stats_list::iterator kmp_stats_list::iterator::operator--() {
    this->ptr = this->ptr->prev;
    return *this;
}
kmp_stats_list::iterator kmp_stats_list::iterator::operator--(int dummy) {
    this->ptr = this->ptr->prev;
    return *this;
}
bool kmp_stats_list::iterator::operator!=(const kmp_stats_list::iterator & rhs) {
   return this->ptr!=rhs.ptr; 
}
bool kmp_stats_list::iterator::operator==(const kmp_stats_list::iterator & rhs) {
   return this->ptr==rhs.ptr; 
}
kmp_stats_list* kmp_stats_list::iterator::operator*() const {
    return this->ptr;
}

/* *************************************************************** */
/* *************  kmp_stats_output_module functions ************** */

const char* kmp_stats_output_module::outputFileName = NULL;
const char* kmp_stats_output_module::eventsFileName = NULL;
const char* kmp_stats_output_module::plotFileName   = NULL;
int kmp_stats_output_module::printPerThreadFlag       = 0;
int kmp_stats_output_module::printPerThreadEventsFlag = 0;

// init() is called very near the beginning of execution time in the constructor of __kmp_stats_global_output
void kmp_stats_output_module::init() 
{
    char * statsFileName  = getenv("KMP_STATS_FILE");
    eventsFileName        = getenv("KMP_STATS_EVENTS_FILE");
    plotFileName          = getenv("KMP_STATS_PLOT_FILE");
    char * threadStats    = getenv("KMP_STATS_THREADS");
    char * threadEvents   = getenv("KMP_STATS_EVENTS");

    // set the stats output filenames based on environment variables and defaults
    outputFileName = statsFileName;
    eventsFileName = eventsFileName ? eventsFileName : "events.dat";
    plotFileName   = plotFileName   ? plotFileName   : "events.plt";

    // set the flags based on environment variables matching: true, on, 1, .true. , .t. , yes
    printPerThreadFlag        = __kmp_str_match_true(threadStats);
    printPerThreadEventsFlag  = __kmp_str_match_true(threadEvents);

    if(printPerThreadEventsFlag) {
        // assigns a color to each timer for printing
        setupEventColors();
    } else {
        // will clear flag so that no event will be logged
        timeStat::clearEventFlags();
    }

    return;
}

void kmp_stats_output_module::setupEventColors() {
    int i;
    int globalColorIndex = 0;
    int numGlobalColors = sizeof(globalColorArray) / sizeof(rgb_color);
    for(i=0;i<TIMER_LAST;i++) {
        if(timeStat::logEvent((timer_e)i)) {
            timerColorInfo[i] = globalColorArray[globalColorIndex];
            globalColorIndex = (globalColorIndex+1)%numGlobalColors;
        }
    }
    return;
}

void kmp_stats_output_module::printStats(FILE *statsOut, statistic const * theStats, bool areTimers)
{
    if (areTimers)
    {
        // Check if we have useful timers, since we don't print zero value timers we need to avoid
        // printing a header and then no data.
        bool haveTimers = false;
        for (int s = 0; s<TIMER_LAST; s++)
        {
            if (theStats[s].getCount() != 0)
            {
                haveTimers = true;
                break;
            }
        }
        if (!haveTimers)
            return;
    }

    // Print
    const char * title = areTimers ? "Timer,                   SampleCount," : "Counter,                 ThreadCount,";
    fprintf (statsOut, "%s    Min,      Mean,       Max,     Total,        SD\n", title);    
    if (areTimers) {
        for (int s = 0; s<TIMER_LAST; s++) {
            statistic const * stat = &theStats[s];
            if (stat->getCount() != 0) {
                char tag = timeStat::noUnits(timer_e(s)) ? ' ' : 'T';
                fprintf (statsOut, "%-25s, %s\n", timeStat::name(timer_e(s)), stat->format(tag, true).c_str());
            }
        }
    } else {   // Counters
        for (int s = 0; s<COUNTER_LAST; s++) {
            statistic const * stat = &theStats[s];
            fprintf (statsOut, "%-25s, %s\n", counter::name(counter_e(s)), stat->format(' ', true).c_str());
        }
    }
} 

void kmp_stats_output_module::printCounters(FILE * statsOut, counter const * theCounters)
{
    // We print all the counters even if they are zero.
    // That makes it easier to slice them into a spreadsheet if you need to.
    fprintf (statsOut, "\nCounter,                    Count\n");
    for (int c = 0; c<COUNTER_LAST; c++) {
        counter const * stat = &theCounters[c];
        fprintf (statsOut, "%-25s, %s\n", counter::name(counter_e(c)), formatSI(stat->getValue(), 9, ' ').c_str());
    }
}

void kmp_stats_output_module::printEvents(FILE* eventsOut, kmp_stats_event_vector* theEvents, int gtid) {
    // sort by start time before printing
    theEvents->sort();
    for (int i = 0; i < theEvents->size(); i++) {
        kmp_stats_event ev = theEvents->at(i);
        rgb_color color = getEventColor(ev.getTimerName());
        fprintf(eventsOut, "%d %lu %lu %1.1f rgb(%1.1f,%1.1f,%1.1f) %s\n", 
                gtid, 
                ev.getStart(), 
                ev.getStop(), 
                1.2 - (ev.getNestLevel() * 0.2),
                color.r, color.g, color.b,
                timeStat::name(ev.getTimerName())
               );
    }
    return;
}

void kmp_stats_output_module::windupExplicitTimers()
{
    // Wind up any explicit timers. We assume that it's fair at this point to just walk all the explcit timers in all threads 
    // and say "it's over".
    // If the timer wasn't running, this won't record anything anyway.
    kmp_stats_list::iterator it;
    for(it = __kmp_stats_list.begin(); it != __kmp_stats_list.end(); it++) {
        for (int timer=0; timer<EXPLICIT_TIMER_LAST; timer++) {
            (*it)->getExplicitTimer(explicit_timer_e(timer))->stop((timer_e)timer);
        }
    }
}

void kmp_stats_output_module::printPloticusFile() {
    int i;
    int size = __kmp_stats_list.size();
    FILE* plotOut = fopen(plotFileName, "w+");

    fprintf(plotOut, "#proc page\n"
                     "   pagesize: 15 10\n"
                     "   scale: 1.0\n\n");

    fprintf(plotOut, "#proc getdata\n"
                     "   file: %s\n\n", 
                     eventsFileName);

    fprintf(plotOut, "#proc areadef\n"
                     "   title: OpenMP Sampling Timeline\n"
                     "   titledetails: align=center size=16\n"
                     "   rectangle: 1 1 13 9\n"
                     "   xautorange: datafield=2,3\n"
                     "   yautorange: -1 %d\n\n", 
                     size);

    fprintf(plotOut, "#proc xaxis\n"
                     "   stubs: inc\n"
                     "   stubdetails: size=12\n"
                     "   label: Time (ticks)\n"
                     "   labeldetails: size=14\n\n");

    fprintf(plotOut, "#proc yaxis\n"
                     "   stubs: inc 1\n"
                     "   stubrange: 0 %d\n"
                     "   stubdetails: size=12\n"
                     "   label: Thread #\n"
                     "   labeldetails: size=14\n\n", 
                     size-1);

    fprintf(plotOut, "#proc bars\n"
                     "   exactcolorfield: 5\n"
                     "   axis: x\n"
                     "   locfield: 1\n"
                     "   segmentfields: 2 3\n"
                     "   barwidthfield: 4\n\n");

    // create legend entries corresponding to the timer color
    for(i=0;i<TIMER_LAST;i++) {
        if(timeStat::logEvent((timer_e)i)) {
            rgb_color c = getEventColor((timer_e)i);
            fprintf(plotOut, "#proc legendentry\n"
                             "   sampletype: color\n"
                             "   label: %s\n"
                             "   details: rgb(%1.1f,%1.1f,%1.1f)\n\n",
                             timeStat::name((timer_e)i),
                             c.r, c.g, c.b);

        }
    }

    fprintf(plotOut, "#proc legend\n"
                     "   format: down\n"
                     "   location: max max\n\n");
    fclose(plotOut);
    return;
}

void kmp_stats_output_module::outputStats(const char* heading) 
{
    statistic allStats[TIMER_LAST];
    statistic allCounters[COUNTER_LAST];

    // stop all the explicit timers for all threads
    windupExplicitTimers();

    FILE * eventsOut;
    FILE * statsOut = outputFileName ? fopen (outputFileName, "a+") : stderr;

    if (eventPrintingEnabled()) {
        eventsOut = fopen(eventsFileName, "w+");
    }

    if (!statsOut)
        statsOut = stderr;

    fprintf(statsOut, "%s\n",heading);
    // Accumulate across threads.
    kmp_stats_list::iterator it;
    for (it = __kmp_stats_list.begin(); it != __kmp_stats_list.end(); it++) {
        int t = (*it)->getGtid();
        // Output per thread stats if requested.
        if (perThreadPrintingEnabled()) {
            fprintf (statsOut, "Thread %d\n", t);
            printStats(statsOut, (*it)->getTimers(), true);
            printCounters(statsOut, (*it)->getCounters());
            fprintf(statsOut,"\n");
        }
        // Output per thread events if requested.
        if (eventPrintingEnabled()) {
            kmp_stats_event_vector events = (*it)->getEventVector();
            printEvents(eventsOut, &events, t);
        }

        for (int s = 0; s<TIMER_LAST; s++) {
            // See if we should ignore this timer when aggregating
            if ((timeStat::masterOnly(timer_e(s)) && (t != 0)) || // Timer is only valid on the master and this thread is a worker
                (timeStat::workerOnly(timer_e(s)) && (t == 0)) || // Timer is only valid on a worker and this thread is the master
                timeStat::synthesized(timer_e(s))                 // It's a synthesized stat, so there's no raw data for it.
               )            
            {
                continue;
            }

            statistic * threadStat = (*it)->getTimer(timer_e(s));
            allStats[s] += *threadStat;
        }

        // Special handling for synthesized statistics.
        // These just have to be coded specially here for now. 
        // At present we only have one: the total parallel work done in each thread.
        // The variance here makes it easy to see load imbalance over the whole program (though, of course,
        // it's possible to have a code with awful load balance in every parallel region but perfect load
        // balance oever the whole program.)
        allStats[TIMER_Total_work].addSample ((*it)->getTimer(TIMER_OMP_work)->getTotal());

        // Time waiting for work (synthesized)
        if ((t != 0) || !timeStat::workerOnly(timer_e(TIMER_OMP_await_work)))
            allStats[TIMER_Total_await_work].addSample ((*it)->getTimer(TIMER_OMP_await_work)->getTotal());

        // Time in explicit barriers.
        allStats[TIMER_Total_barrier].addSample ((*it)->getTimer(TIMER_OMP_barrier)->getTotal());

        for (int c = 0; c<COUNTER_LAST; c++) {
            if (counter::masterOnly(counter_e(c)) && t != 0)
                continue;
            allCounters[c].addSample ((*it)->getCounter(counter_e(c))->getValue());
        }
    }

    if (eventPrintingEnabled()) {
        printPloticusFile();
        fclose(eventsOut);
    }

    fprintf (statsOut, "Aggregate for all threads\n");
    printStats (statsOut, &allStats[0], true);
    fprintf (statsOut, "\n");
    printStats (statsOut, &allCounters[0], false);

    if (statsOut != stderr)
        fclose(statsOut);

}

/* ************************************************** */
/* *************  exported C functions ************** */

// no name mangling for these functions, we want the c files to be able to get at these functions
extern "C" {

void __kmp_reset_stats()
{
    kmp_stats_list::iterator it;
    for(it = __kmp_stats_list.begin(); it != __kmp_stats_list.end(); it++) {
        timeStat * timers     = (*it)->getTimers();
        counter * counters    = (*it)->getCounters();
        explicitTimer * eTimers = (*it)->getExplicitTimers();

        for (int t = 0; t<TIMER_LAST; t++)
            timers[t].reset();

        for (int c = 0; c<COUNTER_LAST; c++)
            counters[c].reset();

        for (int t=0; t<EXPLICIT_TIMER_LAST; t++)
            eTimers[t].reset();

        // reset the event vector so all previous events are "erased"
        (*it)->resetEventVector();

        // May need to restart the explicit timers in thread zero?
    }
    KMP_START_EXPLICIT_TIMER(OMP_serial);
    KMP_START_EXPLICIT_TIMER(OMP_start_end);
}

// This function will reset all stats and stop all threads' explicit timers if they haven't been stopped already.
void __kmp_output_stats(const char * heading)
{
    __kmp_stats_global_output.outputStats(heading);
    __kmp_reset_stats();
}

void __kmp_accumulate_stats_at_exit(void)
{
    // Only do this once.
    if (KMP_XCHG_FIXED32(&statsPrinted, 1) != 0)
        return;

    __kmp_output_stats("Statistics on exit");
    return;
}

void __kmp_stats_init(void) 
{
    return;
}

} // extern "C" 

#endif // KMP_STATS_ENABLED