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