X-Git-Url: http://git.megacz.com/?a=blobdiff_plain;f=ghc%2Frts%2FStats.c;h=28d09bdbedea1bdd15c4e93df873e3776f3c9903;hb=ba41623270c1d541e74bd5182e1b4fcbe99809cc;hp=53dd7fc5935006cf356d41c18971044bde762978;hpb=9874c5e7c747d92121ea61de3319cee628f3a80a;p=ghc-hetmet.git diff --git a/ghc/rts/Stats.c b/ghc/rts/Stats.c index 53dd7fc..28d09bd 100644 --- a/ghc/rts/Stats.c +++ b/ghc/rts/Stats.c @@ -1,163 +1,79 @@ /* ----------------------------------------------------------------------------- - * $Id: Stats.c,v 1.24 2001/03/14 15:01:04 sewardj Exp $ * - * (c) The GHC Team, 1998-1999 + * (c) The GHC Team, 1998-2005 * * Statistics and timing-related functions. * * ---------------------------------------------------------------------------*/ -#define NON_POSIX_SOURCE - #include "Rts.h" #include "RtsFlags.h" #include "RtsUtils.h" -#include "StoragePriv.h" #include "MBlock.h" #include "Schedule.h" #include "Stats.h" - -#ifdef HAVE_UNISTD_H -#include -#endif - -#ifndef mingw32_TARGET_OS -# ifdef HAVE_SYS_TIMES_H -# include -# endif -#endif - -#ifdef HAVE_SYS_TIME_H -#include -#endif - -#ifdef __CYGWIN32__ -# ifdef HAVE_TIME_H -# include -# endif -#endif - -#if ! irix_TARGET_OS && ! defined(mingw32_TARGET_OS) -# if defined(HAVE_SYS_RESOURCE_H) -# include -# endif -#endif - -#ifdef HAVE_SYS_TIMEB_H -#include -#endif - -#if HAVE_STDLIB_H -#include -#endif - -#if HAVE_WINDOWS_H -#include -#endif +#include "ParTicky.h" /* ToDo: move into Rts.h */ +#include "Profiling.h" +#include "Storage.h" +#include "GetTime.h" /* huh? */ #define BIG_STRING_LEN 512 -/* We're not trying to be terribly accurate here, using the - * basic times() function to get a resolution of about 100ths of a - * second, depending on the OS. A long int will do fine for holding - * these values. - */ -#define TICK_TYPE long int -#define TICK_TO_DBL(t) ((double)(t) / TicksPerSecond) +#define TICK_TO_DBL(t) ((double)(t) / TICKS_PER_SECOND) -static int TicksPerSecond = 0; +static Ticks ElapsedTimeStart = 0; -static TICK_TYPE ElapsedTimeStart = 0; -static TICK_TYPE CurrentElapsedTime = 0; -static TICK_TYPE CurrentUserTime = 0; +static Ticks InitUserTime = 0; +static Ticks InitElapsedTime = 0; +static Ticks InitElapsedStamp = 0; -static TICK_TYPE InitUserTime = 0; -static TICK_TYPE InitElapsedTime = 0; -static TICK_TYPE InitElapsedStamp = 0; +static Ticks MutUserTime = 0; +static Ticks MutElapsedTime = 0; +static Ticks MutElapsedStamp = 0; -static TICK_TYPE MutUserTime = 0; -static TICK_TYPE MutElapsedTime = 0; -static TICK_TYPE MutElapsedStamp = 0; - -static TICK_TYPE ExitUserTime = 0; -static TICK_TYPE ExitElapsedTime = 0; +static Ticks ExitUserTime = 0; +static Ticks ExitElapsedTime = 0; static ullong GC_tot_alloc = 0; static ullong GC_tot_copied = 0; +static ullong GC_tot_scavd_copied = 0; -static TICK_TYPE GC_start_time, GC_tot_time = 0; /* User GC Time */ -static TICK_TYPE GCe_start_time, GCe_tot_time = 0; /* Elapsed GC time */ - -lnat MaxResidency = 0; /* in words; for stats only */ -lnat AvgResidency = 0; -lnat ResidencySamples = 0; /* for stats only */ - -static lnat GC_start_faults = 0, GC_end_faults = 0; - -static TICK_TYPE *GC_coll_times; +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 */ -static void getTimes(void); -static nat pageFaults(void); +#ifdef PROFILING +static Ticks RP_start_time = 0, RP_tot_time = 0; /* retainer prof user time */ +static Ticks RPe_start_time = 0, RPe_tot_time = 0; /* retainer prof elap time */ -/* elapsedtime() -- The current elapsed time in seconds */ - -#ifdef _WIN32 -#define NS_PER_SEC 10000000LL -/* Convert FILETIMEs into secs since the Epoch (Jan1-1970) */ -#define FT2longlong(ll,ft) \ - (ll)=(ft).dwHighDateTime; \ - (ll) <<= 32; \ - (ll) |= (ft).dwLowDateTime; \ - (ll) /= (unsigned long long) (NS_PER_SEC / CLOCKS_PER_SEC) +static Ticks HC_start_time, HC_tot_time = 0; // heap census prof user time +static Ticks HCe_start_time, HCe_tot_time = 0; // heap census prof elap time #endif -#ifdef _WIN32 -/* cygwin32 or mingw32 version */ -static void -getTimes(void) -{ - FILETIME creationTime, exitTime, kernelTime, userTime; - long long int kT, uT; - - /* ToDo: pin down elapsed times to just the OS thread(s) that - are evaluating/managing Haskell code. - */ - if (!GetProcessTimes (GetCurrentProcess(), &creationTime, - &exitTime, &kernelTime, &userTime)) { - /* Probably on a Win95 box..*/ - return 0; - } - - FT2longlong(kT,kernelTime); - FT2longlong(uT,userTime); - CurrentElapsedTime = uT + kT; - CurrentUserTime = uT; -} +#ifdef PROFILING +#define PROF_VAL(x) (x) +#else +#define PROF_VAL(x) 0 +#endif -#else /* !_WIN32 */ +static lnat MaxResidency = 0; // in words; for stats only +static lnat AvgResidency = 0; +static lnat ResidencySamples = 0; // for stats only -static void -getTimes(void) -{ +static lnat GC_start_faults = 0, GC_end_faults = 0; -# if !defined(HAVE_TIMES) - /* We will #ifdef around the fprintf for machines - we *know* are unsupported. (WDP 94/05) - */ - fprintf(stderr, "NOTE: `getTimes' does nothing!\n"); - return 0.0; +static Ticks *GC_coll_times; -# else /* not stumped */ - struct tms t; - clock_t r = times(&t); +static void statsPrintf( char *s, ... ) + GNUC3_ATTRIBUTE(format (printf, 1, 2)); - CurrentElapsedTime = r; - CurrentUserTime = t.tms_utime; -#endif +static void statsFlush( void ); +static void statsClose( void ); +Ticks stat_getElapsedGCTime(void) +{ + return GCe_tot_time; } -#endif /* !_WIN32 */ /* mut_user_time_during_GC() and mut_user_time() * @@ -172,46 +88,50 @@ getTimes(void) * stat_startGC() for details) */ double -mut_user_time_during_GC(void) +mut_user_time_during_GC( void ) { - return TICK_TO_DBL(GC_start_time - GC_tot_time); + return TICK_TO_DBL(GC_start_time - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time)); } double -mut_user_time(void) +mut_user_time( void ) { - getTimes(); - return TICK_TO_DBL(CurrentUserTime - GC_tot_time); + Ticks user; + user = getProcessCPUTime(); + return TICK_TO_DBL(user - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time)); } -static nat -pageFaults(void) +#ifdef PROFILING +/* + mut_user_time_during_RP() is similar to mut_user_time_during_GC(); + it returns the MUT time during retainer profiling. + The same is for mut_user_time_during_HC(); + */ +double +mut_user_time_during_RP( void ) { - /* ToDo (on NT): better, get this via the performance data - that's stored in the registry. */ -# if !defined(HAVE_GETRUSAGE) || irix_TARGET_OS || defined(_WIN32) - return 0; -# else - struct rusage t; - - getrusage(RUSAGE_SELF, &t); - return(t.ru_majflt); -# endif + return TICK_TO_DBL(RP_start_time - GC_tot_time - RP_tot_time - HC_tot_time); } +double +mut_user_time_during_heap_census( void ) +{ + return TICK_TO_DBL(HC_start_time - GC_tot_time - RP_tot_time - HC_tot_time); +} +#endif /* PROFILING */ + void initStats(void) { nat i; - FILE *sf = RtsFlags.GcFlags.statsFile; if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) { - fprintf(sf, " Alloc Collect Live GC GC TOT TOT Page Flts\n"); - fprintf(sf, " bytes bytes bytes user elap user elap\n"); + statsPrintf(" Alloc Copied Live GC GC TOT TOT Page Flts\n"); + statsPrintf(" bytes bytes bytes user elap user elap\n"); } GC_coll_times = - (TICK_TYPE *)stgMallocBytes( - sizeof(TICK_TYPE)*RtsFlags.GcFlags.generations, + (Ticks *)stgMallocBytes( + sizeof(Ticks)*RtsFlags.GcFlags.generations, "initStats"); for (i = 0; i < RtsFlags.GcFlags.generations; i++) { GC_coll_times[i] = 0; @@ -225,48 +145,25 @@ initStats(void) void stat_startInit(void) { - /* Determine TicksPerSecond ... */ -#if defined(CLK_TCK) /* defined by POSIX */ - TicksPerSecond = CLK_TCK; - -#elif defined(HAVE_SYSCONF) - long ticks; + Ticks elapsed; - ticks = sysconf(_SC_CLK_TCK); - if ( ticks == -1 ) { - fprintf(stderr, "stat_init: bad call to 'sysconf'!\n"); - stg_exit(EXIT_FAILURE); - } - TicksPerSecond = (double) ticks; - -/* no "sysconf" or CLK_TCK; had better guess */ -#elif defined(HZ) - TicksPerSecond = (StgDouble) (HZ); - -#elif defined(CLOCKS_PER_SEC) - TicksPerSecond = (StgDouble) (CLOCKS_PER_SEC); -#else /* had better guess wildly */ - /* We will #ifdef around the fprintf for machines - we *know* are unsupported. (WDP 94/05) - */ - fprintf(stderr, "NOTE: Guessing `TicksPerSecond = 60'!\n"); - TicksPerSecond = 60.0; -#endif - - getTimes(); - ElapsedTimeStart = CurrentElapsedTime; + elapsed = getProcessElapsedTime(); + ElapsedTimeStart = elapsed; } void stat_endInit(void) { - getTimes(); - InitUserTime = CurrentUserTime; - InitElapsedStamp = CurrentElapsedTime; - if (ElapsedTimeStart > CurrentElapsedTime) { + Ticks user, elapsed; + + getProcessTimes(&user, &elapsed); + + InitUserTime = user; + InitElapsedStamp = elapsed; + if (ElapsedTimeStart > elapsed) { InitElapsedTime = 0; } else { - InitElapsedTime = CurrentElapsedTime - ElapsedTimeStart; + InitElapsedTime = elapsed - ElapsedTimeStart; } } @@ -279,35 +176,28 @@ stat_endInit(void) void stat_startExit(void) { - getTimes(); - MutElapsedStamp = CurrentElapsedTime; - MutElapsedTime = CurrentElapsedTime - GCe_tot_time - InitElapsedStamp; + Ticks user, elapsed; + + getProcessTimes(&user, &elapsed); + + MutElapsedStamp = elapsed; + MutElapsedTime = elapsed - GCe_tot_time - + PROF_VAL(RPe_tot_time + HCe_tot_time) - InitElapsedStamp; if (MutElapsedTime < 0) { MutElapsedTime = 0; } /* sometimes -0.00 */ - - /* for SMP, we don't know the mutator time yet, we have to inspect - * all the running threads to find out, and they haven't stopped - * yet. So we just timestamp MutUserTime at this point so we can - * calculate the EXIT time. The real MutUserTime is calculated - * in stat_exit below. - */ -#ifdef SMP - MutUserTime = CurrentUserTime; -#else - MutUserTime = CurrentUserTime - GC_tot_time - InitUserTime; + + MutUserTime = user - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime; if (MutUserTime < 0) { MutUserTime = 0; } -#endif } void stat_endExit(void) { - getTimes(); -#ifdef SMP - ExitUserTime = CurrentUserTime - MutUserTime; -#else - ExitUserTime = CurrentUserTime - MutUserTime - GC_tot_time - InitUserTime; -#endif - ExitElapsedTime = CurrentElapsedTime - MutElapsedStamp; + Ticks user, elapsed; + + getProcessTimes(&user, &elapsed); + + ExitUserTime = user - MutUserTime - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime; + ExitElapsedTime = elapsed - MutElapsedStamp; if (ExitUserTime < 0) { ExitUserTime = 0; } @@ -334,26 +224,24 @@ stat_startGC(void) if (bell) { if (bell > 1) { - fprintf(stderr, " GC "); + debugBelch(" GC "); rub_bell = 1; } else { - fprintf(stderr, "\007"); + debugBelch("\007"); } } #if defined(PROFILING) || defined(DEBUG) - getTimes(); - GC_start_time = CurrentUserTime; /* needed in mut_user_time_during_GC() */ + GC_start_time = getProcessCPUTime(); // needed in mut_user_time_during_GC() #endif if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) { #if !defined(PROFILING) && !defined(DEBUG) - getTimes(); - GC_start_time = CurrentUserTime; + GC_start_time = getProcessCPUTime(); #endif - GCe_start_time = CurrentElapsedTime; + GCe_start_time = getProcessElapsedTime(); if (RtsFlags.GcFlags.giveStats) { - GC_start_faults = pageFaults(); + GC_start_faults = getPageFaults(); } } } @@ -363,25 +251,23 @@ stat_startGC(void) -------------------------------------------------------------------------- */ void -stat_endGC(lnat alloc, lnat collect, lnat live, lnat copied, lnat gen) +stat_endGC (lnat alloc, lnat live, lnat copied, + lnat scavd_copied, lnat gen) { - FILE *sf = RtsFlags.GcFlags.statsFile; - if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) { - TICK_TYPE time, etime, gc_time, gc_etime; + Ticks time, etime, gc_time, gc_etime; - getTimes(); - time = CurrentUserTime; - etime = CurrentElapsedTime; + getProcessTimes(&time, &etime); gc_time = time - GC_start_time; gc_etime = etime - GCe_start_time; - if (RtsFlags.GcFlags.giveStats == VERBOSE_GC_STATS && sf != NULL) { - nat faults = pageFaults(); + if (RtsFlags.GcFlags.giveStats == VERBOSE_GC_STATS) { + nat faults = getPageFaults(); - fprintf(sf, "%9ld %9ld %9ld", - alloc*sizeof(W_), collect*sizeof(W_), live*sizeof(W_)); - fprintf(sf, " %5.2f %5.2f %7.2f %7.2f %4ld %4ld (Gen: %2ld)\n", + statsPrintf("%9ld %9ld %9ld", + alloc*sizeof(W_), (copied+scavd_copied)*sizeof(W_), + live*sizeof(W_)); + statsPrintf(" %5.2f %5.2f %7.2f %7.2f %4ld %4ld (Gen: %2ld)\n", TICK_TO_DBL(gc_time), TICK_TO_DBL(gc_etime), TICK_TO_DBL(time), @@ -391,27 +277,23 @@ stat_endGC(lnat alloc, lnat collect, lnat live, lnat copied, lnat gen) gen); GC_end_faults = faults; - fflush(sf); + statsFlush(); } GC_coll_times[gen] += gc_time; GC_tot_copied += (ullong) copied; + GC_tot_scavd_copied += (ullong) scavd_copied; GC_tot_alloc += (ullong) alloc; GC_tot_time += gc_time; GCe_tot_time += gc_etime; -#ifdef SMP +#if defined(THREADED_RTS) { - nat i; - pthread_t me = pthread_self(); - - for (i = 0; i < RtsFlags.ParFlags.nNodes; i++) { - if (me == task_ids[i].id) { - task_ids[i].gc_time += gc_time; - task_ids[i].gc_etime += gc_etime; - break; - } + Task *task; + if ((task = myTask()) != NULL) { + task->gc_time += gc_time; + task->gc_etime += gc_etime; } } #endif @@ -426,37 +308,85 @@ stat_endGC(lnat alloc, lnat collect, lnat live, lnat copied, lnat gen) } if (rub_bell) { - fprintf(stderr, "\b\b\b \b\b\b"); + debugBelch("\b\b\b \b\b\b"); rub_bell = 0; } } /* ----------------------------------------------------------------------------- - stat_workerStop + Called at the beginning of each Retainer Profiliing + -------------------------------------------------------------------------- */ +#ifdef PROFILING +void +stat_startRP(void) +{ + Ticks user, elapsed; + getProcessTimes( &user, &elapsed ); + + RP_start_time = user; + RPe_start_time = elapsed; +} +#endif /* PROFILING */ + +/* ----------------------------------------------------------------------------- + Called at the end of each Retainer Profiliing + -------------------------------------------------------------------------- */ + +#ifdef PROFILING +void +stat_endRP( + nat retainerGeneration, +#ifdef DEBUG_RETAINER + nat maxCStackSize, + int maxStackSize, +#endif + double averageNumVisit) +{ + Ticks 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()); +#ifdef 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 under SMP when a worker thread finishes. We drop the timing - stats for this thread into the task_ids struct for that thread. +/* ----------------------------------------------------------------------------- + Called at the beginning of each heap census -------------------------------------------------------------------------- */ +#ifdef PROFILING +void +stat_startHeapCensus(void) +{ + Ticks user, elapsed; + getProcessTimes( &user, &elapsed ); + + HC_start_time = user; + HCe_start_time = elapsed; +} +#endif /* PROFILING */ -#ifdef SMP +/* ----------------------------------------------------------------------------- + Called at the end of each heap census + -------------------------------------------------------------------------- */ +#ifdef PROFILING void -stat_workerStop(void) +stat_endHeapCensus(void) { - nat i; - pthread_t me = pthread_self(); - - for (i = 0; i < RtsFlags.ParFlags.nNodes; i++) { - if (task_ids[i].id == me) { - task_ids[i].mut_time = usertime() - task_ids[i].gc_time; - task_ids[i].mut_etime = elapsedtime() - - GCe_tot_time - - task_ids[i].elapsedtimestart; - if (task_ids[i].mut_time < 0.0) { task_ids[i].mut_time = 0.0; } - if (task_ids[i].mut_etime < 0.0) { task_ids[i].mut_etime = 0.0; } - } - } + Ticks user, elapsed; + getProcessTimes( &user, &elapsed ); + + HC_tot_time += user - HC_start_time; + HCe_tot_time += elapsed - HCe_start_time; } -#endif +#endif /* PROFILING */ /* ----------------------------------------------------------------------------- Called at the end of execution @@ -469,135 +399,138 @@ stat_workerStop(void) void stat_exit(int alloc) { - FILE *sf = RtsFlags.GcFlags.statsFile; - if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) { char temp[BIG_STRING_LEN]; - TICK_TYPE time; - TICK_TYPE etime; + Ticks time; + Ticks etime; nat g, total_collections = 0; - getTimes(); - time = CurrentUserTime; - etime = CurrentElapsedTime - ElapsedTimeStart; + getProcessTimes( &time, &etime ); + etime -= ElapsedTimeStart; GC_tot_alloc += alloc; - /* avoid divide by zero if time is measured as 0.00 seconds -- SDM */ - if (time == 0.0) time = 1; - if (etime == 0.0) etime = 1; - /* Count total garbage collections */ for (g = 0; g < RtsFlags.GcFlags.generations; g++) total_collections += generations[g].collections; - /* For SMP, we have to get the user time from each thread - * and try to work out the total time. - */ -#ifdef SMP - { nat i; - MutUserTime = 0.0; - for (i = 0; i < RtsFlags.ParFlags.nNodes; i++) { - MutUserTime += task_ids[i].mut_time; - } - } - time = MutUserTime + GC_tot_time + InitUserTime + ExitUserTime; - if (MutUserTime < 0) { MutUserTime = 0; } -#endif - - if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS && sf != NULL) { - fprintf(sf, "%9ld %9.9s %9.9s", (lnat)alloc*sizeof(W_), "", ""); - fprintf(sf, " %5.2f %5.2f\n\n", 0.0, 0.0); + /* avoid divide by zero if time is measured as 0.00 seconds -- SDM */ + if (time == 0.0) time = 1; + if (etime == 0.0) etime = 1; + + if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) { + statsPrintf("%9ld %9.9s %9.9s", (lnat)alloc*sizeof(W_), "", ""); + statsPrintf(" %5.2f %5.2f\n\n", 0.0, 0.0); } - if (RtsFlags.GcFlags.giveStats >= SUMMARY_GC_STATS && sf != NULL) { + if (RtsFlags.GcFlags.giveStats >= SUMMARY_GC_STATS) { ullong_format_string(GC_tot_alloc*sizeof(W_), temp, rtsTrue/*commas*/); - fprintf(sf, "%11s bytes allocated in the heap\n", temp); + statsPrintf("%11s bytes allocated in the heap\n", temp); ullong_format_string(GC_tot_copied*sizeof(W_), temp, rtsTrue/*commas*/); - fprintf(sf, "%11s bytes copied during GC\n", temp); + statsPrintf("%11s bytes copied during GC (scavenged)\n", temp); + ullong_format_string(GC_tot_scavd_copied*sizeof(W_), + temp, rtsTrue/*commas*/); + statsPrintf("%11s bytes copied during GC (not scavenged)\n", temp); + if ( ResidencySamples > 0 ) { ullong_format_string(MaxResidency*sizeof(W_), temp, rtsTrue/*commas*/); - fprintf(sf, "%11s bytes maximum residency (%ld sample(s))\n", + statsPrintf("%11s bytes maximum residency (%ld sample(s))\n", temp, ResidencySamples); } - fprintf(sf,"\n"); + statsPrintf("\n"); /* Print garbage collections in each gen */ for (g = 0; g < RtsFlags.GcFlags.generations; g++) { - fprintf(sf, "%11d collections in generation %d (%6.2fs)\n", + statsPrintf("%11d collections in generation %d (%6.2fs)\n", generations[g].collections, g, TICK_TO_DBL(GC_coll_times[g])); } - fprintf(sf,"\n%11ld Mb total memory in use\n\n", + statsPrintf("\n%11ld Mb total memory in use\n\n", mblocks_allocated * MBLOCK_SIZE / (1024 * 1024)); -#ifdef SMP +#if defined(THREADED_RTS) { nat i; - for (i = 0; i < RtsFlags.ParFlags.nNodes; i++) { - fprintf(sf, " Task %2d: MUT time: %6.2fs (%6.2fs elapsed)\n" - " GC time: %6.2fs (%6.2fs elapsed)\n\n", - i, - TICK_TO_DBL(task_ids[i].mut_time), - TICK_TO_DBL(task_ids[i].mut_etime), - TICK_TO_DBL(task_ids[i].gc_time), - TICK_TO_DBL(task_ids[i].gc_etime)); + Task *task; + 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", + i, + (task->tso == NULL) ? "(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)); } } #endif - fprintf(sf, " INIT time %6.2fs (%6.2fs elapsed)\n", + statsPrintf(" INIT time %6.2fs (%6.2fs elapsed)\n", TICK_TO_DBL(InitUserTime), TICK_TO_DBL(InitElapsedTime)); - fprintf(sf, " MUT time %6.2fs (%6.2fs elapsed)\n", + statsPrintf(" MUT time %6.2fs (%6.2fs elapsed)\n", TICK_TO_DBL(MutUserTime), TICK_TO_DBL(MutElapsedTime)); - fprintf(sf, " GC time %6.2fs (%6.2fs elapsed)\n", + statsPrintf(" GC time %6.2fs (%6.2fs elapsed)\n", TICK_TO_DBL(GC_tot_time), TICK_TO_DBL(GCe_tot_time)); - fprintf(sf, " EXIT time %6.2fs (%6.2fs elapsed)\n", +#ifdef PROFILING + statsPrintf(" RP time %6.2fs (%6.2fs elapsed)\n", + TICK_TO_DBL(RP_tot_time), TICK_TO_DBL(RPe_tot_time)); + statsPrintf(" PROF time %6.2fs (%6.2fs elapsed)\n", + TICK_TO_DBL(HC_tot_time), TICK_TO_DBL(HCe_tot_time)); +#endif + statsPrintf(" EXIT time %6.2fs (%6.2fs elapsed)\n", TICK_TO_DBL(ExitUserTime), TICK_TO_DBL(ExitElapsedTime)); - fprintf(sf, " Total time %6.2fs (%6.2fs elapsed)\n\n", + statsPrintf(" Total time %6.2fs (%6.2fs elapsed)\n\n", TICK_TO_DBL(time), TICK_TO_DBL(etime)); - fprintf(sf, " %%GC time %5.1f%% (%.1f%% elapsed)\n\n", - TICK_TO_DBL(GC_tot_time)*100/time, - TICK_TO_DBL(GCe_tot_time)*100/etime); + statsPrintf(" %%GC time %5.1f%% (%.1f%% elapsed)\n\n", + TICK_TO_DBL(GC_tot_time)*100/TICK_TO_DBL(time), + TICK_TO_DBL(GCe_tot_time)*100/TICK_TO_DBL(etime)); - if (time - GC_tot_time == 0) + if (time - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time) == 0) ullong_format_string(0, temp, rtsTrue/*commas*/); else ullong_format_string( (ullong)((GC_tot_alloc*sizeof(W_))/ - TICK_TO_DBL(time - GC_tot_time)), + TICK_TO_DBL(time - GC_tot_time - + PROF_VAL(RP_tot_time + HC_tot_time))), temp, rtsTrue/*commas*/); - fprintf(sf, " Alloc rate %s bytes per MUT second\n\n", temp); + statsPrintf(" Alloc rate %s bytes per MUT second\n\n", temp); - fprintf(sf, " Productivity %5.1f%% of total user, %.1f%% of total elapsed\n\n", - TICK_TO_DBL(time - GC_tot_time - InitUserTime) * 100 + statsPrintf(" Productivity %5.1f%% of total user, %.1f%% of total elapsed\n\n", + TICK_TO_DBL(time - GC_tot_time - + PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime) * 100 / TICK_TO_DBL(time), - TICK_TO_DBL(time - GC_tot_time - InitUserTime) * 100 + TICK_TO_DBL(time - GC_tot_time - + PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime) * 100 / TICK_TO_DBL(etime)); } - if (RtsFlags.GcFlags.giveStats == ONELINE_GC_STATS && sf != NULL) { - fprintf(sf, "<>\n", - GC_tot_alloc*sizeof(W_), total_collections, - AvgResidency*sizeof(W_)/ResidencySamples, + if (RtsFlags.GcFlags.giveStats == ONELINE_GC_STATS) { + /* print the long long separately to avoid bugginess on mingwin (2001-07-02, mingw-0.5) */ + statsPrintf("<>\n", + total_collections, + ResidencySamples == 0 ? 0 : + AvgResidency*sizeof(W_)/ResidencySamples, MaxResidency*sizeof(W_), - ResidencySamples, - mblocks_allocated * MBLOCK_SIZE / (1024 * 1024), + ResidencySamples, + (unsigned long)(mblocks_allocated * MBLOCK_SIZE / (1024L * 1024L)), TICK_TO_DBL(InitUserTime), TICK_TO_DBL(InitElapsedTime), TICK_TO_DBL(MutUserTime), TICK_TO_DBL(MutElapsedTime), TICK_TO_DBL(GC_tot_time), TICK_TO_DBL(GCe_tot_time)); } - fflush(sf); - fclose(sf); + statsFlush(); + statsClose(); } } @@ -606,53 +539,94 @@ stat_exit(int alloc) Produce some detailed info on the state of the generational GC. -------------------------------------------------------------------------- */ +#ifdef DEBUG void -stat_describe_gens(void) +statDescribeGens(void) { - nat g, s, mut, mut_once, lge, live; - StgMutClosure *m; + nat g, s, mut, lge; + lnat live; bdescr *bd; step *step; - fprintf(stderr, " Gen Steps Max Mutable Mut-Once Step Blocks Live Large\n Blocks Closures Closures Objects\n"); + debugBelch( +" Gen Steps Max Mutable Step Blocks Live Large\n" +" Blocks Closures Objects\n"); + mut = 0; for (g = 0; g < RtsFlags.GcFlags.generations; g++) { - for (m = generations[g].mut_list, mut = 0; m != END_MUT_LIST; - m = m->mut_link) - mut++; - for (m = generations[g].mut_once_list, mut_once = 0; m != END_MUT_LIST; - m = m->mut_link) - mut_once++; - fprintf(stderr, "%8d %8d %8d %9d %9d", g, generations[g].n_steps, - generations[g].max_blocks, mut, mut_once); + for (bd = generations[g].mut_list; bd != NULL; bd = bd->link) { + mut += bd->free - bd->start; + } + + debugBelch("%8d %8d %8d %9d", g, generations[g].n_steps, + generations[g].max_blocks, mut); for (s = 0; s < generations[g].n_steps; s++) { step = &generations[g].steps[s]; - for (bd = step->large_objects, lge = 0; bd; bd = bd->link) - lge++; live = 0; - if (RtsFlags.GcFlags.generations == 1) { - bd = step->to_space; - } else { - bd = step->blocks; + for (bd = step->large_objects, lge = 0; bd; bd = bd->link) { + lge++; } + live = step->n_large_blocks * BLOCK_SIZE; + bd = step->blocks; + // This live figure will be slightly less that the "live" figure + // given by +RTS -Sstderr, because we take don't count the + // slop at the end of each block. for (; bd; bd = bd->link) { live += (bd->free - bd->start) * sizeof(W_); } if (s != 0) { - fprintf(stderr,"%46s",""); + debugBelch("%36s",""); } - fprintf(stderr,"%6d %8d %8d %8d\n", s, step->n_blocks, + debugBelch("%6d %8d %8d %8d\n", s, step->n_blocks, live, lge); } } - fprintf(stderr,"\n"); + debugBelch("\n"); } +#endif /* ----------------------------------------------------------------------------- Stats available via a programmatic interface, so eg. GHCi can time each compilation and expression evaluation. -------------------------------------------------------------------------- */ -extern HsInt getAllocations( void ) -{ return (HsInt)(total_allocated * sizeof(W_)); } +extern HsInt64 getAllocations( void ) +{ return (HsInt64)total_allocated * sizeof(W_); } + +/* ----------------------------------------------------------------------------- + Dumping stuff in the stats file, or via the debug message interface + -------------------------------------------------------------------------- */ + +static 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); + } +}