[STATS] Add header information (e.g., machine name, time of run, etc.)

[jlpeyton]

Summary

This change adds a header to the printout of the statistics which includes the time, machine name, and processor info if available. This change also includes some cosmetic changes like using enum casting for timer and counter iteration.

[jcownie]

LGTM

openmp/trunk/runtime/src/kmp.h

typedef struct kmp_cpuinfo {
     int        stepping;     // CPUID(1).EAX[3:0] ( Stepping )
     int        sse2;         // 0 if SSE2 instructions are not supported, 1 otherwise.
     int        rtm;          // 0 if RTM instructions are not supported, 1 otherwise.
     int        cpu_stackoffset;
     int        apic_id;
     int        physical_id;
     int        logical_id;
     kmp_uint64 frequency;    // Nominal CPU frequency in Hz.
+    char       name [3*sizeof (kmp_cpuid_t)]; // CPUID(0x80000002,0x80000003,0x80000004)
 } kmp_cpuinfo_t;
 
 
 #ifdef BUILD_TV
 
 struct tv_threadprivate {
     /* Record type #1 */
     void        *global_addr;

openmp/trunk/runtime/src/kmp_stats.h

  */
 // #define KMP_DEVELOPER_STATS 1
 
 /*!
  * @ingroup STATS_GATHERING
  * \brief flags to describe the statistic ( timers or counter )
  *
 */
-class stats_flags_e {
-    public:
-        const static int onlyInMaster = 1<<0; //!< statistic is valid only for master
-        const static int noUnits      = 1<<1; //!< statistic doesn't need units printed next to it in output
-        const static int notInMaster  = 1<<2; //!< statistic is valid for non-master threads
-        const static int logEvent     = 1<<3; //!< statistic can be logged when KMP_STATS_EVENTS is on (valid only for timers)
+enum stats_flags_e {
+    noTotal      = 1<<0,             //!< do not show a TOTAL_aggregation for this statistic
+    onlyInMaster = (1<<1) | noTotal, //!< statistic is valid only for master
+    noUnits      = (1<<2) | noTotal, //!< statistic doesn't need units printed next to it in output
+    notInMaster  = 1<<3,             //!< statistic is valid only for non-master threads
+    logEvent     = 1<<4              //!< statistic can be logged when KMP_STATS_EVENTS is on (valid only for timers)
 };
 
 /*!
  * \brief Add new counters under KMP_FOREACH_COUNTER() macro in kmp_stats.h
  *
  * @param macro a user defined macro that takes three arguments - macro(COUNTER_NAME, flags, arg)
  * @param arg a user defined argument to send to the user defined macro
  *

 //                           Both adjust for any chunking, so if there were an iteration count of 20 but a chunk size of 10, we'd record 2.
 
 /*!
  * \brief Add new timers under KMP_FOREACH_TIMER() macro in kmp_stats.h
  *
  * @param macro a user defined macro that takes three arguments - macro(TIMER_NAME, flags, arg)
  * @param arg a user defined argument to send to the user defined macro
  *
- * \details A timer collects multiple samples of some count in each thread and then finally aggregates over all the threads.
+ * \details A timer collects multiple samples of some count in each thread and then finally aggregates alll of the samples from all of the threads.
+ * For most timers the printing code also provides an aggregation over the thread totals. These are printed as TOTAL_foo.
  * The count is normally a time (in ticks), hence the name "timer". (But can be any value, so we use this for "number of arguments passed to fork"
  * as well).
  * For timers the threads are not significant, it's the individual observations that count, so the statistics are at that level.
  * Format is "macro(name, flags, arg)"
  *
  * @ingroup STATS_GATHERING2
  */
 #define KMP_FOREACH_TIMER(macro, arg)                           \

 
 class timeStat : public statistic
 {
     static statInfo timerInfo[];
 
  public:
     timeStat() : statistic() {}
     static const char * name(timer_e e) { return timerInfo[e].name; }
+    static bool  noTotal    (timer_e e) { return timerInfo[e].flags & stats_flags_e::noTotal; }
     static bool  masterOnly (timer_e e) { return timerInfo[e].flags & stats_flags_e::onlyInMaster; }
     static bool  workerOnly (timer_e e) { return timerInfo[e].flags & stats_flags_e::notInMaster;  }
     static bool  noUnits    (timer_e e) { return timerInfo[e].flags & stats_flags_e::noUnits;      }
     static bool  logEvent   (timer_e e) { return timerInfo[e].flags & stats_flags_e::logEvent;     }
     static void  clearEventFlags()      {
-        int i;
-        for(i=0;i<TIMER_LAST;i++) {
+        for(int i=0;i<TIMER_LAST;i++) {
             timerInfo[i].flags &= (~(stats_flags_e::logEvent));
         }
     }
 };
 
 // Where we need explicitly to start and end the timer, this version can be used
 // Since these timers normally aren't nicely scoped, so don't have a good place to live
 // on the stack of the thread, they're more work to use.
private:
     static int printPerThreadFlag;
     static int printPerThreadEventsFlag;
     static const rgb_color globalColorArray[];
     static       rgb_color timerColorInfo[];
 
     void init();
     static void setupEventColors();
     static void printPloticusFile();
+    static void printHeaderInfo(FILE *statsOut);
     static void printTimerStats(FILE *statsOut, statistic const * theStats, statistic const * totalStats);
     static void printCounterStats(FILE *statsOut, statistic const * theStats);
     static void printCounters(FILE * statsOut, counter const * theCounters);
     static void printEvents(FILE * eventsOut, kmp_stats_event_vector* theEvents, int gtid);
     static rgb_color getEventColor(timer_e e) { return timerColorInfo[e]; }
     static void windupExplicitTimers();
-    bool eventPrintingEnabled() {
-        if(printPerThreadEventsFlag) return true;
-        else return false;
-    }
-    bool perThreadPrintingEnabled() {
-        if(printPerThreadFlag) return true;
-        else return false;
-    }
+    bool eventPrintingEnabled() const         { return printPerThreadEventsFlag; }
 
  public:
     kmp_stats_output_module() { init(); }
     void outputStats(const char* heading);
 };
 
 #ifdef __cplusplus
 extern "C" {

openmp/trunk/runtime/src/kmp_stats.cpp

 #include "kmp_str.h"
 #include "kmp_lock.h"
 #include "kmp_stats.h"
 
 #include <algorithm>
 #include <sstream>
 #include <iomanip>
 #include <stdlib.h>                             // for atexit
+#include <ctime>
 
 #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}
for(i=0;i<TIMER_LAST;i++) {
         }
     }
     return;
 }
 
 void kmp_stats_output_module::printTimerStats(FILE *statsOut, statistic const * theStats, statistic const * totalStats)
 {
     fprintf (statsOut, "Timer,                      SampleCount,    Min,      Mean,       Max,     Total,        SD\n");
-    for (int s = 0; s<TIMER_LAST; s++) {
+    for (timer_e s = timer_e(0); s<TIMER_LAST; s = timer_e(s+1)) {
         statistic const * stat = &theStats[s];
+        char tag = timeStat::noUnits(s) ? ' ' : 'T';
 
-        char tag = timeStat::noUnits(timer_e(s)) ? ' ' : 'T';
-        fprintf (statsOut, "%-28s, %s\n", timeStat::name(timer_e(s)), stat->format(tag, true).c_str());
+        fprintf (statsOut, "%-28s, %s\n", timeStat::name(s), stat->format(tag, true).c_str());
         // Also print the Total_ versions of times.
-        if (totalStats && tag == 'T' && !timeStat::masterOnly(timer_e(s))) {
-            fprintf(statsOut, "Total_%-22s, %s\n", timeStat::name(timer_e(s)), totalStats[s].format(tag, true).c_str());
-        }
+        if (totalStats && !timeStat::noTotal(s))
+            fprintf(statsOut, "Total_%-22s, %s\n", timeStat::name(s), totalStats[s].format(tag, true).c_str());
     }
 }
 
 void kmp_stats_output_module::printCounterStats(FILE *statsOut, statistic const * theStats)
 {
     fprintf (statsOut, "Counter,                 ThreadCount,    Min,      Mean,       Max,     Total,        SD\n");
     for (int s = 0; s<COUNTER_LAST; s++) {
         statistic const * stat = &theStats[s];
void kmp_stats_output_module::printPloticusFile() {
 
     fprintf(plotOut, "#proc legend\n"
                      "   format: down\n"
                      "   location: max max\n\n");
     fclose(plotOut);
     return;
 }
 
+/*
+ * Print some useful information about
+ *    * the date and time this experiment ran.
+ *    * the machine on which it ran.
+ * We output all of this as stylised comments, though we may decide to parse some of it.
+ */
+void kmp_stats_output_module::printHeaderInfo(FILE * statsOut)
+{
+    std::time_t now = std::time(0);
+    char buffer[40];
+    char hostName[80];
+
+    std::strftime(&buffer[0], sizeof(buffer), "%c", std::localtime(&now));
+    fprintf (statsOut, "# Time of run: %s\n", &buffer[0]);
+    if (gethostname(&hostName[0], sizeof(hostName)) == 0)
+        fprintf (statsOut,"# Hostname: %s\n", &hostName[0]);
+#if KMP_ARCH_X86 || KMP_ARCH_X86_64
+    fprintf (statsOut, "# CPU:  %s\n", &__kmp_cpuinfo.name[0]);
+    fprintf (statsOut, "# Family: %d, Model: %d, Stepping: %d\n", __kmp_cpuinfo.family, __kmp_cpuinfo.model, __kmp_cpuinfo.stepping);
+    fprintf (statsOut, "# Nominal frequency: %sz\n", formatSI(double(__kmp_cpuinfo.frequency),9,'H').c_str());
+#endif
+}
+
 void kmp_stats_output_module::outputStats(const char* heading) 
 {
+    // Stop all the explicit timers in all threads
+    // Do this before declaring the local statistics because thay have constructors so will take time to create.
+    windupExplicitTimers();
+
     statistic allStats[TIMER_LAST];
     statistic totalStats[TIMER_LAST];           /* Synthesized, cross threads versions of normal timer stats */
     statistic allCounters[COUNTER_LAST];
 
-    // stop all the explicit timers for all threads
-    windupExplicitTimers();
-
-    FILE * eventsOut;
     FILE * statsOut = outputFileName ? fopen (outputFileName, "a+") : stderr;
+    if (!statsOut)
+        statsOut = stderr;
 
+    FILE * eventsOut;
     if (eventPrintingEnabled()) {
         eventsOut = fopen(eventsFileName, "w+");
     }
 
-    if (!statsOut)
-        statsOut = stderr;
-
+    printHeaderInfo (statsOut);
     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()) {
+        if (printPerThreadFlag) {
             fprintf (statsOut, "Thread %d\n", t);
-            printTimerStats(statsOut, (*it)->getTimers(), 0);
-            printCounters(statsOut, (*it)->getCounters());
-            fprintf(statsOut,"\n");
+            printTimerStats (statsOut, (*it)->getTimers(), 0);
+            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);
         }
 
         // Accumulate timers.
-        for (int s = 0; s<TIMER_LAST; s++) {
+        for (timer_e s = timer_e(0); s<TIMER_LAST; s = timer_e(s+1)) {
             // 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
+            if ((timeStat::masterOnly(s) && (t != 0)) || // Timer is only valid on the master and this thread is a worker
+                (timeStat::workerOnly(s) && (t == 0))    // Timer is only valid on a worker and this thread is the master
                )            
             {
                 continue;
             }
 
-            statistic * threadStat = (*it)->getTimer(timer_e(s));
+            statistic * threadStat = (*it)->getTimer(s);
             allStats[s] += *threadStat;
 
-            // Add Total stats for all real times (not counts) that are valid in more than one thread
-            if (!timeStat::noUnits(timer_e(s)) && !timeStat::masterOnly(timer_e(s)))
-            {
+            // Add Total stats for timers that are valid in more than one thread
+            if (!timeStat::noTotal(s))
                 totalStats[s].addSample(threadStat->getTotal());
-            }
-        }
 
         // Accumulate counters.
-        for (int c = 0; c<COUNTER_LAST; c++) {
-            if (counter::masterOnly(counter_e(c)) && t != 0)
+        for (counter_e c = counter_e(0); c<COUNTER_LAST; c = counter_e(c+1)) {
+            if (counter::masterOnly(c) && t != 0)
                 continue;
-            allCounters[c].addSample ((*it)->getCounter(counter_e(c))->getValue());
+            allCounters[c].addSample ((*it)->getCounter(c)->getValue());
         }
     }
 
     if (eventPrintingEnabled()) {
         printPloticusFile();
         fclose(eventsOut);
     }
 
     fprintf (statsOut, "Aggregate for all threads\n");
     printTimerStats (statsOut, &allStats[0], &totalStats[0]);
     fprintf (statsOut, "\n");
     printCounterStats (statsOut, &allCounters[0]);
 
     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_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" 
 

openmp/trunk/runtime/src/kmp_utility.c

#if KMP_USE_ADAPTIVE_LOCKS
             /* RTM bit CPUID.07:EBX, bit 11 */
             __kmp_x86_cpuid(7, 0, &buf);
             p->rtm = (buf.ebx >> 11) & 1;
             KA_TRACE( trace_level, (" RTM" ) );
         }
 #endif
     }; // if
 
-    { // Parse CPU brand string for frequency.
-
-        union kmp_cpu_brand_string {
-            struct kmp_cpuid buf[ 3 ];
-            char             string[ sizeof( struct kmp_cpuid ) * 3 + 1 ];
-        }; // union kmp_cpu_brand_string
-        union kmp_cpu_brand_string brand;
+    { // Parse CPU brand string for frequency, saving the string for later.
         int i;
-
-        p->frequency = 0;
+        kmp_cpuid_t * base = (kmp_cpuid_t *)&p->name[0];
 
         // Get CPU brand string.
         for ( i = 0; i < 3; ++ i ) {
-            __kmp_x86_cpuid( 0x80000002 + i, 0, &brand.buf[ i ] );
+            __kmp_x86_cpuid( 0x80000002 + i, 0, base+i );
         }; // for
-        brand.string[ sizeof( brand.string ) - 1 ] = 0; // Just in case. ;-)
-        KA_TRACE( trace_level, ( "cpu brand string: \"%s\"\n", brand.string ) );
+        p->name[ sizeof(p->name) - 1 ] = 0; // Just in case. ;-)
+        KA_TRACE( trace_level, ( "cpu brand string: \"%s\"\n", &p->name[0] ) );
 
         // Parse frequency.
-        p->frequency = __kmp_parse_frequency( strrchr( brand.string, ' ' ) );
+        p->frequency = __kmp_parse_frequency( strrchr( &p->name[0], ' ' ) );
         KA_TRACE( trace_level, ( "cpu frequency from brand string: %" KMP_UINT64_SPEC "\n", p->frequency ) );
     }
 }
 
 #endif /* KMP_ARCH_X86 || KMP_ARCH_X86_64 */
 
 /* ------------------------------------------------------------------------------------ */
 /* ------------------------------------------------------------------------------------ */