1 /* -----------------------------------------------------------------------------
2 * $Id: Stats.c,v 1.21 2000/07/17 15:15:40 rrt Exp $
4 * (c) The GHC Team, 1998-1999
6 * Statistics and timing-related functions.
8 * ---------------------------------------------------------------------------*/
10 #define NON_POSIX_SOURCE
15 #include "StoragePriv.h"
24 #ifndef mingw32_TARGET_OS
25 # ifdef HAVE_SYS_TIMES_H
26 # include <sys/times.h>
30 #ifdef HAVE_SYS_TIME_H
40 #if ! irix_TARGET_OS && ! defined(mingw32_TARGET_OS)
41 # if defined(HAVE_SYS_RESOURCE_H)
42 # include <sys/resource.h>
46 #ifdef HAVE_SYS_TIMEB_H
47 #include <sys/timeb.h>
59 #define BIG_STRING_LEN 512
61 static double ElapsedTimeStart = 0.0;
62 static double TicksPerSecond = 0.0;
64 static double InitUserTime = 0.0;
65 static double InitElapsedTime = 0.0;
66 static double InitElapsedStamp = 0.0;
68 static double MutUserTime = 0.0;
69 static double MutElapsedTime = 0.0;
70 static double MutElapsedStamp = 0.0;
72 static double ExitUserTime = 0.0;
73 static double ExitElapsedTime = 0.0;
75 static ullong GC_tot_alloc = 0;
76 static ullong GC_tot_copied = 0;
78 static double GC_start_time, GC_tot_time = 0; /* User GC Time */
79 static double GCe_start_time, GCe_tot_time = 0; /* Elapsed GC time */
81 lnat MaxResidency = 0; /* in words; for stats only */
82 lnat ResidencySamples = 0; /* for stats only */
84 static lnat GC_start_faults = 0, GC_end_faults = 0;
86 static double *GC_coll_times;
88 /* ToDo: convert this to use integers? --SDM */
90 /* elapsedtime() -- The current elapsed time in seconds */
93 #define NS_PER_SEC 10000000LL
94 /* Convert FILETIMEs into secs since the Epoch (Jan1-1970) */
95 #define FT2longlong(ll,ft) \
96 (ll)=(ft).dwHighDateTime; \
98 (ll) |= (ft).dwLowDateTime; \
99 (ll) /= (unsigned long long) (NS_PER_SEC / CLOCKS_PER_SEC)
103 /* cygwin32 or mingw32 version */
107 FILETIME creationTime, exitTime, kernelTime, userTime;
108 long long int kT, uT;
111 /* ToDo: pin down elapsed times to just the OS thread(s) that
112 are evaluating/managing Haskell code.
114 if (!GetProcessTimes (GetCurrentProcess(), &creationTime,
115 &exitTime, &kernelTime, &userTime)) {
116 /* Probably on a Win95 box..*/
120 FT2longlong(kT,kernelTime);
121 FT2longlong(uT,userTime);
122 return (((StgDouble)(uT + kT))/TicksPerSecond);
131 # if ! (defined(HAVE_TIMES) || defined(HAVE_FTIME))
132 /* We will #ifdef around the fprintf for machines
133 we *know* are unsupported. (WDP 94/05)
135 fprintf(stderr, "NOTE: `elapsedtime' does nothing!\n");
138 # else /* not stumped */
140 /* "ftime" may be nicer, but "times" is more standard;
141 but, on a Sun, if you do not get the SysV one, you are *hosed*...
144 # if defined(HAVE_TIMES) && ! sunos4_TARGET_OS
146 clock_t r = times(&t);
148 return (((double)r)/TicksPerSecond);
150 # else /* HAVE_FTIME */
154 return (fabs(t.time + 1e-3*t.millitm));
156 # endif /* HAVE_FTIME */
157 # endif /* not stumped */
161 /* mut_user_time_during_GC() and mut_user_time()
163 * The former function can be used to get the current mutator time
164 * *during* a GC, i.e. between stat_startGC and stat_endGC. This is
165 * used in the heap profiler for accurately time stamping the heap
168 * ATTENTION: mut_user_time_during_GC() relies on GC_start_time being
169 * defined in stat_startGC() - to minimise system calls,
170 * GC_start_time is, however, only defined when really needed (check
171 * stat_startGC() for details)
174 mut_user_time_during_GC(void)
176 return (GC_start_time - GC_tot_time);
182 return (usertime() - GC_tot_time);
189 /* ToDo (on NT): better, get this via the performance data
190 that's stored in the registry. */
191 # if !defined(HAVE_GETRUSAGE) || irix_TARGET_OS || defined(_WIN32)
196 getrusage(RUSAGE_SELF, &t);
201 /* ToDo: use gettimeofday on systems that support it (u-sec accuracy) */
208 /* Determine TicksPerSecond ... */
210 ticks = sysconf(_SC_CLK_TCK);
212 fprintf(stderr, "stat_init: bad call to 'sysconf'!\n");
213 stg_exit(EXIT_FAILURE);
215 TicksPerSecond = (double) ticks;
217 /* no "sysconf"; had better guess */
219 TicksPerSecond = (StgDouble) (HZ);
221 #elif defined(CLOCKS_PER_SEC)
222 TicksPerSecond = (StgDouble) (CLOCKS_PER_SEC);
223 #else /* had better guess wildly */
224 /* We will #ifdef around the fprintf for machines
225 we *know* are unsupported. (WDP 94/05)
227 fprintf(stderr, "NOTE: Guessing `TicksPerSecond = 60'!\n");
228 TicksPerSecond = 60.0;
231 ElapsedTimeStart = elapsedtime();
239 FILE *sf = RtsFlags.GcFlags.statsFile;
241 if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) {
242 fprintf(sf, " Alloc Collect Live GC GC TOT TOT Page Flts\n");
243 fprintf(sf, " bytes bytes bytes user elap user elap\n");
246 (double *)stgMallocBytes(sizeof(double) * RtsFlags.GcFlags.generations,
248 for (i = 0; i < RtsFlags.GcFlags.generations; i++) {
249 GC_coll_times[i] = 0.0;
257 FILETIME creationTime, exitTime, kernelTime, userTime;
260 /* Convert FILETIMEs into long longs */
262 if (!GetProcessTimes (GetCurrentProcess(), &creationTime,
263 &exitTime, &kernelTime, &userTime)) {
264 /* Probably exec'ing this on a Win95 box..*/
268 FT2longlong(uT,userTime);
269 return (((StgDouble)uT)/TicksPerSecond);
276 # if ! (defined(HAVE_GETRUSAGE) || defined(HAVE_TIMES))
277 /* We will #ifdef around the fprintf for machines
278 we *know* are unsupported. (WDP 94/05)
280 fprintf(stderr, "NOTE: `usertime' does nothing!\n");
283 # else /* not stumped */
285 # if defined(HAVE_TIMES)
289 return(((double)(t.tms_utime))/TicksPerSecond);
291 # else /* HAVE_GETRUSAGE */
294 getrusage(RUSAGE_SELF, &t);
295 return(t.ru_utime.tv_sec + 1e-6*t.ru_utime.tv_usec);
297 # endif /* HAVE_GETRUSAGE */
298 # endif /* not stumped */
300 #endif /* ! _WIN32 */
305 InitUserTime = usertime();
306 InitElapsedStamp = elapsedtime();
307 InitElapsedTime = InitElapsedStamp - ElapsedTimeStart;
308 if (InitElapsedTime < 0.0) {
309 InitElapsedTime = 0.0;
313 /* -----------------------------------------------------------------------------
314 stat_startExit and stat_endExit
316 These two measure the time taken in shutdownHaskell().
317 -------------------------------------------------------------------------- */
322 MutElapsedStamp = elapsedtime();
323 MutElapsedTime = MutElapsedStamp - GCe_tot_time - InitElapsedStamp;
324 if (MutElapsedTime < 0) { MutElapsedTime = 0; } /* sometimes -0.00 */
326 /* for SMP, we don't know the mutator time yet, we have to inspect
327 * all the running threads to find out, and they haven't stopped
328 * yet. So we just timestamp MutUserTime at this point so we can
329 * calculate the EXIT time. The real MutUserTime is calculated
330 * in stat_exit below.
333 MutUserTime = usertime();
335 MutUserTime = usertime() - GC_tot_time - InitUserTime;
336 if (MutUserTime < 0) { MutUserTime = 0; }
344 ExitUserTime = usertime() - MutUserTime;
346 ExitUserTime = usertime() - MutUserTime - GC_tot_time - InitUserTime;
348 ExitElapsedTime = elapsedtime() - MutElapsedStamp;
349 if (ExitUserTime < 0.0) {
352 if (ExitElapsedTime < 0.0) {
353 ExitElapsedTime = 0.0;
357 /* -----------------------------------------------------------------------------
358 Called at the beginning of each GC
359 -------------------------------------------------------------------------- */
361 static nat rub_bell = 0;
363 /* initialise global variables needed during GC
365 * * GC_start_time is read in mut_user_time_during_GC(), which in turn is
366 * needed if either PROFILING or DEBUGing is enabled
371 FILE *sf = RtsFlags.GcFlags.statsFile;
373 nat bell = RtsFlags.GcFlags.ringBell;
377 fprintf(stderr, " GC ");
380 fprintf(stderr, "\007");
384 #if defined(PROFILING) || defined(DEBUG)
385 GC_start_time = usertime(); /* needed in mut_user_time_during_GC() */
389 #if !defined(PROFILING) && !defined(DEBUG)
390 GC_start_time = usertime();
392 GCe_start_time = elapsedtime();
393 if (RtsFlags.GcFlags.giveStats) {
394 GC_start_faults = pagefaults();
399 /* -----------------------------------------------------------------------------
400 Called at the end of each GC
401 -------------------------------------------------------------------------- */
404 stat_endGC(lnat alloc, lnat collect, lnat live, lnat copied, lnat gen)
406 FILE *sf = RtsFlags.GcFlags.statsFile;
409 double time = usertime();
410 double etime = elapsedtime();
411 double gc_time = time - GC_start_time;
412 double gc_etime = etime - GCe_start_time;
414 if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) {
415 nat faults = pagefaults();
417 fprintf(sf, "%9ld %9ld %9ld",
418 alloc*sizeof(W_), collect*sizeof(W_), live*sizeof(W_));
419 fprintf(sf, " %5.2f %5.2f %7.2f %7.2f %4ld %4ld (Gen: %2ld)\n",
423 etime - ElapsedTimeStart,
424 faults - GC_start_faults,
425 GC_start_faults - GC_end_faults,
428 GC_end_faults = faults;
432 GC_coll_times[gen] += gc_time;
434 GC_tot_copied += (ullong) copied;
435 GC_tot_alloc += (ullong) alloc;
436 GC_tot_time += gc_time;
437 GCe_tot_time += gc_etime;
442 pthread_t me = pthread_self();
444 for (i = 0; i < RtsFlags.ParFlags.nNodes; i++) {
445 if (me == task_ids[i].id) {
446 task_ids[i].gc_time += gc_time;
447 task_ids[i].gc_etime += gc_etime;
454 if (gen == RtsFlags.GcFlags.generations-1) { /* major GC? */
455 if (live > MaxResidency) {
463 fprintf(stderr, "\b\b\b \b\b\b");
468 /* -----------------------------------------------------------------------------
471 Called under SMP when a worker thread finishes. We drop the timing
472 stats for this thread into the task_ids struct for that thread.
473 -------------------------------------------------------------------------- */
477 stat_workerStop(void)
480 pthread_t me = pthread_self();
482 for (i = 0; i < RtsFlags.ParFlags.nNodes; i++) {
483 if (task_ids[i].id == me) {
484 task_ids[i].mut_time = usertime() - task_ids[i].gc_time;
485 task_ids[i].mut_etime = elapsedtime()
487 - task_ids[i].elapsedtimestart;
488 if (task_ids[i].mut_time < 0.0) { task_ids[i].mut_time = 0.0; }
489 if (task_ids[i].mut_etime < 0.0) { task_ids[i].mut_etime = 0.0; }
495 /* -----------------------------------------------------------------------------
496 Called at the end of execution
498 NOTE: number of allocations is not entirely accurate: it doesn't
499 take into account the few bytes at the end of the heap that
500 were left unused when the heap-check failed.
501 -------------------------------------------------------------------------- */
506 FILE *sf = RtsFlags.GcFlags.statsFile;
509 char temp[BIG_STRING_LEN];
510 double time = usertime();
511 double etime = elapsedtime() - ElapsedTimeStart;
513 /* avoid divide by zero if time is measured as 0.00 seconds -- SDM */
514 if (time == 0.0) time = 0.0001;
515 if (etime == 0.0) etime = 0.0001;
517 if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) {
518 fprintf(sf, "%9ld %9.9s %9.9s", (lnat)alloc*sizeof(W_), "", "");
519 fprintf(sf, " %5.2f %5.2f\n\n", 0.0, 0.0);
522 GC_tot_alloc += alloc;
524 ullong_format_string(GC_tot_alloc*sizeof(W_), temp, rtsTrue/*commas*/);
525 fprintf(sf, "%11s bytes allocated in the heap\n", temp);
527 ullong_format_string(GC_tot_copied*sizeof(W_), temp, rtsTrue/*commas*/);
528 fprintf(sf, "%11s bytes copied during GC\n", temp);
530 if ( ResidencySamples > 0 ) {
531 ullong_format_string(MaxResidency*sizeof(W_), temp, rtsTrue/*commas*/);
532 fprintf(sf, "%11s bytes maximum residency (%ld sample(s))\n",
538 { /* Count garbage collections */
540 for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
541 fprintf(sf, "%11d collections in generation %d (%6.2fs)\n",
542 generations[g].collections, g, GC_coll_times[g]);
545 fprintf(sf,"\n%11ld Mb total memory in use\n\n",
546 mblocks_allocated * MBLOCK_SIZE / (1024 * 1024));
548 /* For SMP, we have to get the user time from each thread
549 * and try to work out the total time.
555 for (i = 0; i < RtsFlags.ParFlags.nNodes; i++) {
556 MutUserTime += task_ids[i].mut_time;
557 fprintf(sf, " Task %2d: MUT time: %6.2fs (%6.2fs elapsed)\n"
558 " GC time: %6.2fs (%6.2fs elapsed)\n\n",
560 task_ids[i].mut_time, task_ids[i].mut_etime,
561 task_ids[i].gc_time, task_ids[i].gc_etime);
564 time = MutUserTime + GC_tot_time + InitUserTime + ExitUserTime;
565 if (MutUserTime < 0) { MutUserTime = 0; }
568 fprintf(sf, " INIT time %6.2fs (%6.2fs elapsed)\n",
569 InitUserTime, InitElapsedTime);
570 fprintf(sf, " MUT time %6.2fs (%6.2fs elapsed)\n",
571 MutUserTime, MutElapsedTime);
572 fprintf(sf, " GC time %6.2fs (%6.2fs elapsed)\n",
573 GC_tot_time, GCe_tot_time);
574 fprintf(sf, " EXIT time %6.2fs (%6.2fs elapsed)\n",
575 ExitUserTime, ExitElapsedTime);
576 fprintf(sf, " Total time %6.2fs (%6.2fs elapsed)\n\n",
579 fprintf(sf, " %%GC time %5.1f%% (%.1f%% elapsed)\n\n",
580 GC_tot_time*100./time, GCe_tot_time*100./etime);
582 if (time - GC_tot_time == 0.0)
583 ullong_format_string(0, temp, rtsTrue/*commas*/);
585 ullong_format_string((ullong)(GC_tot_alloc*sizeof(W_)/
586 (time - GC_tot_time)),
587 temp, rtsTrue/*commas*/);
589 fprintf(sf, " Alloc rate %s bytes per MUT second\n\n", temp);
591 fprintf(sf, " Productivity %5.1f%% of total user, %.1f%% of total elapsed\n\n",
592 (time - GC_tot_time - InitUserTime) * 100. / time,
593 (time - GC_tot_time - InitUserTime) * 100. / etime);
599 /* -----------------------------------------------------------------------------
602 Produce some detailed info on the state of the generational GC.
603 -------------------------------------------------------------------------- */
605 stat_describe_gens(void)
607 nat g, s, mut, mut_once, lge, live;
612 fprintf(stderr, " Gen Steps Max Mutable Mut-Once Step Blocks Live Large\n Blocks Closures Closures Objects\n");
614 for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
615 for (m = generations[g].mut_list, mut = 0; m != END_MUT_LIST;
618 for (m = generations[g].mut_once_list, mut_once = 0; m != END_MUT_LIST;
621 fprintf(stderr, "%8d %8d %8d %9d %9d", g, generations[g].n_steps,
622 generations[g].max_blocks, mut, mut_once);
624 for (s = 0; s < generations[g].n_steps; s++) {
625 step = &generations[g].steps[s];
626 for (bd = step->large_objects, lge = 0; bd; bd = bd->link)
629 if (RtsFlags.GcFlags.generations == 1) {
634 for (; bd; bd = bd->link) {
635 live += (bd->free - bd->start) * sizeof(W_);
638 fprintf(stderr,"%46s","");
640 fprintf(stderr,"%6d %8d %8d %8d\n", s, step->n_blocks,
644 fprintf(stderr,"\n");