ghc/runtime/storage/SMstats.lc

   1 *********************************************************************
   2
   3                  Stuff for printing out GC statistics
   4
   5 usertime()    -- The current user time in seconds
   6 elapsedtime() -- The current elapsed time in seconds
   7
   8 stat_init
   9 stat_startGC
  10 stat_endGC
  11 stat_exit
  12
  13 *********************************************************************
  14
  15 \begin{code}
  16 #if !defined(_AIX)
  17 #define NON_POSIX_SOURCE /*needed for solaris2 only?*/
  18 #endif
  19
  20 #define NULL_REG_MAP
  21 #include "SMinternal.h"
  22 #include "Ticky.h"
  23
  24 #ifdef hpux_TARGET_OS
  25 #define _INCLUDE_HPUX_SOURCE
  26 #endif
  27
  28 #ifdef HAVE_SYS_TYPES_H
  29 #include <sys/types.h>
  30 #endif
  31
  32 #ifdef HAVE_UNISTD_H
  33 #include <unistd.h>
  34 #endif
  35
  36 #ifdef HAVE_SYS_TIMES_H
  37 #include <sys/times.h>
  38 #endif
  39
  40 #ifdef HAVE_SYS_TIME_H
  41 #include <sys/time.h>
  42 #endif
  43
  44 #if defined(HAVE_SYS_RESOURCE_H) && ! irix_TARGET_OS
  45 #include <sys/resource.h>
  46 #endif
  47
  48 #ifdef HAVE_SYS_TIMEB_H
  49 #include <sys/timeb.h>
  50 #endif
  51
  52 #ifdef hpux_TARGET_OS
  53 #include <sys/syscall.h>
  54 #define getrusage(a, b)  syscall(SYS_GETRUSAGE, a, b)
  55 #define HAVE_GETRUSAGE
  56 #endif
  57
  58 /*
  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.
  62
  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
  68 */
  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>
  74 #endif
  75
  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 */
  78
  79 #if defined(GCap) || defined(GCgn)
  80 static StgDouble GC_min_time = 0;
  81 static StgDouble GCe_min_time = 0;
  82
  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 */
  87 #endif
  88
  89 static I_ GC_maj_no = 0;
  90 static ullong GC_tot_alloc = 0;        /* Total heap allocated -- 64 bits? */
  91
  92 static I_ GC_start_faults = 0, GC_end_faults = 0;
  93
  94 char *
  95 ullong_format_string(ullong x, char *s, rtsBool with_commas)
  96 {
  97     if (x < (ullong)1000)
  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));
 108     else
 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));
 114     return s;
 115 }
 116
 117 /* "constants" for "usertime" and "elapsedtime" */
 118
 119 static StgDouble ElapsedTimeStart = 0.0; /* setup when beginning things */
 120 static StgDouble TicksPerSecond   = 0.0; /* ditto */
 121
 122 /* usertime() -- The current user time in seconds */
 123
 124 StgDouble
 125 usertime()
 126 {
 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)
 130     */
 131     fprintf(stderr, "NOTE: `usertime' does nothing!\n");
 132     return 0.0;
 133
 134 #else /* not stumped */
 135
 136 # if defined(HAVE_TIMES)
 137     struct tms t;
 138
 139     times(&t);
 140     return(((StgDouble)(t.tms_utime))/TicksPerSecond);
 141
 142 #else /* HAVE_GETRUSAGE */
 143     struct rusage t;
 144
 145     getrusage(RUSAGE_SELF, &t);
 146     return(t.ru_utime.tv_sec + 1e-6*t.ru_utime.tv_usec);
 147
 148 # endif /* HAVE_GETRUSAGE */
 149 #endif /* not stumped */
 150 }
 151
 152
 153 /* elapsedtime() -- The current elapsed time in seconds */
 154
 155 StgDouble
 156 elapsedtime()
 157 {
 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)
 161     */
 162     fprintf(stderr, "NOTE: `elapsedtime' does nothing!\n");
 163     return 0.0;
 164
 165 #else /* not stumped */
 166
 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*...
 169  */
 170
 171 # if defined(HAVE_TIMES) && ! sunos4_TARGET_OS
 172     struct tms t;
 173
 174     return (((StgDouble) times(&t))/TicksPerSecond - ElapsedTimeStart);
 175
 176 # else /* HAVE_FTIME */
 177     struct timeb t;
 178
 179     ftime(&t);
 180     return (fabs(t.time + 1e-3*t.millitm - ElapsedTimeStart));
 181
 182 # endif /* HAVE_FTIME */
 183 #endif /* not stumped */
 184 }
 185
 186 void
 187 start_time(STG_NO_ARGS)
 188 {
 189     long ticks;
 190
 191     /* Determine TicksPerSecond ... */
 192 #ifdef HAVE_SYSCONF
 193     ticks = sysconf(_SC_CLK_TCK);
 194     if ( ticks == -1 ) {
 195         fprintf(stderr, "stat_init: bad call to 'sysconf'!\n");
 196         EXIT(EXIT_FAILURE);
 197     }
 198     TicksPerSecond = (StgDouble) ticks;
 199
 200 #else /* no "sysconf"; had better guess */
 201 # ifdef HZ
 202     TicksPerSecond = (StgDouble) (HZ);
 203
 204 # else /* had better guess wildly */
 205     /* We will #ifdef around the fprintf for machines
 206        we *know* are unsupported. (WDP 94/05)
 207     */
 208     fprintf(stderr, "NOTE: Guessing `TicksPerSecond = 60'!\n");
 209     TicksPerSecond = 60.0;
 210     return;
 211 # endif
 212 #endif
 213     ElapsedTimeStart = elapsedtime();
 214 }
 215
 216 static StgDouble InitUserTime = 0.0; /* user time taken for initialization */
 217 static StgDouble InitElapsedTime = 0.0; /* elapsed time taken for initialization */
 218
 219 void end_init(STG_NO_ARGS)
 220 {
 221     InitUserTime = usertime();
 222     InitElapsedTime = elapsedtime();
 223 }
 224
 225 #if defined(solaris2_TARGET_OS)
 226 static I_
 227 pagefaults(STG_NO_ARGS)
 228 {
 229     int         fd;
 230     char        proc[30]; /* Will break when PIDs are repr. by more than 64bits */
 231     prusage_t   prusage;
 232
 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).
 237     */
 238     sprintf(proc,"/proc/%d", getpid()); /* ToDo: this string is static
 239                                            per process, optimise? */
 240
 241     while ((fd = open(proc, O_RDONLY)) == -1 ) {
 242       if ( errno != EINTR ) {
 243              fflush(stdout);
 244              fprintf(stderr,"pagefaults: open() failed\n");
 245              EXIT(EXIT_FAILURE);
 246         }
 247     }
 248     while (ioctl(fd, PIOCUSAGE, &prusage) == -1 ) {
 249       if (errno != EINTR) {
 250              fflush(stdout);
 251              fprintf(stderr,"pagefaults: ioctl() failed\n");
 252              EXIT(EXIT_FAILURE);
 253         }
 254     }
 255     while ((close(fd)) == -1 ) {
 256       if (errno != EINTR) {
 257             fflush(stdout);
 258             fprintf(stderr, "pagefaults: close() failed\n");
 259             EXIT(EXIT_FAILURE);
 260       }
 261     }
 262     return prusage.pr_majf;
 263 }
 264 #else
 265
 266 static I_
 267 pagefaults(STG_NO_ARGS)
 268 {
 269 # if !defined(HAVE_GETRUSAGE) || irix_TARGET_OS
 270     return 0;
 271 # else
 272     struct rusage t;
 273
 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?)
 277     */
 278     return(t.ru_majflt);
 279 # endif
 280 }
 281 #endif
 282
 283 /* Called at the beginning of execution of the program */
 284 /* Writes the command line and inits stats header */
 285
 286 void
 287 stat_init(char *collector, char *comment1, char *comment2)
 288 {
 289     FILE *sf = RTSflags.GcFlags.statsFile;
 290
 291     if (sf != NULL) {
 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");
 298 #endif
 299             fprintf(sf,
 300 /*######## ####### #######  ##.#  ##.## ##.## ####.## ####.## #### ####*/
 301  "  Alloc  Collect   Live   Resid   GC    GC     TOT     TOT  Page Flts  %s\n",
 302                     comment1);
 303             fprintf(sf,
 304  "  bytes   bytes    bytes   ency  user  elap    user    elap   GC  MUT  %s\n",
 305                     comment2);
 306         }
 307
 308 #if defined(GCap) || defined(GCgn)
 309         else {
 310             fprintf(sf,
 311 /*######## #######  ##.#  #######  ##.#   ###  ##.## ##.## ##.## ##.## ####.## ####.## #### ####*/
 312  "  Alloc  Promote  Promo   Live   Resid Minor Minor Minor Major Major    TOT     TOT  Page Flts\n");
 313             fprintf(sf,
 314  "  bytes   bytes    ted    bytes   ency   No   user  elap  user  elap    user    elap  MUT Major\n");
 315         }
 316 #endif /* generational */
 317
 318         fflush(sf);
 319     }
 320 }
 321
 322 /* Called at the beginning of each GC */
 323 static I_ rub_bell = 0;
 324
 325 void
 326 stat_startGC(I_ alloc)
 327 {
 328     FILE *sf = RTSflags.GcFlags.statsFile;
 329
 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 */
 335
 336     if (bell) {
 337         if (bell > 1) {
 338             fprintf(stderr, " GC ");
 339             rub_bell = 1;
 340         } else {
 341             fprintf(stderr, "\007");
 342         }
 343     }
 344
 345     if (sf != NULL) {
 346         GC_start_time = usertime();
 347         GCe_start_time = elapsedtime();
 348
 349 #if defined(GCap) || defined(GCgn)
 350         if (RTSflags.GcFlags.giveStats || alloc == 0) {
 351             GC_start_faults = pagefaults();
 352         }
 353 #else  /* ! generational */
 354         if (RTSflags.GcFlags.giveStats) {
 355             GC_start_faults = pagefaults();
 356         }
 357 #endif /* ! generational */
 358
 359     }
 360 }
 361
 362 /* Called at the end of each GC */
 363
 364 void
 365 stat_endGC(I_ alloc, I_ collect, I_ live, char *comment)
 366 {
 367     FILE *sf = RTSflags.GcFlags.statsFile;
 368
 369     if (sf != NULL) {
 370         StgDouble time = usertime();
 371         StgDouble etime = elapsedtime();
 372
 373         if (RTSflags.GcFlags.giveStats) {
 374             I_ faults = pagefaults();
 375
 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),
 381                     time,
 382                     etime,
 383                     faults - GC_start_faults,
 384                     GC_start_faults - GC_end_faults,
 385                     comment);
 386
 387             GC_end_faults = faults;
 388             fflush(sf);
 389         }
 390
 391 #if defined(GCap) || defined(GCgn)
 392         else if(alloc == 0 && collect != 0) {
 393             I_ faults = pagefaults();
 394
 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),
 403                     time,
 404                     etime,
 405                     faults - GC_start_faults,
 406                     GC_start_faults - GC_end_faults
 407                     );
 408
 409             GC_end_faults = faults;
 410             fflush(sf);
 411         }
 412 #endif /* generational */
 413
 414 #if defined(GCap) || defined(GCgn)
 415         if (alloc == 0 && collect != 0) {
 416             GC_maj_no++;
 417             GC_live_maj = live;
 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;
 423             GC_min_time = 0;
 424             GCe_tot_time += etime-GCe_start_time + GCe_min_time;
 425             GCe_min_time = 0;
 426         } else {
 427             GC_min_since_maj++;
 428             GC_alloc_since_maj += alloc;
 429             GC_min_time += time-GC_start_time;
 430             GCe_min_time += etime-GCe_start_time;
 431         }
 432 #else /* ! generational */
 433         GC_maj_no++;
 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 */
 438
 439     }
 440
 441     if (rub_bell) {
 442         fprintf(stderr, "\b\b\b  \b\b\b");
 443         rub_bell = 0;
 444     }
 445 }
 446
 447 /* Called at the end of execution -- to print a summary of statistics */
 448
 449 void
 450 stat_exit(I_ alloc)
 451 {
 452     FILE *sf = RTSflags.GcFlags.statsFile;
 453
 454     if (sf != NULL){
 455         char temp[BIG_STRING_LEN];
 456         StgDouble time = usertime();
 457         StgDouble etime = elapsedtime();
 458
 459         if (RTSflags.GcFlags.giveStats) {
 460             fprintf(sf, "%8ld\n\n", alloc*sizeof(W_));
 461         }
 462
 463 #if defined(GCap) || defined (GCgn)
 464         else {
 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);
 469         }
 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",
 479                               temp,
 480                               MaxResidency / (StgDouble) RTSflags.GcFlags.heapSize * 100,
 481                               ResidencySamples);
 482         }
 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);
 485
 486 #else  /* ! generational */
 487
 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",
 494                               temp,
 495                               MaxResidency / (StgDouble) RTSflags.GcFlags.heapSize * 100,
 496                               ResidencySamples);
 497         }
 498         fprintf(sf, "%11ld garbage collections performed\n\n", GC_maj_no);
 499
 500 #endif /* ! generational */
 501
 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",
 510                 time, etime);
 511
 512         fprintf(sf, "  %%GC time     %5.1f%%  (%.1f%% elapsed)\n\n",
 513                 GC_tot_time*100./time, GCe_tot_time*100./etime);
 514
 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);
 517
 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);
 521         fflush(sf);
 522         fclose(sf);
 523     }
 524 }
 525 \end{code}