X-Git-Url: http://git.megacz.com/?p=ghc-hetmet.git;a=blobdiff_plain;f=rts%2FStats.c;h=58b113d74b2d78d1f3df46d90e9367560e7f564c;hp=2fdd0a8b3cedf4fec4d1d7902873e8030129f859;hb=7effbbbbdfe7eb05c6402fa9337e358e7e9fadde;hpb=f732e7862bb1fcc65fcfbcfb6eaaf6dde39fdd5f diff --git a/rts/Stats.c b/rts/Stats.c index 2fdd0a8..58b113d 100644 --- a/rts/Stats.c +++ b/rts/Stats.c @@ -6,19 +6,16 @@ * * ---------------------------------------------------------------------------*/ +#include "PosixSource.h" #include "Rts.h" -#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 "GetTime.h" -#include "GC.h" -#include "GCUtils.h" -#include "Evac.h" +#include "sm/Storage.h" +#include "sm/GC.h" // gc_alloc_block_sync, whitehole_spin #if USE_PAPI #include "Papi.h" @@ -45,6 +42,9 @@ static Ticks ExitElapsedTime = 0; static ullong GC_tot_alloc = 0; static ullong GC_tot_copied = 0; +static ullong GC_par_max_copied = 0; +static ullong GC_par_avg_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 */ @@ -65,11 +65,12 @@ static Ticks HCe_start_time, HCe_tot_time = 0; // heap census prof elap time static lnat MaxResidency = 0; // in words; for stats only static lnat AvgResidency = 0; static lnat ResidencySamples = 0; // for stats only +static lnat MaxSlop = 0; static lnat GC_start_faults = 0, GC_end_faults = 0; -static Ticks *GC_coll_times; -static Ticks *GC_coll_etimes; +static Ticks *GC_coll_times = NULL; +static Ticks *GC_coll_etimes = NULL; static void statsFlush( void ); static void statsClose( void ); @@ -129,8 +130,56 @@ mut_user_time_during_heap_census( void ) } #endif /* PROFILING */ +// initStats0() has no dependencies, it can be called right at the beginning +void +initStats0(void) +{ + ElapsedTimeStart = 0; + + InitUserTime = 0; + InitElapsedTime = 0; + InitElapsedStamp = 0; + + MutUserTime = 0; + MutElapsedTime = 0; + MutElapsedStamp = 0; + + ExitUserTime = 0; + ExitElapsedTime = 0; + + GC_tot_alloc = 0; + GC_tot_copied = 0; + GC_par_max_copied = 0; + GC_par_avg_copied = 0; + GC_start_time = 0; + GC_tot_time = 0; + GCe_start_time = 0; + GCe_tot_time = 0; + +#ifdef PROFILING + RP_start_time = 0; + RP_tot_time = 0; + RPe_start_time = 0; + RPe_tot_time = 0; + + HC_start_time = 0; + HC_tot_time = 0; + HCe_start_time = 0; + HCe_tot_time = 0; +#endif + + MaxResidency = 0; + AvgResidency = 0; + ResidencySamples = 0; + MaxSlop = 0; + + GC_start_faults = 0; + GC_end_faults = 0; +} + +// initStats1() can be called after setupRtsFlags() void -initStats(void) +initStats1 (void) { nat i; @@ -150,7 +199,7 @@ initStats(void) GC_coll_times[i] = 0; GC_coll_etimes[i] = 0; } -} +} /* ----------------------------------------------------------------------------- Initialisation time... @@ -294,7 +343,8 @@ stat_startGC(void) -------------------------------------------------------------------------- */ void -stat_endGC (lnat alloc, lnat live, lnat copied, lnat gen) +stat_endGC (lnat alloc, lnat live, lnat copied, lnat gen, + lnat max_copied, lnat avg_copied, lnat slop) { if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) { Ticks time, etime, gc_time, gc_etime; @@ -327,6 +377,8 @@ stat_endGC (lnat alloc, lnat live, lnat copied, lnat gen) GC_tot_copied += (ullong) copied; GC_tot_alloc += (ullong) alloc; + GC_par_max_copied += (ullong) max_copied; + GC_par_avg_copied += (ullong) avg_copied; GC_tot_time += gc_time; GCe_tot_time += gc_etime; @@ -347,6 +399,8 @@ stat_endGC (lnat alloc, lnat live, lnat copied, lnat gen) ResidencySamples++; AvgResidency += live; } + + if (slop > MaxSlop) MaxSlop = slop; } if (rub_bell) { @@ -451,21 +505,11 @@ stat_endHeapCensus(void) -------------------------------------------------------------------------- */ #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) @@ -495,6 +539,7 @@ StgInt TOTAL_CALLS=1; statsPrintf(" (SLOW_CALLS_" #arity ") %% of (TOTAL_CALLS) : %.1f%%\n", \ SLOW_CALLS_##arity * 100.0/TOTAL_CALLS) +extern lnat hw_alloc_blocks; void stat_exit(int alloc) @@ -527,48 +572,81 @@ stat_exit(int alloc) if (RtsFlags.GcFlags.giveStats >= SUMMARY_GC_STATS) { ullong_format_string(GC_tot_alloc*sizeof(W_), temp, rtsTrue/*commas*/); - statsPrintf("%11s bytes allocated in the heap\n", temp); + statsPrintf("%16s bytes allocated in the heap\n", temp); ullong_format_string(GC_tot_copied*sizeof(W_), temp, rtsTrue/*commas*/); - statsPrintf("%11s bytes copied during GC\n", temp); + statsPrintf("%16s bytes copied during GC\n", temp); if ( ResidencySamples > 0 ) { ullong_format_string(MaxResidency*sizeof(W_), temp, rtsTrue/*commas*/); - statsPrintf("%11s bytes maximum residency (%ld sample(s))\n", + statsPrintf("%16s bytes maximum residency (%ld sample(s))\n", temp, ResidencySamples); } - statsPrintf("\n"); + + ullong_format_string(MaxSlop*sizeof(W_), temp, rtsTrue/*commas*/); + statsPrintf("%16s bytes maximum slop\n", temp); + + statsPrintf("%16ld MB total memory in use (%ld MB lost due to fragmentation)\n\n", + mblocks_allocated * MBLOCK_SIZE_W / (1024 * 1024 / sizeof(W_)), + (mblocks_allocated * MBLOCK_SIZE_W - hw_alloc_blocks * BLOCK_SIZE_W) / (1024 * 1024 / sizeof(W_))); /* Print garbage collections in each gen */ for (g = 0; g < RtsFlags.GcFlags.generations; g++) { - statsPrintf("%11d collections in generation %d, %6.2fs, %6.2fs elapsed\n", - generations[g].collections, g, + statsPrintf(" Generation %d: %5d collections, %5d parallel, %5.2fs, %5.2fs elapsed\n", + g, generations[g].collections, + generations[g].par_collections, TICK_TO_DBL(GC_coll_times[g]), TICK_TO_DBL(GC_coll_etimes[g])); } - statsPrintf("\n%11ld MB total memory in use\n\n", - mblocks_allocated * MBLOCK_SIZE / (1024 * 1024)); +#if defined(THREADED_RTS) + if (RtsFlags.ParFlags.parGcEnabled) { + statsPrintf("\n Parallel GC work balance: %.2f (%ld / %ld, ideal %d)\n", + (double)GC_par_avg_copied / (double)GC_par_max_copied, + (lnat)GC_par_avg_copied, (lnat)GC_par_max_copied, + RtsFlags.ParFlags.nNodes + ); + } +#endif + + statsPrintf("\n"); #if defined(THREADED_RTS) { nat i; Task *task; + statsPrintf(" MUT time (elapsed) GC time (elapsed)\n"); for (i = 0, task = all_tasks; task != NULL; i++, task = task->all_link) { - statsPrintf(" Task %2d %-8s : MUT time: %6.2fs (%6.2fs elapsed)\n" - " GC time: %6.2fs (%6.2fs elapsed)\n\n", + statsPrintf(" Task %2d %-8s : %6.2fs (%6.2fs) %6.2fs (%6.2fs)\n", i, - (task->tso == NULL) ? "(worker)" : "(bound)", + (task->worker) ? "(worker)" : "(bound)", TICK_TO_DBL(task->mut_time), TICK_TO_DBL(task->mut_etime), TICK_TO_DBL(task->gc_time), TICK_TO_DBL(task->gc_etime)); } } + + statsPrintf("\n"); + + { + nat i; + lnat sparks_created = 0; + lnat sparks_converted = 0; + lnat sparks_pruned = 0; + for (i = 0; i < n_capabilities; i++) { + sparks_created += capabilities[i].sparks_created; + sparks_converted += capabilities[i].sparks_converted; + sparks_pruned += capabilities[i].sparks_pruned; + } + + statsPrintf(" SPARKS: %ld (%ld converted, %ld pruned)\n\n", + sparks_created, sparks_converted, sparks_pruned); + } #endif statsPrintf(" INIT time %6.2fs (%6.2fs elapsed)\n", @@ -621,12 +699,43 @@ stat_exit(int alloc) #if USE_PAPI papi_stats_report(); #endif +#if defined(THREADED_RTS) && defined(PROF_SPIN) + { + nat g; + + 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++) { + statsPrintf("gen[%d].sync_large_objects: %"FMT_Word64"\n", g, generations[g].sync_large_objects.spin); + } + } +#endif } if (RtsFlags.GcFlags.giveStats == ONELINE_GC_STATS) { + char *fmt1, *fmt2; + if (RtsFlags.MiscFlags.machineReadable) { + fmt1 = " [(\"bytes allocated\", \"%llu\")\n"; + fmt2 = " ,(\"num_GCs\", \"%d\")\n" + " ,(\"average_bytes_used\", \"%ld\")\n" + " ,(\"max_bytes_used\", \"%ld\")\n" + " ,(\"num_byte_usage_samples\", \"%ld\")\n" + " ,(\"peak_megabytes_allocated\", \"%lu\")\n" + " ,(\"init_cpu_seconds\", \"%.2f\")\n" + " ,(\"init_wall_seconds\", \"%.2f\")\n" + " ,(\"mutator_cpu_seconds\", \"%.2f\")\n" + " ,(\"mutator_wall_seconds\", \"%.2f\")\n" + " ,(\"GC_cpu_seconds\", \"%.2f\")\n" + " ,(\"GC_wall_seconds\", \"%.2f\")\n" + " ]\n"; + } + else { + fmt1 = "<>\n", + statsPrintf(fmt1, GC_tot_alloc*(ullong)sizeof(W_)); + statsPrintf(fmt2, total_collections, ResidencySamples == 0 ? 0 : AvgResidency*sizeof(W_)/ResidencySamples, @@ -641,26 +750,13 @@ stat_exit(int alloc) statsFlush(); statsClose(); } + if (GC_coll_times) stgFree(GC_coll_times); GC_coll_times = NULL; - -#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("static_objects_sync: %"FMT_Word64"\n", static_objects_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 + if (GC_coll_etimes) + stgFree(GC_coll_etimes); + GC_coll_etimes = NULL; } /* ----------------------------------------------------------------------------- @@ -671,41 +767,43 @@ stat_exit(int alloc) void statDescribeGens(void) { - nat g, s, mut, lge; - lnat live; + nat g, mut, lge; + lnat live, slop; + lnat tot_live, tot_slop; bdescr *bd; - step *step; - + generation *gen; + debugBelch( -" Gen Steps Max Mut-list Step Blocks Live Large\n" -" Blocks Bytes Objects\n"); +"----------------------------------------------------------\n" +" Gen Max Mut-list 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); + gen = &generations[g]; - 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++; - } - // 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. - live += countOccupied(step->blocks) + countOccupied(step->large_objects); - if (s != 0) { - debugBelch("%36s",""); + debugBelch("%5d %7d %9d", g, gen->max_blocks, mut); + + for (bd = gen->large_objects, lge = 0; bd; bd = bd->link) { + lge++; } - debugBelch("%6d %8d %8ld %8d\n", s, step->n_blocks, - live, lge); - } + live = gen->n_words + countOccupied(gen->large_objects); + slop = (gen->n_blocks + gen->n_large_blocks) * BLOCK_SIZE_W - live; + debugBelch("%8d %8d %8ld %8ld\n", gen->n_blocks, lge, + live*sizeof(W_), slop*sizeof(W_)); + tot_live += live; + tot_slop += slop; } + debugBelch("----------------------------------------------------------\n"); + debugBelch("%41s%8ld %8ld\n","",tot_live*sizeof(W_),tot_slop*sizeof(W_)); + debugBelch("----------------------------------------------------------\n"); debugBelch("\n"); } @@ -715,7 +813,7 @@ statDescribeGens(void) -------------------------------------------------------------------------- */ extern HsInt64 getAllocations( void ) -{ return (HsInt64)total_allocated * sizeof(W_); } +{ return (HsInt64)GC_tot_alloc * sizeof(W_); } /* ----------------------------------------------------------------------------- Dumping stuff in the stats file, or via the debug message interface