Refactor PAPI support, and add profiling of multithreaded GC
[ghc-hetmet.git] / rts / Stats.c
index ec8d583..1127b81 100644 (file)
 #include "RtsFlags.h"
 #include "RtsUtils.h"
 #include "MBlock.h"
+#include "Storage.h"
 #include "Schedule.h"
 #include "Stats.h"
 #include "ParTicky.h"                       /* ToDo: move into Rts.h */
 #include "Profiling.h"
-#include "Storage.h"
 #include "GetTime.h"
 
+#if USE_PAPI
+#include "Papi.h"
+#endif
+
 /* huh? */
 #define BIG_STRING_LEN              512
 
@@ -37,7 +41,6 @@ static Ticks ExitElapsedTime  = 0;
 
 static ullong GC_tot_alloc        = 0;
 static ullong GC_tot_copied       = 0;
-static ullong GC_tot_scavd_copied = 0;
 
 static Ticks GC_start_time = 0,  GC_tot_time  = 0;  /* User GC Time */
 static Ticks GCe_start_time = 0, GCe_tot_time = 0;  /* Elapsed GC time */
@@ -64,9 +67,6 @@ static lnat GC_start_faults = 0, GC_end_faults = 0;
 
 static Ticks *GC_coll_times;
 
-static void statsPrintf( char *s, ... ) 
-    GNUC3_ATTRIBUTE(format (printf, 1, 2));
-
 static void statsFlush( void );
 static void statsClose( void );
 
@@ -170,6 +170,16 @@ stat_endInit(void)
     } else {
        InitElapsedTime = elapsed - ElapsedTimeStart;
     }
+#if USE_PAPI
+    /* We start counting events for the mutator
+     * when garbage collection starts
+     * we switch to the GC event set. */
+    papi_start_mutator_count();
+
+    /* This flag is needed to avoid counting the last GC */
+    papi_is_reporting = 1;
+
+#endif
 }
 
 /* -----------------------------------------------------------------------------
@@ -192,6 +202,16 @@ stat_startExit(void)
 
     MutUserTime = user - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime;
     if (MutUserTime < 0) { MutUserTime = 0; }
+
+#if USE_PAPI
+    /* We stop counting mutator events
+     * GC events are not being counted at this point */
+    papi_stop_mutator_count();
+
+    /* This flag is needed, because GC is run once more after this function */
+    papi_is_reporting = 0;
+
+#endif
 }
 
 void
@@ -249,6 +269,15 @@ stat_startGC(void)
            GC_start_faults = getPageFaults();
        }
     }
+
+#if USE_PAPI
+    if(papi_is_reporting) {
+      /* Switch to counting GC events */
+      papi_stop_mutator_count();
+      papi_start_gc_count();
+    }
+#endif
+
 }
 
 /* -----------------------------------------------------------------------------
@@ -256,8 +285,7 @@ stat_startGC(void)
    -------------------------------------------------------------------------- */
 
 void
-stat_endGC (lnat alloc, lnat live, lnat copied, 
-           lnat scavd_copied, lnat gen)
+stat_endGC (lnat alloc, lnat live, lnat copied, lnat gen)
 {
     if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
        Ticks time, etime, gc_time, gc_etime;
@@ -270,7 +298,7 @@ stat_endGC (lnat alloc, lnat live, lnat copied,
            nat faults = getPageFaults();
            
            statsPrintf("%9ld %9ld %9ld",
-                   alloc*sizeof(W_), (copied+scavd_copied)*sizeof(W_), 
+                   alloc*sizeof(W_), copied*sizeof(W_), 
                        live*sizeof(W_));
            statsPrintf(" %5.2f %5.2f %7.2f %7.2f %4ld %4ld  (Gen: %2ld)\n", 
                    TICK_TO_DBL(gc_time),
@@ -288,7 +316,6 @@ stat_endGC (lnat alloc, lnat live, lnat copied,
        GC_coll_times[gen] += gc_time;
 
        GC_tot_copied += (ullong) copied;
-       GC_tot_scavd_copied += (ullong) scavd_copied;
        GC_tot_alloc  += (ullong) alloc;
        GC_tot_time   += gc_time;
        GCe_tot_time  += gc_etime;
@@ -316,6 +343,14 @@ stat_endGC (lnat alloc, lnat live, lnat copied,
        debugBelch("\b\b\b  \b\b\b");
        rub_bell = 0;
     }
+
+#if USE_PAPI
+    if(papi_is_reporting) {
+      /* Switch to counting mutator events */
+      papi_stop_gc_count();
+      papi_start_mutator_count();
+    }
+#endif
 }
 
 /* -----------------------------------------------------------------------------
@@ -401,6 +436,52 @@ stat_endHeapCensus(void)
    were left unused when the heap-check failed.
    -------------------------------------------------------------------------- */
 
+#ifdef DEBUG
+#define TICK_VAR(arity) \
+  extern StgInt SLOW_CALLS_##arity; \
+  extern StgInt RIGHT_ARITY_##arity; \
+  extern StgInt TAGGED_PTR_##arity;
+
+#define TICK_VAR_INI(arity) \
+  StgInt SLOW_CALLS_##arity = 1; \
+  StgInt RIGHT_ARITY_##arity = 1; \
+  StgInt TAGGED_PTR_##arity = 0;
+
+extern StgInt TOTAL_CALLS;
+
+TICK_VAR(1)
+TICK_VAR(2)
+
+TICK_VAR_INI(1)
+TICK_VAR_INI(2)
+
+StgInt TOTAL_CALLS=1;
+#endif
+
+/* Report the value of a counter */
+#define REPORT(counter) \
+  { \
+    ullong_format_string(counter,temp,rtsTrue/*commas*/); \
+    statsPrintf("  (" #counter ")  : %s\n",temp);                              \
+  }
+
+/* Report the value of a counter as a percentage of another counter */
+#define REPORT_PCT(counter,countertot) \
+  statsPrintf("  (" #counter ") %% of (" #countertot ") : %.1f%%\n", \
+             counter*100.0/countertot)
+
+#define TICK_PRINT(arity) \
+  REPORT(SLOW_CALLS_##arity); \
+  REPORT_PCT(RIGHT_ARITY_##arity,SLOW_CALLS_##arity); \
+  REPORT_PCT(TAGGED_PTR_##arity,RIGHT_ARITY_##arity); \
+  REPORT(RIGHT_ARITY_##arity); \
+  REPORT(TAGGED_PTR_##arity)
+
+#define TICK_PRINT_TOT(arity) \
+  statsPrintf("  (SLOW_CALLS_" #arity ") %% of (TOTAL_CALLS) : %.1f%%\n", \
+             SLOW_CALLS_##arity * 100.0/TOTAL_CALLS)
+
+
 void
 stat_exit(int alloc)
 {
@@ -436,12 +517,8 @@ stat_exit(int alloc)
 
            ullong_format_string(GC_tot_copied*sizeof(W_), 
                                 temp, rtsTrue/*commas*/);
-           statsPrintf("%11s bytes copied during GC (scavenged)\n", temp);
+           statsPrintf("%11s bytes copied during GC\n", temp);
 
-           ullong_format_string(GC_tot_scavd_copied*sizeof(W_), 
-                                temp, rtsTrue/*commas*/);
-           statsPrintf("%11s bytes copied during GC (not scavenged)\n", temp);
-  
            if ( ResidencySamples > 0 ) {
                ullong_format_string(MaxResidency*sizeof(W_), 
                                     temp, rtsTrue/*commas*/);
@@ -517,6 +594,18 @@ stat_exit(int alloc)
                    TICK_TO_DBL(time - GC_tot_time - 
                                PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime) * 100 
                    / TICK_TO_DBL(etime));
+
+            /*
+            TICK_PRINT(1);
+            TICK_PRINT(2);
+           REPORT(TOTAL_CALLS);
+            TICK_PRINT_TOT(1);
+            TICK_PRINT_TOT(2);
+            */
+
+#if USE_PAPI
+            papi_stats_report();
+#endif
        }
 
        if (RtsFlags.GcFlags.giveStats == ONELINE_GC_STATS) {
@@ -537,6 +626,9 @@ stat_exit(int alloc)
        statsFlush();
        statsClose();
     }
+    if (GC_coll_times)
+      stgFree(GC_coll_times);
+    GC_coll_times = NULL;
 }
 
 /* -----------------------------------------------------------------------------
@@ -554,13 +646,13 @@ statDescribeGens(void)
   step *step;
 
   debugBelch(
-"     Gen    Steps      Max   Mutable  Step   Blocks     Live    Large\n"
-"                     Blocks Closures                          Objects\n");
+"     Gen    Steps      Max  Mut-list  Step   Blocks     Live    Large\n"
+"                    Blocks     Bytes                          Objects\n");
 
   mut = 0;
   for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
       for (bd = generations[g].mut_list; bd != NULL; bd = bd->link) {
-         mut += bd->free - bd->start;
+         mut += (bd->free - bd->start) * sizeof(W_);
       }
 
     debugBelch("%8d %8d %8d %9d", g, generations[g].n_steps,
@@ -603,7 +695,7 @@ extern HsInt64 getAllocations( void )
    Dumping stuff in the stats file, or via the debug message interface
    -------------------------------------------------------------------------- */
 
-static void
+void
 statsPrintf( char *s, ... )
 {
     FILE *sf = RtsFlags.GcFlags.statsFile;