/* ----------------------------------------------------------------------------- * * (c) The GHC Team, 1998-2005 * * Statistics and timing-related functions. * * ---------------------------------------------------------------------------*/ #include "PosixSource.h" #include "Rts.h" #include "RtsFlags.h" #include "RtsUtils.h" #include "Schedule.h" #include "Stats.h" #include "Profiling.h" #include "GetTime.h" #include "sm/Storage.h" #include "sm/GCThread.h" #include "sm/BlockAlloc.h" // for spin/yield counters #include "sm/GC.h" #include "ThreadPaused.h" #include "Messages.h" #include // for memset #define TimeToSecondsDbl(t) ((double)(t) / TIME_RESOLUTION) static Time start_init_cpu, start_init_elapsed, end_init_cpu, end_init_elapsed, start_exit_cpu, start_exit_elapsed, start_exit_gc_elapsed, start_exit_gc_cpu, end_exit_cpu, end_exit_elapsed; #if defined(PROFILING) static Time RP_start_time = 0, RP_tot_time = 0; // retainer prof user time static Time RPe_start_time = 0, RPe_tot_time = 0; // retainer prof elap time static Time HC_start_time, HC_tot_time = 0; // heap census prof user time static Time HCe_start_time, HCe_tot_time = 0; // heap census prof elap time #endif #if defined(PROF_SPIN) volatile StgWord64 whitehole_lockClosure_spin = 0; volatile StgWord64 whitehole_lockClosure_yield = 0; volatile StgWord64 whitehole_threadPaused_spin = 0; volatile StgWord64 whitehole_executeMessage_spin = 0; #endif // // All the stats! // // This is where we accumulate all the stats during execution, and it's also // in a convenient form that we can copy over to a caller of getRTSStats(). // static RTSStats stats; static W_ GC_end_faults = 0; static Time *GC_coll_cpu = NULL; static Time *GC_coll_elapsed = NULL; static Time *GC_coll_max_pause = NULL; static void statsPrintf( char *s, ... ) GNUC3_ATTRIBUTE(format (PRINTF, 1, 2)); static void statsFlush( void ); static void statsClose( void ); /* ----------------------------------------------------------------------------- Current elapsed time ------------------------------------------------------------------------- */ Time stat_getElapsedTime(void) { return getProcessElapsedTime() - start_init_elapsed; } /* --------------------------------------------------------------------------- Measure the current MUT time, for profiling ------------------------------------------------------------------------ */ double mut_user_time_until( Time t ) { return TimeToSecondsDbl(t - stats.gc_cpu_ns); // heapCensus() time is included in GC_tot_cpu, so we don't need // to subtract it here. // TODO: This seems wrong to me. Surely we should be subtracting // (at least) start_init_cpu? } double mut_user_time( void ) { Time cpu; cpu = getProcessCPUTime(); return mut_user_time_until(cpu); } #if defined(PROFILING) /* mut_user_time_during_RP() returns the MUT time during retainer profiling. The same is for mut_user_time_during_HC(); */ static double mut_user_time_during_RP( void ) { return TimeToSecondsDbl(RP_start_time - stats.gc_cpu_ns - RP_tot_time); } #endif /* PROFILING */ /* --------------------------------------------------------------------------- initStats0() has no dependencies, it can be called right at the beginning ------------------------------------------------------------------------ */ void initStats0(void) { start_init_cpu = 0; start_init_elapsed = 0; end_init_cpu = 0; end_init_elapsed = 0; start_exit_cpu = 0; start_exit_elapsed = 0; start_exit_gc_cpu = 0; start_exit_gc_elapsed = 0; end_exit_cpu = 0; end_exit_elapsed = 0; #if defined(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 GC_end_faults = 0; stats = (RTSStats) { .gcs = 0, .major_gcs = 0, .allocated_bytes = 0, .max_live_bytes = 0, .max_large_objects_bytes = 0, .max_compact_bytes = 0, .max_slop_bytes = 0, .max_mem_in_use_bytes = 0, .cumulative_live_bytes = 0, .copied_bytes = 0, .par_copied_bytes = 0, .cumulative_par_max_copied_bytes = 0, .cumulative_par_balanced_copied_bytes = 0, .gc_spin_spin = 0, .gc_spin_yield = 0, .mut_spin_spin = 0, .mut_spin_yield = 0, .any_work = 0, .no_work = 0, .scav_find_work = 0, .init_cpu_ns = 0, .init_elapsed_ns = 0, .mutator_cpu_ns = 0, .mutator_elapsed_ns = 0, .gc_cpu_ns = 0, .gc_elapsed_ns = 0, .cpu_ns = 0, .elapsed_ns = 0, .gc = { .gen = 0, .threads = 0, .allocated_bytes = 0, .live_bytes = 0, .large_objects_bytes = 0, .compact_bytes = 0, .slop_bytes = 0, .mem_in_use_bytes = 0, .copied_bytes = 0, .par_max_copied_bytes = 0, .par_balanced_copied_bytes = 0, .sync_elapsed_ns = 0, .cpu_ns = 0, .elapsed_ns = 0 } }; } /* --------------------------------------------------------------------------- initStats1() can be called after setupRtsFlags() ------------------------------------------------------------------------ */ void initGenerationStats(void); void initStats1 (void) { if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) { statsPrintf(" Alloc Copied Live GC GC TOT TOT Page Flts\n"); statsPrintf(" bytes bytes bytes user elap user elap\n"); } GC_coll_cpu = (Time *)stgMallocBytes( sizeof(Time)*RtsFlags.GcFlags.generations, "initStats"); GC_coll_elapsed = (Time *)stgMallocBytes( sizeof(Time)*RtsFlags.GcFlags.generations, "initStats"); GC_coll_max_pause = (Time *)stgMallocBytes( sizeof(Time)*RtsFlags.GcFlags.generations, "initStats"); initGenerationStats(); } void initGenerationStats() { for (uint32_t i = 0; i < RtsFlags.GcFlags.generations; i++) { GC_coll_cpu[i] = 0; GC_coll_elapsed[i] = 0; GC_coll_max_pause[i] = 0; } } /* --------------------------------------------------------------------------- Reset stats of child process after fork() ------------------------------------------------------------------------ */ void resetChildProcessStats() { initStats0(); initGenerationStats(); } /* ----------------------------------------------------------------------------- Initialisation time... -------------------------------------------------------------------------- */ void stat_startInit(void) { getProcessTimes(&start_init_cpu, &start_init_elapsed); } void stat_endInit(void) { getProcessTimes(&end_init_cpu, &end_init_elapsed); stats.init_cpu_ns = end_init_cpu - start_init_cpu; stats.init_elapsed_ns = end_init_elapsed - start_init_elapsed; } /* ----------------------------------------------------------------------------- stat_startExit and stat_endExit These two measure the time taken in shutdownHaskell(). -------------------------------------------------------------------------- */ void stat_startExit(void) { getProcessTimes(&start_exit_cpu, &start_exit_elapsed); start_exit_gc_elapsed = stats.gc_elapsed_ns; start_exit_gc_cpu = stats.gc_cpu_ns; } void stat_endExit(void) { getProcessTimes(&end_exit_cpu, &end_exit_elapsed); } void stat_startGCSync (gc_thread *gct) { gct->gc_sync_start_elapsed = getProcessElapsedTime(); } /* ----------------------------------------------------------------------------- Called at the beginning of each GC -------------------------------------------------------------------------- */ void stat_startGC (Capability *cap, gc_thread *gct) { if (RtsFlags.GcFlags.ringBell) { debugBelch("\007"); } getProcessTimes(&gct->gc_start_cpu, &gct->gc_start_elapsed); // Post EVENT_GC_START with the same timestamp as used for stats // (though converted from Time=StgInt64 to EventTimestamp=StgWord64). // Here, as opposed to other places, the event is emitted on the cap // that initiates the GC and external tools expect it to have the same // timestamp as used in +RTS -s calculcations. traceEventGcStartAtT(cap, TimeToNS(gct->gc_start_elapsed - start_init_elapsed)); if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) { gct->gc_start_faults = getPageFaults(); } updateNurseriesStats(); } /* ----------------------------------------------------------------------------- Called at the end of each GC -------------------------------------------------------------------------- */ void stat_endGC (Capability *cap, gc_thread *gct, W_ live, W_ copied, W_ slop, uint32_t gen, uint32_t par_n_threads, W_ par_max_copied, W_ par_balanced_copied, W_ gc_spin_spin, W_ gc_spin_yield, W_ mut_spin_spin, W_ mut_spin_yield, W_ any_work, W_ no_work, W_ scav_find_work) { // ------------------------------------------------- // Collect all the stats about this GC in stats.gc. We always do this since // it's relatively cheap and we need allocated_bytes to catch heap // overflows. stats.gc.gen = gen; stats.gc.threads = par_n_threads; uint64_t tot_alloc_bytes = calcTotalAllocated() * sizeof(W_); // allocated since the last GC stats.gc.allocated_bytes = tot_alloc_bytes - stats.allocated_bytes; stats.gc.live_bytes = live * sizeof(W_); stats.gc.large_objects_bytes = calcTotalLargeObjectsW() * sizeof(W_); stats.gc.compact_bytes = calcTotalCompactW() * sizeof(W_); stats.gc.slop_bytes = slop * sizeof(W_); stats.gc.mem_in_use_bytes = mblocks_allocated * MBLOCK_SIZE; stats.gc.copied_bytes = copied * sizeof(W_); stats.gc.par_max_copied_bytes = par_max_copied * sizeof(W_); stats.gc.par_balanced_copied_bytes = par_balanced_copied * sizeof(W_); bool stats_enabled = RtsFlags.GcFlags.giveStats != NO_GC_STATS || rtsConfig.gcDoneHook != NULL; if (stats_enabled || RtsFlags.ProfFlags.doHeapProfile) // heap profiling needs GC_tot_time { // We only update the times when stats are explicitly enabled since // getProcessTimes (e.g. requiring a system call) can be expensive on // some platforms. Time current_cpu, current_elapsed; getProcessTimes(¤t_cpu, ¤t_elapsed); stats.cpu_ns = current_cpu - start_init_cpu; stats.elapsed_ns = current_elapsed - start_init_elapsed; stats.gc.sync_elapsed_ns = gct->gc_start_elapsed - gct->gc_sync_start_elapsed; stats.gc.elapsed_ns = current_elapsed - gct->gc_start_elapsed; stats.gc.cpu_ns = current_cpu - gct->gc_start_cpu; } // ------------------------------------------------- // Update the cumulative stats stats.gcs++; stats.allocated_bytes = tot_alloc_bytes; stats.max_mem_in_use_bytes = peak_mblocks_allocated * MBLOCK_SIZE; GC_coll_cpu[gen] += stats.gc.cpu_ns; GC_coll_elapsed[gen] += stats.gc.elapsed_ns; if (GC_coll_max_pause[gen] < stats.gc.elapsed_ns) { GC_coll_max_pause[gen] = stats.gc.elapsed_ns; } stats.copied_bytes += stats.gc.copied_bytes; if (par_n_threads > 1) { stats.par_copied_bytes += stats.gc.copied_bytes; stats.cumulative_par_max_copied_bytes += stats.gc.par_max_copied_bytes; stats.cumulative_par_balanced_copied_bytes += stats.gc.par_balanced_copied_bytes; stats.any_work += any_work; stats.no_work += no_work; stats.scav_find_work += scav_find_work; stats.gc_spin_spin += gc_spin_spin; stats.gc_spin_yield += gc_spin_yield; stats.mut_spin_spin += mut_spin_spin; stats.mut_spin_yield += mut_spin_yield; } stats.gc_cpu_ns += stats.gc.cpu_ns; stats.gc_elapsed_ns += stats.gc.elapsed_ns; if (gen == RtsFlags.GcFlags.generations-1) { // major GC? stats.major_gcs++; if (stats.gc.live_bytes > stats.max_live_bytes) { stats.max_live_bytes = stats.gc.live_bytes; } if (stats.gc.large_objects_bytes > stats.max_large_objects_bytes) { stats.max_large_objects_bytes = stats.gc.large_objects_bytes; } if (stats.gc.compact_bytes > stats.max_compact_bytes) { stats.max_compact_bytes = stats.gc.compact_bytes; } if (stats.gc.slop_bytes > stats.max_slop_bytes) { stats.max_slop_bytes = stats.gc.slop_bytes; } stats.cumulative_live_bytes += stats.gc.live_bytes; } // ------------------------------------------------- // Do the more expensive bits only when stats are enabled. if (stats_enabled) { // ------------------------------------------------- // Emit events to the event log // Has to be emitted while all caps stopped for GC, but before GC_END. // See trac.haskell.org/ThreadScope/wiki/RTSsummaryEvents // for a detailed design rationale of the current setup // of GC eventlog events. traceEventGcGlobalSync(cap); // Emitted before GC_END on all caps, which simplifies tools code. traceEventGcStats(cap, CAPSET_HEAP_DEFAULT, stats.gc.gen, stats.gc.copied_bytes, stats.gc.slop_bytes, /* current loss due to fragmentation */ (mblocks_allocated * BLOCKS_PER_MBLOCK - n_alloc_blocks) * BLOCK_SIZE, par_n_threads, stats.gc.par_max_copied_bytes, stats.gc.copied_bytes, stats.gc.par_balanced_copied_bytes); // Post EVENT_GC_END with the same timestamp as used for stats // (though converted from Time=StgInt64 to EventTimestamp=StgWord64). // Here, as opposed to other places, the event is emitted on the cap // that initiates the GC and external tools expect it to have the same // timestamp as used in +RTS -s calculcations. traceEventGcEndAtT(cap, TimeToNS(stats.elapsed_ns)); if (gen == RtsFlags.GcFlags.generations-1) { // major GC? traceEventHeapLive(cap, CAPSET_HEAP_DEFAULT, stats.gc.live_bytes); } // ------------------------------------------------- // Print GC stats to stdout or a file (+RTS -S/-s) if (RtsFlags.GcFlags.giveStats == VERBOSE_GC_STATS) { W_ faults = getPageFaults(); statsPrintf("%9" FMT_Word64 " %9" FMT_Word64 " %9" FMT_Word64, stats.gc.allocated_bytes, stats.gc.copied_bytes, stats.gc.live_bytes); statsPrintf(" %6.3f %6.3f %8.3f %8.3f %4" FMT_Word " %4" FMT_Word " (Gen: %2d)\n", TimeToSecondsDbl(stats.gc.cpu_ns), TimeToSecondsDbl(stats.gc.elapsed_ns), TimeToSecondsDbl(stats.cpu_ns), TimeToSecondsDbl(stats.elapsed_ns), faults - gct->gc_start_faults, gct->gc_start_faults - GC_end_faults, gen); GC_end_faults = faults; statsFlush(); } if (rtsConfig.gcDoneHook != NULL) { rtsConfig.gcDoneHook(&stats.gc); } traceEventHeapSize(cap, CAPSET_HEAP_DEFAULT, mblocks_allocated * MBLOCK_SIZE); } } /* ----------------------------------------------------------------------------- Called at the beginning of each Retainer Profiliing -------------------------------------------------------------------------- */ #if defined(PROFILING) void stat_startRP(void) { Time user, elapsed; getProcessTimes( &user, &elapsed ); RP_start_time = user; RPe_start_time = elapsed; } #endif /* PROFILING */ /* ----------------------------------------------------------------------------- Called at the end of each Retainer Profiliing -------------------------------------------------------------------------- */ #if defined(PROFILING) void stat_endRP( uint32_t retainerGeneration, #if defined(DEBUG_RETAINER) uint32_t maxCStackSize, int maxStackSize, #endif double averageNumVisit) { Time user, elapsed; getProcessTimes( &user, &elapsed ); RP_tot_time += user - RP_start_time; RPe_tot_time += elapsed - RPe_start_time; fprintf(prof_file, "Retainer Profiling: %d, at %f seconds\n", retainerGeneration, mut_user_time_during_RP()); #if defined(DEBUG_RETAINER) fprintf(prof_file, "\tMax C stack size = %u\n", maxCStackSize); fprintf(prof_file, "\tMax auxiliary stack size = %u\n", maxStackSize); #endif fprintf(prof_file, "\tAverage number of visits per object = %f\n", averageNumVisit); } #endif /* PROFILING */ /* ----------------------------------------------------------------------------- Called at the beginning of each heap census -------------------------------------------------------------------------- */ #if defined(PROFILING) void stat_startHeapCensus(void) { Time user, elapsed; getProcessTimes( &user, &elapsed ); HC_start_time = user; HCe_start_time = elapsed; } #endif /* PROFILING */ /* ----------------------------------------------------------------------------- Called at the end of each heap census -------------------------------------------------------------------------- */ #if defined(PROFILING) void stat_endHeapCensus(void) { Time user, elapsed; getProcessTimes( &user, &elapsed ); HC_tot_time += user - HC_start_time; HCe_tot_time += elapsed - HCe_start_time; } #endif /* PROFILING */ /* ----------------------------------------------------------------------------- Called at the end of execution NOTE: number of allocations is not entirely accurate: it doesn't take into account the few bytes at the end of the heap that were left unused when the heap-check failed. -------------------------------------------------------------------------- */ #if defined(DEBUG) #define TICK_VAR_INI(arity) \ StgInt SLOW_CALLS_##arity = 1; \ StgInt RIGHT_ARITY_##arity = 1; \ StgInt TAGGED_PTR_##arity = 0; TICK_VAR_INI(1) TICK_VAR_INI(2) StgInt TOTAL_CALLS=1; #endif /* Report the value of a counter */ #define REPORT(counter) \ { \ showStgWord64(counter,temp,true/*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) /* Note [RTS Stats Reporting] ========================== There are currently three reporting functions: * report_summary: Responsible for producing '+RTS -s' output. Will report internal counters if the RTS flag --internal-counters is passed. See [Internal Counters Stats] * report_machine_readable: Responsible for producing '+RTS -t --machine-readable' output. * report_one_line: Responsible for productin '+RTS -t' output Stats are accumulated into the global variable 'stats' as the program runs, then in 'stat_exit' we do the following: * Finalise 'stats'. This involves setting final running times and allocations that have not yet been accounted for. * Create a RTSSummaryStats. This contains all data for reports that is not included in stats (because they do not make sense before the program has completed) or in a global variable. * call the appropriate report_* function, passing the newly constructed RTSSummaryStats. To ensure that the data in the different reports is kept consistent, the report_* functions should not do any calculation, excepting unit changes and formatting. If you need to add a new calculated field, add it to RTSSummaryStats. */ static void init_RTSSummaryStats(RTSSummaryStats* sum) { const size_t sizeof_gc_summary_stats = RtsFlags.GcFlags.generations * sizeof(GenerationSummaryStats); memset(sum, 0, sizeof(RTSSummaryStats)); sum->gc_summary_stats = stgMallocBytes(sizeof_gc_summary_stats, "alloc_RTSSummaryStats.gc_summary_stats"); memset(sum->gc_summary_stats, 0, sizeof_gc_summary_stats); } static void free_RTSSummaryStats(RTSSummaryStats * sum) { stgFree(sum->gc_summary_stats); sum->gc_summary_stats = NULL; } static void report_summary(const RTSSummaryStats* sum) { // We should do no calculation, other than unit changes and formatting, and // we should not not use any data from outside of globals, sum and stats // here. See Note [RTS Stats Reporting] uint32_t g; char temp[512]; showStgWord64(stats.allocated_bytes, temp, true/*commas*/); statsPrintf("%16s bytes allocated in the heap\n", temp); showStgWord64(stats.copied_bytes, temp, true/*commas*/); statsPrintf("%16s bytes copied during GC\n", temp); if ( stats.major_gcs > 0 ) { showStgWord64(stats.max_live_bytes, temp, true/*commas*/); statsPrintf("%16s bytes maximum residency (%" FMT_Word32 " sample(s))\n", temp, stats.major_gcs); } showStgWord64(stats.max_slop_bytes, temp, true/*commas*/); statsPrintf("%16s bytes maximum slop\n", temp); statsPrintf("%16" FMT_Word64 " MB total memory in use (%" FMT_Word64 " MB lost due to fragmentation)\n\n", stats.max_live_bytes / (1024 * 1024), sum->fragmentation_bytes / (1024 * 1024)); /* Print garbage collections in each gen */ statsPrintf(" Tot time (elapsed) Avg pause Max pause\n"); for (g = 0; g < RtsFlags.GcFlags.generations; g++) { const GenerationSummaryStats * gen_stats = &sum->gc_summary_stats[g]; statsPrintf(" Gen %2d %5d colls" ", %5d par %6.3fs %6.3fs %3.4fs %3.4fs\n", g, // REVIEWERS: this used to be gen->no //, this can't ever be different right? gen_stats->collections, gen_stats->par_collections, TimeToSecondsDbl(gen_stats->cpu_ns), TimeToSecondsDbl(gen_stats->elapsed_ns), TimeToSecondsDbl(gen_stats->avg_pause_ns), TimeToSecondsDbl(gen_stats->max_pause_ns)); } statsPrintf("\n"); #if defined(THREADED_RTS) if (RtsFlags.ParFlags.parGcEnabled && sum->work_balance > 0) { // See Note [Work Balance] statsPrintf(" Parallel GC work balance: " "%.2f%% (serial 0%%, perfect 100%%)\n\n", sum->work_balance * 100); } statsPrintf(" TASKS: %d " "(%d bound, %d peak workers (%d total), using -N%d)\n\n", taskCount, sum->bound_task_count, peakWorkerCount, workerCount, n_capabilities); statsPrintf(" SPARKS: %" FMT_Word64 " (%" FMT_Word " converted, %" FMT_Word " overflowed, %" FMT_Word " dud, %" FMT_Word " GC'd, %" FMT_Word " fizzled)\n\n", sum->sparks_count, sum->sparks.converted, sum->sparks.overflowed, sum->sparks.dud, sum->sparks.gcd, sum->sparks.fizzled); #endif statsPrintf(" INIT time %7.3fs (%7.3fs elapsed)\n", TimeToSecondsDbl(stats.init_cpu_ns), TimeToSecondsDbl(stats.init_elapsed_ns)); statsPrintf(" MUT time %7.3fs (%7.3fs elapsed)\n", TimeToSecondsDbl(stats.mutator_cpu_ns), TimeToSecondsDbl(stats.mutator_elapsed_ns)); statsPrintf(" GC time %7.3fs (%7.3fs elapsed)\n", TimeToSecondsDbl(stats.gc_cpu_ns), TimeToSecondsDbl(stats.gc_elapsed_ns)); #if defined(PROFILING) statsPrintf(" RP time %7.3fs (%7.3fs elapsed)\n", TimeToSecondsDbl(sum->rp_cpu_ns), TimeToSecondsDbl(sum->rp_elapsed_ns)); statsPrintf(" PROF time %7.3fs (%7.3fs elapsed)\n", TimeToSecondsDbl(sum->hc_cpu_ns), TimeToSecondsDbl(sum->hc_elapsed_ns)); #endif statsPrintf(" EXIT time %7.3fs (%7.3fs elapsed)\n", TimeToSecondsDbl(sum->exit_cpu_ns), TimeToSecondsDbl(sum->exit_elapsed_ns)); statsPrintf(" Total time %7.3fs (%7.3fs elapsed)\n\n", TimeToSecondsDbl(stats.cpu_ns), TimeToSecondsDbl(stats.elapsed_ns)); #if !defined(THREADED_RTS) statsPrintf(" %%GC time %5.1f%% (%.1f%% elapsed)\n\n", sum->gc_cpu_percent * 100, sum->gc_elapsed_percent * 100); #endif showStgWord64(sum->alloc_rate, temp, true/*commas*/); statsPrintf(" Alloc rate %s bytes per MUT second\n\n", temp); statsPrintf(" Productivity %5.1f%% of total user, " "%.1f%% of total elapsed\n\n", sum->productivity_cpu_percent * 100, sum->productivity_elapsed_percent * 100); // See Note [Internal Counter Stats] for a description of the // following counters. If you add a counter here, please remember // to update the Note. if (RtsFlags.MiscFlags.internalCounters) { #if defined(THREADED_RTS) && defined(PROF_SPIN) const int32_t col_width[] = {4, -30, 14, 14}; statsPrintf("Internal Counters:\n"); statsPrintf("%*s" "%*s" "%*s" "%*s" "\n" , col_width[0], "" , col_width[1], "SpinLock" , col_width[2], "Spins" , col_width[3], "Yields"); statsPrintf("%*s" "%*s" "%*" FMT_Word64 "%*" FMT_Word64 "\n" , col_width[0], "" , col_width[1], "gc_alloc_block_sync" , col_width[2], gc_alloc_block_sync.spin , col_width[3], gc_alloc_block_sync.yield); statsPrintf("%*s" "%*s" "%*" FMT_Word64 "%*" FMT_Word64 "\n" , col_width[0], "" , col_width[1], "gc_spin" , col_width[2], stats.gc_spin_spin , col_width[3], stats.gc_spin_yield); statsPrintf("%*s" "%*s" "%*" FMT_Word64 "%*" FMT_Word64 "\n" , col_width[0], "" , col_width[1], "mut_spin" , col_width[2], stats.mut_spin_spin , col_width[3], stats.mut_spin_yield); statsPrintf("%*s" "%*s" "%*" FMT_Word64 "%*s\n" , col_width[0], "" , col_width[1], "whitehole_gc" , col_width[2], whitehole_gc_spin , col_width[3], "n/a"); statsPrintf("%*s" "%*s" "%*" FMT_Word64 "%*s\n" , col_width[0], "" , col_width[1], "whitehole_threadPaused" , col_width[2], whitehole_threadPaused_spin , col_width[3], "n/a"); statsPrintf("%*s" "%*s" "%*" FMT_Word64 "%*s\n" , col_width[0], "" , col_width[1], "whitehole_executeMessage" , col_width[2], whitehole_executeMessage_spin , col_width[3], "n/a"); statsPrintf("%*s" "%*s" "%*" FMT_Word64 "%*" FMT_Word64 "\n" , col_width[0], "" , col_width[1], "whitehole_lockClosure" , col_width[2], whitehole_lockClosure_spin , col_width[3], whitehole_lockClosure_yield); // waitForGcThreads isn't really spin-locking(see the function) // but these numbers still seem useful. statsPrintf("%*s" "%*s" "%*" FMT_Word64 "%*" FMT_Word64 "\n" , col_width[0], "" , col_width[1], "waitForGcThreads" , col_width[2], waitForGcThreads_spin , col_width[3], waitForGcThreads_yield); for (g = 0; g < RtsFlags.GcFlags.generations; g++) { int prefix_length = 0; statsPrintf("%*s" "gen[%" FMT_Word32 "%n", col_width[0], "", g, &prefix_length); prefix_length -= col_width[0]; int suffix_length = col_width[1] + prefix_length; suffix_length = suffix_length > 0 ? col_width[1] : suffix_length; statsPrintf("%*s" "%*" FMT_Word64 "%*" FMT_Word64 "\n" , suffix_length, "].sync" , col_width[2], generations[g].sync.spin , col_width[3], generations[g].sync.yield); } statsPrintf("\n"); statsPrintf("%*s" "%*s" "%*" FMT_Word64 "\n" , col_width[0], "" , col_width[1], "any_work" , col_width[2], stats.any_work); statsPrintf("%*s" "%*s" "%*" FMT_Word64 "\n" , col_width[0], "" , col_width[1], "no_work" , col_width[2], stats.no_work); statsPrintf("%*s" "%*s" "%*" FMT_Word64 "\n" , col_width[0], "" , col_width[1], "scav_find_work" , col_width[2], stats.scav_find_work); #elif defined(THREADED_RTS) // THREADED_RTS && PROF_SPIN statsPrintf("Internal Counters require the RTS to be built " "with PROF_SPIN"); // PROF_SPIN is not #defined here #else // THREADED_RTS statsPrintf("Internal Counters require the threaded RTS"); #endif } } static void report_machine_readable (const RTSSummaryStats * sum) { // We should do no calculation, other than unit changes and formatting, and // we should not not use any data from outside of globals, sum and stats // here. See Note [RTS Stats Reporting] uint32_t g; #define MR_STAT(field_name,format,value) \ statsPrintf(" ,(\"" field_name "\", \"%" format "\")\n", value) #define MR_STAT_GEN(gen,field_name,format,value) \ statsPrintf(" ,(\"gen_%" FMT_Word32 "_" field_name "\", \"%" \ format "\")\n", g, value) // These first values are for backwards compatibility. // Some of these first fields are duplicated with more machine-readable // names, or to match the name in RtsStats. // we don't use for the first field helper macro here because the prefix is // different statsPrintf(" [(\"%s\", \"%" FMT_Word64 "\")\n", "bytes allocated", stats.allocated_bytes); MR_STAT("num_GCs", FMT_Word32, stats.gcs); MR_STAT("average_bytes_used", FMT_Word64, sum->average_bytes_used); MR_STAT("max_bytes_used", FMT_Word64, stats.max_live_bytes); MR_STAT("num_byte_usage_samples", FMT_Word32, stats.major_gcs); MR_STAT("peak_megabytes_allocated", FMT_Word64, stats.max_mem_in_use_bytes / (1024 * 1024)); MR_STAT("init_cpu_seconds", "f", TimeToSecondsDbl(stats.init_cpu_ns)); MR_STAT("init_wall_seconds", "f", TimeToSecondsDbl(stats.init_elapsed_ns)); MR_STAT("mut_cpu_seconds", "f", TimeToSecondsDbl(stats.mutator_cpu_ns)); MR_STAT("mut_wall_seconds", "f", TimeToSecondsDbl(stats.mutator_elapsed_ns)); MR_STAT("GC_cpu_seconds", "f", TimeToSecondsDbl(stats.gc_cpu_ns)); MR_STAT("GC_wall_seconds", "f", TimeToSecondsDbl(stats.gc_elapsed_ns)); // end backward compatibility // First, the rest of the times MR_STAT("exit_cpu_seconds", "f", TimeToSecondsDbl(sum->exit_cpu_ns)); MR_STAT("exit_wall_seconds", "f", TimeToSecondsDbl(sum->exit_elapsed_ns)); #if defined(PROFILING) MR_STAT("rp_cpu_seconds", "f", TimeToSecondsDbl(sum->rp_cpu_ns)); MR_STAT("rp_wall_seconds", "f", TimeToSecondsDbl(sum->rp_elapsed_ns)); MR_STAT("hc_cpu_seconds", "f", TimeToSecondsDbl(sum->hc_cpu_ns)); MR_STAT("hc_wall_seconds", "f", TimeToSecondsDbl(sum->hc_elapsed_ns)); #endif MR_STAT("total_cpu_seconds", "f", TimeToSecondsDbl(stats.cpu_ns)); MR_STAT("total_wall_seconds", "f", TimeToSecondsDbl(stats.elapsed_ns)); // next, the remainder of the fields of RTSStats, except internal counters // The first two are duplicates of those above, but have more machine // readable names that match the field names in RTSStats. // gcs has been done as num_GCs above MR_STAT("major_gcs", FMT_Word32, stats.major_gcs); MR_STAT("allocated_bytes", FMT_Word64, stats.allocated_bytes); MR_STAT("max_live_bytes", FMT_Word64, stats.max_live_bytes); MR_STAT("max_large_objects_bytes", FMT_Word64, stats.max_large_objects_bytes); MR_STAT("max_compact_bytes", FMT_Word64, stats.max_compact_bytes); MR_STAT("max_slop_bytes", FMT_Word64, stats.max_slop_bytes); // This duplicates, except for unit, peak_megabytes_allocated above MR_STAT("max_mem_in_use_bytes", FMT_Word64, stats.max_mem_in_use_bytes); MR_STAT("cumulative_live_bytes", FMT_Word64, stats.cumulative_live_bytes); MR_STAT("copied_bytes", FMT_Word64, stats.copied_bytes); MR_STAT("par_copied_bytes", FMT_Word64, stats.par_copied_bytes); MR_STAT("cumulative_par_max_copied_bytes", FMT_Word64, stats.cumulative_par_max_copied_bytes); MR_STAT("cumulative_par_balanced_copied_bytes", FMT_Word64, stats.cumulative_par_balanced_copied_bytes); // next, the computed fields in RTSSummaryStats #if !defined(THREADED_RTS) // THREADED_RTS MR_STAT("gc_cpu_percent", "f", sum->gc_cpu_percent); MR_STAT("gc_wall_percent", "f", sum->gc_cpu_percent); #endif MR_STAT("fragmentation_bytes", FMT_Word64, sum->fragmentation_bytes); // average_bytes_used is done above MR_STAT("alloc_rate", FMT_Word64, sum->alloc_rate); MR_STAT("productivity_cpu_percent", "f", sum->productivity_cpu_percent); MR_STAT("productivity_wall_percent", "f", sum->productivity_elapsed_percent); // next, the THREADED_RTS fields in RTSSummaryStats #if defined(THREADED_RTS) MR_STAT("bound_task_count", FMT_Word32, sum->bound_task_count); MR_STAT("sparks_count", FMT_Word64, sum->sparks_count); MR_STAT("sparks_converted", FMT_Word, sum->sparks.converted); MR_STAT("sparks_overflowed", FMT_Word, sum->sparks.overflowed); MR_STAT("sparks_dud ", FMT_Word, sum->sparks.dud); MR_STAT("sparks_gcd", FMT_Word, sum->sparks.gcd); MR_STAT("sparks_fizzled", FMT_Word, sum->sparks.fizzled); MR_STAT("work_balance", "f", sum->work_balance); // next, globals (other than internal counters) MR_STAT("n_capabilities", FMT_Word32, n_capabilities); MR_STAT("task_count", FMT_Word32, taskCount); MR_STAT("peak_worker_count", FMT_Word32, peakWorkerCount); MR_STAT("worker_count", FMT_Word32, workerCount); // next, internal counters #if defined(PROF_SPIN) MR_STAT("gc_alloc_block_sync_spin", FMT_Word64, gc_alloc_block_sync.spin); MR_STAT("gc_alloc_block_sync_yield", FMT_Word64, gc_alloc_block_sync.yield); MR_STAT("gc_alloc_block_sync_spin", FMT_Word64, gc_alloc_block_sync.spin); MR_STAT("gc_spin_spin", FMT_Word64, stats.gc_spin_spin); MR_STAT("gc_spin_yield", FMT_Word64, stats.gc_spin_yield); MR_STAT("mut_spin_spin", FMT_Word64, stats.mut_spin_spin); MR_STAT("mut_spin_yield", FMT_Word64, stats.mut_spin_yield); MR_STAT("waitForGcThreads_spin", FMT_Word64, waitForGcThreads_spin); MR_STAT("waitForGcThreads_yield", FMT_Word64, waitForGcThreads_yield); MR_STAT("whitehole_gc_spin", FMT_Word64, whitehole_gc_spin); MR_STAT("whitehole_lockClosure_spin", FMT_Word64, whitehole_lockClosure_spin); MR_STAT("whitehole_lockClosure_yield", FMT_Word64, whitehole_lockClosure_yield); MR_STAT("whitehole_executeMessage_spin", FMT_Word64, whitehole_executeMessage_spin); MR_STAT("whitehole_threadPaused_spin", FMT_Word64, whitehole_threadPaused_spin); MR_STAT("any_work", FMT_Word64, stats.any_work); MR_STAT("no_work", FMT_Word64, stats.no_work); MR_STAT("scav_find_work", FMT_Word64, stats.scav_find_work); #endif // PROF_SPIN #endif // THREADED_RTS // finally, per-generation stats. Named as, for example for generation 0, // gen_0_collections for (g = 0; g < RtsFlags.GcFlags.generations; g++) { const GenerationSummaryStats* gc_sum = &sum->gc_summary_stats[g]; MR_STAT_GEN(g, "collections", FMT_Word32, gc_sum->collections); MR_STAT_GEN(g, "par_collections", FMT_Word32, gc_sum->par_collections); MR_STAT_GEN(g, "cpu_seconds", "f", TimeToSecondsDbl(gc_sum->cpu_ns)); MR_STAT_GEN(g, "wall_seconds", "f", TimeToSecondsDbl(gc_sum->elapsed_ns)); MR_STAT_GEN(g, "max_pause_seconds", "f", TimeToSecondsDbl(gc_sum->max_pause_ns)); MR_STAT_GEN(g, "avg_pause_seconds", "f", TimeToSecondsDbl(gc_sum->avg_pause_ns)); #if defined(THREADED_RTS) && defined(PROF_SPIN) MR_STAT_GEN(g, "sync_spin", FMT_Word64, gc_sum->sync_spin); MR_STAT_GEN(g, "sync_yield", FMT_Word64, gc_sum->sync_yield); #endif } statsPrintf(" ]\n"); } static void report_one_line(const RTSSummaryStats * sum) { // We should do no calculation, other than unit changes and formatting, and // we should not not use any data from outside of globals, sum and stats // here. See Note [RTS Stats Reporting] /* print the long long separately to avoid bugginess on mingwin (2001-07-02, mingw-0.5) */ statsPrintf("<>\n", stats.allocated_bytes, stats.gcs, sum->average_bytes_used, stats.max_live_bytes, stats.major_gcs, stats.max_mem_in_use_bytes / (1024 * 1024), TimeToSecondsDbl(stats.init_cpu_ns), TimeToSecondsDbl(stats.init_elapsed_ns), TimeToSecondsDbl(stats.mutator_cpu_ns), TimeToSecondsDbl(stats.mutator_elapsed_ns), TimeToSecondsDbl(stats.gc_cpu_ns), TimeToSecondsDbl(stats.gc_elapsed_ns)); } void stat_exit (void) { RTSSummaryStats sum; init_RTSSummaryStats(&sum); if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) { // First we tidy the times in stats, and populate the times in sum. // In particular, we adjust the gc_* time in stats to remove // profiling times. { Time now_cpu_ns, now_elapsed_ns; getProcessTimes(&now_cpu_ns, &now_elapsed_ns); stats.cpu_ns = now_cpu_ns - start_init_cpu; stats.elapsed_ns = now_elapsed_ns - start_init_elapsed; /* avoid divide by zero if stats.total_cpu_ns is measured as 0.00 seconds -- SDM */ if (stats.cpu_ns <= 0) { stats.cpu_ns = 1; } if (stats.elapsed_ns <= 0) { stats.elapsed_ns = 1; } #if defined(PROFILING) sum.rp_cpu_ns = RP_tot_time; sum.rp_elapsed_ns = RPe_tot_time; sum.hc_cpu_ns = HC_tot_time; sum.hc_elapsed_ns = HCe_tot_time; #endif // PROFILING // We do a GC during the EXIT phase. We'll attribute the cost of // that to GC instead of EXIT, so carefully subtract it from the // EXIT time. // Note that exit_gc includes RP and HC for the exit GC too. Time exit_gc_cpu = stats.gc_cpu_ns - start_exit_gc_cpu; Time exit_gc_elapsed = stats.gc_elapsed_ns - start_exit_gc_elapsed; ASSERT(exit_gc_elapsed > 0); sum.exit_cpu_ns = end_exit_cpu - start_exit_cpu - exit_gc_cpu; sum.exit_elapsed_ns = end_exit_elapsed - start_exit_elapsed - exit_gc_elapsed; ASSERT(sum.exit_elapsed_ns >= 0); stats.mutator_cpu_ns = start_exit_cpu - end_init_cpu - (stats.gc_cpu_ns - exit_gc_cpu); stats.mutator_elapsed_ns = start_exit_elapsed - end_init_elapsed - (stats.gc_elapsed_ns - exit_gc_elapsed); ASSERT(stats.mutator_elapsed_ns >= 0); if (stats.mutator_cpu_ns < 0) { stats.mutator_cpu_ns = 0; } // The subdivision of runtime into INIT/EXIT/GC/MUT is just adding // and subtracting, so the parts should add up to the total exactly. // Note that stats->total_ns is captured a tiny bit later than // end_exit_elapsed, so we don't use it here. ASSERT(stats.init_elapsed_ns // INIT + stats.mutator_elapsed_ns // MUT + stats.gc_elapsed_ns // GC + sum.exit_elapsed_ns // EXIT == end_exit_elapsed - start_init_elapsed); // heapCensus() is called by the GC, so RP and HC time are // included in the GC stats. We therefore subtract them to // obtain the actual GC cpu time. Time prof_cpu = sum.rp_cpu_ns + sum.hc_cpu_ns; Time prof_elapsed = sum.rp_elapsed_ns + sum.hc_elapsed_ns; stats.gc_cpu_ns -= prof_cpu; stats.gc_elapsed_ns -= prof_elapsed; // This assertion is probably not necessary; make sure the // subdivision with PROF also makes sense ASSERT(stats.init_elapsed_ns // INIT + stats.mutator_elapsed_ns // MUT + stats.gc_elapsed_ns // GC + sum.exit_elapsed_ns // EXIT + (sum.rp_elapsed_ns + sum.hc_elapsed_ns) // PROF == end_exit_elapsed - start_init_elapsed); } // REVIEWERS: it's not clear to me why the following isn't done in // stat_endGC of the last garbage collection? // We account for the last garbage collection { uint64_t tot_alloc_bytes = calcTotalAllocated() * sizeof(W_); stats.gc.allocated_bytes = tot_alloc_bytes - stats.allocated_bytes; stats.allocated_bytes = tot_alloc_bytes; if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) { statsPrintf("%9" FMT_Word " %9.9s %9.9s", (W_)stats.gc.allocated_bytes, "", ""); statsPrintf(" %6.3f %6.3f\n\n", 0.0, 0.0); } } // We populate the remainder (non-time elements) of sum { #if defined(THREADED_RTS) sum.bound_task_count = taskCount - workerCount; for (uint32_t i = 0; i < n_capabilities; i++) { sum.sparks.created += capabilities[i]->spark_stats.created; sum.sparks.dud += capabilities[i]->spark_stats.dud; sum.sparks.overflowed+= capabilities[i]->spark_stats.overflowed; sum.sparks.converted += capabilities[i]->spark_stats.converted; sum.sparks.gcd += capabilities[i]->spark_stats.gcd; sum.sparks.fizzled += capabilities[i]->spark_stats.fizzled; } sum.sparks_count = sum.sparks.created + sum.sparks.dud + sum.sparks.overflowed; if (RtsFlags.ParFlags.parGcEnabled && stats.par_copied_bytes > 0) { // See Note [Work Balance] sum.work_balance = (double)stats.cumulative_par_balanced_copied_bytes / (double)stats.par_copied_bytes; } else { sum.work_balance = 0; } #else // THREADED_RTS sum.gc_cpu_percent = stats.gc_cpu_ns / stats.cpu_ns; sum.gc_elapsed_percent = stats.gc_elapsed_ns / stats.elapsed_ns; #endif // THREADED_RTS sum.fragmentation_bytes = (uint64_t)(peak_mblocks_allocated * BLOCKS_PER_MBLOCK * BLOCK_SIZE_W - hw_alloc_blocks * BLOCK_SIZE_W) / (uint64_t)sizeof(W_); sum.average_bytes_used = stats.major_gcs == 0 ? 0 : stats.cumulative_live_bytes/stats.major_gcs, sum.alloc_rate = stats.mutator_cpu_ns == 0 ? 0 : (uint64_t)((double)stats.allocated_bytes / TimeToSecondsDbl(stats.mutator_cpu_ns)); // REVIEWERS: These two values didn't used to include the exit times sum.productivity_cpu_percent = TimeToSecondsDbl(stats.cpu_ns - stats.gc_cpu_ns - stats.init_cpu_ns - sum.exit_cpu_ns) / TimeToSecondsDbl(stats.cpu_ns); ASSERT(sum.productivity_cpu_percent >= 0); sum.productivity_elapsed_percent = TimeToSecondsDbl(stats.elapsed_ns - stats.gc_elapsed_ns - stats.init_elapsed_ns - sum.exit_elapsed_ns) / TimeToSecondsDbl(stats.elapsed_ns); ASSERT(sum.productivity_elapsed_percent >= 0); for(uint32_t g = 0; g < RtsFlags.GcFlags.generations; ++g) { const generation* gen = &generations[g]; GenerationSummaryStats* gen_stats = &sum.gc_summary_stats[g]; gen_stats->collections = gen->collections; gen_stats->par_collections = gen->par_collections; gen_stats->cpu_ns = GC_coll_cpu[g]; gen_stats->elapsed_ns = GC_coll_elapsed[g]; gen_stats->max_pause_ns = GC_coll_max_pause[g]; gen_stats->avg_pause_ns = gen->collections == 0 ? 0 : (GC_coll_elapsed[g] / gen->collections); #if defined(THREADED_RTS) && defined(PROF_SPIN) gen_stats->sync_spin = gen->sync.spin; gen_stats->sync_yield = gen->sync.yield; #endif // PROF_SPIN } } // Now we generate the report if (RtsFlags.GcFlags.giveStats >= SUMMARY_GC_STATS) { report_summary(&sum); } if (RtsFlags.GcFlags.giveStats == ONELINE_GC_STATS) { if (RtsFlags.MiscFlags.machineReadable) { report_machine_readable(&sum); } else { report_one_line(&sum); } } statsFlush(); statsClose(); } free_RTSSummaryStats(&sum); if (GC_coll_cpu) { stgFree(GC_coll_cpu); GC_coll_cpu = NULL; } if (GC_coll_elapsed) { stgFree(GC_coll_elapsed); GC_coll_elapsed = NULL; } if (GC_coll_max_pause) { stgFree(GC_coll_max_pause); GC_coll_max_pause = NULL; } } /* Note [Work Balance] ---------------------- Work balance is a measure of how evenly the work done during parallel garbage collection is spread across threads. To compute work balance we must take care to account for the number of GC threads changing between GCs. The statistics we track must have the number of GC threads "integrated out". We accumulate two values from each garbage collection: * par_copied: is a measure of the total work done during parallel garbage collection * par_balanced_copied: is a measure of the balanced work done during parallel garbage collection. par_copied is simple to compute, but par_balanced_copied_bytes is somewhat more complicated: For a given garbage collection: Let gc_copied := total copies during the gc gc_copied_i := copies by the ith thread during the gc num_gc_threads := the number of threads participating in the gc balance_limit := (gc_copied / num_gc_threads) If we were to graph gc_copied_i, sorted from largest to smallest we would see something like: |X ^ |X X | |X X X X: unbalanced copies copies |----------- Y: balanced copies by the busiest GC thread |Y Z Z Z: other balanced copies |Y Z Z Z |Y Z Z Z Z |Y Z Z Z Z Z |=========== |1 2 3 4 5 6 i -> where the --- line is at balance_limit. Balanced copies are those under the --- line, i.e. the area of the Ys and Zs. Note that the area occupied by the Ys will always equal balance_limit. Completely balanced gc has every thread copying balance_limit and a completely unbalanced gc has a single thread copying gc_copied. One could define par_balance_copied as the areas of the Ys and Zs in the graph above, however we would like the ratio of (par_balance_copied / gc_copied) to range from 0 to 1, so that work_balance will be a nice percentage, also ranging from 0 to 1. We therefore define par_balanced_copied as: ( num_gc_threads ) {Sum[Min(gc_copied_i,balance_limit)] - balance_limit} * (------------------) i (num_gc_threads - 1) vvv vvv S T Where the S and T terms serve to remove the area of the Ys, and to normalize the result to lie between 0 and gc_copied. Note that the implementation orders these operations differently to minimize error due to integer rounding. Then cumulative work balance is computed as (cumulative_par_balanced_copied_bytes / par_copied_byes) Previously, cumulative work balance was computed as: (cumulative_par_max_copied_bytes) (-------------------------------) - 1 ( par_copied_bytes ) ------------------------------------- (n_capabilities - 1) This was less accurate than the current method, and invalid whenever a garbage collection had occurred with num_gc_threads /= n_capabilities; which can happen when setNumCapabilities is called, when -qn is passed as an RTS option, or when the number of gc threads is limited to the number of cores. See #13830 */ /* Note [Internal Counter Stats] ----------------------------- What do the counts at the end of a '+RTS -s --internal-counters' report mean? They are detailed below. Most of these counters are used by multiple threads with no attempt at synchronisation. This means that reported values may be lower than the true value and this becomes more likely and more severe as contention increases. The first counters are for various SpinLock-like constructs in the RTS. See Spinlock.h for the definition of a SpinLock. We maintain up two counters per SpinLock: * spin: The number of busy-spins over the length of the program. * yield: The number of times the SpinLock spun SPIN_COUNT times without success and called yieldThread(). Not all of these are actual SpinLocks, see the details below. Actual SpinLocks: * gc_alloc_block: This SpinLock protects the block allocator and free list manager. See BlockAlloc.c. * gc_spin and mut_spin: These SpinLocks are used to herd gc worker threads during parallel garbage collection. See gcWorkerThread, wakeup_gc_threads and releaseGCThreads. * gen[g].sync: These SpinLocks, one per generation, protect the generations[g] data structure during garbage collection. waitForGcThreads: These counters are incremented while we wait for all threads to be ready for a parallel garbage collection. We yield more than we spin in this case. In several places in the runtime we must take a lock on a closure. To do this, we replace its info table with stg_WHITEHOLE_info, spinning if it is already a white-hole. Sometimes we yieldThread() if we spin too long, sometimes we don't. We count these white-hole spins and include them in the SpinLocks table. If a particular loop does not yield, we put "n/a" in the table. They are named for the function that has the spinning loop except that several loops in the garbage collector accumulate into whitehole_gc. TODO: Should these counters be more or less granular? white-hole spin counters: * whitehole_gc * whitehole_lockClosure * whitehole_executeMessage * whitehole_threadPaused We count the number of calls of several functions in the parallel garbage collector. Parallel garbage collector counters: * any_work: A cheap function called whenever a gc_thread is ready for work. Does not do any work. * no_work: Incremented whenever any_work finds no work. * scav_find_work: Called to do work when any_work return true. */ /* ----------------------------------------------------------------------------- stat_describe_gens Produce some detailed info on the state of the generational GC. -------------------------------------------------------------------------- */ void statDescribeGens(void) { uint32_t g, mut, lge, compacts, i; W_ gen_slop; W_ tot_live, tot_slop; W_ gen_live, gen_blocks; bdescr *bd; generation *gen; debugBelch( "----------------------------------------------------------------------\n" " Gen Max Mut-list Blocks Large Compacts Live Slop\n" " Blocks Bytes Objects \n" "----------------------------------------------------------------------\n"); tot_live = 0; tot_slop = 0; for (g = 0; g < RtsFlags.GcFlags.generations; g++) { gen = &generations[g]; for (bd = gen->large_objects, lge = 0; bd; bd = bd->link) { lge++; } for (bd = gen->compact_objects, compacts = 0; bd; bd = bd->link) { compacts++; } gen_live = genLiveWords(gen); gen_blocks = genLiveBlocks(gen); mut = 0; for (i = 0; i < n_capabilities; i++) { mut += countOccupied(capabilities[i]->mut_lists[g]); // Add the pinned object block. bd = capabilities[i]->pinned_object_block; if (bd != NULL) { gen_live += bd->free - bd->start; gen_blocks += bd->blocks; } gen_live += gcThreadLiveWords(i,g); gen_blocks += gcThreadLiveBlocks(i,g); } debugBelch("%5d %7" FMT_Word " %9d", g, (W_)gen->max_blocks, mut); gen_slop = gen_blocks * BLOCK_SIZE_W - gen_live; debugBelch("%8" FMT_Word " %8d %8d %9" FMT_Word " %9" FMT_Word "\n", gen_blocks, lge, compacts, gen_live*(W_)sizeof(W_), gen_slop*(W_)sizeof(W_)); tot_live += gen_live; tot_slop += gen_slop; } debugBelch("----------------------------------------------------------------------\n"); debugBelch("%51s%9" FMT_Word " %9" FMT_Word "\n", "",tot_live*(W_)sizeof(W_),tot_slop*(W_)sizeof(W_)); debugBelch("----------------------------------------------------------------------\n"); debugBelch("\n"); } /* ----------------------------------------------------------------------------- Stats available via a programmatic interface, so eg. GHCi can time each compilation and expression evaluation. -------------------------------------------------------------------------- */ uint64_t getAllocations( void ) { return stats.allocated_bytes; } int getRTSStatsEnabled( void ) { return RtsFlags.GcFlags.giveStats != NO_GC_STATS; } void getRTSStats( RTSStats *s ) { Time current_elapsed = 0; Time current_cpu = 0; *s = stats; getProcessTimes(¤t_cpu, ¤t_elapsed); s->cpu_ns = current_cpu - end_init_cpu; s->elapsed_ns = current_elapsed - end_init_elapsed; s->mutator_cpu_ns = current_cpu - end_init_cpu - stats.gc_cpu_ns; s->mutator_elapsed_ns = current_elapsed - end_init_elapsed - stats.gc_elapsed_ns; } /* ----------------------------------------------------------------------------- Dumping stuff in the stats file, or via the debug message interface -------------------------------------------------------------------------- */ void statsPrintf( char *s, ... ) { FILE *sf = RtsFlags.GcFlags.statsFile; va_list ap; va_start(ap,s); if (sf == NULL) { vdebugBelch(s,ap); } else { vfprintf(sf, s, ap); } va_end(ap); } static void statsFlush( void ) { FILE *sf = RtsFlags.GcFlags.statsFile; if (sf != NULL) { fflush(sf); } } static void statsClose( void ) { FILE *sf = RtsFlags.GcFlags.statsFile; if (sf != NULL) { fclose(sf); } }