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