/* ----------------------------------------------------------------------------- * * (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" #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(PROFILING) #define PROF_VAL(x) (x) #else #define PROF_VAL(x) 0 #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. } 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, .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 initStats1 (void) { uint32_t i; 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"); for (i = 0; i < RtsFlags.GcFlags.generations; i++) { GC_coll_cpu[i] = 0; GC_coll_elapsed[i] = 0; GC_coll_max_pause[i] = 0; } } /* ----------------------------------------------------------------------------- Initialisation time... -------------------------------------------------------------------------- */ void stat_startInit(void) { getProcessTimes(&start_init_cpu, &start_init_elapsed); } void stat_endInit(void) { getProcessTimes(&end_init_cpu, &end_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) STATIC_INLINE Time get_init_cpu(void) { return end_init_cpu - start_init_cpu; } STATIC_INLINE Time get_init_elapsed(void) { return end_init_elapsed - start_init_elapsed; } void stat_exit (void) { generation *gen; Time gc_cpu = 0; Time gc_elapsed = 0; Time init_cpu = 0; Time init_elapsed = 0; Time mut_cpu = 0; Time mut_elapsed = 0; Time exit_cpu = 0; Time exit_elapsed = 0; Time exit_gc_cpu = 0; Time exit_gc_elapsed = 0; if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) { char temp[512]; Time tot_cpu; Time tot_elapsed; uint32_t g; getProcessTimes( &tot_cpu, &tot_elapsed ); tot_cpu -= start_init_cpu; tot_elapsed -= start_init_elapsed; uint64_t tot_alloc_bytes = calcTotalAllocated() * sizeof(W_); // allocated since the last GC stats.gc.allocated_bytes = tot_alloc_bytes - stats.allocated_bytes; stats.allocated_bytes = tot_alloc_bytes; /* avoid divide by zero if tot_cpu is measured as 0.00 seconds -- SDM */ if (tot_cpu <= 0) tot_cpu = 1; if (tot_elapsed <= 0) tot_elapsed = 1; 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); } // 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. gc_cpu = stats.gc_cpu_ns - PROF_VAL(RP_tot_time + HC_tot_time); gc_elapsed = stats.gc_elapsed_ns - PROF_VAL(RPe_tot_time + HCe_tot_time); init_cpu = get_init_cpu(); init_elapsed = get_init_elapsed(); // 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. exit_gc_cpu = stats.gc_cpu_ns - start_exit_gc_cpu; exit_gc_elapsed = stats.gc_elapsed_ns - start_exit_gc_elapsed; exit_cpu = end_exit_cpu - start_exit_cpu - exit_gc_cpu; exit_elapsed = end_exit_elapsed - start_exit_elapsed - exit_gc_elapsed; mut_elapsed = start_exit_elapsed - end_init_elapsed - (gc_elapsed - exit_gc_elapsed) - PROF_VAL(RPe_tot_time + HCe_tot_time); mut_cpu = start_exit_cpu - end_init_cpu - (gc_cpu - exit_gc_cpu) - PROF_VAL(RP_tot_time + HC_tot_time); if (mut_cpu < 0) { mut_cpu = 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 tot_elapsed is captured a tiny bit later than end_exit_elapsed, // so we don't use it here. ASSERT(init_elapsed + mut_elapsed + gc_elapsed + exit_elapsed == end_exit_elapsed - start_init_elapsed); if (RtsFlags.GcFlags.giveStats >= SUMMARY_GC_STATS) { 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_SizeT " MB total memory in use (%" FMT_SizeT " MB lost due to fragmentation)\n\n", (size_t)(peak_mblocks_allocated * MBLOCK_SIZE_W) / (1024 * 1024 / sizeof(W_)), (size_t)(peak_mblocks_allocated * BLOCKS_PER_MBLOCK * BLOCK_SIZE_W - hw_alloc_blocks * BLOCK_SIZE_W) / (1024 * 1024 / sizeof(W_))); /* Print garbage collections in each gen */ statsPrintf(" Tot time (elapsed) Avg pause Max pause\n"); for (g = 0; g < RtsFlags.GcFlags.generations; g++) { gen = &generations[g]; statsPrintf(" Gen %2d %5d colls, %5d par %6.3fs %6.3fs %3.4fs %3.4fs\n", gen->no, gen->collections, gen->par_collections, TimeToSecondsDbl(GC_coll_cpu[g]), TimeToSecondsDbl(GC_coll_elapsed[g]), gen->collections == 0 ? 0 : TimeToSecondsDbl(GC_coll_elapsed[g] / gen->collections), TimeToSecondsDbl(GC_coll_max_pause[g])); } #if defined(THREADED_RTS) if (RtsFlags.ParFlags.parGcEnabled && stats.par_copied_bytes > 0) { // See Note [Work Balance] statsPrintf("\n Parallel GC work balance: %.2f%% (serial 0%%, perfect 100%%)\n", 100 * (double)stats.cumulative_par_balanced_copied_bytes / (double)stats.par_copied_bytes); } #endif statsPrintf("\n"); #if defined(THREADED_RTS) statsPrintf(" TASKS: %d (%d bound, %d peak workers (%d total), using -N%d)\n", taskCount, taskCount - workerCount, peakWorkerCount, workerCount, n_capabilities); statsPrintf("\n"); { uint32_t i; SparkCounters sparks = { 0, 0, 0, 0, 0, 0}; for (i = 0; i < n_capabilities; i++) { sparks.created += capabilities[i]->spark_stats.created; sparks.dud += capabilities[i]->spark_stats.dud; sparks.overflowed+= capabilities[i]->spark_stats.overflowed; sparks.converted += capabilities[i]->spark_stats.converted; sparks.gcd += capabilities[i]->spark_stats.gcd; sparks.fizzled += capabilities[i]->spark_stats.fizzled; } statsPrintf(" SPARKS: %" FMT_Word " (%" FMT_Word " converted, %" FMT_Word " overflowed, %" FMT_Word " dud, %" FMT_Word " GC'd, %" FMT_Word " fizzled)\n\n", sparks.created + sparks.dud + sparks.overflowed, sparks.converted, sparks.overflowed, sparks.dud, sparks.gcd, sparks.fizzled); } #endif statsPrintf(" INIT time %7.3fs (%7.3fs elapsed)\n", TimeToSecondsDbl(init_cpu), TimeToSecondsDbl(init_elapsed)); statsPrintf(" MUT time %7.3fs (%7.3fs elapsed)\n", TimeToSecondsDbl(mut_cpu), TimeToSecondsDbl(mut_elapsed)); statsPrintf(" GC time %7.3fs (%7.3fs elapsed)\n", TimeToSecondsDbl(gc_cpu), TimeToSecondsDbl(gc_elapsed)); #if defined(PROFILING) statsPrintf(" RP time %7.3fs (%7.3fs elapsed)\n", TimeToSecondsDbl(RP_tot_time), TimeToSecondsDbl(RPe_tot_time)); statsPrintf(" PROF time %7.3fs (%7.3fs elapsed)\n", TimeToSecondsDbl(HC_tot_time), TimeToSecondsDbl(HCe_tot_time)); #endif statsPrintf(" EXIT time %7.3fs (%7.3fs elapsed)\n", TimeToSecondsDbl(exit_cpu), TimeToSecondsDbl(exit_elapsed)); statsPrintf(" Total time %7.3fs (%7.3fs elapsed)\n\n", TimeToSecondsDbl(tot_cpu), TimeToSecondsDbl(tot_elapsed)); #if !defined(THREADED_RTS) statsPrintf(" %%GC time %5.1f%% (%.1f%% elapsed)\n\n", TimeToSecondsDbl(gc_cpu)*100/TimeToSecondsDbl(tot_cpu), TimeToSecondsDbl(gc_elapsed)*100/TimeToSecondsDbl(tot_elapsed)); #endif if (mut_cpu == 0) { showStgWord64(0, temp, true/*commas*/); } else { showStgWord64( (StgWord64)((double)stats.allocated_bytes / TimeToSecondsDbl(mut_cpu)), 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", TimeToSecondsDbl(tot_cpu - gc_cpu - PROF_VAL(RP_tot_time + HC_tot_time) - init_cpu) * 100 / TimeToSecondsDbl(tot_cpu), TimeToSecondsDbl(tot_elapsed - gc_elapsed - PROF_VAL(RPe_tot_time + HCe_tot_time) - init_elapsed) * 100 / TimeToSecondsDbl(tot_elapsed)); // 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) uint32_t g; 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 } } if (RtsFlags.GcFlags.giveStats == ONELINE_GC_STATS) { char *fmt; if (RtsFlags.MiscFlags.machineReadable) { fmt = " [(\"bytes allocated\", \"%" FMT_Word64 "\")\n" " ,(\"num_GCs\", \"%" FMT_Word32 "\")\n" " ,(\"average_bytes_used\", \"%" FMT_Word64 "\")\n" " ,(\"max_bytes_used\", \"%" FMT_Word64 "\")\n" " ,(\"num_byte_usage_samples\", \"%" FMT_Word32 "\")\n" " ,(\"peak_megabytes_allocated\", \"%" FMT_Word64 "\")\n" " ,(\"init_cpu_seconds\", \"%.3f\")\n" " ,(\"init_wall_seconds\", \"%.3f\")\n" " ,(\"mutator_cpu_seconds\", \"%.3f\")\n" " ,(\"mutator_wall_seconds\", \"%.3f\")\n" " ,(\"GC_cpu_seconds\", \"%.3f\")\n" " ,(\"GC_wall_seconds\", \"%.3f\")\n" " ]\n"; } else { fmt = "<>\n"; } /* print the long long separately to avoid bugginess on mingwin (2001-07-02, mingw-0.5) */ statsPrintf(fmt, stats.allocated_bytes, stats.gcs, (uint64_t) (stats.major_gcs == 0 ? 0 : stats.cumulative_live_bytes/stats.major_gcs), stats.max_live_bytes, stats.major_gcs, (uint64_t) (peak_mblocks_allocated * MBLOCK_SIZE / (1024L * 1024L)), TimeToSecondsDbl(init_cpu), TimeToSecondsDbl(init_elapsed), TimeToSecondsDbl(mut_cpu), TimeToSecondsDbl(mut_elapsed), TimeToSecondsDbl(gc_cpu), TimeToSecondsDbl(gc_elapsed)); } statsFlush(); statsClose(); } 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 it's 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*sizeof(W_),tot_slop*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); } }