1 *********************************************************************
3 Stuff for printing out GC statistics
5 usertime() -- The current user time in seconds
6 elapsedtime() -- The current elapsed time in seconds
13 *********************************************************************
17 #define NON_POSIX_SOURCE /*needed for solaris2 only?*/
21 #include "SMinternal.h"
25 #define _INCLUDE_HPUX_SOURCE
28 #ifdef HAVE_SYS_TYPES_H
29 #include <sys/types.h>
36 #ifdef HAVE_SYS_TIMES_H
37 #include <sys/times.h>
40 #ifdef HAVE_SYS_TIME_H
44 #if defined(HAVE_SYS_RESOURCE_H) && ! irix_TARGET_OS
45 #include <sys/resource.h>
48 #ifdef HAVE_SYS_TIMEB_H
49 #include <sys/timeb.h>
53 #include <sys/syscall.h>
54 #define getrusage(a, b) syscall(SYS_GETRUSAGE, a, b)
55 #define HAVE_GETRUSAGE
59 getrusage() is not the preferred way of getting at process-specific
60 info under Solaris...at least it wasn't. It was supported via a BSD
61 compatibility library in 2.4, whereas 2.5 has it in libc.
63 The upshot of this change of heart is that we cannot rely on getrusage()
64 being available via libc, i.e., 2.5 binaries will not run under 2.4
65 without some extra work. Could use libucb under 2.5 as well, but
66 a simpler solution is simply to avoid the problem and stay away
67 from getrusage() for Solaris -- SOF
69 #if solaris2_TARGET_OS
70 #undef __STRICT_ANSI__ /* oh, dear */
71 #include <sys/fcntl.h>
72 #include <sys/signal.h>
73 #include <sys/procfs.h>
76 static StgDouble GC_start_time, GC_tot_time = 0; /* User GC Time */
77 static StgDouble GCe_start_time, GCe_tot_time = 0; /* Elapsed GC time */
79 #if defined(GCap) || defined(GCgn)
80 static StgDouble GC_min_time = 0;
81 static StgDouble GCe_min_time = 0;
83 static I_ GC_min_no = 0;
84 static I_ GC_min_since_maj = 0;
85 static I_ GC_live_maj = 0; /* Heap live at last major collection */
86 static I_ GC_alloc_since_maj = 0; /* Heap alloc since collection major */
89 static I_ GC_maj_no = 0;
90 static ullong GC_tot_alloc = 0; /* Total heap allocated -- 64 bits? */
92 static I_ GC_start_faults = 0, GC_end_faults = 0;
95 ullong_format_string(ullong x, char *s, rtsBool with_commas)
98 sprintf(s, "%ld", (I_)x);
99 else if (x < (ullong)1000000)
100 sprintf(s, (with_commas) ? "%ld,%3.3ld" : "%ld%3.3ld",
101 (I_)((x)/(ullong)1000),
102 (I_)((x)%(ullong)1000));
103 else if (x < (ullong)1000000000)
104 sprintf(s, (with_commas) ? "%ld,%3.3ld,%3.3ld" : "%ld%3.3ld%3.3ld",
105 (I_)((x)/(ullong)1000000),
106 (I_)((x)/(ullong)1000%(ullong)1000),
107 (I_)((x)%(ullong)1000));
109 sprintf(s, (with_commas) ? "%ld,%3.3ld,%3.3ld,%3.3ld" : "%ld%3.3ld%3.3ld%3.3ld",
110 (I_)((x)/(ullong)1000000000),
111 (I_)((x)/(ullong)1000000%(ullong)1000),
112 (I_)((x)/(ullong)1000%(ullong)1000),
113 (I_)((x)%(ullong)1000));
117 /* "constants" for "usertime" and "elapsedtime" */
119 static StgDouble ElapsedTimeStart = 0.0; /* setup when beginning things */
120 static StgDouble TicksPerSecond = 0.0; /* ditto */
122 /* usertime() -- The current user time in seconds */
127 #if ! (defined(HAVE_GETRUSAGE) || defined(HAVE_TIMES))
128 /* We will #ifdef around the fprintf for machines
129 we *know* are unsupported. (WDP 94/05)
131 fprintf(stderr, "NOTE: `usertime' does nothing!\n");
134 #else /* not stumped */
136 # if defined(HAVE_TIMES)
140 return(((StgDouble)(t.tms_utime))/TicksPerSecond);
142 #else /* HAVE_GETRUSAGE */
145 getrusage(RUSAGE_SELF, &t);
146 return(t.ru_utime.tv_sec + 1e-6*t.ru_utime.tv_usec);
148 # endif /* HAVE_GETRUSAGE */
149 #endif /* not stumped */
153 /* elapsedtime() -- The current elapsed time in seconds */
158 #if ! (defined(HAVE_TIMES) || defined(HAVE_FTIME))
159 /* We will #ifdef around the fprintf for machines
160 we *know* are unsupported. (WDP 94/05)
162 fprintf(stderr, "NOTE: `elapsedtime' does nothing!\n");
165 #else /* not stumped */
167 /* "ftime" may be nicer, but "times" is more standard;
168 but, on a Sun, if you do not get the SysV one, you are *hosed*...
171 # if defined(HAVE_TIMES) && ! sunos4_TARGET_OS
174 return (((StgDouble) times(&t))/TicksPerSecond - ElapsedTimeStart);
176 # else /* HAVE_FTIME */
180 return (fabs(t.time + 1e-3*t.millitm - ElapsedTimeStart));
182 # endif /* HAVE_FTIME */
183 #endif /* not stumped */
187 start_time(STG_NO_ARGS)
191 /* Determine TicksPerSecond ... */
193 ticks = sysconf(_SC_CLK_TCK);
195 fprintf(stderr, "stat_init: bad call to 'sysconf'!\n");
198 TicksPerSecond = (StgDouble) ticks;
200 #else /* no "sysconf"; had better guess */
202 TicksPerSecond = (StgDouble) (HZ);
204 # else /* had better guess wildly */
205 /* We will #ifdef around the fprintf for machines
206 we *know* are unsupported. (WDP 94/05)
208 fprintf(stderr, "NOTE: Guessing `TicksPerSecond = 60'!\n");
209 TicksPerSecond = 60.0;
213 ElapsedTimeStart = elapsedtime();
216 static StgDouble InitUserTime = 0.0; /* user time taken for initialization */
217 static StgDouble InitElapsedTime = 0.0; /* elapsed time taken for initialization */
219 void end_init(STG_NO_ARGS)
221 InitUserTime = usertime();
222 InitElapsedTime = elapsedtime();
225 #if defined(solaris2_TARGET_OS)
227 pagefaults(STG_NO_ARGS)
230 char proc[30]; /* Will break when PIDs are repr. by more than 64bits */
233 /* Under Solaris, we get at the number of major page faults
234 via the process file descriptor and ioctl()ing with
235 PIOCUSAGE to get the prusage_t structure.
236 (as per proc(4) man page and Solaris porting FAQ).
238 sprintf(proc,"/proc/%d", getpid()); /* ToDo: this string is static
239 per process, optimise? */
241 while ((fd = open(proc, O_RDONLY)) == -1 ) {
242 if ( errno != EINTR ) {
244 fprintf(stderr,"pagefaults: open() failed\n");
248 while (ioctl(fd, PIOCUSAGE, &prusage) == -1 ) {
249 if (errno != EINTR) {
251 fprintf(stderr,"pagefaults: ioctl() failed\n");
255 while ((close(fd)) == -1 ) {
256 if (errno != EINTR) {
258 fprintf(stderr, "pagefaults: close() failed\n");
262 return prusage.pr_majf;
267 pagefaults(STG_NO_ARGS)
269 # if !defined(HAVE_GETRUSAGE) || irix_TARGET_OS
274 getrusage(RUSAGE_SELF, &t);
275 /* cygwin32 note: Last time I looked (b18), the ru_majflt field
276 was always filled in with a 0. -- SOF (ToDo: Win32ify?)
283 /* Called at the beginning of execution of the program */
284 /* Writes the command line and inits stats header */
287 stat_init(char *collector, char *comment1, char *comment2)
289 FILE *sf = RTSflags.GcFlags.statsFile;
292 char temp[BIG_STRING_LEN];
293 ullong_format_string( (ullong)RTSflags.GcFlags.heapSize*sizeof(W_), temp, rtsTrue/*commas*/);
294 fprintf(sf, "\nCollector: %s HeapSize: %s (bytes)\n\n", collector, temp);
295 if (RTSflags.GcFlags.giveStats) {
296 #if !defined(HAVE_GETRUSAGE) || irix_TARGET_OS
297 fprintf(sf, "NOTE: `pagefaults' does nothing!\n");
300 /*######## ####### ####### ##.# ##.## ##.## ####.## ####.## #### ####*/
301 " Alloc Collect Live Resid GC GC TOT TOT Page Flts %s\n",
304 " bytes bytes bytes ency user elap user elap GC MUT %s\n",
308 #if defined(GCap) || defined(GCgn)
311 /*######## ####### ##.# ####### ##.# ### ##.## ##.## ##.## ##.## ####.## ####.## #### ####*/
312 " Alloc Promote Promo Live Resid Minor Minor Minor Major Major TOT TOT Page Flts\n");
314 " bytes bytes ted bytes ency No user elap user elap user elap MUT Major\n");
316 #endif /* generational */
322 /* Called at the beginning of each GC */
323 static I_ rub_bell = 0;
326 stat_startGC(I_ alloc)
328 FILE *sf = RTSflags.GcFlags.statsFile;
330 #if defined(GCap) || defined(GCgn)
331 I_ bell = alloc == 0 ? RTSflags.GcFlags.ringBell : 0;
332 #else /* ! generational */
333 I_ bell = RTSflags.GcFlags.ringBell;
334 #endif /* ! generational */
338 fprintf(stderr, " GC ");
341 fprintf(stderr, "\007");
346 GC_start_time = usertime();
347 GCe_start_time = elapsedtime();
349 #if defined(GCap) || defined(GCgn)
350 if (RTSflags.GcFlags.giveStats || alloc == 0) {
351 GC_start_faults = pagefaults();
353 #else /* ! generational */
354 if (RTSflags.GcFlags.giveStats) {
355 GC_start_faults = pagefaults();
357 #endif /* ! generational */
362 /* Called at the end of each GC */
365 stat_endGC(I_ alloc, I_ collect, I_ live, char *comment)
367 FILE *sf = RTSflags.GcFlags.statsFile;
370 StgDouble time = usertime();
371 StgDouble etime = elapsedtime();
373 if (RTSflags.GcFlags.giveStats) {
374 I_ faults = pagefaults();
376 fprintf(sf, "%8ld %7ld %7ld %5.1f%%",
377 alloc*sizeof(W_), collect*sizeof(W_), live*sizeof(W_), collect == 0 ? 0.0 : (live / (StgDouble) collect * 100));
378 fprintf(sf, " %5.2f %5.2f %7.2f %7.2f %4ld %4ld %s\n",
379 (time-GC_start_time),
380 (etime-GCe_start_time),
383 faults - GC_start_faults,
384 GC_start_faults - GC_end_faults,
387 GC_end_faults = faults;
391 #if defined(GCap) || defined(GCgn)
392 else if(alloc == 0 && collect != 0) {
393 I_ faults = pagefaults();
395 fprintf(sf, "%8ld %7ld %5.1f%% %7ld %5.1f%%",
396 GC_alloc_since_maj*sizeof(W_), (collect - GC_live_maj)*sizeof(W_),
397 (collect - GC_live_maj) / (StgDouble) GC_alloc_since_maj * 100,
398 live*sizeof(W_), live / (StgDouble) RTSflags.GcFlags.heapSize * 100);
399 fprintf(sf, " %3ld %5.2f %5.2f %5.2f %5.2f %7.2f %7.2f %4ld %4ld\n",
400 GC_min_since_maj, GC_min_time, GCe_min_time,
401 (time-GC_start_time),
402 (etime-GCe_start_time),
405 faults - GC_start_faults,
406 GC_start_faults - GC_end_faults
409 GC_end_faults = faults;
412 #endif /* generational */
414 #if defined(GCap) || defined(GCgn)
415 if (alloc == 0 && collect != 0) {
418 GC_min_no += GC_min_since_maj;
419 GC_min_since_maj = 0;
420 GC_tot_alloc += (ullong) GC_alloc_since_maj;
421 GC_alloc_since_maj = 0;
422 GC_tot_time += time-GC_start_time + GC_min_time;
424 GCe_tot_time += etime-GCe_start_time + GCe_min_time;
428 GC_alloc_since_maj += alloc;
429 GC_min_time += time-GC_start_time;
430 GCe_min_time += etime-GCe_start_time;
432 #else /* ! generational */
434 GC_tot_alloc += (ullong) alloc;
435 GC_tot_time += time-GC_start_time;
436 GCe_tot_time += etime-GCe_start_time;
437 #endif /* ! generational */
442 fprintf(stderr, "\b\b\b \b\b\b");
447 /* Called at the end of execution -- to print a summary of statistics */
452 FILE *sf = RTSflags.GcFlags.statsFile;
455 char temp[BIG_STRING_LEN];
456 StgDouble time = usertime();
457 StgDouble etime = elapsedtime();
459 /* avoid divide by zero if time is measured as 0.00 seconds -- SDM */
460 if (time == 0.0) time = 0.0001;
461 if (etime == 0.0) etime = 0.0001;
464 if (RTSflags.GcFlags.giveStats) {
465 fprintf(sf, "%8ld\n\n", alloc*sizeof(W_));
468 #if defined(GCap) || defined (GCgn)
470 fprintf(sf, "%8ld %7.7s %6.6s %7.7s %6.6s",
471 (GC_alloc_since_maj + alloc)*sizeof(W_), "", "", "", "");
472 fprintf(sf, " %3ld %5.2f %5.2f\n\n",
473 GC_min_since_maj, GC_min_time, GCe_min_time);
475 GC_min_no += GC_min_since_maj;
476 GC_tot_time += GC_min_time;
477 GCe_tot_time += GCe_min_time;
478 GC_tot_alloc += (ullong) (GC_alloc_since_maj + alloc);
479 ullong_format_string(GC_tot_alloc*sizeof(W_), temp, rtsTrue/*commas*/);
480 fprintf(sf, "%11s bytes allocated in the heap\n", temp);
481 if ( ResidencySamples > 0 ) {
482 ullong_format_string(MaxResidency*sizeof(W_), temp, rtsTrue/*commas*/);
483 fprintf(sf, "%11s bytes maximum residency (%.1f%%, %ld sample(s))\n",
485 MaxResidency / (StgDouble) RTSflags.GcFlags.heapSize * 100,
488 fprintf(sf, "%11ld garbage collections performed (%ld major, %ld minor)\n\n",
489 GC_maj_no + GC_min_no, GC_maj_no, GC_min_no);
491 #else /* ! generational */
493 GC_tot_alloc += (ullong) alloc;
494 ullong_format_string(GC_tot_alloc*sizeof(W_), temp, rtsTrue/*commas*/);
495 fprintf(sf, "%11s bytes allocated in the heap\n", temp);
496 if ( ResidencySamples > 0 ) {
497 ullong_format_string(MaxResidency*sizeof(W_), temp, rtsTrue/*commas*/);
498 fprintf(sf, "%11s bytes maximum residency (%.1f%%, %ld sample(s))\n",
500 MaxResidency / (StgDouble) RTSflags.GcFlags.heapSize * 100,
503 fprintf(sf, "%11ld garbage collections performed\n\n", GC_maj_no);
505 #endif /* ! generational */
507 fprintf(sf, " INIT time %6.2fs (%6.2fs elapsed)\n",
508 InitUserTime, InitElapsedTime);
509 fprintf(sf, " MUT time %6.2fs (%6.2fs elapsed)\n",
510 time - GC_tot_time - InitUserTime,
511 etime - GCe_tot_time - InitElapsedTime);
512 fprintf(sf, " GC time %6.2fs (%6.2fs elapsed)\n",
513 GC_tot_time, GCe_tot_time);
514 fprintf(sf, " Total time %6.2fs (%6.2fs elapsed)\n\n",
517 fprintf(sf, " %%GC time %5.1f%% (%.1f%% elapsed)\n\n",
518 GC_tot_time*100./time, GCe_tot_time*100./etime);
520 if (time - GC_tot_time == 0.0)
521 ullong_format_string((ullong)0, temp, rtsTrue/*commas*/);
523 ullong_format_string((ullong)(time - GC_tot_time),
524 temp, rtsTrue/*commas*/);
526 fprintf(sf, " Alloc rate %s bytes per MUT second\n\n", temp);
528 fprintf(sf, " Productivity %5.1f%% of total user, %.1f%% of total elapsed\n\n",
529 (time - GC_tot_time - InitUserTime) * 100. / time,
530 (time - GC_tot_time - InitUserTime) * 100. / etime);