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