X-Git-Url: http://git.megacz.com/?a=blobdiff_plain;f=ghc%2Frts%2FStats.c;h=28d09bdbedea1bdd15c4e93df873e3776f3c9903;hb=ba41623270c1d541e74bd5182e1b4fcbe99809cc;hp=4b2699040e3e5ee11caebd79ac2edf9a8597f803;hpb=dbef766ce79e37a74468a07a93b15ba1f06fe8f8;p=ghc-hetmet.git diff --git a/ghc/rts/Stats.c b/ghc/rts/Stats.c index 4b26990..28d09bd 100644 --- a/ghc/rts/Stats.c +++ b/ghc/rts/Stats.c @@ -1,217 +1,80 @@ /* ----------------------------------------------------------------------------- - * $Id: Stats.c,v 1.39 2001/11/26 16:54:22 simonmar Exp $ * - * (c) The GHC Team, 1998-1999 + * (c) The GHC Team, 1998-2005 * * Statistics and timing-related functions. * * ---------------------------------------------------------------------------*/ -/* Alas, no. This source is non-posix. - #include "PosixSource.h" -*/ - #include "Rts.h" #include "RtsFlags.h" #include "RtsUtils.h" -#include "StoragePriv.h" #include "MBlock.h" #include "Schedule.h" #include "Stats.h" #include "ParTicky.h" /* ToDo: move into Rts.h */ #include "Profiling.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 - -#if defined(PAR) || !(!defined(HAVE_GETRUSAGE) || irix_TARGET_OS || defined(mingw32_TARGET_OS) || defined(cygwin32_TARGET_OS)) -#include -#endif +#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 = 0, GC_tot_time = 0; /* User GC Time */ -static TICK_TYPE GCe_start_time = 0, GCe_tot_time = 0; /* Elapsed GC time */ +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 */ #ifdef PROFILING -static TICK_TYPE RP_start_time = 0, RP_tot_time = 0; /* retainer prof user time */ -static TICK_TYPE RPe_start_time = 0, RPe_tot_time = 0; /* retainer prof elap time */ +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 */ -static TICK_TYPE HC_start_time, HC_tot_time = 0; // heap census prof user time -static TICK_TYPE HCe_start_time, HCe_tot_time = 0; // heap census prof elap time +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 PROFILING -#define PROF_VAL(x) x +#define PROF_VAL(x) (x) #else #define PROF_VAL(x) 0 #endif -lnat MaxResidency = 0; /* in words; for stats only */ -lnat AvgResidency = 0; -lnat ResidencySamples = 0; /* for stats only */ +static lnat MaxResidency = 0; // in words; for stats only +static lnat AvgResidency = 0; +static 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_coll_times; -static void getTimes(void); -static nat pageFaults(void); +static void statsPrintf( char *s, ... ) + GNUC3_ATTRIBUTE(format (printf, 1, 2)); -/* elapsedtime() -- The current elapsed time in seconds */ +static void statsFlush( void ); +static void statsClose( void ); -#if defined(mingw32_TARGET_OS) || defined(cygwin32_TARGET_OS) -#define HNS_PER_SEC 10000000LL /* FILETIMES are in units of 100ns */ -/* Convert FILETIMEs into secs */ -#define FT2longlong(ll,ft) \ - (ll)=(ft).dwHighDateTime; \ - (ll) <<= 32; \ - (ll) |= (ft).dwLowDateTime; \ - (ll) /= (unsigned long long) (HNS_PER_SEC / CLOCKS_PER_SEC) -#endif - -#if defined(mingw32_TARGET_OS) || defined(cygwin32_TARGET_OS) -/* cygwin32 or mingw32 version */ -static void -getTimes(void) +Ticks stat_getElapsedGCTime(void) { - static int is_win9x = -1; - - FILETIME creationTime, exitTime, userTime, kernelTime = {0,0}; - long long int kT, uT; - - if (is_win9x < 0) { - /* figure out whether we're on a Win9x box or not. */ - OSVERSIONINFO oi; - BOOL b; - - /* Need to init the size field first.*/ - oi.dwOSVersionInfoSize = sizeof(OSVERSIONINFO); - b = GetVersionEx(&oi); - - is_win9x = ( (b && (oi.dwPlatformId & VER_PLATFORM_WIN32_WINDOWS)) ? 1 : 0); - } - - if (is_win9x) { - /* On Win9x, just attribute all running time to the user. */ - SYSTEMTIME st; - - GetSystemTime(&st); - SystemTimeToFileTime(&st,&userTime); - } else { - /* 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..*/ - CurrentElapsedTime = 0; - CurrentUserTime = 0; - return; - } - } - - FT2longlong(kT,kernelTime); - FT2longlong(uT,userTime); - CurrentElapsedTime = uT + kT; - CurrentUserTime = uT; - - if (is_win9x) { - /* Adjust for the fact that we're using system time & not - process time on Win9x. */ - CurrentUserTime -= ElapsedTimeStart; - CurrentElapsedTime -= ElapsedTimeStart; - } + return GCe_tot_time; } -#else /* !win32 */ - -static void -getTimes(void) -{ - -#ifndef 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; - -#else /* not stumped */ - struct tms t; - clock_t r = times(&t); - - CurrentElapsedTime = r; - CurrentUserTime = t.tms_utime; -#endif - -} -#endif /* !win32 */ - /* mut_user_time_during_GC() and mut_user_time() * * The former function can be used to get the current mutator time @@ -233,8 +96,9 @@ mut_user_time_during_GC( void ) double mut_user_time( void ) { - getTimes(); - return TICK_TO_DBL(CurrentUserTime - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time)); + Ticks user; + user = getProcessCPUTime(); + return TICK_TO_DBL(user - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time)); } #ifdef PROFILING @@ -256,34 +120,18 @@ mut_user_time_during_heap_census( void ) } #endif /* PROFILING */ -static nat -pageFaults(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(mingw32_TARGET_OS) || defined(cygwin32_TARGET_OS) - return 0; -# else - struct rusage t; - - getrusage(RUSAGE_SELF, &t); - return(t.ru_majflt); -# endif -} - 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; @@ -297,49 +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 = sysconf(_SC_CLK_TCK); - if ( ticks == -1 ) { - fprintf(stderr, "stat_init: bad call to 'sysconf'!\n"); - stg_exit(EXIT_FAILURE); - } - TicksPerSecond = ticks; + Ticks elapsed; -/* no "sysconf" or CLK_TCK; had better guess */ -#elif defined(HZ) - TicksPerSecond = HZ; - -#elif defined(CLOCKS_PER_SEC) - TicksPerSecond = 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; -#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; } } @@ -352,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 - PROF_VAL(RP_tot_time + HC_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 - PROF_VAL(RP_tot_time + HC_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; } @@ -407,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(); } } } @@ -436,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), @@ -464,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 @@ -499,7 +308,7 @@ 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; } } @@ -511,9 +320,11 @@ stat_endGC(lnat alloc, lnat collect, lnat live, lnat copied, lnat gen) void stat_startRP(void) { - getTimes(); - RP_start_time = CurrentUserTime; - RPe_start_time = CurrentElapsedTime; + Ticks user, elapsed; + getProcessTimes( &user, &elapsed ); + + RP_start_time = user; + RPe_start_time = elapsed; } #endif /* PROFILING */ @@ -531,9 +342,11 @@ stat_endRP( #endif double averageNumVisit) { - getTimes(); - RP_tot_time += CurrentUserTime - RP_start_time; - RPe_tot_time += CurrentElapsedTime - RPe_start_time; + 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()); @@ -552,9 +365,11 @@ stat_endRP( void stat_startHeapCensus(void) { - getTimes(); - HC_start_time = CurrentUserTime; - HCe_start_time = CurrentElapsedTime; + Ticks user, elapsed; + getProcessTimes( &user, &elapsed ); + + HC_start_time = user; + HCe_start_time = elapsed; } #endif /* PROFILING */ @@ -565,38 +380,13 @@ stat_startHeapCensus(void) void stat_endHeapCensus(void) { - getTimes(); - HC_tot_time += CurrentUserTime - HC_start_time; - HCe_tot_time += CurrentElapsedTime - HCe_start_time; -} -#endif /* PROFILING */ + Ticks user, elapsed; + getProcessTimes( &user, &elapsed ); -/* ----------------------------------------------------------------------------- - stat_workerStop - - Called under SMP when a worker thread finishes. We drop the timing - stats for this thread into the task_ids struct for that thread. - -------------------------------------------------------------------------- */ - -#ifdef SMP -void -stat_workerStop(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; } - } - } + HC_tot_time += user - HC_start_time; + HCe_tot_time += elapsed - HCe_start_time; } -#endif +#endif /* PROFILING */ /* ----------------------------------------------------------------------------- Called at the end of execution @@ -609,107 +399,98 @@ 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)); #ifdef PROFILING - fprintf(sf, " RP time %6.2fs (%6.2fs elapsed)\n", + statsPrintf(" RP time %6.2fs (%6.2fs elapsed)\n", TICK_TO_DBL(RP_tot_time), TICK_TO_DBL(RPe_tot_time)); - fprintf(sf, " PROF time %6.2fs (%6.2fs elapsed)\n", + statsPrintf(" PROF time %6.2fs (%6.2fs elapsed)\n", TICK_TO_DBL(HC_tot_time), TICK_TO_DBL(HCe_tot_time)); #endif - fprintf(sf, " EXIT time %6.2fs (%6.2fs elapsed)\n", + 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", + 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)); @@ -722,9 +503,9 @@ stat_exit(int alloc) 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", + 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), @@ -733,12 +514,13 @@ stat_exit(int alloc) / TICK_TO_DBL(etime)); } - if (RtsFlags.GcFlags.giveStats == ONELINE_GC_STATS && sf != NULL) { + if (RtsFlags.GcFlags.giveStats == ONELINE_GC_STATS) { /* print the long long separately to avoid bugginess on mingwin (2001-07-02, mingw-0.5) */ - fprintf(sf, "<>\n", + statsPrintf("<>\n", total_collections, - AvgResidency*sizeof(W_)/ResidencySamples, + ResidencySamples == 0 ? 0 : + AvgResidency*sizeof(W_)/ResidencySamples, MaxResidency*sizeof(W_), ResidencySamples, (unsigned long)(mblocks_allocated * MBLOCK_SIZE / (1024L * 1024L)), @@ -747,8 +529,8 @@ stat_exit(int alloc) TICK_TO_DBL(GC_tot_time), TICK_TO_DBL(GCe_tot_time)); } - fflush(sf); - fclose(sf); + statsFlush(); + statsClose(); } } @@ -761,44 +543,46 @@ stat_exit(int alloc) 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_blocks; - } 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 @@ -807,5 +591,42 @@ statDescribeGens(void) 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); + } +}