X-Git-Url: http://git.megacz.com/?a=blobdiff_plain;f=ghc%2Frts%2FStats.c;h=529201971ab7d5e4b02c0e08f31feb6fb1ba9826;hb=14ba76f47ab6fd51a18ff15b788fe29c5f849689;hp=efa3e314985008d05e5bf36cacbf2d3d09ffb9a8;hpb=9a92cb1ca49cb555ff66dcfcb9295ebf75d1ce01;p=ghc-hetmet.git diff --git a/ghc/rts/Stats.c b/ghc/rts/Stats.c index efa3e31..5292019 100644 --- a/ghc/rts/Stats.c +++ b/ghc/rts/Stats.c @@ -1,15 +1,11 @@ /* ----------------------------------------------------------------------------- * - * (c) The GHC Team, 1998-2004 + * (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" @@ -19,90 +15,39 @@ #include "ParTicky.h" /* ToDo: move into Rts.h */ #include "Profiling.h" #include "Storage.h" -#include "Task.h" - -#ifdef HAVE_UNISTD_H -#include -#endif - -#ifndef mingw32_HOST_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_HOST_OS && ! defined(mingw32_HOST_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_HOST_OS || defined(mingw32_HOST_OS) || defined(cygwin32_HOST_OS)) -#include -#endif +#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 @@ -117,10 +62,7 @@ static lnat ResidencySamples = 0; // for stats only static lnat GC_start_faults = 0, GC_end_faults = 0; -static TICK_TYPE *GC_coll_times; - -static void getTimes(void); -static nat pageFaults(void); +static Ticks *GC_coll_times; static void statsPrintf( char *s, ... ) GNUC3_ATTRIBUTE(format (printf, 1, 2)); @@ -128,96 +70,11 @@ static void statsPrintf( char *s, ... ) static void statsFlush( void ); static void statsClose( void ); -/* elapsedtime() -- The current elapsed time in seconds */ - -#if defined(mingw32_HOST_OS) || defined(cygwin32_HOST_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_HOST_OS) || defined(cygwin32_HOST_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) - */ - debugBelch("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 @@ -239,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 @@ -262,33 +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_HOST_OS || defined(mingw32_HOST_OS) || defined(cygwin32_HOST_OS) - return 0; -# else - struct rusage t; - - getrusage(RUSAGE_SELF, &t); - return(t.ru_majflt); -# endif -} - void initStats(void) { nat i; if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) { - statsPrintf(" Alloc Collect Live GC GC TOT TOT Page Flts\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; @@ -302,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 ) { - debugBelch("stat_init: bad call to 'sysconf'!\n"); - stg_exit(EXIT_FAILURE); - } - TicksPerSecond = ticks; - -/* 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) - */ - debugBelch("NOTE: Guessing `TicksPerSecond = 60'!\n"); - TicksPerSecond = 60; -#endif + Ticks elapsed; - 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; } } @@ -357,36 +176,28 @@ stat_endInit(void) void stat_startExit(void) { - getTimes(); - MutElapsedStamp = CurrentElapsedTime; - MutElapsedTime = CurrentElapsedTime - GCe_tot_time - + 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 threads, 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. - */ -#if defined(RTS_SUPPORTS_THREADS) - 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(); -#if defined(RTS_SUPPORTS_THREADS) - 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; } @@ -421,18 +232,16 @@ stat_startGC(void) } #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(); } } } @@ -442,22 +251,22 @@ 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) { 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) { - nat faults = pageFaults(); + nat faults = getPageFaults(); statsPrintf("%9ld %9ld %9ld", - alloc*sizeof(W_), collect*sizeof(W_), live*sizeof(W_)); + 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), @@ -474,17 +283,17 @@ stat_endGC(lnat alloc, lnat collect, lnat live, lnat copied, lnat gen) 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; -#if defined(RTS_SUPPORTS_THREADS) +#if defined(THREADED_RTS) { - TaskInfo *task_info = taskOfId(osThreadId()); - - if (task_info != NULL) { - task_info->gc_time += gc_time; - task_info->gc_etime += gc_etime; + Task *task; + if ((task = myTask()) != NULL) { + task->gc_time += gc_time; + task->gc_etime += gc_etime; } } #endif @@ -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,29 +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 taskTable struct for that thread. - -------------------------------------------------------------------------- */ - -void -stat_getTimes ( long *currentElapsedTime, - long *currentUserTime, - long *elapsedGCTime ) -{ - getTimes(); - *currentElapsedTime = CurrentElapsedTime; - *currentUserTime = CurrentUserTime; - *elapsedGCTime = GCe_tot_time; + HC_tot_time += user - HC_start_time; + HCe_tot_time += elapsed - HCe_start_time; } +#endif /* PROFILING */ /* ----------------------------------------------------------------------------- Called at the end of execution @@ -603,12 +402,12 @@ stat_exit(int alloc) 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(); - etime = CurrentElapsedTime - ElapsedTimeStart; + getProcessTimes( &time, &etime ); + etime -= ElapsedTimeStart; GC_tot_alloc += alloc; @@ -616,23 +415,6 @@ stat_exit(int alloc) 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. - */ -#if defined(RTS_SUPPORTS_THREADS) - { - nat i; - MutUserTime = 0.0; - for (i = 0; i < taskCount; i++) { - MutUserTime += taskTable[i].mut_time; - } - } - time = MutUserTime + GC_tot_time + InitUserTime + ExitUserTime; - if (MutUserTime < 0) { MutUserTime = 0; } -#else - time = CurrentUserTime; -#endif - /* 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; @@ -649,8 +431,12 @@ stat_exit(int alloc) ullong_format_string(GC_tot_copied*sizeof(W_), temp, rtsTrue/*commas*/); - statsPrintf("%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*/); @@ -669,18 +455,21 @@ stat_exit(int alloc) statsPrintf("\n%11ld Mb total memory in use\n\n", mblocks_allocated * MBLOCK_SIZE / (1024 * 1024)); -#if defined(RTS_SUPPORTS_THREADS) +#if defined(THREADED_RTS) { nat i; - for (i = 0; i < taskCount; i++) { + 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, - taskTable[i].is_worker ? "(worker)" : "(bound)", - TICK_TO_DBL(taskTable[i].mut_time), - TICK_TO_DBL(taskTable[i].mut_etime), - TICK_TO_DBL(taskTable[i].gc_time), - TICK_TO_DBL(taskTable[i].gc_etime)); + (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 @@ -758,7 +547,9 @@ statDescribeGens(void) bdescr *bd; step *step; - debugBelch(" Gen Steps Max Mutable 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++) { @@ -774,16 +565,12 @@ statDescribeGens(void) 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; - } + bd = step->blocks; for (; bd; bd = bd->link) { live += (bd->free - bd->start) * sizeof(W_); } if (s != 0) { - debugBelch("%46s",""); + debugBelch("%36s",""); } debugBelch("%6d %8d %8d %8d\n", s, step->n_blocks, live, lge);