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       if (gen == 0) {
 351           papi_stop_gc0_count();
 352       } else {
 353           papi_stop_gc1_count();
 354       }
 355       papi_start_mutator_count();
 356     }
 357 #endif
 358 }
 359
 360 /* -----------------------------------------------------------------------------
 361    Called at the beginning of each Retainer Profiliing
 362    -------------------------------------------------------------------------- */
 363 #ifdef PROFILING
 364 void
 365 stat_startRP(void)
 366 {
 367     Ticks user, elapsed;
 368     getProcessTimes( &user, &elapsed );
 369
 370     RP_start_time = user;
 371     RPe_start_time = elapsed;
 372 }
 373 #endif /* PROFILING */
 374
 375 /* -----------------------------------------------------------------------------
 376    Called at the end of each Retainer Profiliing
 377    -------------------------------------------------------------------------- */
 378
 379 #ifdef PROFILING
 380 void
 381 stat_endRP(
 382   nat retainerGeneration,
 383 #ifdef DEBUG_RETAINER
 384   nat maxCStackSize,
 385   int maxStackSize,
 386 #endif
 387   double averageNumVisit)
 388 {
 389     Ticks user, elapsed;
 390     getProcessTimes( &user, &elapsed );
 391
 392     RP_tot_time += user - RP_start_time;
 393     RPe_tot_time += elapsed - RPe_start_time;
 394
 395   fprintf(prof_file, "Retainer Profiling: %d, at %f seconds\n",
 396     retainerGeneration, mut_user_time_during_RP());
 397 #ifdef DEBUG_RETAINER
 398   fprintf(prof_file, "\tMax C stack size = %u\n", maxCStackSize);
 399   fprintf(prof_file, "\tMax auxiliary stack size = %u\n", maxStackSize);
 400 #endif
 401   fprintf(prof_file, "\tAverage number of visits per object = %f\n", averageNumVisit);
 402 }
 403 #endif /* PROFILING */
 404
 405 /* -----------------------------------------------------------------------------
 406    Called at the beginning of each heap census
 407    -------------------------------------------------------------------------- */
 408 #ifdef PROFILING
 409 void
 410 stat_startHeapCensus(void)
 411 {
 412     Ticks user, elapsed;
 413     getProcessTimes( &user, &elapsed );
 414
 415     HC_start_time = user;
 416     HCe_start_time = elapsed;
 417 }
 418 #endif /* PROFILING */
 419
 420 /* -----------------------------------------------------------------------------
 421    Called at the end of each heap census
 422    -------------------------------------------------------------------------- */
 423 #ifdef PROFILING
 424 void
 425 stat_endHeapCensus(void)
 426 {
 427     Ticks user, elapsed;
 428     getProcessTimes( &user, &elapsed );
 429
 430     HC_tot_time += user - HC_start_time;
 431     HCe_tot_time += elapsed - HCe_start_time;
 432 }
 433 #endif /* PROFILING */
 434
 435 /* -----------------------------------------------------------------------------
 436    Called at the end of execution
 437
 438    NOTE: number of allocations is not entirely accurate: it doesn't
 439    take into account the few bytes at the end of the heap that
 440    were left unused when the heap-check failed.
 441    -------------------------------------------------------------------------- */
 442
 443 #ifdef DEBUG
 444 #define TICK_VAR(arity) \
 445   extern StgInt SLOW_CALLS_##arity; \
 446   extern StgInt RIGHT_ARITY_##arity; \
 447   extern StgInt TAGGED_PTR_##arity;
 448
 449 #define TICK_VAR_INI(arity) \
 450   StgInt SLOW_CALLS_##arity = 1; \
 451   StgInt RIGHT_ARITY_##arity = 1; \
 452   StgInt TAGGED_PTR_##arity = 0;
 453
 454 extern StgInt TOTAL_CALLS;
 455
 456 TICK_VAR(1)
 457 TICK_VAR(2)
 458
 459 TICK_VAR_INI(1)
 460 TICK_VAR_INI(2)
 461
 462 StgInt TOTAL_CALLS=1;
 463 #endif
 464
 465 /* Report the value of a counter */
 466 #define REPORT(counter) \
 467   { \
 468     ullong_format_string(counter,temp,rtsTrue/*commas*/); \
 469     statsPrintf("  (" #counter ")  : %s\n",temp);                               \
 470   }
 471
 472 /* Report the value of a counter as a percentage of another counter */
 473 #define REPORT_PCT(counter,countertot) \
 474   statsPrintf("  (" #counter ") %% of (" #countertot ") : %.1f%%\n", \
 475               counter*100.0/countertot)
 476
 477 #define TICK_PRINT(arity) \
 478   REPORT(SLOW_CALLS_##arity); \
 479   REPORT_PCT(RIGHT_ARITY_##arity,SLOW_CALLS_##arity); \
 480   REPORT_PCT(TAGGED_PTR_##arity,RIGHT_ARITY_##arity); \
 481   REPORT(RIGHT_ARITY_##arity); \
 482   REPORT(TAGGED_PTR_##arity)
 483
 484 #define TICK_PRINT_TOT(arity) \
 485   statsPrintf("  (SLOW_CALLS_" #arity ") %% of (TOTAL_CALLS) : %.1f%%\n", \
 486               SLOW_CALLS_##arity * 100.0/TOTAL_CALLS)
 487
 488
 489 void
 490 stat_exit(int alloc)
 491 {
 492     if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
 493
 494         char temp[BIG_STRING_LEN];
 495         Ticks time;
 496         Ticks etime;
 497         nat g, total_collections = 0;
 498
 499         getProcessTimes( &time, &etime );
 500         etime -= ElapsedTimeStart;
 501
 502         GC_tot_alloc += alloc;
 503
 504         /* Count total garbage collections */
 505         for (g = 0; g < RtsFlags.GcFlags.generations; g++)
 506             total_collections += generations[g].collections;
 507
 508         /* avoid divide by zero if time is measured as 0.00 seconds -- SDM */
 509         if (time  == 0.0)  time = 1;
 510         if (etime == 0.0) etime = 1;
 511
 512         if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) {
 513             statsPrintf("%9ld %9.9s %9.9s", (lnat)alloc*sizeof(W_), "", "");
 514             statsPrintf(" %5.2f %5.2f\n\n", 0.0, 0.0);
 515         }
 516
 517         if (RtsFlags.GcFlags.giveStats >= SUMMARY_GC_STATS) {
 518             ullong_format_string(GC_tot_alloc*sizeof(W_),
 519                                  temp, rtsTrue/*commas*/);
 520             statsPrintf("%11s bytes allocated in the heap\n", temp);
 521
 522             ullong_format_string(GC_tot_copied*sizeof(W_),
 523                                  temp, rtsTrue/*commas*/);
 524             statsPrintf("%11s bytes copied during GC\n", temp);
 525
 526             if ( ResidencySamples > 0 ) {
 527                 ullong_format_string(MaxResidency*sizeof(W_),
 528                                      temp, rtsTrue/*commas*/);
 529                 statsPrintf("%11s bytes maximum residency (%ld sample(s))\n",
 530                         temp, ResidencySamples);
 531             }
 532             statsPrintf("\n");
 533
 534             /* Print garbage collections in each gen */
 535             for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
 536                 statsPrintf("%11d collections in generation %d (%6.2fs)\n",
 537                         generations[g].collections, g,
 538                         TICK_TO_DBL(GC_coll_times[g]));
 539             }
 540
 541             statsPrintf("\n%11ld Mb total memory in use\n\n",
 542                     mblocks_allocated * MBLOCK_SIZE / (1024 * 1024));
 543
 544 #if defined(THREADED_RTS)
 545             {
 546                 nat i;
 547                 Task *task;
 548                 for (i = 0, task = all_tasks;
 549                      task != NULL;
 550                      i++, task = task->all_link) {
 551                     statsPrintf("  Task %2d %-8s :  MUT time: %6.2fs  (%6.2fs elapsed)\n"
 552                             "                      GC  time: %6.2fs  (%6.2fs elapsed)\n\n",
 553                                 i,
 554                                 (task->tso == NULL) ? "(worker)" : "(bound)",
 555                                 TICK_TO_DBL(task->mut_time),
 556                                 TICK_TO_DBL(task->mut_etime),
 557                                 TICK_TO_DBL(task->gc_time),
 558                                 TICK_TO_DBL(task->gc_etime));
 559                 }
 560             }
 561 #endif
 562
 563             statsPrintf("  INIT  time  %6.2fs  (%6.2fs elapsed)\n",
 564                     TICK_TO_DBL(InitUserTime), TICK_TO_DBL(InitElapsedTime));
 565             statsPrintf("  MUT   time  %6.2fs  (%6.2fs elapsed)\n",
 566                     TICK_TO_DBL(MutUserTime), TICK_TO_DBL(MutElapsedTime));
 567             statsPrintf("  GC    time  %6.2fs  (%6.2fs elapsed)\n",
 568                     TICK_TO_DBL(GC_tot_time), TICK_TO_DBL(GCe_tot_time));
 569 #ifdef PROFILING
 570             statsPrintf("  RP    time  %6.2fs  (%6.2fs elapsed)\n",
 571                     TICK_TO_DBL(RP_tot_time), TICK_TO_DBL(RPe_tot_time));
 572             statsPrintf("  PROF  time  %6.2fs  (%6.2fs elapsed)\n",
 573                     TICK_TO_DBL(HC_tot_time), TICK_TO_DBL(HCe_tot_time));
 574 #endif
 575             statsPrintf("  EXIT  time  %6.2fs  (%6.2fs elapsed)\n",
 576                     TICK_TO_DBL(ExitUserTime), TICK_TO_DBL(ExitElapsedTime));
 577             statsPrintf("  Total time  %6.2fs  (%6.2fs elapsed)\n\n",
 578                     TICK_TO_DBL(time), TICK_TO_DBL(etime));
 579             statsPrintf("  %%GC time     %5.1f%%  (%.1f%% elapsed)\n\n",
 580                     TICK_TO_DBL(GC_tot_time)*100/TICK_TO_DBL(time),
 581                     TICK_TO_DBL(GCe_tot_time)*100/TICK_TO_DBL(etime));
 582
 583             if (time - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time) == 0)
 584                 ullong_format_string(0, temp, rtsTrue/*commas*/);
 585             else
 586                 ullong_format_string(
 587                     (ullong)((GC_tot_alloc*sizeof(W_))/
 588                              TICK_TO_DBL(time - GC_tot_time -
 589                                          PROF_VAL(RP_tot_time + HC_tot_time))),
 590                     temp, rtsTrue/*commas*/);
 591
 592             statsPrintf("  Alloc rate    %s bytes per MUT second\n\n", temp);
 593
 594             statsPrintf("  Productivity %5.1f%% of total user, %.1f%% of total elapsed\n\n",
 595                     TICK_TO_DBL(time - GC_tot_time -
 596                                 PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime) * 100
 597                     / TICK_TO_DBL(time),
 598                     TICK_TO_DBL(time - GC_tot_time -
 599                                 PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime) * 100
 600                     / TICK_TO_DBL(etime));
 601
 602             /*
 603             TICK_PRINT(1);
 604             TICK_PRINT(2);
 605             REPORT(TOTAL_CALLS);
 606             TICK_PRINT_TOT(1);
 607             TICK_PRINT_TOT(2);
 608             */
 609
 610 #if USE_PAPI
 611             papi_stats_report();
 612 #endif
 613         }
 614
 615         if (RtsFlags.GcFlags.giveStats == ONELINE_GC_STATS) {
 616           /* print the long long separately to avoid bugginess on mingwin (2001-07-02, mingw-0.5) */
 617           statsPrintf("<<ghc: %llu bytes, ", GC_tot_alloc*(ullong)sizeof(W_));
 618           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",
 619                     total_collections,
 620                     ResidencySamples == 0 ? 0 :
 621                         AvgResidency*sizeof(W_)/ResidencySamples,
 622                     MaxResidency*sizeof(W_),
 623                     ResidencySamples,
 624                     (unsigned long)(mblocks_allocated * MBLOCK_SIZE / (1024L * 1024L)),
 625                     TICK_TO_DBL(InitUserTime), TICK_TO_DBL(InitElapsedTime),
 626                     TICK_TO_DBL(MutUserTime), TICK_TO_DBL(MutElapsedTime),
 627                     TICK_TO_DBL(GC_tot_time), TICK_TO_DBL(GCe_tot_time));
 628         }
 629
 630         statsFlush();
 631         statsClose();
 632     }
 633     if (GC_coll_times)
 634       stgFree(GC_coll_times);
 635     GC_coll_times = NULL;
 636 }
 637
 638 /* -----------------------------------------------------------------------------
 639    stat_describe_gens
 640
 641    Produce some detailed info on the state of the generational GC.
 642    -------------------------------------------------------------------------- */
 643 #ifdef DEBUG
 644 void
 645 statDescribeGens(void)
 646 {
 647   nat g, s, mut, lge;
 648   lnat live;
 649   bdescr *bd;
 650   step *step;
 651
 652   debugBelch(
 653 "     Gen    Steps      Max  Mut-list  Step   Blocks     Live    Large\n"
 654 "                    Blocks     Bytes                          Objects\n");
 655
 656   mut = 0;
 657   for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
 658       for (bd = generations[g].mut_list; bd != NULL; bd = bd->link) {
 659           mut += (bd->free - bd->start) * sizeof(W_);
 660       }
 661
 662     debugBelch("%8d %8d %8d %9d", g, generations[g].n_steps,
 663             generations[g].max_blocks, mut);
 664
 665     for (s = 0; s < generations[g].n_steps; s++) {
 666       step = &generations[g].steps[s];
 667       live = 0;
 668       for (bd = step->large_objects, lge = 0; bd; bd = bd->link) {
 669         lge++;
 670       }
 671       live = step->n_large_blocks * BLOCK_SIZE;
 672       bd = step->blocks;
 673       // This live figure will be slightly less that the "live" figure
 674       // given by +RTS -Sstderr, because we take don't count the
 675       // slop at the end of each block.
 676       for (; bd; bd = bd->link) {
 677         live += (bd->free - bd->start) * sizeof(W_);
 678       }
 679       if (s != 0) {
 680         debugBelch("%36s","");
 681       }
 682       debugBelch("%6d %8d %8ld %8d\n", s, step->n_blocks,
 683               live, lge);
 684     }
 685   }
 686   debugBelch("\n");
 687 }
 688 #endif
 689
 690 /* -----------------------------------------------------------------------------
 691    Stats available via a programmatic interface, so eg. GHCi can time
 692    each compilation and expression evaluation.
 693    -------------------------------------------------------------------------- */
 694
 695 extern HsInt64 getAllocations( void )
 696 { return (HsInt64)total_allocated * sizeof(W_); }
 697
 698 /* -----------------------------------------------------------------------------
 699    Dumping stuff in the stats file, or via the debug message interface
 700    -------------------------------------------------------------------------- */
 701
 702 void
 703 statsPrintf( char *s, ... )
 704 {
 705     FILE *sf = RtsFlags.GcFlags.statsFile;
 706     va_list ap;
 707
 708     va_start(ap,s);
 709     if (sf == NULL) {
 710         vdebugBelch(s,ap);
 711     } else {
 712         vfprintf(sf, s, ap);
 713     }
 714     va_end(ap);
 715 }
 716
 717 static void
 718 statsFlush( void )
 719 {
 720     FILE *sf = RtsFlags.GcFlags.statsFile;
 721     if (sf != NULL) {
 722         fflush(sf);
 723     }
 724 }
 725
 726 static void
 727 statsClose( void )
 728 {
 729     FILE *sf = RtsFlags.GcFlags.statsFile;
 730     if (sf != NULL) {
 731         fclose(sf);
 732     }
 733 }