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 if (RTSflags.GcFlags.giveStats) {
460 fprintf(sf, "%8ld\n\n", alloc*sizeof(W_));
463 #if defined(GCap) || defined (GCgn)
465 fprintf(sf, "%8ld %7.7s %6.6s %7.7s %6.6s",
466 (GC_alloc_since_maj + alloc)*sizeof(W_), "", "", "", "");
467 fprintf(sf, " %3ld %5.2f %5.2f\n\n",
468 GC_min_since_maj, GC_min_time, GCe_min_time);
470 GC_min_no += GC_min_since_maj;
471 GC_tot_time += GC_min_time;
472 GCe_tot_time += GCe_min_time;
473 GC_tot_alloc += (ullong) (GC_alloc_since_maj + alloc);
474 ullong_format_string(GC_tot_alloc*sizeof(W_), temp, rtsTrue/*commas*/);
475 fprintf(sf, "%11s bytes allocated in the heap\n", temp);
476 if ( ResidencySamples > 0 ) {
477 ullong_format_string(MaxResidency*sizeof(W_), temp, rtsTrue/*commas*/);
478 fprintf(sf, "%11s bytes maximum residency (%.1f%%, %ld sample(s))\n",
480 MaxResidency / (StgDouble) RTSflags.GcFlags.heapSize * 100,
483 fprintf(sf, "%11ld garbage collections performed (%ld major, %ld minor)\n\n",
484 GC_maj_no + GC_min_no, GC_maj_no, GC_min_no);
486 #else /* ! generational */
488 GC_tot_alloc += (ullong) alloc;
489 ullong_format_string(GC_tot_alloc*sizeof(W_), temp, rtsTrue/*commas*/);
490 fprintf(sf, "%11s bytes allocated in the heap\n", temp);
491 if ( ResidencySamples > 0 ) {
492 ullong_format_string(MaxResidency*sizeof(W_), temp, rtsTrue/*commas*/);
493 fprintf(sf, "%11s bytes maximum residency (%.1f%%, %ld sample(s))\n",
495 MaxResidency / (StgDouble) RTSflags.GcFlags.heapSize * 100,
498 fprintf(sf, "%11ld garbage collections performed\n\n", GC_maj_no);
500 #endif /* ! generational */
502 fprintf(sf, " INIT time %6.2fs (%6.2fs elapsed)\n",
503 InitUserTime, InitElapsedTime);
504 fprintf(sf, " MUT time %6.2fs (%6.2fs elapsed)\n",
505 time - GC_tot_time - InitUserTime,
506 etime - GCe_tot_time - InitElapsedTime);
507 fprintf(sf, " GC time %6.2fs (%6.2fs elapsed)\n",
508 GC_tot_time, GCe_tot_time);
509 fprintf(sf, " Total time %6.2fs (%6.2fs elapsed)\n\n",
512 fprintf(sf, " %%GC time %5.1f%% (%.1f%% elapsed)\n\n",
513 GC_tot_time*100./time, GCe_tot_time*100./etime);
515 ullong_format_string((ullong)(GC_tot_alloc*sizeof(W_)/(time - GC_tot_time)), temp, rtsTrue/*commas*/);
516 fprintf(sf, " Alloc rate %s bytes per MUT second\n\n", temp);
518 fprintf(sf, " Productivity %5.1f%% of total user, %.1f%% of total elapsed\n\n",
519 (time - GC_tot_time - InitUserTime) * 100. / time,
520 (time - GC_tot_time - InitUserTime) * 100. / etime);