1 /* -----------------------------------------------------------------------------
2 * $Id: Stats.c,v 1.8 1999/02/23 12:02:57 simonm 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_ */
58 #ifdef HAVE_SYS_TIMES_H
59 #include <sys/times.h>
62 #ifdef HAVE_SYS_TIME_H
66 #if defined(HAVE_SYS_RESOURCE_H) && ! irix_TARGET_OS
67 #include <sys/resource.h>
70 #ifdef HAVE_SYS_TIMEB_H
71 #include <sys/timeb.h>
79 #define BIG_STRING_LEN 512
81 static double ElapsedTimeStart = 0.0;
82 static double TicksPerSecond = 0.0;
84 static double InitUserTime = 0.0;
85 static double InitElapsedTime = 0.0;
87 static ullong GC_tot_alloc = 0;
89 static double GC_start_time, GC_tot_time = 0; /* User GC Time */
90 static double GCe_start_time, GCe_tot_time = 0; /* Elapsed GC time */
92 lnat MaxResidency = 0; /* in words; for stats only */
93 lnat ResidencySamples = 0; /* for stats only */
95 static lnat GC_start_faults = 0, GC_end_faults = 0;
97 static double *GC_coll_times;
99 /* ToDo: convert this to use integers? --SDM */
101 /* elapsedtime() -- The current elapsed time in seconds */
106 #if ! (defined(HAVE_TIMES) || defined(HAVE_FTIME))
107 /* We will #ifdef around the fprintf for machines
108 we *know* are unsupported. (WDP 94/05)
110 fprintf(stderr, "NOTE: `elapsedtime' does nothing!\n");
113 #else /* not stumped */
115 /* "ftime" may be nicer, but "times" is more standard;
116 but, on a Sun, if you do not get the SysV one, you are *hosed*...
119 # if defined(HAVE_TIMES) && ! sunos4_TARGET_OS
121 clock_t r = times(&t);
123 return (((double)r)/TicksPerSecond - ElapsedTimeStart);
125 # else /* HAVE_FTIME */
129 return (fabs(t.time + 1e-3*t.millitm - ElapsedTimeStart));
131 # endif /* HAVE_FTIME */
132 #endif /* not stumped */
138 # if !defined(HAVE_GETRUSAGE) || irix_TARGET_OS
143 getrusage(RUSAGE_SELF, &t);
148 /* ToDo: use gettimeofday on systems that support it (u-sec accuracy) */
154 /* Determine TicksPerSecond ... */
156 ticks = sysconf(_SC_CLK_TCK);
158 fprintf(stderr, "stat_init: bad call to 'sysconf'!\n");
159 stg_exit(EXIT_FAILURE);
161 TicksPerSecond = (double) ticks;
163 #else /* no "sysconf"; had better guess */
165 TicksPerSecond = (double) (HZ);
167 # else /* had better guess wildly */
168 /* We will #ifdef around the fprintf for machines
169 we *know* are unsupported. (WDP 94/05)
171 fprintf(stderr, "NOTE: Guessing `TicksPerSecond = 60'!\n");
172 TicksPerSecond = 60.0;
176 ElapsedTimeStart = elapsedtime();
184 FILE *sf = RtsFlags.GcFlags.statsFile;
186 if (RtsFlags.GcFlags.giveStats) {
187 fprintf(sf, " Alloc Collect Live GC GC TOT TOT Page Flts\n");
188 fprintf(sf, " bytes bytes bytes user elap user elap\n");
192 (double *)stgMallocBytes(sizeof(double) * RtsFlags.GcFlags.generations,
194 for (i = 0; i < RtsFlags.GcFlags.generations; i++) {
195 GC_coll_times[i] = 0.0;
203 #if ! (defined(HAVE_GETRUSAGE) || defined(HAVE_TIMES))
204 /* We will #ifdef around the fprintf for machines
205 we *know* are unsupported. (WDP 94/05)
207 fprintf(stderr, "NOTE: `usertime' does nothing!\n");
210 #else /* not stumped */
212 # if defined(HAVE_TIMES)
216 return(((double)(t.tms_utime))/TicksPerSecond);
218 #else /* HAVE_GETRUSAGE */
221 getrusage(RUSAGE_SELF, &t);
222 return(t.ru_utime.tv_sec + 1e-6*t.ru_utime.tv_usec);
224 # endif /* HAVE_GETRUSAGE */
225 #endif /* not stumped */
231 InitUserTime = usertime();
232 InitElapsedTime = elapsedtime();
233 if (InitElapsedTime < 0.0) {
234 InitElapsedTime = 0.0;
238 /* -----------------------------------------------------------------------------
239 Called at the beginning of each GC
240 -------------------------------------------------------------------------- */
242 static nat rub_bell = 0;
247 FILE *sf = RtsFlags.GcFlags.statsFile;
249 nat bell = RtsFlags.GcFlags.ringBell;
253 fprintf(stderr, " GC ");
256 fprintf(stderr, "\007");
261 GC_start_time = usertime();
262 GCe_start_time = elapsedtime();
263 if (RtsFlags.GcFlags.giveStats) {
264 GC_start_faults = pagefaults();
269 /* -----------------------------------------------------------------------------
270 Called at the end of each GC
271 -------------------------------------------------------------------------- */
274 stat_endGC(lnat alloc, lnat collect, lnat live, lnat gen)
276 FILE *sf = RtsFlags.GcFlags.statsFile;
279 double time = usertime();
280 double etime = elapsedtime();
282 if (RtsFlags.GcFlags.giveStats) {
283 nat faults = pagefaults();
285 fprintf(sf, "%9ld %9ld %9ld",
286 alloc*sizeof(W_), collect*sizeof(W_), live*sizeof(W_));
287 fprintf(sf, " %5.2f %5.2f %7.2f %7.2f %4ld %4ld (Gen: %2ld)\n",
288 (time-GC_start_time),
289 (etime-GCe_start_time),
292 faults - GC_start_faults,
293 GC_start_faults - GC_end_faults,
296 GC_end_faults = faults;
300 GC_coll_times[gen] += time-GC_start_time;
302 GC_tot_alloc += (ullong) alloc;
303 GC_tot_time += time-GC_start_time;
304 GCe_tot_time += etime-GCe_start_time;
306 if (gen == RtsFlags.GcFlags.generations-1) { /* major GC? */
307 if (live > MaxResidency) {
315 fprintf(stderr, "\b\b\b \b\b\b");
320 /* -----------------------------------------------------------------------------
321 Called at the end of execution
323 NOTE: number of allocations is not entirely accurate: it doesn't
324 take into account the few bytes at the end of the heap that
325 were left unused when the heap-check failed.
326 -------------------------------------------------------------------------- */
331 FILE *sf = RtsFlags.GcFlags.statsFile;
334 char temp[BIG_STRING_LEN];
335 double time = usertime();
336 double etime = elapsedtime();
337 double MutTime, MutElapsedTime;
339 /* avoid divide by zero if time is measured as 0.00 seconds -- SDM */
340 if (time == 0.0) time = 0.0001;
341 if (etime == 0.0) etime = 0.0001;
344 fprintf(sf, "%9ld %9.9s %9.9s",
345 (lnat)alloc*sizeof(W_), "", "");
346 fprintf(sf, " %5.2f %5.2f\n\n", 0.0, 0.0);
348 GC_tot_alloc += alloc;
350 ullong_format_string(GC_tot_alloc*sizeof(W_), temp, rtsTrue/*commas*/);
351 fprintf(sf, "%11s bytes allocated in the heap\n", temp);
353 if ( ResidencySamples > 0 ) {
354 ullong_format_string(MaxResidency*sizeof(W_), temp, rtsTrue/*commas*/);
355 fprintf(sf, "%11s bytes maximum residency (%ld sample(s))\n",
361 { /* Count garbage collections */
363 for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
364 fprintf(sf, "%11d collections in generation %d (%6.2fs)\n",
365 generations[g].collections, g, GC_coll_times[g]);
368 fprintf(sf,"\n%11ld Mb total memory in use\n\n",
369 mblocks_allocated * MBLOCK_SIZE / (1024 * 1024));
371 MutTime = time - GC_tot_time - InitUserTime;
372 if (MutTime < 0) { MutTime = 0; }
373 MutElapsedTime = etime - GCe_tot_time - InitElapsedTime;
374 if (MutElapsedTime < 0) { MutElapsedTime = 0; } /* sometimes -0.00 */
376 fprintf(sf, " INIT time %6.2fs (%6.2fs elapsed)\n",
377 InitUserTime, InitElapsedTime);
378 fprintf(sf, " MUT time %6.2fs (%6.2fs elapsed)\n",
379 MutTime, MutElapsedTime);
380 fprintf(sf, " GC time %6.2fs (%6.2fs elapsed)\n",
381 GC_tot_time, GCe_tot_time);
382 fprintf(sf, " Total time %6.2fs (%6.2fs elapsed)\n\n",
385 fprintf(sf, " %%GC time %5.1f%% (%.1f%% elapsed)\n\n",
386 GC_tot_time*100./time, GCe_tot_time*100./etime);
388 if (time - GC_tot_time == 0.0)
389 ullong_format_string(0, temp, rtsTrue/*commas*/);
391 ullong_format_string((ullong)(GC_tot_alloc*sizeof(W_)/
392 (time - GC_tot_time)),
393 temp, rtsTrue/*commas*/);
395 fprintf(sf, " Alloc rate %s bytes per MUT second\n\n", temp);
397 fprintf(sf, " Productivity %5.1f%% of total user, %.1f%% of total elapsed\n\n",
398 (time - GC_tot_time - InitUserTime) * 100. / time,
399 (time - GC_tot_time - InitUserTime) * 100. / etime);
405 /* -----------------------------------------------------------------------------
408 Produce some detailed info on the state of the generational GC.
409 -------------------------------------------------------------------------- */
411 stat_describe_gens(void)
413 nat g, s, mut, mut_once, lge, live;
418 fprintf(stderr, " Gen Steps Max Mutable Mut-Once Step Blocks Live Large\n Blocks Closures Closures Objects\n");
420 for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
421 for (m = generations[g].mut_list, mut = 0; m != END_MUT_LIST;
424 for (m = generations[g].mut_once_list, mut_once = 0; m != END_MUT_LIST;
427 fprintf(stderr, "%8d %8d %8d %9d %9d", g, generations[g].n_steps,
428 generations[g].max_blocks, mut, mut_once);
430 for (s = 0; s < generations[g].n_steps; s++) {
431 step = &generations[g].steps[s];
432 for (bd = step->large_objects, lge = 0; bd; bd = bd->link)
435 if (RtsFlags.GcFlags.generations == 1) {
440 for (; bd; bd = bd->link) {
441 live += (bd->free - bd->start) * sizeof(W_);
444 fprintf(stderr,"%46s","");
446 fprintf(stderr,"%6d %8d %8d %8d\n", s, step->n_blocks,
450 fprintf(stderr,"\n");