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