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