Keep track of an accurate count of live words in each step
[ghc-hetmet.git] / rts / Stats.c
index 1b0abaa..cd61116 100644 (file)
@@ -16,6 +16,9 @@
 #include "ParTicky.h"                       /* ToDo: move into Rts.h */
 #include "Profiling.h"
 #include "GetTime.h"
+#include "GC.h"
+#include "GCUtils.h"
+#include "Evac.h"
 
 #if USE_PAPI
 #include "Papi.h"
@@ -65,7 +68,8 @@ static lnat ResidencySamples = 0; // for stats only
 
 static lnat GC_start_faults = 0, GC_end_faults = 0;
 
-static Ticks *GC_coll_times;
+static Ticks *GC_coll_times = NULL;
+static Ticks *GC_coll_etimes = NULL;
 
 static void statsFlush( void );
 static void statsClose( void );
@@ -138,8 +142,13 @@ initStats(void)
        (Ticks *)stgMallocBytes(
            sizeof(Ticks)*RtsFlags.GcFlags.generations,
            "initStats");
+    GC_coll_etimes = 
+       (Ticks *)stgMallocBytes(
+           sizeof(Ticks)*RtsFlags.GcFlags.generations,
+           "initStats");
     for (i = 0; i < RtsFlags.GcFlags.generations; i++) {
        GC_coll_times[i] = 0;
+       GC_coll_etimes[i] = 0;
     }
 }    
 
@@ -171,8 +180,6 @@ stat_endInit(void)
        InitElapsedTime = elapsed - ElapsedTimeStart;
     }
 #if USE_PAPI
-    papi_init_eventsets();
-
     /* We start counting events for the mutator
      * when garbage collection starts
      * we switch to the GC event set. */
@@ -316,6 +323,7 @@ stat_endGC (lnat alloc, lnat live, lnat copied, lnat gen)
        }
 
        GC_coll_times[gen] += gc_time;
+       GC_coll_etimes[gen] += gc_etime;
 
        GC_tot_copied += (ullong) copied;
        GC_tot_alloc  += (ullong) alloc;
@@ -349,7 +357,11 @@ stat_endGC (lnat alloc, lnat live, lnat copied, lnat gen)
 #if USE_PAPI
     if(papi_is_reporting) {
       /* Switch to counting mutator events */
-      papi_stop_gc_count();
+      if (gen == 0) {
+          papi_stop_gc0_count();
+      } else {
+          papi_stop_gc1_count();
+      }
       papi_start_mutator_count();
     }
 #endif
@@ -531,12 +543,13 @@ stat_exit(int alloc)
 
            /* Print garbage collections in each gen */
            for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
-               statsPrintf("%11d collections in generation %d (%6.2fs)\n", 
+               statsPrintf("%11d collections in generation %d, %6.2fs, %6.2fs elapsed\n", 
                        generations[g].collections, g, 
-                       TICK_TO_DBL(GC_coll_times[g]));
+                        TICK_TO_DBL(GC_coll_times[g]),
+                        TICK_TO_DBL(GC_coll_etimes[g]));
            }
 
-           statsPrintf("\n%11ld Mb total memory in use\n\n", 
+           statsPrintf("\n%11ld MB total memory in use\n\n", 
                    mblocks_allocated * MBLOCK_SIZE / (1024 * 1024));
 
 #if defined(THREADED_RTS)
@@ -606,16 +619,7 @@ stat_exit(int alloc)
             */
 
 #if USE_PAPI
-           /* PAPI reporting, should put somewhere else?
-            * Note that the cycles are counted _after_ the initialization of the RTS -- AR */
-
-           statsPrintf("  -- CPU Mutator counters --\n");
-           papi_mut_cycles();
-           papi_report(MutatorCounters);
-
-           statsPrintf("\n  -- CPU GC counters --\n");
-           papi_gc_cycles();
-           papi_report(GCCounters);
+            papi_stats_report();
 #endif
        }
 
@@ -634,12 +638,32 @@ stat_exit(int alloc)
                    TICK_TO_DBL(GC_tot_time), TICK_TO_DBL(GCe_tot_time));
        }
 
+#if defined(THREADED_RTS) && defined(PROF_SPIN)
+        {
+            nat g, s;
+            
+            statsPrintf("recordMutableGen_sync: %"FMT_Word64"\n", recordMutableGen_sync.spin);
+            statsPrintf("gc_alloc_block_sync: %"FMT_Word64"\n", gc_alloc_block_sync.spin);
+            statsPrintf("whitehole_spin: %"FMT_Word64"\n", whitehole_spin);
+            for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
+                for (s = 0; s < generations[g].n_steps; s++) {
+                    statsPrintf("gen[%d].steps[%d].sync_todo: %"FMT_Word64"\n", g, s, generations[g].steps[s].sync_todo.spin);
+                    statsPrintf("gen[%d].steps[%d].sync_large_objects: %"FMT_Word64"\n", g, s, generations[g].steps[s].sync_large_objects.spin);
+                }
+            }
+        }
+#endif
+
        statsFlush();
        statsClose();
     }
+
     if (GC_coll_times)
       stgFree(GC_coll_times);
     GC_coll_times = NULL;
+    if (GC_coll_etimes)
+      stgFree(GC_coll_etimes);
+    GC_coll_etimes = NULL;
 }
 
 /* -----------------------------------------------------------------------------
@@ -647,52 +671,52 @@ stat_exit(int alloc)
 
    Produce some detailed info on the state of the generational GC.
    -------------------------------------------------------------------------- */
-#ifdef DEBUG
 void
 statDescribeGens(void)
 {
   nat g, s, mut, lge;
-  lnat live;
+  lnat live, slop;
+  lnat tot_live, tot_slop;
   bdescr *bd;
   step *step;
 
   debugBelch(
-"     Gen    Steps      Max  Mut-list  Step   Blocks     Live    Large\n"
-"                    Blocks     Bytes                          Objects\n");
+"-----------------------------------------------------------------\n"
+"  Gen     Max  Mut-list  Step   Blocks    Large     Live     Slop\n"
+"       Blocks     Bytes                 Objects                  \n"
+"-----------------------------------------------------------------\n");
 
-  mut = 0;
+  tot_live = 0;
+  tot_slop = 0;
   for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
+      mut = 0;
       for (bd = generations[g].mut_list; bd != NULL; bd = bd->link) {
          mut += (bd->free - bd->start) * sizeof(W_);
       }
 
-    debugBelch("%8d %8d %8d %9d", g, generations[g].n_steps,
-           generations[g].max_blocks, mut);
+    debugBelch("%5d %7d %9d", g, generations[g].max_blocks, mut);
 
     for (s = 0; s < generations[g].n_steps; s++) {
       step = &generations[g].steps[s];
-      live = 0;
       for (bd = step->large_objects, lge = 0; bd; bd = bd->link) {
        lge++;
       }
-      live = step->n_large_blocks * BLOCK_SIZE;
-      bd = step->blocks;
-      // This live figure will be slightly less that the "live" figure
-      // given by +RTS -Sstderr, because we take don't count the
-      // slop at the end of each block.
-      for (; bd; bd = bd->link) {
-       live += (bd->free - bd->start) * sizeof(W_);
-      }
+      live = step->n_words + countOccupied(step->large_objects);
       if (s != 0) {
-       debugBelch("%36s","");
+       debugBelch("%23s","");
       }
-      debugBelch("%6d %8d %8ld %8d\n", s, step->n_blocks,
-             live, lge);
+      slop = (step->n_blocks + step->n_large_blocks) * BLOCK_SIZE_W - live;
+      debugBelch("%6d %8d %8d %8ld %8ld\n", s, step->n_blocks, lge,
+                 live*sizeof(W_), slop*sizeof(W_));
+      tot_live += live;
+      tot_slop += slop;
     }
   }
+  debugBelch("-----------------------------------------------------------------\n");
+  debugBelch("%48s%8ld %8ld\n","",tot_live*sizeof(W_),tot_slop*sizeof(W_));
+  debugBelch("-----------------------------------------------------------------\n");
   debugBelch("\n");
 }
-#endif
 
 /* -----------------------------------------------------------------------------
    Stats available via a programmatic interface, so eg. GHCi can time