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