ghc/rts/Stats.c

   1 /* -----------------------------------------------------------------------------
   2  * $Id: Stats.c,v 1.35 2001/11/20 21:39:12 sof Exp $
   3  *
   4  * (c) The GHC Team, 1998-1999
   5  *
   6  * Statistics and timing-related functions.
   7  *
   8  * ---------------------------------------------------------------------------*/
   9
  10 /* Alas, no.  This source is non-posix.
  11    #include "PosixSource.h"
  12 */
  13
  14 #include "Rts.h"
  15 #include "RtsFlags.h"
  16 #include "RtsUtils.h"
  17 #include "StoragePriv.h"
  18 #include "MBlock.h"
  19 #include "Schedule.h"
  20 #include "Stats.h"
  21 #include "ParTicky.h"                       // ToDo: move into Rts.h
  22
  23 #ifdef HAVE_UNISTD_H
  24 #include <unistd.h>
  25 #endif
  26
  27 #ifndef mingw32_TARGET_OS
  28 # ifdef HAVE_SYS_TIMES_H
  29 #  include <sys/times.h>
  30 # endif
  31 #endif
  32
  33 #ifdef HAVE_SYS_TIME_H
  34 #include <sys/time.h>
  35 #endif
  36
  37 #ifdef __CYGWIN32__
  38 # ifdef HAVE_TIME_H
  39 #  include <time.h>
  40 # endif
  41 #endif
  42
  43 #if ! irix_TARGET_OS && ! defined(mingw32_TARGET_OS)
  44 # if defined(HAVE_SYS_RESOURCE_H)
  45 #  include <sys/resource.h>
  46 # endif
  47 #endif
  48
  49 #ifdef HAVE_SYS_TIMEB_H
  50 #include <sys/timeb.h>
  51 #endif
  52
  53 #if HAVE_STDLIB_H
  54 #include <stdlib.h>
  55 #endif
  56
  57 #if HAVE_WINDOWS_H
  58 #include <windows.h>
  59 #endif
  60
  61 #if defined(PAR) || !(!defined(HAVE_GETRUSAGE) || irix_TARGET_OS || defined(mingw32_TARGET_OS) || defined(cygwin32_TARGET_OS))
  62 #include <sys/resource.h>
  63 #endif
  64
  65 /* huh? */
  66 #define BIG_STRING_LEN              512
  67
  68 /* We're not trying to be terribly accurate here, using the
  69  * basic times() function to get a resolution of about 100ths of a
  70  * second, depending on the OS.  A long int will do fine for holding
  71  * these values.
  72  */
  73 #define TICK_TYPE long int
  74 #define TICK_TO_DBL(t) ((double)(t) / TicksPerSecond)
  75
  76 static int TicksPerSecond = 0;
  77
  78 static TICK_TYPE ElapsedTimeStart = 0;
  79 static TICK_TYPE CurrentElapsedTime = 0;
  80 static TICK_TYPE CurrentUserTime    = 0;
  81
  82 static TICK_TYPE InitUserTime     = 0;
  83 static TICK_TYPE InitElapsedTime  = 0;
  84 static TICK_TYPE InitElapsedStamp = 0;
  85
  86 static TICK_TYPE MutUserTime      = 0;
  87 static TICK_TYPE MutElapsedTime   = 0;
  88 static TICK_TYPE MutElapsedStamp  = 0;
  89
  90 static TICK_TYPE ExitUserTime     = 0;
  91 static TICK_TYPE ExitElapsedTime  = 0;
  92
  93 static ullong GC_tot_alloc        = 0;
  94 static ullong GC_tot_copied       = 0;
  95
  96 static TICK_TYPE GC_start_time,  GC_tot_time = 0;  /* User GC Time */
  97 static TICK_TYPE GCe_start_time, GCe_tot_time = 0; /* Elapsed GC time */
  98
  99 lnat MaxResidency = 0;     /* in words; for stats only */
 100 lnat AvgResidency = 0;
 101 lnat ResidencySamples = 0; /* for stats only */
 102
 103 static lnat GC_start_faults = 0, GC_end_faults = 0;
 104
 105 static TICK_TYPE *GC_coll_times;
 106
 107 static void  getTimes(void);
 108 static nat   pageFaults(void);
 109
 110 /* elapsedtime() -- The current elapsed time in seconds */
 111
 112 #if defined(mingw32_TARGET_OS) || defined(cygwin32_TARGET_OS)
 113 #define HNS_PER_SEC 10000000LL /* FILETIMES are in units of 100ns */
 114 /* Convert FILETIMEs into secs */
 115 #define FT2longlong(ll,ft)    \
 116     (ll)=(ft).dwHighDateTime; \
 117     (ll) <<= 32;              \
 118     (ll) |= (ft).dwLowDateTime; \
 119     (ll) /= (unsigned long long) (HNS_PER_SEC / CLOCKS_PER_SEC)
 120 #endif
 121
 122 #if defined(mingw32_TARGET_OS) || defined(cygwin32_TARGET_OS)
 123 /* cygwin32 or mingw32 version */
 124 static void
 125 getTimes(void)
 126 {
 127     static int is_win9x = -1;
 128
 129     FILETIME creationTime, exitTime, userTime, kernelTime = {0,0};
 130     long long int kT, uT;
 131
 132     if (is_win9x < 0) {
 133       /* figure out whether we're on a Win9x box or not. */
 134       OSVERSIONINFO oi;
 135       BOOL b;
 136
 137       /* Need to init the size field first.*/
 138       oi.dwOSVersionInfoSize = sizeof(OSVERSIONINFO);
 139       b = GetVersionEx(&oi);
 140
 141       is_win9x = ( (b && (oi.dwPlatformId & VER_PLATFORM_WIN32_WINDOWS)) ? 1 : 0);
 142     }
 143
 144     if (is_win9x) {
 145       /* On Win9x, just attribute all running time to the user. */
 146       SYSTEMTIME st;
 147
 148       GetSystemTime(&st);
 149       SystemTimeToFileTime(&st,&userTime);
 150     } else {
 151       /* ToDo: pin down elapsed times to just the OS thread(s) that
 152          are evaluating/managing Haskell code.
 153       */
 154       if (!GetProcessTimes (GetCurrentProcess(), &creationTime,
 155                           &exitTime, &kernelTime, &userTime)) {
 156         /* Probably on a Win95 box..*/
 157         CurrentElapsedTime = 0;
 158         CurrentUserTime = 0;
 159         return;
 160       }
 161     }
 162
 163     FT2longlong(kT,kernelTime);
 164     FT2longlong(uT,userTime);
 165     CurrentElapsedTime = uT + kT;
 166     CurrentUserTime = uT;
 167
 168     if (is_win9x) {
 169       /* Adjust for the fact that we're using system time & not
 170          process time on Win9x. */
 171       CurrentUserTime    -= ElapsedTimeStart;
 172       CurrentElapsedTime -= ElapsedTimeStart;
 173     }
 174 }
 175
 176 #else /* !win32 */
 177
 178 static void
 179 getTimes(void)
 180 {
 181
 182 #ifndef HAVE_TIMES
 183     /* We will #ifdef around the fprintf for machines
 184        we *know* are unsupported. (WDP 94/05)
 185     */
 186     fprintf(stderr, "NOTE: `getTimes' does nothing!\n");
 187     return 0.0;
 188
 189 #else /* not stumped */
 190     struct tms t;
 191     clock_t r = times(&t);
 192
 193     CurrentElapsedTime = r;
 194     CurrentUserTime = t.tms_utime;
 195 #endif
 196
 197 }
 198 #endif /* !win32 */
 199
 200 /* mut_user_time_during_GC() and mut_user_time()
 201  *
 202  * The former function can be used to get the current mutator time
 203  * *during* a GC, i.e. between stat_startGC and stat_endGC.  This is
 204  * used in the heap profiler for accurately time stamping the heap
 205  * sample.
 206  *
 207  * ATTENTION: mut_user_time_during_GC() relies on GC_start_time being
 208  *            defined in stat_startGC() - to minimise system calls,
 209  *            GC_start_time is, however, only defined when really needed (check
 210  *            stat_startGC() for details)
 211  */
 212 double
 213 mut_user_time_during_GC(void)
 214 {
 215   return TICK_TO_DBL(GC_start_time - GC_tot_time);
 216 }
 217
 218 double
 219 mut_user_time(void)
 220 {
 221     getTimes();
 222     return TICK_TO_DBL(CurrentUserTime - GC_tot_time);
 223 }
 224
 225 static nat
 226 pageFaults(void)
 227 {
 228   /* ToDo (on NT): better, get this via the performance data
 229      that's stored in the registry. */
 230 # if !defined(HAVE_GETRUSAGE) || irix_TARGET_OS || defined(mingw32_TARGET_OS) || defined(cygwin32_TARGET_OS)
 231     return 0;
 232 # else
 233     struct rusage t;
 234
 235     getrusage(RUSAGE_SELF, &t);
 236     return(t.ru_majflt);
 237 # endif
 238 }
 239
 240 void
 241 initStats(void)
 242 {
 243     nat i;
 244     FILE *sf = RtsFlags.GcFlags.statsFile;
 245
 246     if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) {
 247         fprintf(sf, "    Alloc    Collect    Live    GC    GC     TOT     TOT  Page Flts\n");
 248         fprintf(sf, "    bytes     bytes     bytes  user  elap    user    elap\n");
 249     }
 250     GC_coll_times =
 251         (TICK_TYPE *)stgMallocBytes(
 252             sizeof(TICK_TYPE)*RtsFlags.GcFlags.generations,
 253             "initStats");
 254     for (i = 0; i < RtsFlags.GcFlags.generations; i++) {
 255         GC_coll_times[i] = 0;
 256     }
 257 }
 258
 259 /* -----------------------------------------------------------------------------
 260    Initialisation time...
 261    -------------------------------------------------------------------------- */
 262
 263 void
 264 stat_startInit(void)
 265 {
 266     /* Determine TicksPerSecond ... */
 267 #if defined(CLK_TCK)            /* defined by POSIX */
 268     TicksPerSecond = CLK_TCK;
 269
 270 #elif defined(HAVE_SYSCONF)
 271     long ticks;
 272
 273     ticks = sysconf(_SC_CLK_TCK);
 274     if ( ticks == -1 ) {
 275         fprintf(stderr, "stat_init: bad call to 'sysconf'!\n");
 276         stg_exit(EXIT_FAILURE);
 277     }
 278     TicksPerSecond = ticks;
 279
 280 /* no "sysconf" or CLK_TCK; had better guess */
 281 #elif defined(HZ)
 282     TicksPerSecond = HZ;
 283
 284 #elif defined(CLOCKS_PER_SEC)
 285     TicksPerSecond = CLOCKS_PER_SEC;
 286
 287 #else /* had better guess wildly */
 288     /* We will #ifdef around the fprintf for machines
 289        we *know* are unsupported. (WDP 94/05)
 290     */
 291     fprintf(stderr, "NOTE: Guessing `TicksPerSecond = 60'!\n");
 292     TicksPerSecond = 60;
 293 #endif
 294
 295     getTimes();
 296     ElapsedTimeStart = CurrentElapsedTime;
 297 }
 298
 299 void
 300 stat_endInit(void)
 301 {
 302     getTimes();
 303     InitUserTime = CurrentUserTime;
 304     InitElapsedStamp = CurrentElapsedTime;
 305     if (ElapsedTimeStart > CurrentElapsedTime) {
 306         InitElapsedTime = 0;
 307     } else {
 308         InitElapsedTime = CurrentElapsedTime - ElapsedTimeStart;
 309     }
 310 }
 311
 312 /* -----------------------------------------------------------------------------
 313    stat_startExit and stat_endExit
 314
 315    These two measure the time taken in shutdownHaskell().
 316    -------------------------------------------------------------------------- */
 317
 318 void
 319 stat_startExit(void)
 320 {
 321     getTimes();
 322     MutElapsedStamp = CurrentElapsedTime;
 323     MutElapsedTime = CurrentElapsedTime - GCe_tot_time - InitElapsedStamp;
 324     if (MutElapsedTime < 0) { MutElapsedTime = 0; }     /* sometimes -0.00 */
 325
 326     /* for SMP, we don't know the mutator time yet, we have to inspect
 327      * all the running threads to find out, and they haven't stopped
 328      * yet.  So we just timestamp MutUserTime at this point so we can
 329      * calculate the EXIT time.  The real MutUserTime is calculated
 330      * in stat_exit below.
 331      */
 332 #ifdef SMP
 333     MutUserTime = CurrentUserTime;
 334 #else
 335     MutUserTime = CurrentUserTime - GC_tot_time - InitUserTime;
 336     if (MutUserTime < 0) { MutUserTime = 0; }
 337 #endif
 338 }
 339
 340 void
 341 stat_endExit(void)
 342 {
 343     getTimes();
 344 #ifdef SMP
 345     ExitUserTime = CurrentUserTime - MutUserTime;
 346 #else
 347     ExitUserTime = CurrentUserTime - MutUserTime - GC_tot_time - InitUserTime;
 348 #endif
 349     ExitElapsedTime = CurrentElapsedTime - MutElapsedStamp;
 350     if (ExitUserTime < 0) {
 351         ExitUserTime = 0;
 352     }
 353     if (ExitElapsedTime < 0) {
 354         ExitElapsedTime = 0;
 355     }
 356 }
 357
 358 /* -----------------------------------------------------------------------------
 359    Called at the beginning of each GC
 360    -------------------------------------------------------------------------- */
 361
 362 static nat rub_bell = 0;
 363
 364 /*  initialise global variables needed during GC
 365  *
 366  *  * GC_start_time is read in mut_user_time_during_GC(), which in turn is
 367  *    needed if either PROFILING or DEBUGing is enabled
 368  */
 369 void
 370 stat_startGC(void)
 371 {
 372     nat bell = RtsFlags.GcFlags.ringBell;
 373
 374     if (bell) {
 375         if (bell > 1) {
 376             fprintf(stderr, " GC ");
 377             rub_bell = 1;
 378         } else {
 379             fprintf(stderr, "\007");
 380         }
 381     }
 382
 383 #if defined(PROFILING) || defined(DEBUG)
 384     getTimes();
 385     GC_start_time = CurrentUserTime;  /* needed in mut_user_time_during_GC() */
 386 #endif
 387
 388     if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
 389 #if !defined(PROFILING) && !defined(DEBUG)
 390         getTimes();
 391         GC_start_time = CurrentUserTime;
 392 #endif
 393         GCe_start_time = CurrentElapsedTime;
 394         if (RtsFlags.GcFlags.giveStats) {
 395             GC_start_faults = pageFaults();
 396         }
 397     }
 398 }
 399
 400 /* -----------------------------------------------------------------------------
 401    Called at the end of each GC
 402    -------------------------------------------------------------------------- */
 403
 404 void
 405 stat_endGC(lnat alloc, lnat collect, lnat live, lnat copied, lnat gen)
 406 {
 407     FILE *sf = RtsFlags.GcFlags.statsFile;
 408
 409     if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
 410         TICK_TYPE time, etime, gc_time, gc_etime;
 411
 412         getTimes();
 413         time     = CurrentUserTime;
 414         etime    = CurrentElapsedTime;
 415         gc_time  = time - GC_start_time;
 416         gc_etime = etime - GCe_start_time;
 417
 418         if (RtsFlags.GcFlags.giveStats == VERBOSE_GC_STATS && sf != NULL) {
 419             nat faults = pageFaults();
 420
 421             fprintf(sf, "%9ld %9ld %9ld",
 422                     alloc*sizeof(W_), collect*sizeof(W_), live*sizeof(W_));
 423             fprintf(sf, " %5.2f %5.2f %7.2f %7.2f %4ld %4ld  (Gen: %2ld)\n",
 424                     TICK_TO_DBL(gc_time),
 425                     TICK_TO_DBL(gc_etime),
 426                     TICK_TO_DBL(time),
 427                     TICK_TO_DBL(etime - ElapsedTimeStart),
 428                     faults - GC_start_faults,
 429                     GC_start_faults - GC_end_faults,
 430                     gen);
 431
 432             GC_end_faults = faults;
 433             fflush(sf);
 434         }
 435
 436         GC_coll_times[gen] += gc_time;
 437
 438         GC_tot_copied += (ullong) copied;
 439         GC_tot_alloc  += (ullong) alloc;
 440         GC_tot_time   += gc_time;
 441         GCe_tot_time  += gc_etime;
 442
 443 #ifdef SMP
 444         {
 445             nat i;
 446             pthread_t me = pthread_self();
 447
 448             for (i = 0; i < RtsFlags.ParFlags.nNodes; i++) {
 449                 if (me == task_ids[i].id) {
 450                     task_ids[i].gc_time += gc_time;
 451                     task_ids[i].gc_etime += gc_etime;
 452                     break;
 453                 }
 454             }
 455         }
 456 #endif
 457
 458         if (gen == RtsFlags.GcFlags.generations-1) { /* major GC? */
 459             if (live > MaxResidency) {
 460                 MaxResidency = live;
 461             }
 462             ResidencySamples++;
 463             AvgResidency += live;
 464         }
 465     }
 466
 467     if (rub_bell) {
 468         fprintf(stderr, "\b\b\b  \b\b\b");
 469         rub_bell = 0;
 470     }
 471 }
 472
 473 /* -----------------------------------------------------------------------------
 474    stat_workerStop
 475
 476    Called under SMP when a worker thread finishes.  We drop the timing
 477    stats for this thread into the task_ids struct for that thread.
 478    -------------------------------------------------------------------------- */
 479
 480 #ifdef SMP
 481 void
 482 stat_workerStop(void)
 483 {
 484     nat i;
 485     pthread_t me = pthread_self();
 486
 487     for (i = 0; i < RtsFlags.ParFlags.nNodes; i++) {
 488         if (task_ids[i].id == me) {
 489             task_ids[i].mut_time = usertime() - task_ids[i].gc_time;
 490             task_ids[i].mut_etime = elapsedtime()
 491                 - GCe_tot_time
 492                 - task_ids[i].elapsedtimestart;
 493             if (task_ids[i].mut_time < 0.0)  { task_ids[i].mut_time = 0.0;  }
 494             if (task_ids[i].mut_etime < 0.0) { task_ids[i].mut_etime = 0.0; }
 495         }
 496     }
 497 }
 498 #endif
 499
 500 /* -----------------------------------------------------------------------------
 501    Called at the end of execution
 502
 503    NOTE: number of allocations is not entirely accurate: it doesn't
 504    take into account the few bytes at the end of the heap that
 505    were left unused when the heap-check failed.
 506    -------------------------------------------------------------------------- */
 507
 508 void
 509 stat_exit(int alloc)
 510 {
 511     FILE *sf = RtsFlags.GcFlags.statsFile;
 512
 513     if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
 514
 515         char temp[BIG_STRING_LEN];
 516         TICK_TYPE time;
 517         TICK_TYPE etime;
 518         nat g, total_collections = 0;
 519
 520         getTimes();
 521         time = CurrentUserTime;
 522         etime = CurrentElapsedTime - ElapsedTimeStart;
 523
 524         GC_tot_alloc += alloc;
 525
 526         /* avoid divide by zero if time is measured as 0.00 seconds -- SDM */
 527         if (time  == 0.0)  time = 1;
 528         if (etime == 0.0) etime = 1;
 529
 530         /* Count total garbage collections */
 531         for (g = 0; g < RtsFlags.GcFlags.generations; g++)
 532             total_collections += generations[g].collections;
 533
 534         /* For SMP, we have to get the user time from each thread
 535          * and try to work out the total time.
 536          */
 537 #ifdef SMP
 538         {   nat i;
 539             MutUserTime = 0.0;
 540             for (i = 0; i < RtsFlags.ParFlags.nNodes; i++) {
 541                 MutUserTime += task_ids[i].mut_time;
 542             }
 543         }
 544         time = MutUserTime + GC_tot_time + InitUserTime + ExitUserTime;
 545         if (MutUserTime < 0) { MutUserTime = 0; }
 546 #endif
 547
 548         if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS && sf != NULL) {
 549             fprintf(sf, "%9ld %9.9s %9.9s", (lnat)alloc*sizeof(W_), "", "");
 550             fprintf(sf, " %5.2f %5.2f\n\n", 0.0, 0.0);
 551         }
 552
 553         if (RtsFlags.GcFlags.giveStats >= SUMMARY_GC_STATS && sf != NULL) {
 554             ullong_format_string(GC_tot_alloc*sizeof(W_),
 555                                  temp, rtsTrue/*commas*/);
 556             fprintf(sf, "%11s bytes allocated in the heap\n", temp);
 557
 558             ullong_format_string(GC_tot_copied*sizeof(W_),
 559                                  temp, rtsTrue/*commas*/);
 560             fprintf(sf, "%11s bytes copied during GC\n", temp);
 561
 562             if ( ResidencySamples > 0 ) {
 563                 ullong_format_string(MaxResidency*sizeof(W_),
 564                                      temp, rtsTrue/*commas*/);
 565                 fprintf(sf, "%11s bytes maximum residency (%ld sample(s))\n",
 566                         temp, ResidencySamples);
 567             }
 568             fprintf(sf,"\n");
 569
 570             /* Print garbage collections in each gen */
 571             for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
 572                 fprintf(sf, "%11d collections in generation %d (%6.2fs)\n",
 573                         generations[g].collections, g,
 574                         TICK_TO_DBL(GC_coll_times[g]));
 575             }
 576
 577             fprintf(sf,"\n%11ld Mb total memory in use\n\n",
 578                     mblocks_allocated * MBLOCK_SIZE / (1024 * 1024));
 579
 580 #ifdef SMP
 581             {
 582                 nat i;
 583                 for (i = 0; i < RtsFlags.ParFlags.nNodes; i++) {
 584                     fprintf(sf, "  Task %2d:  MUT time: %6.2fs  (%6.2fs elapsed)\n"
 585                             "            GC  time: %6.2fs  (%6.2fs elapsed)\n\n",
 586                             i,
 587                             TICK_TO_DBL(task_ids[i].mut_time),
 588                             TICK_TO_DBL(task_ids[i].mut_etime),
 589                             TICK_TO_DBL(task_ids[i].gc_time),
 590                             TICK_TO_DBL(task_ids[i].gc_etime));
 591                 }
 592             }
 593 #endif
 594
 595             fprintf(sf, "  INIT  time  %6.2fs  (%6.2fs elapsed)\n",
 596                     TICK_TO_DBL(InitUserTime), TICK_TO_DBL(InitElapsedTime));
 597             fprintf(sf, "  MUT   time  %6.2fs  (%6.2fs elapsed)\n",
 598                     TICK_TO_DBL(MutUserTime), TICK_TO_DBL(MutElapsedTime));
 599             fprintf(sf, "  GC    time  %6.2fs  (%6.2fs elapsed)\n",
 600                     TICK_TO_DBL(GC_tot_time), TICK_TO_DBL(GCe_tot_time));
 601             fprintf(sf, "  EXIT  time  %6.2fs  (%6.2fs elapsed)\n",
 602                     TICK_TO_DBL(ExitUserTime), TICK_TO_DBL(ExitElapsedTime));
 603             fprintf(sf, "  Total time  %6.2fs  (%6.2fs elapsed)\n\n",
 604                     TICK_TO_DBL(time), TICK_TO_DBL(etime));
 605             fprintf(sf, "  %%GC time     %5.1f%%  (%.1f%% elapsed)\n\n",
 606                     TICK_TO_DBL(GC_tot_time)*100/TICK_TO_DBL(time),
 607                     TICK_TO_DBL(GCe_tot_time)*100/TICK_TO_DBL(etime));
 608
 609             if (time - GC_tot_time == 0)
 610                 ullong_format_string(0, temp, rtsTrue/*commas*/);
 611             else
 612                 ullong_format_string(
 613                     (ullong)((GC_tot_alloc*sizeof(W_))/
 614                              TICK_TO_DBL(time - GC_tot_time)),
 615                     temp, rtsTrue/*commas*/);
 616
 617             fprintf(sf, "  Alloc rate    %s bytes per MUT second\n\n", temp);
 618
 619             fprintf(sf, "  Productivity %5.1f%% of total user, %.1f%% of total elapsed\n\n",
 620                     TICK_TO_DBL(time - GC_tot_time - InitUserTime) * 100
 621                     / TICK_TO_DBL(time),
 622                     TICK_TO_DBL(time - GC_tot_time - InitUserTime) * 100
 623                     / TICK_TO_DBL(etime));
 624         }
 625
 626         if (RtsFlags.GcFlags.giveStats == ONELINE_GC_STATS && sf != NULL) {
 627           /* print the long long separately to avoid bugginess on mingwin (2001-07-02, mingw-0.5) */
 628           fprintf(sf, "<<ghc: %llu bytes, ", GC_tot_alloc*sizeof(W_));
 629           fprintf(sf, "%d GCs, %ld/%ld avg/max bytes residency (%ld samples), %luM in use, %.2f INIT (%.2f elapsed), %.2f MUT (%.2f elapsed), %.2f GC (%.2f elapsed) :ghc>>\n",
 630                     total_collections,
 631                     AvgResidency*sizeof(W_)/ResidencySamples,
 632                     MaxResidency*sizeof(W_),
 633                     ResidencySamples,
 634                     (unsigned long)(mblocks_allocated * MBLOCK_SIZE / (1024L * 1024L)),
 635                     TICK_TO_DBL(InitUserTime), TICK_TO_DBL(InitElapsedTime),
 636                     TICK_TO_DBL(MutUserTime), TICK_TO_DBL(MutElapsedTime),
 637                     TICK_TO_DBL(GC_tot_time), TICK_TO_DBL(GCe_tot_time));
 638         }
 639
 640         fflush(sf);
 641         fclose(sf);
 642     }
 643 }
 644
 645 /* -----------------------------------------------------------------------------
 646    stat_describe_gens
 647
 648    Produce some detailed info on the state of the generational GC.
 649    -------------------------------------------------------------------------- */
 650 void
 651 statDescribeGens(void)
 652 {
 653   nat g, s, mut, mut_once, lge, live;
 654   StgMutClosure *m;
 655   bdescr *bd;
 656   step *step;
 657
 658   fprintf(stderr, "     Gen    Steps      Max   Mutable  Mut-Once  Step   Blocks     Live    Large\n                    Blocks  Closures  Closures                          Objects\n");
 659
 660   for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
 661     for (m = generations[g].mut_list, mut = 0; m != END_MUT_LIST;
 662          m = m->mut_link)
 663       mut++;
 664     for (m = generations[g].mut_once_list, mut_once = 0; m != END_MUT_LIST;
 665          m = m->mut_link)
 666       mut_once++;
 667     fprintf(stderr, "%8d %8d %8d %9d %9d", g, generations[g].n_steps,
 668             generations[g].max_blocks, mut, mut_once);
 669
 670     for (s = 0; s < generations[g].n_steps; s++) {
 671       step = &generations[g].steps[s];
 672       for (bd = step->large_objects, lge = 0; bd; bd = bd->link)
 673         lge++;
 674       live = 0;
 675       if (RtsFlags.GcFlags.generations == 1) {
 676         bd = step->to_blocks;
 677       } else {
 678         bd = step->blocks;
 679       }
 680       for (; bd; bd = bd->link) {
 681         live += (bd->free - bd->start) * sizeof(W_);
 682       }
 683       if (s != 0) {
 684         fprintf(stderr,"%46s","");
 685       }
 686       fprintf(stderr,"%6d %8d %8d %8d\n", s, step->n_blocks,
 687               live, lge);
 688     }
 689   }
 690   fprintf(stderr,"\n");
 691 }
 692
 693 /* -----------------------------------------------------------------------------
 694    Stats available via a programmatic interface, so eg. GHCi can time
 695    each compilation and expression evaluation.
 696    -------------------------------------------------------------------------- */
 697
 698 extern HsInt getAllocations( void )
 699 { return (HsInt)(total_allocated * sizeof(W_)); }