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 #ifdef hpux_TARGET_OS
  17 #define _INCLUDE_HPUX_SOURCE
  18 #endif
  19
  20 #define NULL_REG_MAP
  21 #include "SMinternal.h"
  22 #include "Ticky.h"
  23
  24 #ifdef HAVE_SYS_TYPES_H
  25 #include <sys/types.h>
  26 #endif
  27
  28 #ifdef HAVE_UNISTD_H
  29 #include <unistd.h>
  30 #endif
  31
  32 #ifdef HAVE_SYS_TIMES_H
  33 #include <sys/times.h>
  34 #endif
  35
  36 #ifdef HAVE_SYS_TIME_H
  37 #include <sys/time.h>
  38 #endif
  39
  40 #if defined(HAVE_SYS_RESOURCE_H) && ! irix_TARGET_OS
  41 #include <sys/resource.h>
  42 #endif
  43
  44 #ifdef HAVE_SYS_TIMEB_H
  45 #include <sys/timeb.h>
  46 #endif
  47
  48 #ifdef hpux_TARGET_OS
  49 #include <sys/syscall.h>
  50 #define getrusage(a, b)  syscall(SYS_GETRUSAGE, a, b)
  51 #define HAVE_GETRUSAGE
  52 #endif
  53
  54 static StgDouble GC_start_time,  GC_tot_time = 0;  /* User GC Time */
  55 static StgDouble GCe_start_time, GCe_tot_time = 0; /* Elapsed GC time */
  56
  57 #if defined(GCap) || defined(GCgn)
  58 static StgDouble GC_min_time = 0;
  59 static StgDouble GCe_min_time = 0;
  60
  61 static I_ GC_min_no = 0;
  62 static I_ GC_min_since_maj = 0;
  63 static I_ GC_live_maj = 0;         /* Heap live at last major collection */
  64 static I_ GC_alloc_since_maj = 0;  /* Heap alloc since collection major */
  65 #endif
  66
  67 static I_ GC_maj_no = 0;
  68 static ullong GC_tot_alloc = 0;        /* Total heap allocated -- 64 bits? */
  69
  70 static I_ GC_start_faults = 0, GC_end_faults = 0;
  71
  72 char *
  73 ullong_format_string(ullong x, char *s, rtsBool with_commas)
  74 {
  75     if (x < (ullong)1000)
  76         sprintf(s, "%ld", (I_)x);
  77     else if (x < (ullong)1000000)
  78         sprintf(s, (with_commas) ? "%ld,%3.3ld" : "%ld%3.3ld",
  79                 (I_)((x)/(ullong)1000),
  80                 (I_)((x)%(ullong)1000));
  81     else if (x < (ullong)1000000000)
  82         sprintf(s, (with_commas) ? "%ld,%3.3ld,%3.3ld" :  "%ld%3.3ld%3.3ld",
  83                 (I_)((x)/(ullong)1000000),
  84                 (I_)((x)/(ullong)1000%(ullong)1000),
  85                 (I_)((x)%(ullong)1000));
  86     else
  87         sprintf(s, (with_commas) ? "%ld,%3.3ld,%3.3ld,%3.3ld" : "%ld%3.3ld%3.3ld%3.3ld",
  88                 (I_)((x)/(ullong)1000000000),
  89                 (I_)((x)/(ullong)1000000%(ullong)1000),
  90                 (I_)((x)/(ullong)1000%(ullong)1000),
  91                 (I_)((x)%(ullong)1000));
  92     return s;
  93 }
  94
  95 /* "constants" for "usertime" and "elapsedtime" */
  96
  97 static StgDouble ElapsedTimeStart = 0.0; /* setup when beginning things */
  98 static StgDouble TicksPerSecond   = 0.0; /* ditto */
  99
 100 /* usertime() -- The current user time in seconds */
 101
 102 StgDouble
 103 usertime()
 104 {
 105 #if ! (defined(HAVE_GETRUSAGE) || defined(HAVE_TIMES))
 106     /* We will #ifdef around the fprintf for machines
 107        we *know* are unsupported. (WDP 94/05)
 108     */
 109     fprintf(stderr, "NOTE: `usertime' does nothing!\n");
 110     return 0.0;
 111
 112 #else /* not stumped */
 113
 114 /* "times" is the more standard, but we prefer "getrusage"
 115     (because we are old worn-out BSD hackers)
 116 */
 117 # if defined(HAVE_GETRUSAGE) && ! irix_TARGET_OS
 118     struct rusage t;
 119
 120     getrusage(RUSAGE_SELF, &t);
 121     return(t.ru_utime.tv_sec + 1e-6*t.ru_utime.tv_usec);
 122
 123 # else /* HAVE_TIMES */
 124     struct tms t;
 125
 126     times(&t);
 127     return(((StgDouble)(t.tms_utime))/TicksPerSecond);
 128
 129 # endif /* HAVE_TIMES */
 130 #endif /* not stumped */
 131 }
 132
 133
 134 /* elapsedtime() -- The current elapsed time in seconds */
 135
 136 StgDouble
 137 elapsedtime()
 138 {
 139 #if ! (defined(HAVE_TIMES) || defined(HAVE_FTIME))
 140     /* We will #ifdef around the fprintf for machines
 141        we *know* are unsupported. (WDP 94/05)
 142     */
 143     fprintf(stderr, "NOTE: `elapsedtime' does nothing!\n");
 144     return 0.0;
 145
 146 #else /* not stumped */
 147
 148 /* "ftime" may be nicer, but "times" is more standard;
 149    but, on a Sun, if you do not get the SysV one, you are *hosed*...
 150  */
 151
 152 # if defined(HAVE_TIMES) && ! sunos4_TARGET_OS
 153     struct tms t;
 154
 155     return (((StgDouble) times(&t))/TicksPerSecond - ElapsedTimeStart);
 156
 157 # else /* HAVE_FTIME */
 158     struct timeb t;
 159
 160     ftime(&t);
 161     return t.time + 1e-3*t.millitm - ElapsedTimeStart;
 162
 163 # endif /* HAVE_FTIME */
 164 #endif /* not stumped */
 165 }
 166
 167 void
 168 start_time(STG_NO_ARGS)
 169 {
 170     long ticks;
 171
 172     /* Determine TicksPerSecond ... */
 173 #ifdef HAVE_SYSCONF
 174     ticks = sysconf(_SC_CLK_TCK);
 175     if ( ticks == -1 ) {
 176         fprintf(stderr, "stat_init: bad call to 'sysconf'!\n");
 177         EXIT(EXIT_FAILURE);
 178     }
 179     TicksPerSecond = (StgDouble) ticks;
 180
 181 #else /* no "sysconf"; had better guess */
 182 # ifdef HZ
 183     TicksPerSecond = (StgDouble) (HZ);
 184
 185 # else /* had better guess wildly */
 186     /* We will #ifdef around the fprintf for machines
 187        we *know* are unsupported. (WDP 94/05)
 188     */
 189     fprintf(stderr, "NOTE: Guessing `TicksPerSecond = 60'!\n");
 190     TicksPerSecond = 60.0;
 191     return;
 192 # endif
 193 #endif
 194     ElapsedTimeStart = elapsedtime();
 195 }
 196
 197 static StgDouble InitUserTime = 0.0; /* user time taken for initialization */
 198 static StgDouble InitElapsedTime = 0.0; /* elapsed time taken for initialization */
 199
 200 void end_init(STG_NO_ARGS)
 201 {
 202     InitUserTime = usertime();
 203     InitElapsedTime = elapsedtime();
 204 }
 205
 206 static I_
 207 pagefaults(STG_NO_ARGS)
 208 {
 209 #if !defined(HAVE_GETRUSAGE) || irix_TARGET_OS
 210     return 0;
 211 #else
 212     struct rusage t;
 213
 214     getrusage(RUSAGE_SELF, &t);
 215     return(t.ru_majflt);
 216 #endif
 217 }
 218
 219 /* Called at the beginning of execution of the program */
 220 /* Writes the command line and inits stats header */
 221
 222 void
 223 stat_init(char *collector, char *comment1, char *comment2)
 224 {
 225     FILE *sf = RTSflags.GcFlags.statsFile;
 226
 227     if (sf != NULL) {
 228         char temp[BIG_STRING_LEN];
 229         ullong_format_string( (ullong)RTSflags.GcFlags.heapSize*sizeof(W_), temp, rtsTrue/*commas*/);
 230         fprintf(sf, "\nCollector: %s  HeapSize: %s (bytes)\n\n", collector, temp);
 231         if (RTSflags.GcFlags.giveStats) {
 232 #if !defined(HAVE_GETRUSAGE) || irix_TARGET_OS
 233             fprintf(sf, "NOTE: `pagefaults' does nothing!\n");
 234 #endif
 235             fprintf(sf,
 236 /*######## ####### #######  ##.#  ##.## ##.## ####.## ####.## #### ####*/
 237  "  Alloc  Collect   Live   Resid   GC    GC     TOT     TOT  Page Flts  %s\n",
 238                     comment1);
 239             fprintf(sf,
 240  "  bytes   bytes    bytes   ency  user  elap    user    elap   GC  MUT  %s\n",
 241                     comment2);
 242         }
 243
 244 #if defined(GCap) || defined(GCgn)
 245         else {
 246             fprintf(sf,
 247 /*######## #######  ##.#  #######  ##.#   ###  ##.## ##.## ##.## ##.## ####.## ####.## #### ####*/
 248  "  Alloc  Promote  Promo   Live   Resid Minor Minor Minor Major Major    TOT     TOT  Page Flts\n");
 249             fprintf(sf,
 250  "  bytes   bytes    ted    bytes   ency   No   user  elap  user  elap    user    elap  MUT Major\n");
 251         }
 252 #endif /* generational */
 253
 254         fflush(sf);
 255     }
 256 }
 257
 258 /* Called at the beginning of each GC */
 259 static I_ rub_bell = 0;
 260
 261 void
 262 stat_startGC(I_ alloc)
 263 {
 264     FILE *sf = RTSflags.GcFlags.statsFile;
 265
 266 #if defined(GCap) || defined(GCgn)
 267     I_ bell = alloc == 0 ? RTSflags.GcFlags.ringBell : 0;
 268 #else  /* ! generational */
 269     I_ bell = RTSflags.GcFlags.ringBell;
 270 #endif /* ! generational */
 271
 272     if (bell) {
 273         if (bell > 1) {
 274             fprintf(stderr, " GC ");
 275             rub_bell = 1;
 276         } else {
 277             fprintf(stderr, "\007");
 278         }
 279     }
 280
 281     if (sf != NULL) {
 282         GC_start_time = usertime();
 283         GCe_start_time = elapsedtime();
 284
 285 #if defined(GCap) || defined(GCgn)
 286         if (RTSflags.GcFlags.giveStats || alloc == 0) {
 287             GC_start_faults = pagefaults();
 288         }
 289 #else  /* ! generational */
 290         if (RTSflags.GcFlags.giveStats) {
 291             GC_start_faults = pagefaults();
 292         }
 293 #endif /* ! generational */
 294
 295     }
 296 }
 297
 298 /* Called at the end of each GC */
 299
 300 void
 301 stat_endGC(I_ alloc, I_ collect, I_ live, char *comment)
 302 {
 303     FILE *sf = RTSflags.GcFlags.statsFile;
 304
 305     if (sf != NULL) {
 306         StgDouble time = usertime();
 307         StgDouble etime = elapsedtime();
 308
 309         if (RTSflags.GcFlags.giveStats) {
 310             I_ faults = pagefaults();
 311
 312             fprintf(sf, "%8ld %7ld %7ld %5.1f%%",
 313                     alloc*sizeof(W_), collect*sizeof(W_), live*sizeof(W_), collect == 0 ? 0.0 : (live / (StgDouble) collect * 100));
 314             fprintf(sf, " %5.2f %5.2f %7.2f %7.2f %4ld %4ld  %s\n",
 315                     (time-GC_start_time),
 316                     (etime-GCe_start_time),
 317                     time,
 318                     etime,
 319                     faults - GC_start_faults,
 320                     GC_start_faults - GC_end_faults,
 321                     comment);
 322
 323             GC_end_faults = faults;
 324             fflush(sf);
 325         }
 326
 327 #if defined(GCap) || defined(GCgn)
 328         else if(alloc == 0 && collect != 0) {
 329             I_ faults = pagefaults();
 330
 331             fprintf(sf, "%8ld %7ld %5.1f%% %7ld %5.1f%%",
 332                     GC_alloc_since_maj*sizeof(W_), (collect - GC_live_maj)*sizeof(W_),
 333                     (collect - GC_live_maj) / (StgDouble) GC_alloc_since_maj * 100,
 334                     live*sizeof(W_), live / (StgDouble) RTSflags.GcFlags.heapSize * 100);
 335             fprintf(sf, "  %3ld  %5.2f %5.2f %5.2f %5.2f %7.2f %7.2f %4ld %4ld\n",
 336                     GC_min_since_maj, GC_min_time, GCe_min_time,
 337                     (time-GC_start_time),
 338                     (etime-GCe_start_time),
 339                     time,
 340                     etime,
 341                     faults - GC_start_faults,
 342                     GC_start_faults - GC_end_faults
 343                     );
 344
 345             GC_end_faults = faults;
 346             fflush(sf);
 347         }
 348 #endif /* generational */
 349
 350 #if defined(GCap) || defined(GCgn)
 351         if (alloc == 0 && collect != 0) {
 352             GC_maj_no++;
 353             GC_live_maj = live;
 354             GC_min_no += GC_min_since_maj;
 355             GC_min_since_maj = 0;
 356             GC_tot_alloc += (ullong) GC_alloc_since_maj;
 357             GC_alloc_since_maj = 0;
 358             GC_tot_time  += time-GC_start_time + GC_min_time;
 359             GC_min_time = 0;
 360             GCe_tot_time += etime-GCe_start_time + GCe_min_time;
 361             GCe_min_time = 0;
 362         } else {
 363             GC_min_since_maj++;
 364             GC_alloc_since_maj += alloc;
 365             GC_min_time += time-GC_start_time;
 366             GCe_min_time += etime-GCe_start_time;
 367         }
 368 #else /* ! generational */
 369         GC_maj_no++;
 370         GC_tot_alloc += (ullong) alloc;
 371         GC_tot_time  += time-GC_start_time;
 372         GCe_tot_time += etime-GCe_start_time;
 373 #endif /* ! generational */
 374
 375     }
 376
 377     if (rub_bell) {
 378         fprintf(stderr, "\b\b\b  \b\b\b");
 379         rub_bell = 0;
 380     }
 381 }
 382
 383 /* Called at the end of execution -- to print a summary of statistics */
 384
 385 void
 386 stat_exit(I_ alloc)
 387 {
 388     FILE *sf = RTSflags.GcFlags.statsFile;
 389
 390     if (sf != NULL){
 391         char temp[BIG_STRING_LEN];
 392         StgDouble time = usertime();
 393         StgDouble etime = elapsedtime();
 394
 395         if (RTSflags.GcFlags.giveStats) {
 396             fprintf(sf, "%8ld\n\n", alloc*sizeof(W_));
 397         }
 398
 399 #if defined(GCap) || defined (GCgn)
 400         else {
 401             fprintf(sf, "%8ld %7.7s %6.6s %7.7s %6.6s",
 402                     (GC_alloc_since_maj + alloc)*sizeof(W_), "", "", "", "");
 403             fprintf(sf, "  %3ld  %5.2f %5.2f\n\n",
 404                     GC_min_since_maj, GC_min_time, GCe_min_time);
 405         }
 406         GC_min_no    += GC_min_since_maj;
 407         GC_tot_time  += GC_min_time;
 408         GCe_tot_time += GCe_min_time;
 409         GC_tot_alloc += (ullong) (GC_alloc_since_maj + alloc);
 410         ullong_format_string(GC_tot_alloc*sizeof(W_), temp, rtsTrue/*commas*/);
 411         fprintf(sf, "%11s bytes allocated in the heap\n", temp);
 412         if ( ResidencySamples > 0 ) {
 413             ullong_format_string(MaxResidency*sizeof(W_), temp, rtsTrue/*commas*/);
 414             fprintf(sf, "%11s bytes maximum residency (%.1f%%, %ld sample(s))\n",
 415                               temp,
 416                               MaxResidency / (StgDouble) RTSflags.GcFlags.heapSize * 100,
 417                               ResidencySamples);
 418         }
 419         fprintf(sf, "%11ld garbage collections performed (%ld major, %ld minor)\n\n",
 420                 GC_maj_no + GC_min_no, GC_maj_no, GC_min_no);
 421
 422 #else  /* ! generational */
 423
 424         GC_tot_alloc += (ullong) alloc;
 425         ullong_format_string(GC_tot_alloc*sizeof(W_), temp, rtsTrue/*commas*/);
 426         fprintf(sf, "%11s bytes allocated in the heap\n", temp);
 427         if ( ResidencySamples > 0 ) {
 428             ullong_format_string(MaxResidency*sizeof(W_), temp, rtsTrue/*commas*/);
 429             fprintf(sf, "%11s bytes maximum residency (%.1f%%, %ld sample(s))\n",
 430                               temp,
 431                               MaxResidency / (StgDouble) RTSflags.GcFlags.heapSize * 100,
 432                               ResidencySamples);
 433         }
 434         fprintf(sf, "%11ld garbage collections performed\n\n", GC_maj_no);
 435
 436 #endif /* ! generational */
 437
 438         fprintf(sf, "  INIT  time  %6.2fs  (%6.2fs elapsed)\n",
 439                 InitUserTime, InitElapsedTime);
 440         fprintf(sf, "  MUT   time  %6.2fs  (%6.2fs elapsed)\n",
 441                 time - GC_tot_time - InitUserTime,
 442                 etime - GCe_tot_time - InitElapsedTime);
 443         fprintf(sf, "  GC    time  %6.2fs  (%6.2fs elapsed)\n",
 444                 GC_tot_time, GCe_tot_time);
 445         fprintf(sf, "  Total time  %6.2fs  (%6.2fs elapsed)\n\n",
 446                 time, etime);
 447
 448         fprintf(sf, "  %%GC time     %5.1f%%  (%.1f%% elapsed)\n\n",
 449                 GC_tot_time*100./time, GCe_tot_time*100./etime);
 450
 451         ullong_format_string((ullong)(GC_tot_alloc*sizeof(W_)/(time - GC_tot_time)), temp, rtsTrue/*commas*/);
 452         fprintf(sf, "  Alloc rate    %s bytes per MUT second\n\n", temp);
 453
 454         fprintf(sf, "  Productivity %5.1f%% of total user, %.1f%% of total elapsed\n\n",
 455                 (time - GC_tot_time - InitUserTime) * 100. / time,
 456                 (time - GC_tot_time - InitUserTime) * 100. / etime);
 457         fflush(sf);
 458         fclose(sf);
 459     }
 460 }
 461 \end{code}