X-Git-Url: http://git.megacz.com/?p=ghc-hetmet.git;a=blobdiff_plain;f=rts%2FStats.c;h=f18e26fbd578591b22cbbb3775134b76a69065cc;hp=28d09bdbedea1bdd15c4e93df873e3776f3c9903;hb=ff073cf32346caaa00f2c15161c88de6a3c5f8db;hpb=0065d5ab628975892cea1ec7303f968c3338cbe1 diff --git a/rts/Stats.c b/rts/Stats.c index 28d09bd..f18e26f 100644 --- a/rts/Stats.c +++ b/rts/Stats.c @@ -10,13 +10,17 @@ #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 @@ -64,9 +68,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 ); @@ -75,6 +76,11 @@ Ticks stat_getElapsedGCTime(void) return GCe_tot_time; } +Ticks stat_getElapsedTime(void) +{ + return getProcessElapsedTime() - ElapsedTimeStart; +} + /* mut_user_time_during_GC() and mut_user_time() * * The former function can be used to get the current mutator time @@ -165,6 +171,18 @@ stat_endInit(void) } else { 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. */ + papi_start_mutator_count(); + + /* This flag is needed to avoid counting the last GC */ + papi_is_reporting = 1; + +#endif } /* ----------------------------------------------------------------------------- @@ -187,6 +205,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 @@ -244,6 +272,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 + } /* ----------------------------------------------------------------------------- @@ -311,6 +348,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 } /* ----------------------------------------------------------------------------- @@ -396,6 +441,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) { @@ -512,6 +603,27 @@ 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 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); +#endif } if (RtsFlags.GcFlags.giveStats == ONELINE_GC_STATS) { @@ -532,6 +644,9 @@ stat_exit(int alloc) statsFlush(); statsClose(); } + if (GC_coll_times) + stgFree(GC_coll_times); + GC_coll_times = NULL; } /* ----------------------------------------------------------------------------- @@ -549,13 +664,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, @@ -578,7 +693,7 @@ statDescribeGens(void) if (s != 0) { debugBelch("%36s",""); } - debugBelch("%6d %8d %8d %8d\n", s, step->n_blocks, + debugBelch("%6d %8d %8ld %8d\n", s, step->n_blocks, live, lge); } } @@ -598,7 +713,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;