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