rts/Stats.c

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