rts/Stats.c

   1 /* -----------------------------------------------------------------------------
   2  *
   3  * (c) The GHC Team, 1998-2005
   4  *
   5  * Statistics and timing-related functions.
   6  *
   7  * ---------------------------------------------------------------------------*/
   8
   9 #include "Rts.h"
  10 #include "RtsFlags.h"
  11 #include "RtsUtils.h"
  12 #include "MBlock.h"
  13 #include "Storage.h"
  14 #include "Schedule.h"
  15 #include "Stats.h"
  16 #include "ParTicky.h"                       /* ToDo: move into Rts.h */
  17 #include "Profiling.h"
  18 #include "GetTime.h"
  19
  20 #if USE_PAPI
  21 #include "Papi.h"
  22 #endif
  23
  24 /* huh? */
  25 #define BIG_STRING_LEN              512
  26
  27 #define TICK_TO_DBL(t) ((double)(t) / TICKS_PER_SECOND)
  28
  29 static Ticks ElapsedTimeStart = 0;
  30
  31 static Ticks InitUserTime     = 0;
  32 static Ticks InitElapsedTime  = 0;
  33 static Ticks InitElapsedStamp = 0;
  34
  35 static Ticks MutUserTime      = 0;
  36 static Ticks MutElapsedTime   = 0;
  37 static Ticks MutElapsedStamp  = 0;
  38
  39 static Ticks ExitUserTime     = 0;
  40 static Ticks ExitElapsedTime  = 0;
  41
  42 static ullong GC_tot_alloc        = 0;
  43 static ullong GC_tot_copied       = 0;
  44
  45 static Ticks GC_start_time = 0,  GC_tot_time  = 0;  /* User GC Time */
  46 static Ticks GCe_start_time = 0, GCe_tot_time = 0;  /* Elapsed GC time */
  47
  48 #ifdef PROFILING
  49 static Ticks RP_start_time  = 0, RP_tot_time  = 0;  /* retainer prof user time */
  50 static Ticks RPe_start_time = 0, RPe_tot_time = 0;  /* retainer prof elap time */
  51
  52 static Ticks HC_start_time, HC_tot_time = 0;     // heap census prof user time
  53 static Ticks HCe_start_time, HCe_tot_time = 0;   // heap census prof elap time
  54 #endif
  55
  56 #ifdef PROFILING
  57 #define PROF_VAL(x)   (x)
  58 #else
  59 #define PROF_VAL(x)   0
  60 #endif
  61
  62 static lnat MaxResidency = 0;     // in words; for stats only
  63 static lnat AvgResidency = 0;
  64 static lnat ResidencySamples = 0; // for stats only
  65
  66 static lnat GC_start_faults = 0, GC_end_faults = 0;
  67
  68 static Ticks *GC_coll_times;
  69
  70 static void statsFlush( void );
  71 static void statsClose( void );
  72
  73 Ticks stat_getElapsedGCTime(void)
  74 {
  75     return GCe_tot_time;
  76 }
  77
  78 Ticks stat_getElapsedTime(void)
  79 {
  80     return getProcessElapsedTime() - ElapsedTimeStart;
  81 }
  82
  83 /* mut_user_time_during_GC() and mut_user_time()
  84  *
  85  * The former function can be used to get the current mutator time
  86  * *during* a GC, i.e. between stat_startGC and stat_endGC.  This is
  87  * used in the heap profiler for accurately time stamping the heap
  88  * sample.
  89  *
  90  * ATTENTION: mut_user_time_during_GC() relies on GC_start_time being
  91  *            defined in stat_startGC() - to minimise system calls,
  92  *            GC_start_time is, however, only defined when really needed (check
  93  *            stat_startGC() for details)
  94  */
  95 double
  96 mut_user_time_during_GC( void )
  97 {
  98   return TICK_TO_DBL(GC_start_time - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time));
  99 }
 100
 101 double
 102 mut_user_time( void )
 103 {
 104     Ticks user;
 105     user = getProcessCPUTime();
 106     return TICK_TO_DBL(user - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time));
 107 }
 108
 109 #ifdef PROFILING
 110 /*
 111   mut_user_time_during_RP() is similar to mut_user_time_during_GC();
 112   it returns the MUT time during retainer profiling.
 113   The same is for mut_user_time_during_HC();
 114  */
 115 double
 116 mut_user_time_during_RP( void )
 117 {
 118   return TICK_TO_DBL(RP_start_time - GC_tot_time - RP_tot_time - HC_tot_time);
 119 }
 120
 121 double
 122 mut_user_time_during_heap_census( void )
 123 {
 124   return TICK_TO_DBL(HC_start_time - GC_tot_time - RP_tot_time - HC_tot_time);
 125 }
 126 #endif /* PROFILING */
 127
 128 void
 129 initStats(void)
 130 {
 131     nat i;
 132
 133     if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) {
 134         statsPrintf("    Alloc    Copied     Live    GC    GC     TOT     TOT  Page Flts\n");
 135         statsPrintf("    bytes     bytes     bytes  user  elap    user    elap\n");
 136     }
 137     GC_coll_times =
 138         (Ticks *)stgMallocBytes(
 139             sizeof(Ticks)*RtsFlags.GcFlags.generations,
 140             "initStats");
 141     for (i = 0; i < RtsFlags.GcFlags.generations; i++) {
 142         GC_coll_times[i] = 0;
 143     }
 144 }
 145
 146 /* -----------------------------------------------------------------------------
 147    Initialisation time...
 148    -------------------------------------------------------------------------- */
 149
 150 void
 151 stat_startInit(void)
 152 {
 153     Ticks elapsed;
 154
 155     elapsed = getProcessElapsedTime();
 156     ElapsedTimeStart = elapsed;
 157 }
 158
 159 void
 160 stat_endInit(void)
 161 {
 162     Ticks user, elapsed;
 163
 164     getProcessTimes(&user, &elapsed);
 165
 166     InitUserTime = user;
 167     InitElapsedStamp = elapsed;
 168     if (ElapsedTimeStart > elapsed) {
 169         InitElapsedTime = 0;
 170     } else {
 171         InitElapsedTime = elapsed - ElapsedTimeStart;
 172     }
 173 #if USE_PAPI
 174     papi_init_eventsets();
 175
 176     /* We start counting events for the mutator
 177      * when garbage collection starts
 178      * we switch to the GC event set. */
 179     papi_start_mutator_count();
 180
 181     /* This flag is needed to avoid counting the last GC */
 182     papi_is_reporting = 1;
 183
 184 #endif
 185 }
 186
 187 /* -----------------------------------------------------------------------------
 188    stat_startExit and stat_endExit
 189
 190    These two measure the time taken in shutdownHaskell().
 191    -------------------------------------------------------------------------- */
 192
 193 void
 194 stat_startExit(void)
 195 {
 196     Ticks user, elapsed;
 197
 198     getProcessTimes(&user, &elapsed);
 199
 200     MutElapsedStamp = elapsed;
 201     MutElapsedTime = elapsed - GCe_tot_time -
 202         PROF_VAL(RPe_tot_time + HCe_tot_time) - InitElapsedStamp;
 203     if (MutElapsedTime < 0) { MutElapsedTime = 0; }     /* sometimes -0.00 */
 204
 205     MutUserTime = user - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime;
 206     if (MutUserTime < 0) { MutUserTime = 0; }
 207
 208 #if USE_PAPI
 209     /* We stop counting mutator events
 210      * GC events are not being counted at this point */
 211     papi_stop_mutator_count();
 212
 213     /* This flag is needed, because GC is run once more after this function */
 214     papi_is_reporting = 0;
 215
 216 #endif
 217 }
 218
 219 void
 220 stat_endExit(void)
 221 {
 222     Ticks user, elapsed;
 223
 224     getProcessTimes(&user, &elapsed);
 225
 226     ExitUserTime = user - MutUserTime - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime;
 227     ExitElapsedTime = elapsed - MutElapsedStamp;
 228     if (ExitUserTime < 0) {
 229         ExitUserTime = 0;
 230     }
 231     if (ExitElapsedTime < 0) {
 232         ExitElapsedTime = 0;
 233     }
 234 }
 235
 236 /* -----------------------------------------------------------------------------
 237    Called at the beginning of each GC
 238    -------------------------------------------------------------------------- */
 239
 240 static nat rub_bell = 0;
 241
 242 /*  initialise global variables needed during GC
 243  *
 244  *  * GC_start_time is read in mut_user_time_during_GC(), which in turn is
 245  *    needed if either PROFILING or DEBUGing is enabled
 246  */
 247 void
 248 stat_startGC(void)
 249 {
 250     nat bell = RtsFlags.GcFlags.ringBell;
 251
 252     if (bell) {
 253         if (bell > 1) {
 254             debugBelch(" GC ");
 255             rub_bell = 1;
 256         } else {
 257             debugBelch("\007");
 258         }
 259     }
 260
 261 #if defined(PROFILING) || defined(DEBUG)
 262     GC_start_time = getProcessCPUTime();  // needed in mut_user_time_during_GC()
 263 #endif
 264
 265     if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
 266 #if !defined(PROFILING) && !defined(DEBUG)
 267         GC_start_time = getProcessCPUTime();
 268 #endif
 269         GCe_start_time = getProcessElapsedTime();
 270         if (RtsFlags.GcFlags.giveStats) {
 271             GC_start_faults = getPageFaults();
 272         }
 273     }
 274
 275 #if USE_PAPI
 276     if(papi_is_reporting) {
 277       /* Switch to counting GC events */
 278       papi_stop_mutator_count();
 279       papi_start_gc_count();
 280     }
 281 #endif
 282
 283 }
 284
 285 /* -----------------------------------------------------------------------------
 286    Called at the end of each GC
 287    -------------------------------------------------------------------------- */
 288
 289 void
 290 stat_endGC (lnat alloc, lnat live, lnat copied, lnat gen)
 291 {
 292     if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
 293         Ticks time, etime, gc_time, gc_etime;
 294
 295         getProcessTimes(&time, &etime);
 296         gc_time  = time - GC_start_time;
 297         gc_etime = etime - GCe_start_time;
 298
 299         if (RtsFlags.GcFlags.giveStats == VERBOSE_GC_STATS) {
 300             nat faults = getPageFaults();
 301
 302             statsPrintf("%9ld %9ld %9ld",
 303                     alloc*sizeof(W_), copied*sizeof(W_),
 304                         live*sizeof(W_));
 305             statsPrintf(" %5.2f %5.2f %7.2f %7.2f %4ld %4ld  (Gen: %2ld)\n",
 306                     TICK_TO_DBL(gc_time),
 307                     TICK_TO_DBL(gc_etime),
 308                     TICK_TO_DBL(time),
 309                     TICK_TO_DBL(etime - ElapsedTimeStart),
 310                     faults - GC_start_faults,
 311                     GC_start_faults - GC_end_faults,
 312                     gen);
 313
 314             GC_end_faults = faults;
 315             statsFlush();
 316         }
 317
 318         GC_coll_times[gen] += gc_time;
 319
 320         GC_tot_copied += (ullong) copied;
 321         GC_tot_alloc  += (ullong) alloc;
 322         GC_tot_time   += gc_time;
 323         GCe_tot_time  += gc_etime;
 324
 325 #if defined(THREADED_RTS)
 326         {
 327             Task *task;
 328             if ((task = myTask()) != NULL) {
 329                 task->gc_time += gc_time;
 330                 task->gc_etime += gc_etime;
 331             }
 332         }
 333 #endif
 334
 335         if (gen == RtsFlags.GcFlags.generations-1) { /* major GC? */
 336             if (live > MaxResidency) {
 337                 MaxResidency = live;
 338             }
 339             ResidencySamples++;
 340             AvgResidency += live;
 341         }
 342     }
 343
 344     if (rub_bell) {
 345         debugBelch("\b\b\b  \b\b\b");
 346         rub_bell = 0;
 347     }
 348
 349 #if USE_PAPI
 350     if(papi_is_reporting) {
 351       /* Switch to counting mutator events */
 352       papi_stop_gc_count();
 353       papi_start_mutator_count();
 354     }
 355 #endif
 356 }
 357
 358 /* -----------------------------------------------------------------------------
 359    Called at the beginning of each Retainer Profiliing
 360    -------------------------------------------------------------------------- */
 361 #ifdef PROFILING
 362 void
 363 stat_startRP(void)
 364 {
 365     Ticks user, elapsed;
 366     getProcessTimes( &user, &elapsed );
 367
 368     RP_start_time = user;
 369     RPe_start_time = elapsed;
 370 }
 371 #endif /* PROFILING */
 372
 373 /* -----------------------------------------------------------------------------
 374    Called at the end of each Retainer Profiliing
 375    -------------------------------------------------------------------------- */
 376
 377 #ifdef PROFILING
 378 void
 379 stat_endRP(
 380   nat retainerGeneration,
 381 #ifdef DEBUG_RETAINER
 382   nat maxCStackSize,
 383   int maxStackSize,
 384 #endif
 385   double averageNumVisit)
 386 {
 387     Ticks user, elapsed;
 388     getProcessTimes( &user, &elapsed );
 389
 390     RP_tot_time += user - RP_start_time;
 391     RPe_tot_time += elapsed - RPe_start_time;
 392
 393   fprintf(prof_file, "Retainer Profiling: %d, at %f seconds\n",
 394     retainerGeneration, mut_user_time_during_RP());
 395 #ifdef DEBUG_RETAINER
 396   fprintf(prof_file, "\tMax C stack size = %u\n", maxCStackSize);
 397   fprintf(prof_file, "\tMax auxiliary stack size = %u\n", maxStackSize);
 398 #endif
 399   fprintf(prof_file, "\tAverage number of visits per object = %f\n", averageNumVisit);
 400 }
 401 #endif /* PROFILING */
 402
 403 /* -----------------------------------------------------------------------------
 404    Called at the beginning of each heap census
 405    -------------------------------------------------------------------------- */
 406 #ifdef PROFILING
 407 void
 408 stat_startHeapCensus(void)
 409 {
 410     Ticks user, elapsed;
 411     getProcessTimes( &user, &elapsed );
 412
 413     HC_start_time = user;
 414     HCe_start_time = elapsed;
 415 }
 416 #endif /* PROFILING */
 417
 418 /* -----------------------------------------------------------------------------
 419    Called at the end of each heap census
 420    -------------------------------------------------------------------------- */
 421 #ifdef PROFILING
 422 void
 423 stat_endHeapCensus(void)
 424 {
 425     Ticks user, elapsed;
 426     getProcessTimes( &user, &elapsed );
 427
 428     HC_tot_time += user - HC_start_time;
 429     HCe_tot_time += elapsed - HCe_start_time;
 430 }
 431 #endif /* PROFILING */
 432
 433 /* -----------------------------------------------------------------------------
 434    Called at the end of execution
 435
 436    NOTE: number of allocations is not entirely accurate: it doesn't
 437    take into account the few bytes at the end of the heap that
 438    were left unused when the heap-check failed.
 439    -------------------------------------------------------------------------- */
 440
 441 #ifdef DEBUG
 442 #define TICK_VAR(arity) \
 443   extern StgInt SLOW_CALLS_##arity; \
 444   extern StgInt RIGHT_ARITY_##arity; \
 445   extern StgInt TAGGED_PTR_##arity;
 446
 447 #define TICK_VAR_INI(arity) \
 448   StgInt SLOW_CALLS_##arity = 1; \
 449   StgInt RIGHT_ARITY_##arity = 1; \
 450   StgInt TAGGED_PTR_##arity = 0;
 451
 452 extern StgInt TOTAL_CALLS;
 453
 454 TICK_VAR(1)
 455 TICK_VAR(2)
 456
 457 TICK_VAR_INI(1)
 458 TICK_VAR_INI(2)
 459
 460 StgInt TOTAL_CALLS=1;
 461 #endif
 462
 463 /* Report the value of a counter */
 464 #define REPORT(counter) \
 465   { \
 466     ullong_format_string(counter,temp,rtsTrue/*commas*/); \
 467     statsPrintf("  (" #counter ")  : %s\n",temp);                               \
 468   }
 469
 470 /* Report the value of a counter as a percentage of another counter */
 471 #define REPORT_PCT(counter,countertot) \
 472   statsPrintf("  (" #counter ") %% of (" #countertot ") : %.1f%%\n", \
 473               counter*100.0/countertot)
 474
 475 #define TICK_PRINT(arity) \
 476   REPORT(SLOW_CALLS_##arity); \
 477   REPORT_PCT(RIGHT_ARITY_##arity,SLOW_CALLS_##arity); \
 478   REPORT_PCT(TAGGED_PTR_##arity,RIGHT_ARITY_##arity); \
 479   REPORT(RIGHT_ARITY_##arity); \
 480   REPORT(TAGGED_PTR_##arity)
 481
 482 #define TICK_PRINT_TOT(arity) \
 483   statsPrintf("  (SLOW_CALLS_" #arity ") %% of (TOTAL_CALLS) : %.1f%%\n", \
 484               SLOW_CALLS_##arity * 100.0/TOTAL_CALLS)
 485
 486
 487 void
 488 stat_exit(int alloc)
 489 {
 490     if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
 491
 492         char temp[BIG_STRING_LEN];
 493         Ticks time;
 494         Ticks etime;
 495         nat g, total_collections = 0;
 496
 497         getProcessTimes( &time, &etime );
 498         etime -= ElapsedTimeStart;
 499
 500         GC_tot_alloc += alloc;
 501
 502         /* Count total garbage collections */
 503         for (g = 0; g < RtsFlags.GcFlags.generations; g++)
 504             total_collections += generations[g].collections;
 505
 506         /* avoid divide by zero if time is measured as 0.00 seconds -- SDM */
 507         if (time  == 0.0)  time = 1;
 508         if (etime == 0.0) etime = 1;
 509
 510         if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) {
 511             statsPrintf("%9ld %9.9s %9.9s", (lnat)alloc*sizeof(W_), "", "");
 512             statsPrintf(" %5.2f %5.2f\n\n", 0.0, 0.0);
 513         }
 514
 515         if (RtsFlags.GcFlags.giveStats >= SUMMARY_GC_STATS) {
 516             ullong_format_string(GC_tot_alloc*sizeof(W_),
 517                                  temp, rtsTrue/*commas*/);
 518             statsPrintf("%11s bytes allocated in the heap\n", temp);
 519
 520             ullong_format_string(GC_tot_copied*sizeof(W_),
 521                                  temp, rtsTrue/*commas*/);
 522             statsPrintf("%11s bytes copied during GC\n", temp);
 523
 524             if ( ResidencySamples > 0 ) {
 525                 ullong_format_string(MaxResidency*sizeof(W_),
 526                                      temp, rtsTrue/*commas*/);
 527                 statsPrintf("%11s bytes maximum residency (%ld sample(s))\n",
 528                         temp, ResidencySamples);
 529             }
 530             statsPrintf("\n");
 531
 532             /* Print garbage collections in each gen */
 533             for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
 534                 statsPrintf("%11d collections in generation %d (%6.2fs)\n",
 535                         generations[g].collections, g,
 536                         TICK_TO_DBL(GC_coll_times[g]));
 537             }
 538
 539             statsPrintf("\n%11ld Mb total memory in use\n\n",
 540                     mblocks_allocated * MBLOCK_SIZE / (1024 * 1024));
 541
 542 #if defined(THREADED_RTS)
 543             {
 544                 nat i;
 545                 Task *task;
 546                 for (i = 0, task = all_tasks;
 547                      task != NULL;
 548                      i++, task = task->all_link) {
 549                     statsPrintf("  Task %2d %-8s :  MUT time: %6.2fs  (%6.2fs elapsed)\n"
 550                             "                      GC  time: %6.2fs  (%6.2fs elapsed)\n\n",
 551                                 i,
 552                                 (task->tso == NULL) ? "(worker)" : "(bound)",
 553                                 TICK_TO_DBL(task->mut_time),
 554                                 TICK_TO_DBL(task->mut_etime),
 555                                 TICK_TO_DBL(task->gc_time),
 556                                 TICK_TO_DBL(task->gc_etime));
 557                 }
 558             }
 559 #endif
 560
 561             statsPrintf("  INIT  time  %6.2fs  (%6.2fs elapsed)\n",
 562                     TICK_TO_DBL(InitUserTime), TICK_TO_DBL(InitElapsedTime));
 563             statsPrintf("  MUT   time  %6.2fs  (%6.2fs elapsed)\n",
 564                     TICK_TO_DBL(MutUserTime), TICK_TO_DBL(MutElapsedTime));
 565             statsPrintf("  GC    time  %6.2fs  (%6.2fs elapsed)\n",
 566                     TICK_TO_DBL(GC_tot_time), TICK_TO_DBL(GCe_tot_time));
 567 #ifdef PROFILING
 568             statsPrintf("  RP    time  %6.2fs  (%6.2fs elapsed)\n",
 569                     TICK_TO_DBL(RP_tot_time), TICK_TO_DBL(RPe_tot_time));
 570             statsPrintf("  PROF  time  %6.2fs  (%6.2fs elapsed)\n",
 571                     TICK_TO_DBL(HC_tot_time), TICK_TO_DBL(HCe_tot_time));
 572 #endif
 573             statsPrintf("  EXIT  time  %6.2fs  (%6.2fs elapsed)\n",
 574                     TICK_TO_DBL(ExitUserTime), TICK_TO_DBL(ExitElapsedTime));
 575             statsPrintf("  Total time  %6.2fs  (%6.2fs elapsed)\n\n",
 576                     TICK_TO_DBL(time), TICK_TO_DBL(etime));
 577             statsPrintf("  %%GC time     %5.1f%%  (%.1f%% elapsed)\n\n",
 578                     TICK_TO_DBL(GC_tot_time)*100/TICK_TO_DBL(time),
 579                     TICK_TO_DBL(GCe_tot_time)*100/TICK_TO_DBL(etime));
 580
 581             if (time - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time) == 0)
 582                 ullong_format_string(0, temp, rtsTrue/*commas*/);
 583             else
 584                 ullong_format_string(
 585                     (ullong)((GC_tot_alloc*sizeof(W_))/
 586                              TICK_TO_DBL(time - GC_tot_time -
 587                                          PROF_VAL(RP_tot_time + HC_tot_time))),
 588                     temp, rtsTrue/*commas*/);
 589
 590             statsPrintf("  Alloc rate    %s bytes per MUT second\n\n", temp);
 591
 592             statsPrintf("  Productivity %5.1f%% of total user, %.1f%% of total elapsed\n\n",
 593                     TICK_TO_DBL(time - GC_tot_time -
 594                                 PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime) * 100
 595                     / TICK_TO_DBL(time),
 596                     TICK_TO_DBL(time - GC_tot_time -
 597                                 PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime) * 100
 598                     / TICK_TO_DBL(etime));
 599
 600             /*
 601             TICK_PRINT(1);
 602             TICK_PRINT(2);
 603             REPORT(TOTAL_CALLS);
 604             TICK_PRINT_TOT(1);
 605             TICK_PRINT_TOT(2);
 606             */
 607
 608 #if USE_PAPI
 609             /* PAPI reporting, should put somewhere else?
 610              * Note that the cycles are counted _after_ the initialization of the RTS -- AR */
 611
 612             statsPrintf("  -- CPU Mutator counters --\n");
 613             papi_mut_cycles();
 614             papi_report(MutatorCounters);
 615
 616             statsPrintf("\n  -- CPU GC counters --\n");
 617             papi_gc_cycles();
 618             papi_report(GCCounters);
 619 #endif
 620         }
 621
 622         if (RtsFlags.GcFlags.giveStats == ONELINE_GC_STATS) {
 623           /* print the long long separately to avoid bugginess on mingwin (2001-07-02, mingw-0.5) */
 624           statsPrintf("<<ghc: %llu bytes, ", GC_tot_alloc*(ullong)sizeof(W_));
 625           statsPrintf("%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",
 626                     total_collections,
 627                     ResidencySamples == 0 ? 0 :
 628                         AvgResidency*sizeof(W_)/ResidencySamples,
 629                     MaxResidency*sizeof(W_),
 630                     ResidencySamples,
 631                     (unsigned long)(mblocks_allocated * MBLOCK_SIZE / (1024L * 1024L)),
 632                     TICK_TO_DBL(InitUserTime), TICK_TO_DBL(InitElapsedTime),
 633                     TICK_TO_DBL(MutUserTime), TICK_TO_DBL(MutElapsedTime),
 634                     TICK_TO_DBL(GC_tot_time), TICK_TO_DBL(GCe_tot_time));
 635         }
 636
 637         statsFlush();
 638         statsClose();
 639     }
 640     if (GC_coll_times)
 641       stgFree(GC_coll_times);
 642     GC_coll_times = NULL;
 643 }
 644
 645 /* -----------------------------------------------------------------------------
 646    stat_describe_gens
 647
 648    Produce some detailed info on the state of the generational GC.
 649    -------------------------------------------------------------------------- */
 650 #ifdef DEBUG
 651 void
 652 statDescribeGens(void)
 653 {
 654   nat g, s, mut, lge;
 655   lnat live;
 656   bdescr *bd;
 657   step *step;
 658
 659   debugBelch(
 660 "     Gen    Steps      Max  Mut-list  Step   Blocks     Live    Large\n"
 661 "                    Blocks     Bytes                          Objects\n");
 662
 663   mut = 0;
 664   for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
 665       for (bd = generations[g].mut_list; bd != NULL; bd = bd->link) {
 666           mut += (bd->free - bd->start) * sizeof(W_);
 667       }
 668
 669     debugBelch("%8d %8d %8d %9d", g, generations[g].n_steps,
 670             generations[g].max_blocks, mut);
 671
 672     for (s = 0; s < generations[g].n_steps; s++) {
 673       step = &generations[g].steps[s];
 674       live = 0;
 675       for (bd = step->large_objects, lge = 0; bd; bd = bd->link) {
 676         lge++;
 677       }
 678       live = step->n_large_blocks * BLOCK_SIZE;
 679       bd = step->blocks;
 680       // This live figure will be slightly less that the "live" figure
 681       // given by +RTS -Sstderr, because we take don't count the
 682       // slop at the end of each block.
 683       for (; bd; bd = bd->link) {
 684         live += (bd->free - bd->start) * sizeof(W_);
 685       }
 686       if (s != 0) {
 687         debugBelch("%36s","");
 688       }
 689       debugBelch("%6d %8d %8ld %8d\n", s, step->n_blocks,
 690               live, lge);
 691     }
 692   }
 693   debugBelch("\n");
 694 }
 695 #endif
 696
 697 /* -----------------------------------------------------------------------------
 698    Stats available via a programmatic interface, so eg. GHCi can time
 699    each compilation and expression evaluation.
 700    -------------------------------------------------------------------------- */
 701
 702 extern HsInt64 getAllocations( void )
 703 { return (HsInt64)total_allocated * sizeof(W_); }
 704
 705 /* -----------------------------------------------------------------------------
 706    Dumping stuff in the stats file, or via the debug message interface
 707    -------------------------------------------------------------------------- */
 708
 709 void
 710 statsPrintf( char *s, ... )
 711 {
 712     FILE *sf = RtsFlags.GcFlags.statsFile;
 713     va_list ap;
 714
 715     va_start(ap,s);
 716     if (sf == NULL) {
 717         vdebugBelch(s,ap);
 718     } else {
 719         vfprintf(sf, s, ap);
 720     }
 721     va_end(ap);
 722 }
 723
 724 static void
 725 statsFlush( void )
 726 {
 727     FILE *sf = RtsFlags.GcFlags.statsFile;
 728     if (sf != NULL) {
 729         fflush(sf);
 730     }
 731 }
 732
 733 static void
 734 statsClose( void )
 735 {
 736     FILE *sf = RtsFlags.GcFlags.statsFile;
 737     if (sf != NULL) {
 738         fclose(sf);
 739     }
 740 }