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