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 ullong GC_tot_alloc        = 0;
  43 static ullong GC_tot_copied       = 0;
  44
  45 static ullong GC_par_max_copied = 0;
  46 static ullong 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 - PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime;
 262     if (MutUserTime < 0) { MutUserTime = 0; }
 263
 264 #if USE_PAPI
 265     /* We stop counting mutator events
 266      * GC events are not being counted at this point */
 267     papi_stop_mutator_count();
 268
 269     /* This flag is needed, because GC is run once more after this function */
 270     papi_is_reporting = 0;
 271
 272 #endif
 273 }
 274
 275 void
 276 stat_endExit(void)
 277 {
 278     Ticks user, elapsed;
 279
 280     getProcessTimes(&user, &elapsed);
 281
 282     ExitUserTime = user - MutUserTime - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime;
 283     ExitElapsedTime = elapsed - MutElapsedStamp;
 284     if (ExitUserTime < 0) {
 285         ExitUserTime = 0;
 286     }
 287     if (ExitElapsedTime < 0) {
 288         ExitElapsedTime = 0;
 289     }
 290 }
 291
 292 /* -----------------------------------------------------------------------------
 293    Called at the beginning of each GC
 294    -------------------------------------------------------------------------- */
 295
 296 static nat rub_bell = 0;
 297
 298 /*  initialise global variables needed during GC
 299  *
 300  *  * GC_start_time is read in mut_user_time_during_GC(), which in turn is
 301  *    needed if either PROFILING or DEBUGing is enabled
 302  */
 303 void
 304 stat_startGC(void)
 305 {
 306     nat bell = RtsFlags.GcFlags.ringBell;
 307
 308     if (bell) {
 309         if (bell > 1) {
 310             debugBelch(" GC ");
 311             rub_bell = 1;
 312         } else {
 313             debugBelch("\007");
 314         }
 315     }
 316
 317 #if defined(PROFILING) || defined(DEBUG)
 318     GC_start_time = getProcessCPUTime();  // needed in mut_user_time_during_GC()
 319 #endif
 320
 321     if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
 322 #if !defined(PROFILING) && !defined(DEBUG)
 323         GC_start_time = getProcessCPUTime();
 324 #endif
 325         GCe_start_time = getProcessElapsedTime();
 326         if (RtsFlags.GcFlags.giveStats) {
 327             GC_start_faults = getPageFaults();
 328         }
 329     }
 330
 331 #if USE_PAPI
 332     if(papi_is_reporting) {
 333       /* Switch to counting GC events */
 334       papi_stop_mutator_count();
 335       papi_start_gc_count();
 336     }
 337 #endif
 338
 339 }
 340
 341 /* -----------------------------------------------------------------------------
 342    Called at the end of each GC
 343    -------------------------------------------------------------------------- */
 344
 345 void
 346 stat_endGC (lnat alloc, lnat live, lnat copied, lnat gen,
 347             lnat max_copied, lnat avg_copied, lnat slop)
 348 {
 349     if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
 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 += (ullong) copied;
 379         GC_tot_alloc  += (ullong) alloc;
 380         GC_par_max_copied += (ullong) max_copied;
 381         GC_par_avg_copied += (ullong) 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     ullong_format_string(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             ullong_format_string(GC_tot_alloc*sizeof(W_),
 574                                  temp, rtsTrue/*commas*/);
 575             statsPrintf("%16s bytes allocated in the heap\n", temp);
 576
 577             ullong_format_string(GC_tot_copied*sizeof(W_),
 578                                  temp, rtsTrue/*commas*/);
 579             statsPrintf("%16s bytes copied during GC\n", temp);
 580
 581             if ( ResidencySamples > 0 ) {
 582                 ullong_format_string(MaxResidency*sizeof(W_),
 583                                      temp, rtsTrue/*commas*/);
 584                 statsPrintf("%16s bytes maximum residency (%ld sample(s))\n",
 585                         temp, ResidencySamples);
 586             }
 587
 588             ullong_format_string(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                         mblocks_allocated * MBLOCK_SIZE_W / (1024 * 1024 / sizeof(W_)),
 593                         (mblocks_allocated * MBLOCK_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->tso == NULL) ? "(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_converted = 0;
 640                 lnat sparks_pruned    = 0;
 641                 for (i = 0; i < n_capabilities; i++) {
 642                     sparks_created   += capabilities[i].sparks_created;
 643                     sparks_converted += capabilities[i].sparks_converted;
 644                     sparks_pruned    += capabilities[i].sparks_pruned;
 645                 }
 646
 647                 statsPrintf("  SPARKS: %ld (%ld converted, %ld pruned)\n\n",
 648                             sparks_created, sparks_converted, sparks_pruned);
 649             }
 650 #endif
 651
 652             statsPrintf("  INIT  time  %6.2fs  (%6.2fs elapsed)\n",
 653                     TICK_TO_DBL(InitUserTime), TICK_TO_DBL(InitElapsedTime));
 654             statsPrintf("  MUT   time  %6.2fs  (%6.2fs elapsed)\n",
 655                     TICK_TO_DBL(MutUserTime), TICK_TO_DBL(MutElapsedTime));
 656             statsPrintf("  GC    time  %6.2fs  (%6.2fs elapsed)\n",
 657                     TICK_TO_DBL(GC_tot_time), TICK_TO_DBL(GCe_tot_time));
 658 #ifdef PROFILING
 659             statsPrintf("  RP    time  %6.2fs  (%6.2fs elapsed)\n",
 660                     TICK_TO_DBL(RP_tot_time), TICK_TO_DBL(RPe_tot_time));
 661             statsPrintf("  PROF  time  %6.2fs  (%6.2fs elapsed)\n",
 662                     TICK_TO_DBL(HC_tot_time), TICK_TO_DBL(HCe_tot_time));
 663 #endif
 664             statsPrintf("  EXIT  time  %6.2fs  (%6.2fs elapsed)\n",
 665                     TICK_TO_DBL(ExitUserTime), TICK_TO_DBL(ExitElapsedTime));
 666             statsPrintf("  Total time  %6.2fs  (%6.2fs elapsed)\n\n",
 667                     TICK_TO_DBL(time), TICK_TO_DBL(etime));
 668             statsPrintf("  %%GC time     %5.1f%%  (%.1f%% elapsed)\n\n",
 669                     TICK_TO_DBL(GC_tot_time)*100/TICK_TO_DBL(time),
 670                     TICK_TO_DBL(GCe_tot_time)*100/TICK_TO_DBL(etime));
 671
 672             if (time - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time) == 0)
 673                 ullong_format_string(0, temp, rtsTrue/*commas*/);
 674             else
 675                 ullong_format_string(
 676                     (ullong)((GC_tot_alloc*sizeof(W_))/
 677                              TICK_TO_DBL(time - GC_tot_time -
 678                                          PROF_VAL(RP_tot_time + HC_tot_time))),
 679                     temp, rtsTrue/*commas*/);
 680
 681             statsPrintf("  Alloc rate    %s bytes per MUT second\n\n", temp);
 682
 683             statsPrintf("  Productivity %5.1f%% of total user, %.1f%% of total elapsed\n\n",
 684                     TICK_TO_DBL(time - GC_tot_time -
 685                                 PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime) * 100
 686                     / TICK_TO_DBL(time),
 687                     TICK_TO_DBL(time - GC_tot_time -
 688                                 PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime) * 100
 689                     / TICK_TO_DBL(etime));
 690
 691             /*
 692             TICK_PRINT(1);
 693             TICK_PRINT(2);
 694             REPORT(TOTAL_CALLS);
 695             TICK_PRINT_TOT(1);
 696             TICK_PRINT_TOT(2);
 697             */
 698
 699 #if USE_PAPI
 700             papi_stats_report();
 701 #endif
 702 #if defined(THREADED_RTS) && defined(PROF_SPIN)
 703             {
 704                 nat g, s;
 705
 706                 statsPrintf("gc_alloc_block_sync: %"FMT_Word64"\n", gc_alloc_block_sync.spin);
 707                 statsPrintf("whitehole_spin: %"FMT_Word64"\n", whitehole_spin);
 708                 for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
 709                     for (s = 0; s < generations[g].n_steps; s++) {
 710                         statsPrintf("gen[%d].steps[%d].sync_large_objects: %"FMT_Word64"\n", g, s, generations[g].steps[s].sync_large_objects.spin);
 711                     }
 712                 }
 713             }
 714 #endif
 715         }
 716
 717         if (RtsFlags.GcFlags.giveStats == ONELINE_GC_STATS) {
 718       char *fmt1, *fmt2;
 719       if (RtsFlags.MiscFlags.machineReadable) {
 720           fmt1 = " [(\"bytes allocated\", \"%llu\")\n";
 721           fmt2 = " ,(\"num_GCs\", \"%d\")\n"
 722                  " ,(\"average_bytes_used\", \"%ld\")\n"
 723                  " ,(\"max_bytes_used\", \"%ld\")\n"
 724                  " ,(\"num_byte_usage_samples\", \"%ld\")\n"
 725                  " ,(\"peak_megabytes_allocated\", \"%lu\")\n"
 726                  " ,(\"init_cpu_seconds\", \"%.2f\")\n"
 727                  " ,(\"init_wall_seconds\", \"%.2f\")\n"
 728                  " ,(\"mutator_cpu_seconds\", \"%.2f\")\n"
 729                  " ,(\"mutator_wall_seconds\", \"%.2f\")\n"
 730                  " ,(\"GC_cpu_seconds\", \"%.2f\")\n"
 731                  " ,(\"GC_wall_seconds\", \"%.2f\")\n"
 732                  " ]\n";
 733       }
 734       else {
 735           fmt1 = "<<ghc: %llu bytes, ";
 736           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";
 737       }
 738           /* print the long long separately to avoid bugginess on mingwin (2001-07-02, mingw-0.5) */
 739           statsPrintf(fmt1, GC_tot_alloc*(ullong)sizeof(W_));
 740           statsPrintf(fmt2,
 741                     total_collections,
 742                     ResidencySamples == 0 ? 0 :
 743                         AvgResidency*sizeof(W_)/ResidencySamples,
 744                     MaxResidency*sizeof(W_),
 745                     ResidencySamples,
 746                     (unsigned long)(mblocks_allocated * MBLOCK_SIZE / (1024L * 1024L)),
 747                     TICK_TO_DBL(InitUserTime), TICK_TO_DBL(InitElapsedTime),
 748                     TICK_TO_DBL(MutUserTime), TICK_TO_DBL(MutElapsedTime),
 749                     TICK_TO_DBL(GC_tot_time), TICK_TO_DBL(GCe_tot_time));
 750         }
 751
 752         statsFlush();
 753         statsClose();
 754     }
 755
 756     if (GC_coll_times)
 757       stgFree(GC_coll_times);
 758     GC_coll_times = NULL;
 759     if (GC_coll_etimes)
 760       stgFree(GC_coll_etimes);
 761     GC_coll_etimes = NULL;
 762 }
 763
 764 /* -----------------------------------------------------------------------------
 765    stat_describe_gens
 766
 767    Produce some detailed info on the state of the generational GC.
 768    -------------------------------------------------------------------------- */
 769 void
 770 statDescribeGens(void)
 771 {
 772   nat g, s, mut, lge;
 773   lnat live, slop;
 774   lnat tot_live, tot_slop;
 775   bdescr *bd;
 776   step *step;
 777
 778   debugBelch(
 779 "-----------------------------------------------------------------\n"
 780 "  Gen     Max  Mut-list  Step   Blocks    Large     Live     Slop\n"
 781 "       Blocks     Bytes                 Objects                  \n"
 782 "-----------------------------------------------------------------\n");
 783
 784   tot_live = 0;
 785   tot_slop = 0;
 786   for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
 787       mut = 0;
 788       for (bd = generations[g].mut_list; bd != NULL; bd = bd->link) {
 789           mut += (bd->free - bd->start) * sizeof(W_);
 790       }
 791
 792     debugBelch("%5d %7d %9d", g, generations[g].max_blocks, mut);
 793
 794     for (s = 0; s < generations[g].n_steps; s++) {
 795       step = &generations[g].steps[s];
 796       for (bd = step->large_objects, lge = 0; bd; bd = bd->link) {
 797         lge++;
 798       }
 799       live = step->n_words + countOccupied(step->large_objects);
 800       if (s != 0) {
 801         debugBelch("%23s","");
 802       }
 803       slop = (step->n_blocks + step->n_large_blocks) * BLOCK_SIZE_W - live;
 804       debugBelch("%6d %8d %8d %8ld %8ld\n", s, step->n_blocks, lge,
 805                  live*sizeof(W_), slop*sizeof(W_));
 806       tot_live += live;
 807       tot_slop += slop;
 808     }
 809   }
 810   debugBelch("-----------------------------------------------------------------\n");
 811   debugBelch("%48s%8ld %8ld\n","",tot_live*sizeof(W_),tot_slop*sizeof(W_));
 812   debugBelch("-----------------------------------------------------------------\n");
 813   debugBelch("\n");
 814 }
 815
 816 /* -----------------------------------------------------------------------------
 817    Stats available via a programmatic interface, so eg. GHCi can time
 818    each compilation and expression evaluation.
 819    -------------------------------------------------------------------------- */
 820
 821 extern HsInt64 getAllocations( void )
 822 { return (HsInt64)total_allocated * sizeof(W_); }
 823
 824 /* -----------------------------------------------------------------------------
 825    Dumping stuff in the stats file, or via the debug message interface
 826    -------------------------------------------------------------------------- */
 827
 828 void
 829 statsPrintf( char *s, ... )
 830 {
 831     FILE *sf = RtsFlags.GcFlags.statsFile;
 832     va_list ap;
 833
 834     va_start(ap,s);
 835     if (sf == NULL) {
 836         vdebugBelch(s,ap);
 837     } else {
 838         vfprintf(sf, s, ap);
 839     }
 840     va_end(ap);
 841 }
 842
 843 static void
 844 statsFlush( void )
 845 {
 846     FILE *sf = RtsFlags.GcFlags.statsFile;
 847     if (sf != NULL) {
 848         fflush(sf);
 849     }
 850 }
 851
 852 static void
 853 statsClose( void )
 854 {
 855     FILE *sf = RtsFlags.GcFlags.statsFile;
 856     if (sf != NULL) {
 857         fclose(sf);
 858     }
 859 }