1 /* -----------------------------------------------------------------------------
2 * $Id: Stats.c,v 1.14 1999/09/15 13:45:20 simonmar Exp $
4 * (c) The GHC Team, 1998-1999
6 * Statistics and timing-related functions.
8 * ---------------------------------------------------------------------------*/
10 #define NON_POSIX_SOURCE
15 #include "StoragePriv.h"
19 * Ian: For the moment we just want to ignore
23 #ifdef HAVE_SYS_TIMES_H
24 #undef HAVE_SYS_TIMES_H /* <sys/times.h> */
26 #ifdef HAVE_SYS_RESOURCE_H /* <sys/resource.h> */
27 #undef HAVE_SYS_RESOURCE_H
29 #ifdef HAVE_SYS_TIME_H /* <sys/time.h> */
30 #undef HAVE_SYS_TIME_H
32 #ifdef HAVE_SYS_TIMEB_H
33 #undef HAVE_SYS_TIMEB_H /* <sys/timeb.h> */
36 #undef HAVE_UNISTD_H /* <unistd.h> */
50 #endif /* _NEMESIS_OS_ */
59 # ifdef HAVE_SYS_TIMES_H
60 # include <sys/times.h>
64 #ifdef HAVE_SYS_TIME_H
74 #if ! irix_TARGET_OS && ! defined(__MINGW32__)
75 # if defined(HAVE_SYS_RESOURCE_H)
76 # include <sys/resource.h>
80 #ifdef HAVE_SYS_TIMEB_H
81 #include <sys/timeb.h>
93 #define BIG_STRING_LEN 512
95 static double ElapsedTimeStart = 0.0;
96 static double TicksPerSecond = 0.0;
98 static double InitUserTime = 0.0;
99 static double InitElapsedTime = 0.0;
101 static ullong GC_tot_alloc = 0;
102 static ullong GC_tot_copied = 0;
104 static double GC_start_time, GC_tot_time = 0; /* User GC Time */
105 static double GCe_start_time, GCe_tot_time = 0; /* Elapsed GC time */
107 lnat MaxResidency = 0; /* in words; for stats only */
108 lnat ResidencySamples = 0; /* for stats only */
110 static lnat GC_start_faults = 0, GC_end_faults = 0;
112 static double *GC_coll_times;
114 /* ToDo: convert this to use integers? --SDM */
116 /* elapsedtime() -- The current elapsed time in seconds */
119 #define NS_PER_SEC 10000000LL
120 /* Convert FILETIMEs into secs since the Epoch (Jan1-1970) */
121 #define FT2longlong(ll,ft) \
122 (ll)=(ft).dwHighDateTime; \
124 (ll) |= (ft).dwLowDateTime; \
125 (ll) /= (unsigned long long) (NS_PER_SEC / CLOCKS_PER_SEC)
129 /* cygwin32 or mingw32 version */
133 FILETIME creationTime, exitTime, kernelTime, userTime;
134 long long int kT, uT;
137 /* ToDo: pin down elapsed times to just the OS thread(s) that
138 are evaluating/managing Haskell code.
140 if (!GetProcessTimes (GetCurrentProcess(), &creationTime,
141 &exitTime, &kernelTime, &userTime)) {
142 /* Probably on a Win95 box..*/
146 FT2longlong(kT,kernelTime);
147 FT2longlong(uT,userTime);
148 return (((StgDouble)(uT + kT))/TicksPerSecond - ElapsedTimeStart);
156 # if ! (defined(HAVE_TIMES) || defined(HAVE_FTIME))
157 /* We will #ifdef around the fprintf for machines
158 we *know* are unsupported. (WDP 94/05)
160 fprintf(stderr, "NOTE: `elapsedtime' does nothing!\n");
163 # else /* not stumped */
165 /* "ftime" may be nicer, but "times" is more standard;
166 but, on a Sun, if you do not get the SysV one, you are *hosed*...
169 # if defined(HAVE_TIMES) && ! sunos4_TARGET_OS
171 clock_t r = times(&t);
173 return (((double)r)/TicksPerSecond - ElapsedTimeStart);
175 # else /* HAVE_FTIME */
179 return (fabs(t.time + 1e-3*t.millitm - ElapsedTimeStart));
181 # endif /* HAVE_FTIME */
182 # endif /* not stumped */
186 /* mut_user_time_during_GC() and mut_user_time()
188 * This function can be used to get the current mutator time *during*
189 * a GC, i.e. between stat_startGC and stat_endGC. This is used in
190 * the heap profiler for accurately time stamping the heap sample.
193 mut_user_time_during_GC(void)
195 return (GC_start_time - GC_tot_time);
201 return (usertime() - GC_tot_time);
208 /* ToDo (on NT): better, get this via the performance data
209 that's stored in the registry. */
210 # if !defined(HAVE_GETRUSAGE) || irix_TARGET_OS || defined(_WIN32)
215 getrusage(RUSAGE_SELF, &t);
220 /* ToDo: use gettimeofday on systems that support it (u-sec accuracy) */
227 /* Determine TicksPerSecond ... */
229 ticks = sysconf(_SC_CLK_TCK);
231 fprintf(stderr, "stat_init: bad call to 'sysconf'!\n");
232 stg_exit(EXIT_FAILURE);
234 TicksPerSecond = (double) ticks;
236 /* no "sysconf"; had better guess */
238 TicksPerSecond = (StgDouble) (HZ);
240 #elif defined(CLOCKS_PER_SEC)
241 TicksPerSecond = (StgDouble) (CLOCKS_PER_SEC);
242 #else /* had better guess wildly */
243 /* We will #ifdef around the fprintf for machines
244 we *know* are unsupported. (WDP 94/05)
246 fprintf(stderr, "NOTE: Guessing `TicksPerSecond = 60'!\n");
247 TicksPerSecond = 60.0;
250 ElapsedTimeStart = elapsedtime();
258 FILE *sf = RtsFlags.GcFlags.statsFile;
260 if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) {
261 fprintf(sf, " Alloc Collect Live GC GC TOT TOT Page Flts\n");
262 fprintf(sf, " bytes bytes bytes user elap user elap\n");
265 (double *)stgMallocBytes(sizeof(double) * RtsFlags.GcFlags.generations,
267 for (i = 0; i < RtsFlags.GcFlags.generations; i++) {
268 GC_coll_times[i] = 0.0;
276 FILETIME creationTime, exitTime, kernelTime, userTime;
279 /* Convert FILETIMEs into long longs */
281 if (!GetProcessTimes (GetCurrentProcess(), &creationTime,
282 &exitTime, &kernelTime, &userTime)) {
283 /* Probably exec'ing this on a Win95 box..*/
287 FT2longlong(uT,userTime);
288 return (((StgDouble)uT)/TicksPerSecond);
295 # if ! (defined(HAVE_GETRUSAGE) || defined(HAVE_TIMES))
296 /* We will #ifdef around the fprintf for machines
297 we *know* are unsupported. (WDP 94/05)
299 fprintf(stderr, "NOTE: `usertime' does nothing!\n");
302 # else /* not stumped */
304 # if defined(HAVE_TIMES)
308 return(((double)(t.tms_utime))/TicksPerSecond);
310 # else /* HAVE_GETRUSAGE */
313 getrusage(RUSAGE_SELF, &t);
314 return(t.ru_utime.tv_sec + 1e-6*t.ru_utime.tv_usec);
316 # endif /* HAVE_GETRUSAGE */
317 # endif /* not stumped */
319 #endif /* ! _WIN32 */
324 InitUserTime = usertime();
325 InitElapsedTime = elapsedtime();
326 if (InitElapsedTime < 0.0) {
327 InitElapsedTime = 0.0;
331 /* -----------------------------------------------------------------------------
332 Called at the beginning of each GC
333 -------------------------------------------------------------------------- */
335 static nat rub_bell = 0;
340 FILE *sf = RtsFlags.GcFlags.statsFile;
342 nat bell = RtsFlags.GcFlags.ringBell;
346 fprintf(stderr, " GC ");
349 fprintf(stderr, "\007");
354 GC_start_time = usertime();
355 GCe_start_time = elapsedtime();
356 if (RtsFlags.GcFlags.giveStats) {
357 GC_start_faults = pagefaults();
362 /* -----------------------------------------------------------------------------
363 Called at the end of each GC
364 -------------------------------------------------------------------------- */
367 stat_endGC(lnat alloc, lnat collect, lnat live, lnat copied, lnat gen)
369 FILE *sf = RtsFlags.GcFlags.statsFile;
372 double time = usertime();
373 double etime = elapsedtime();
375 if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) {
376 nat faults = pagefaults();
378 fprintf(sf, "%9ld %9ld %9ld",
379 alloc*sizeof(W_), collect*sizeof(W_), live*sizeof(W_));
380 fprintf(sf, " %5.2f %5.2f %7.2f %7.2f %4ld %4ld (Gen: %2ld)\n",
381 (time-GC_start_time),
382 (etime-GCe_start_time),
385 faults - GC_start_faults,
386 GC_start_faults - GC_end_faults,
389 GC_end_faults = faults;
393 GC_coll_times[gen] += time-GC_start_time;
395 GC_tot_copied += (ullong) copied;
396 GC_tot_alloc += (ullong) alloc;
397 GC_tot_time += time-GC_start_time;
398 GCe_tot_time += etime-GCe_start_time;
400 if (gen == RtsFlags.GcFlags.generations-1) { /* major GC? */
401 if (live > MaxResidency) {
409 fprintf(stderr, "\b\b\b \b\b\b");
414 /* -----------------------------------------------------------------------------
415 Called at the end of execution
417 NOTE: number of allocations is not entirely accurate: it doesn't
418 take into account the few bytes at the end of the heap that
419 were left unused when the heap-check failed.
420 -------------------------------------------------------------------------- */
425 FILE *sf = RtsFlags.GcFlags.statsFile;
428 char temp[BIG_STRING_LEN];
429 double time = usertime();
430 double etime = elapsedtime();
431 double MutTime, MutElapsedTime;
433 /* avoid divide by zero if time is measured as 0.00 seconds -- SDM */
434 if (time == 0.0) time = 0.0001;
435 if (etime == 0.0) etime = 0.0001;
438 fprintf(sf, "%9ld %9.9s %9.9s",
439 (lnat)alloc*sizeof(W_), "", "");
440 fprintf(sf, " %5.2f %5.2f\n\n", 0.0, 0.0);
442 GC_tot_alloc += alloc;
444 ullong_format_string(GC_tot_alloc*sizeof(W_), temp, rtsTrue/*commas*/);
445 fprintf(sf, "%11s bytes allocated in the heap\n", temp);
447 ullong_format_string(GC_tot_copied*sizeof(W_), temp, rtsTrue/*commas*/);
448 fprintf(sf, "%11s bytes copied during GC\n", temp);
450 if ( ResidencySamples > 0 ) {
451 ullong_format_string(MaxResidency*sizeof(W_), temp, rtsTrue/*commas*/);
452 fprintf(sf, "%11s bytes maximum residency (%ld sample(s))\n",
458 { /* Count garbage collections */
460 for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
461 fprintf(sf, "%11d collections in generation %d (%6.2fs)\n",
462 generations[g].collections, g, GC_coll_times[g]);
465 fprintf(sf,"\n%11ld Mb total memory in use\n\n",
466 mblocks_allocated * MBLOCK_SIZE / (1024 * 1024));
468 MutTime = time - GC_tot_time - InitUserTime;
469 if (MutTime < 0) { MutTime = 0; }
470 MutElapsedTime = etime - GCe_tot_time - InitElapsedTime;
471 if (MutElapsedTime < 0) { MutElapsedTime = 0; } /* sometimes -0.00 */
473 fprintf(sf, " INIT time %6.2fs (%6.2fs elapsed)\n",
474 InitUserTime, InitElapsedTime);
475 fprintf(sf, " MUT time %6.2fs (%6.2fs elapsed)\n",
476 MutTime, MutElapsedTime);
477 fprintf(sf, " GC time %6.2fs (%6.2fs elapsed)\n",
478 GC_tot_time, GCe_tot_time);
479 fprintf(sf, " Total time %6.2fs (%6.2fs elapsed)\n\n",
482 fprintf(sf, " %%GC time %5.1f%% (%.1f%% elapsed)\n\n",
483 GC_tot_time*100./time, GCe_tot_time*100./etime);
485 if (time - GC_tot_time == 0.0)
486 ullong_format_string(0, temp, rtsTrue/*commas*/);
488 ullong_format_string((ullong)(GC_tot_alloc*sizeof(W_)/
489 (time - GC_tot_time)),
490 temp, rtsTrue/*commas*/);
492 fprintf(sf, " Alloc rate %s bytes per MUT second\n\n", temp);
494 fprintf(sf, " Productivity %5.1f%% of total user, %.1f%% of total elapsed\n\n",
495 (time - GC_tot_time - InitUserTime) * 100. / time,
496 (time - GC_tot_time - InitUserTime) * 100. / etime);
502 /* -----------------------------------------------------------------------------
505 Produce some detailed info on the state of the generational GC.
506 -------------------------------------------------------------------------- */
508 stat_describe_gens(void)
510 nat g, s, mut, mut_once, lge, live;
515 fprintf(stderr, " Gen Steps Max Mutable Mut-Once Step Blocks Live Large\n Blocks Closures Closures Objects\n");
517 for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
518 for (m = generations[g].mut_list, mut = 0; m != END_MUT_LIST;
521 for (m = generations[g].mut_once_list, mut_once = 0; m != END_MUT_LIST;
524 fprintf(stderr, "%8d %8d %8d %9d %9d", g, generations[g].n_steps,
525 generations[g].max_blocks, mut, mut_once);
527 for (s = 0; s < generations[g].n_steps; s++) {
528 step = &generations[g].steps[s];
529 for (bd = step->large_objects, lge = 0; bd; bd = bd->link)
532 if (RtsFlags.GcFlags.generations == 1) {
537 for (; bd; bd = bd->link) {
538 live += (bd->free - bd->start) * sizeof(W_);
541 fprintf(stderr,"%46s","");
543 fprintf(stderr,"%6d %8d %8d %8d\n", s, step->n_blocks,
547 fprintf(stderr,"\n");