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 solaris2_TARGET_OS
  29 #define __EXTENSIONS__
  30 #endif
  31
  32 #ifdef HAVE_SYS_TYPES_H
  33 #include <sys/types.h>
  34 #endif
  35
  36 #ifdef HAVE_UNISTD_H
  37 #include <unistd.h>
  38 #endif
  39
  40 #ifdef HAVE_SYS_TIMES_H
  41 #include <sys/times.h>
  42 #endif
  43
  44 #ifdef HAVE_SYS_TIME_H
  45 #include <sys/time.h>
  46 #endif
  47
  48 #if defined(HAVE_SYS_RESOURCE_H) && ! irix_TARGET_OS
  49 #include <sys/resource.h>
  50 #endif
  51
  52 #ifdef HAVE_SYS_TIMEB_H
  53 #include <sys/timeb.h>
  54 #endif
  55
  56 #ifdef hpux_TARGET_OS
  57 #include <sys/syscall.h>
  58 #define getrusage(a, b)  syscall(SYS_GETRUSAGE, a, b)
  59 #define HAVE_GETRUSAGE
  60 #endif
  61
  62 /*
  63  getrusage() is not the preferred way of getting at process-specific
  64  info under Solaris...at least it wasn't. It was supported via a BSD
  65  compatibility library in 2.4, whereas 2.5 has it in libc.
  66
  67  The upshot of this change of heart is that we cannot rely on getrusage()
  68  being available via libc, i.e., 2.5 binaries will not run under 2.4
  69  without some extra work. Could use libucb under 2.5 as well, but
  70  a simpler solution is simply to avoid the problem and stay away
  71  from getrusage() for Solaris   -- SOF
  72 */
  73 #if solaris2_TARGET_OS
  74 #include <sys/fcntl.h>
  75 #include <sys/signal.h>
  76 #include <sys/procfs.h>
  77 #endif
  78
  79 static StgDouble GC_start_time,  GC_tot_time = 0;  /* User GC Time */
  80 static StgDouble GCe_start_time, GCe_tot_time = 0; /* Elapsed GC time */
  81
  82 #if defined(GCap) || defined(GCgn)
  83 static StgDouble GC_min_time = 0;
  84 static StgDouble GCe_min_time = 0;
  85
  86 static I_ GC_min_no = 0;
  87 static I_ GC_min_since_maj = 0;
  88 static I_ GC_live_maj = 0;         /* Heap live at last major collection */
  89 static I_ GC_alloc_since_maj = 0;  /* Heap alloc since collection major */
  90 #endif
  91
  92 static I_ GC_maj_no = 0;
  93 static ullong GC_tot_alloc = 0;        /* Total heap allocated -- 64 bits? */
  94
  95 static I_ GC_start_faults = 0, GC_end_faults = 0;
  96
  97 char *
  98 ullong_format_string(ullong x, char *s, rtsBool with_commas)
  99 {
 100     if (x < (ullong)1000)
 101         sprintf(s, "%ld", (I_)x);
 102     else if (x < (ullong)1000000)
 103         sprintf(s, (with_commas) ? "%ld,%3.3ld" : "%ld%3.3ld",
 104                 (I_)((x)/(ullong)1000),
 105                 (I_)((x)%(ullong)1000));
 106     else if (x < (ullong)1000000000)
 107         sprintf(s, (with_commas) ? "%ld,%3.3ld,%3.3ld" :  "%ld%3.3ld%3.3ld",
 108                 (I_)((x)/(ullong)1000000),
 109                 (I_)((x)/(ullong)1000%(ullong)1000),
 110                 (I_)((x)%(ullong)1000));
 111     else
 112         sprintf(s, (with_commas) ? "%ld,%3.3ld,%3.3ld,%3.3ld" : "%ld%3.3ld%3.3ld%3.3ld",
 113                 (I_)((x)/(ullong)1000000000),
 114                 (I_)((x)/(ullong)1000000%(ullong)1000),
 115                 (I_)((x)/(ullong)1000%(ullong)1000),
 116                 (I_)((x)%(ullong)1000));
 117     return s;
 118 }
 119
 120 /* "constants" for "usertime" and "elapsedtime" */
 121
 122 static StgDouble ElapsedTimeStart = 0.0; /* setup when beginning things */
 123 static StgDouble TicksPerSecond   = 0.0; /* ditto */
 124
 125 /* usertime() -- The current user time in seconds */
 126
 127 StgDouble
 128 usertime()
 129 {
 130 #if ! (defined(HAVE_GETRUSAGE) || defined(HAVE_TIMES))
 131     /* We will #ifdef around the fprintf for machines
 132        we *know* are unsupported. (WDP 94/05)
 133     */
 134     fprintf(stderr, "NOTE: `usertime' does nothing!\n");
 135     return 0.0;
 136
 137 #else /* not stumped */
 138
 139 # if defined(HAVE_TIMES)
 140     struct tms t;
 141
 142     times(&t);
 143     return(((StgDouble)(t.tms_utime))/TicksPerSecond);
 144
 145 #else /* HAVE_GETRUSAGE */
 146     struct rusage t;
 147
 148     getrusage(RUSAGE_SELF, &t);
 149     return(t.ru_utime.tv_sec + 1e-6*t.ru_utime.tv_usec);
 150
 151 # endif /* HAVE_GETRUSAGE */
 152 #endif /* not stumped */
 153 }
 154
 155
 156 /* elapsedtime() -- The current elapsed time in seconds */
 157
 158 StgDouble
 159 elapsedtime()
 160 {
 161 #if ! (defined(HAVE_TIMES) || defined(HAVE_FTIME))
 162     /* We will #ifdef around the fprintf for machines
 163        we *know* are unsupported. (WDP 94/05)
 164     */
 165     fprintf(stderr, "NOTE: `elapsedtime' does nothing!\n");
 166     return 0.0;
 167
 168 #else /* not stumped */
 169
 170 /* "ftime" may be nicer, but "times" is more standard;
 171    but, on a Sun, if you do not get the SysV one, you are *hosed*...
 172  */
 173
 174 # if defined(HAVE_TIMES) && ! sunos4_TARGET_OS
 175     struct tms t;
 176
 177     return (((StgDouble) times(&t))/TicksPerSecond - ElapsedTimeStart);
 178
 179 # else /* HAVE_FTIME */
 180     struct timeb t;
 181
 182     ftime(&t);
 183     return (fabs(t.time + 1e-3*t.millitm - ElapsedTimeStart));
 184
 185 # endif /* HAVE_FTIME */
 186 #endif /* not stumped */
 187 }
 188
 189 void
 190 start_time(STG_NO_ARGS)
 191 {
 192     long ticks;
 193
 194     /* Determine TicksPerSecond ... */
 195 #ifdef HAVE_SYSCONF
 196     ticks = sysconf(_SC_CLK_TCK);
 197     if ( ticks == -1 ) {
 198         fprintf(stderr, "stat_init: bad call to 'sysconf'!\n");
 199         EXIT(EXIT_FAILURE);
 200     }
 201     TicksPerSecond = (StgDouble) ticks;
 202
 203 #else /* no "sysconf"; had better guess */
 204 # ifdef HZ
 205     TicksPerSecond = (StgDouble) (HZ);
 206
 207 # else /* had better guess wildly */
 208     /* We will #ifdef around the fprintf for machines
 209        we *know* are unsupported. (WDP 94/05)
 210     */
 211     fprintf(stderr, "NOTE: Guessing `TicksPerSecond = 60'!\n");
 212     TicksPerSecond = 60.0;
 213     return;
 214 # endif
 215 #endif
 216     ElapsedTimeStart = elapsedtime();
 217 }
 218
 219 static StgDouble InitUserTime = 0.0; /* user time taken for initialization */
 220 static StgDouble InitElapsedTime = 0.0; /* elapsed time taken for initialization */
 221
 222 void end_init(STG_NO_ARGS)
 223 {
 224     InitUserTime = usertime();
 225     InitElapsedTime = elapsedtime();
 226 }
 227
 228 #if defined(solaris2_TARGET_OS)
 229 static I_
 230 pagefaults(STG_NO_ARGS)
 231 {
 232     int         fd;
 233     char        proc[30]; /* Will break when PIDs are repr. by more than 64bits */
 234     prusage_t   prusage;
 235
 236     /* Under Solaris, we get at the number of major page faults
 237        via the process file descriptor and ioctl()ing with
 238        PIOCUSAGE to get the prusage_t structure.
 239        (as per proc(4) man page and Solaris porting FAQ).
 240     */
 241     sprintf(proc,"/proc/%d", getpid()); /* ToDo: this string is static
 242                                            per process, optimise? */
 243
 244     while ((fd = open(proc, O_RDONLY)) == -1 ) {
 245       if ( errno != EINTR ) {
 246              fflush(stdout);
 247              fprintf(stderr,"pagefaults: open() failed\n");
 248              EXIT(EXIT_FAILURE);
 249         }
 250     }
 251     while (ioctl(fd, PIOCUSAGE, &prusage) == -1 ) {
 252       if (errno != EINTR) {
 253              fflush(stdout);
 254              fprintf(stderr,"pagefaults: ioctl() failed\n");
 255              EXIT(EXIT_FAILURE);
 256         }
 257     }
 258     while ((close(fd)) == -1 ) {
 259       if (errno != EINTR) {
 260             fflush(stdout);
 261             fprintf(stderr, "pagefaults: close() failed\n");
 262             EXIT(EXIT_FAILURE);
 263       }
 264     }
 265     return prusage.pr_majf;
 266 }
 267 #else
 268
 269 static I_
 270 pagefaults(STG_NO_ARGS)
 271 {
 272 # if !defined(HAVE_GETRUSAGE) || irix_TARGET_OS
 273     return 0;
 274 # else
 275     struct rusage t;
 276
 277     getrusage(RUSAGE_SELF, &t);
 278     /* cygwin32 note: Last time I looked (b18), the ru_majflt field
 279        was always filled in with a 0. -- SOF (ToDo: Win32ify?)
 280     */
 281     return(t.ru_majflt);
 282 # endif
 283 }
 284 #endif
 285
 286 /* Called at the beginning of execution of the program */
 287 /* Writes the command line and inits stats header */
 288
 289 void
 290 stat_init(char *collector, char *comment1, char *comment2)
 291 {
 292     FILE *sf = RTSflags.GcFlags.statsFile;
 293
 294     if (sf != NULL) {
 295         char temp[BIG_STRING_LEN];
 296         ullong_format_string( (ullong)RTSflags.GcFlags.heapSize*sizeof(W_), temp, rtsTrue/*commas*/);
 297         fprintf(sf, "\nCollector: %s  HeapSize: %s (bytes)\n\n", collector, temp);
 298         if (RTSflags.GcFlags.giveStats) {
 299 #if !defined(HAVE_GETRUSAGE) || irix_TARGET_OS
 300             fprintf(sf, "NOTE: `pagefaults' does nothing!\n");
 301 #endif
 302             fprintf(sf,
 303 /*######## ####### #######  ##.#  ##.## ##.## ####.## ####.## #### ####*/
 304  "  Alloc  Collect   Live   Resid   GC    GC     TOT     TOT  Page Flts  %s\n",
 305                     comment1);
 306             fprintf(sf,
 307  "  bytes   bytes    bytes   ency  user  elap    user    elap   GC  MUT  %s\n",
 308                     comment2);
 309         }
 310
 311 #if defined(GCap) || defined(GCgn)
 312         else {
 313             fprintf(sf,
 314 /*######## #######  ##.#  #######  ##.#   ###  ##.## ##.## ##.## ##.## ####.## ####.## #### ####*/
 315  "  Alloc  Promote  Promo   Live   Resid Minor Minor Minor Major Major    TOT     TOT  Page Flts\n");
 316             fprintf(sf,
 317  "  bytes   bytes    ted    bytes   ency   No   user  elap  user  elap    user    elap  MUT Major\n");
 318         }
 319 #endif /* generational */
 320
 321         fflush(sf);
 322     }
 323 }
 324
 325 /* Called at the beginning of each GC */
 326 static I_ rub_bell = 0;
 327
 328 void
 329 stat_startGC(I_ alloc)
 330 {
 331     FILE *sf = RTSflags.GcFlags.statsFile;
 332
 333 #if defined(GCap) || defined(GCgn)
 334     I_ bell = alloc == 0 ? RTSflags.GcFlags.ringBell : 0;
 335 #else  /* ! generational */
 336     I_ bell = RTSflags.GcFlags.ringBell;
 337 #endif /* ! generational */
 338
 339     if (bell) {
 340         if (bell > 1) {
 341             fprintf(stderr, " GC ");
 342             rub_bell = 1;
 343         } else {
 344             fprintf(stderr, "\007");
 345         }
 346     }
 347
 348     if (sf != NULL) {
 349         GC_start_time = usertime();
 350         GCe_start_time = elapsedtime();
 351
 352 #if defined(GCap) || defined(GCgn)
 353         if (RTSflags.GcFlags.giveStats || alloc == 0) {
 354             GC_start_faults = pagefaults();
 355         }
 356 #else  /* ! generational */
 357         if (RTSflags.GcFlags.giveStats) {
 358             GC_start_faults = pagefaults();
 359         }
 360 #endif /* ! generational */
 361
 362     }
 363 }
 364
 365 /* Called at the end of each GC */
 366
 367 void
 368 stat_endGC(I_ alloc, I_ collect, I_ live, char *comment)
 369 {
 370     FILE *sf = RTSflags.GcFlags.statsFile;
 371
 372     if (sf != NULL) {
 373         StgDouble time = usertime();
 374         StgDouble etime = elapsedtime();
 375
 376         if (RTSflags.GcFlags.giveStats) {
 377             I_ faults = pagefaults();
 378
 379             fprintf(sf, "%8ld %7ld %7ld %5.1f%%",
 380                     alloc*sizeof(W_), collect*sizeof(W_), live*sizeof(W_), collect == 0 ? 0.0 : (live / (StgDouble) collect * 100));
 381             fprintf(sf, " %5.2f %5.2f %7.2f %7.2f %4ld %4ld  %s\n",
 382                     (time-GC_start_time),
 383                     (etime-GCe_start_time),
 384                     time,
 385                     etime,
 386                     faults - GC_start_faults,
 387                     GC_start_faults - GC_end_faults,
 388                     comment);
 389
 390             GC_end_faults = faults;
 391             fflush(sf);
 392         }
 393
 394 #if defined(GCap) || defined(GCgn)
 395         else if(alloc == 0 && collect != 0) {
 396             I_ faults = pagefaults();
 397
 398             fprintf(sf, "%8ld %7ld %5.1f%% %7ld %5.1f%%",
 399                     GC_alloc_since_maj*sizeof(W_), (collect - GC_live_maj)*sizeof(W_),
 400                     (collect - GC_live_maj) / (StgDouble) GC_alloc_since_maj * 100,
 401                     live*sizeof(W_), live / (StgDouble) RTSflags.GcFlags.heapSize * 100);
 402             fprintf(sf, "  %3ld  %5.2f %5.2f %5.2f %5.2f %7.2f %7.2f %4ld %4ld\n",
 403                     GC_min_since_maj, GC_min_time, GCe_min_time,
 404                     (time-GC_start_time),
 405                     (etime-GCe_start_time),
 406                     time,
 407                     etime,
 408                     faults - GC_start_faults,
 409                     GC_start_faults - GC_end_faults
 410                     );
 411
 412             GC_end_faults = faults;
 413             fflush(sf);
 414         }
 415 #endif /* generational */
 416
 417 #if defined(GCap) || defined(GCgn)
 418         if (alloc == 0 && collect != 0) {
 419             GC_maj_no++;
 420             GC_live_maj = live;
 421             GC_min_no += GC_min_since_maj;
 422             GC_min_since_maj = 0;
 423             GC_tot_alloc += (ullong) GC_alloc_since_maj;
 424             GC_alloc_since_maj = 0;
 425             GC_tot_time  += time-GC_start_time + GC_min_time;
 426             GC_min_time = 0;
 427             GCe_tot_time += etime-GCe_start_time + GCe_min_time;
 428             GCe_min_time = 0;
 429         } else {
 430             GC_min_since_maj++;
 431             GC_alloc_since_maj += alloc;
 432             GC_min_time += time-GC_start_time;
 433             GCe_min_time += etime-GCe_start_time;
 434         }
 435 #else /* ! generational */
 436         GC_maj_no++;
 437         GC_tot_alloc += (ullong) alloc;
 438         GC_tot_time  += time-GC_start_time;
 439         GCe_tot_time += etime-GCe_start_time;
 440 #endif /* ! generational */
 441
 442     }
 443
 444     if (rub_bell) {
 445         fprintf(stderr, "\b\b\b  \b\b\b");
 446         rub_bell = 0;
 447     }
 448 }
 449
 450 /* Called at the end of execution -- to print a summary of statistics */
 451
 452 void
 453 stat_exit(I_ alloc)
 454 {
 455     FILE *sf = RTSflags.GcFlags.statsFile;
 456
 457     if (sf != NULL){
 458         char temp[BIG_STRING_LEN];
 459         StgDouble time = usertime();
 460         StgDouble etime = elapsedtime();
 461
 462         /* avoid divide by zero if time is measured as 0.00 seconds -- SDM */
 463         if (time  == 0.0)  time = 0.0001;
 464         if (etime == 0.0) etime = 0.0001;
 465
 466
 467         if (RTSflags.GcFlags.giveStats) {
 468             fprintf(sf, "%8ld\n\n", alloc*sizeof(W_));
 469         }
 470
 471 #if defined(GCap) || defined (GCgn)
 472         else {
 473             fprintf(sf, "%8ld %7.7s %6.6s %7.7s %6.6s",
 474                     (GC_alloc_since_maj + alloc)*sizeof(W_), "", "", "", "");
 475             fprintf(sf, "  %3ld  %5.2f %5.2f\n\n",
 476                     GC_min_since_maj, GC_min_time, GCe_min_time);
 477         }
 478         GC_min_no    += GC_min_since_maj;
 479         GC_tot_time  += GC_min_time;
 480         GCe_tot_time += GCe_min_time;
 481         GC_tot_alloc += (ullong) (GC_alloc_since_maj + alloc);
 482         ullong_format_string(GC_tot_alloc*sizeof(W_), temp, rtsTrue/*commas*/);
 483         fprintf(sf, "%11s bytes allocated in the heap\n", temp);
 484         if ( ResidencySamples > 0 ) {
 485             ullong_format_string(MaxResidency*sizeof(W_), temp, rtsTrue/*commas*/);
 486             fprintf(sf, "%11s bytes maximum residency (%.1f%%, %ld sample(s))\n",
 487                               temp,
 488                               MaxResidency / (StgDouble) RTSflags.GcFlags.heapSize * 100,
 489                               ResidencySamples);
 490         }
 491         fprintf(sf, "%11ld garbage collections performed (%ld major, %ld minor)\n\n",
 492                 GC_maj_no + GC_min_no, GC_maj_no, GC_min_no);
 493
 494 #else  /* ! generational */
 495
 496         GC_tot_alloc += (ullong) alloc;
 497         ullong_format_string(GC_tot_alloc*sizeof(W_), temp, rtsTrue/*commas*/);
 498         fprintf(sf, "%11s bytes allocated in the heap\n", temp);
 499         if ( ResidencySamples > 0 ) {
 500             ullong_format_string(MaxResidency*sizeof(W_), temp, rtsTrue/*commas*/);
 501             fprintf(sf, "%11s bytes maximum residency (%.1f%%, %ld sample(s))\n",
 502                               temp,
 503                               MaxResidency / (StgDouble) RTSflags.GcFlags.heapSize * 100,
 504                               ResidencySamples);
 505         }
 506         fprintf(sf, "%11ld garbage collections performed\n\n", GC_maj_no);
 507
 508 #endif /* ! generational */
 509
 510         fprintf(sf, "  INIT  time  %6.2fs  (%6.2fs elapsed)\n",
 511                 InitUserTime, InitElapsedTime);
 512         fprintf(sf, "  MUT   time  %6.2fs  (%6.2fs elapsed)\n",
 513                 time - GC_tot_time - InitUserTime,
 514                 etime - GCe_tot_time - InitElapsedTime);
 515         fprintf(sf, "  GC    time  %6.2fs  (%6.2fs elapsed)\n",
 516                 GC_tot_time, GCe_tot_time);
 517         fprintf(sf, "  Total time  %6.2fs  (%6.2fs elapsed)\n\n",
 518                 time, etime);
 519
 520         fprintf(sf, "  %%GC time     %5.1f%%  (%.1f%% elapsed)\n\n",
 521                 GC_tot_time*100./time, GCe_tot_time*100./etime);
 522
 523         if (time - GC_tot_time == 0.0)
 524                 ullong_format_string((ullong)0, temp, rtsTrue/*commas*/);
 525         else
 526                 ullong_format_string((ullong)(GC_tot_alloc*sizeof(W_)/(time - GC_tot_time)),
 527                          temp, rtsTrue/*commas*/);
 528
 529         fprintf(sf, "  Alloc rate    %s bytes per MUT second\n\n", temp);
 530
 531         fprintf(sf, "  Productivity %5.1f%% of total user, %.1f%% of total elapsed\n\n",
 532                 (time - GC_tot_time - InitUserTime) * 100. / time,
 533                 (time - GC_tot_time - InitUserTime) * 100. / etime);
 534         fflush(sf);
 535         fclose(sf);
 536     }
 537 }
 538 \end{code}