ghc/rts/Stats.c

   1 /* -----------------------------------------------------------------------------
   2  *
   3  * (c) The GHC Team, 1998-2004
   4  *
   5  * Statistics and timing-related functions.
   6  *
   7  * ---------------------------------------------------------------------------*/
   8
   9 /* Alas, no.  This source is non-posix.
  10    #include "PosixSource.h"
  11 */
  12
  13 #include "Rts.h"
  14 #include "RtsFlags.h"
  15 #include "RtsUtils.h"
  16 #include "MBlock.h"
  17 #include "Schedule.h"
  18 #include "Stats.h"
  19 #include "ParTicky.h"                       /* ToDo: move into Rts.h */
  20 #include "Profiling.h"
  21 #include "Storage.h"
  22
  23 #ifdef HAVE_UNISTD_H
  24 #include <unistd.h>
  25 #endif
  26
  27 #ifndef mingw32_HOST_OS
  28 # ifdef HAVE_SYS_TIMES_H
  29 #  include <sys/times.h>
  30 # endif
  31 #endif
  32
  33 #ifdef HAVE_SYS_TIME_H
  34 #include <sys/time.h>
  35 #endif
  36
  37 #ifdef __CYGWIN32__
  38 # ifdef HAVE_TIME_H
  39 #  include <time.h>
  40 # endif
  41 #endif
  42
  43 #if ! irix_HOST_OS && ! defined(mingw32_HOST_OS)
  44 # if defined(HAVE_SYS_RESOURCE_H)
  45 #  include <sys/resource.h>
  46 # endif
  47 #endif
  48
  49 #ifdef HAVE_SYS_TIMEB_H
  50 #include <sys/timeb.h>
  51 #endif
  52
  53 #if HAVE_STDLIB_H
  54 #include <stdlib.h>
  55 #endif
  56
  57 #if HAVE_WINDOWS_H
  58 #include <windows.h>
  59 #endif
  60
  61 #if defined(PAR) || !(!defined(HAVE_GETRUSAGE) || irix_HOST_OS || defined(mingw32_HOST_OS) || defined(cygwin32_HOST_OS))
  62 #include <sys/resource.h>
  63 #endif
  64
  65 /* huh? */
  66 #define BIG_STRING_LEN              512
  67
  68 /* We're not trying to be terribly accurate here, using the
  69  * basic times() function to get a resolution of about 100ths of a
  70  * second, depending on the OS.  A long int will do fine for holding
  71  * these values.
  72  */
  73 #define TICK_TYPE long int
  74 #define TICK_TO_DBL(t) ((double)(t) / TicksPerSecond)
  75
  76 static int TicksPerSecond = 0;
  77
  78 static TICK_TYPE ElapsedTimeStart = 0;
  79 static TICK_TYPE CurrentElapsedTime = 0;
  80 static TICK_TYPE CurrentUserTime    = 0;
  81
  82 static TICK_TYPE InitUserTime     = 0;
  83 static TICK_TYPE InitElapsedTime  = 0;
  84 static TICK_TYPE InitElapsedStamp = 0;
  85
  86 static TICK_TYPE MutUserTime      = 0;
  87 static TICK_TYPE MutElapsedTime   = 0;
  88 static TICK_TYPE MutElapsedStamp  = 0;
  89
  90 static TICK_TYPE ExitUserTime     = 0;
  91 static TICK_TYPE ExitElapsedTime  = 0;
  92
  93 static ullong GC_tot_alloc        = 0;
  94 static ullong GC_tot_copied       = 0;
  95
  96 static TICK_TYPE GC_start_time = 0,  GC_tot_time  = 0;  /* User GC Time */
  97 static TICK_TYPE GCe_start_time = 0, GCe_tot_time = 0;  /* Elapsed GC time */
  98
  99 #ifdef PROFILING
 100 static TICK_TYPE RP_start_time  = 0, RP_tot_time  = 0;  /* retainer prof user time */
 101 static TICK_TYPE RPe_start_time = 0, RPe_tot_time = 0;  /* retainer prof elap time */
 102
 103 static TICK_TYPE HC_start_time, HC_tot_time = 0;     // heap census prof user time
 104 static TICK_TYPE HCe_start_time, HCe_tot_time = 0;   // heap census prof elap time
 105 #endif
 106
 107 #ifdef PROFILING
 108 #define PROF_VAL(x)   (x)
 109 #else
 110 #define PROF_VAL(x)   0
 111 #endif
 112
 113 static lnat MaxResidency = 0;     // in words; for stats only
 114 static lnat AvgResidency = 0;
 115 static lnat ResidencySamples = 0; // for stats only
 116
 117 static lnat GC_start_faults = 0, GC_end_faults = 0;
 118
 119 static TICK_TYPE *GC_coll_times;
 120
 121 static void  getTimes(void);
 122 static nat   pageFaults(void);
 123
 124 static void statsPrintf( char *s, ... )
 125     GNUC3_ATTRIBUTE(format (printf, 1, 2));
 126
 127 static void statsFlush( void );
 128 static void statsClose( void );
 129
 130 /* elapsedtime() -- The current elapsed time in seconds */
 131
 132 #if defined(mingw32_HOST_OS) || defined(cygwin32_HOST_OS)
 133 #define HNS_PER_SEC 10000000LL /* FILETIMES are in units of 100ns */
 134 /* Convert FILETIMEs into secs */
 135 #define FT2longlong(ll,ft)    \
 136     (ll)=(ft).dwHighDateTime; \
 137     (ll) <<= 32;              \
 138     (ll) |= (ft).dwLowDateTime; \
 139     (ll) /= (unsigned long long) (HNS_PER_SEC / CLOCKS_PER_SEC)
 140 #endif
 141
 142 #if defined(mingw32_HOST_OS) || defined(cygwin32_HOST_OS)
 143 /* cygwin32 or mingw32 version */
 144 static void
 145 getTimes(void)
 146 {
 147     static int is_win9x = -1;
 148
 149     FILETIME creationTime, exitTime, userTime, kernelTime = {0,0};
 150     long long int kT, uT;
 151
 152     if (is_win9x < 0) {
 153       /* figure out whether we're on a Win9x box or not. */
 154       OSVERSIONINFO oi;
 155       BOOL b;
 156
 157       /* Need to init the size field first.*/
 158       oi.dwOSVersionInfoSize = sizeof(OSVERSIONINFO);
 159       b = GetVersionEx(&oi);
 160
 161       is_win9x = ( (b && (oi.dwPlatformId & VER_PLATFORM_WIN32_WINDOWS)) ? 1 : 0);
 162     }
 163
 164     if (is_win9x) {
 165       /* On Win9x, just attribute all running time to the user. */
 166       SYSTEMTIME st;
 167
 168       GetSystemTime(&st);
 169       SystemTimeToFileTime(&st,&userTime);
 170     } else {
 171       /* ToDo: pin down elapsed times to just the OS thread(s) that
 172          are evaluating/managing Haskell code.
 173       */
 174       if (!GetProcessTimes (GetCurrentProcess(), &creationTime,
 175                           &exitTime, &kernelTime, &userTime)) {
 176         /* Probably on a Win95 box..*/
 177         CurrentElapsedTime = 0;
 178         CurrentUserTime = 0;
 179         return;
 180       }
 181     }
 182
 183     FT2longlong(kT,kernelTime);
 184     FT2longlong(uT,userTime);
 185     CurrentElapsedTime = uT + kT;
 186     CurrentUserTime = uT;
 187
 188     if (is_win9x) {
 189       /* Adjust for the fact that we're using system time & not
 190          process time on Win9x. */
 191       CurrentUserTime    -= ElapsedTimeStart;
 192       CurrentElapsedTime -= ElapsedTimeStart;
 193     }
 194 }
 195
 196 #else /* !win32 */
 197
 198 static void
 199 getTimes(void)
 200 {
 201
 202 #ifndef HAVE_TIMES
 203     /* We will #ifdef around the fprintf for machines
 204        we *know* are unsupported. (WDP 94/05)
 205     */
 206     debugBelch("NOTE: `getTimes' does nothing!\n");
 207     return 0.0;
 208
 209 #else /* not stumped */
 210     struct tms t;
 211     clock_t r = times(&t);
 212
 213     CurrentElapsedTime = r;
 214     CurrentUserTime = t.tms_utime;
 215 #endif
 216
 217 }
 218 #endif /* !win32 */
 219
 220 /* mut_user_time_during_GC() and mut_user_time()
 221  *
 222  * The former function can be used to get the current mutator time
 223  * *during* a GC, i.e. between stat_startGC and stat_endGC.  This is
 224  * used in the heap profiler for accurately time stamping the heap
 225  * sample.
 226  *
 227  * ATTENTION: mut_user_time_during_GC() relies on GC_start_time being
 228  *            defined in stat_startGC() - to minimise system calls,
 229  *            GC_start_time is, however, only defined when really needed (check
 230  *            stat_startGC() for details)
 231  */
 232 double
 233 mut_user_time_during_GC( void )
 234 {
 235   return TICK_TO_DBL(GC_start_time - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time));
 236 }
 237
 238 double
 239 mut_user_time( void )
 240 {
 241     getTimes();
 242     return TICK_TO_DBL(CurrentUserTime - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time));
 243 }
 244
 245 #ifdef PROFILING
 246 /*
 247   mut_user_time_during_RP() is similar to mut_user_time_during_GC();
 248   it returns the MUT time during retainer profiling.
 249   The same is for mut_user_time_during_HC();
 250  */
 251 double
 252 mut_user_time_during_RP( void )
 253 {
 254   return TICK_TO_DBL(RP_start_time - GC_tot_time - RP_tot_time - HC_tot_time);
 255 }
 256
 257 double
 258 mut_user_time_during_heap_census( void )
 259 {
 260   return TICK_TO_DBL(HC_start_time - GC_tot_time - RP_tot_time - HC_tot_time);
 261 }
 262 #endif /* PROFILING */
 263
 264 static nat
 265 pageFaults(void)
 266 {
 267   /* ToDo (on NT): better, get this via the performance data
 268      that's stored in the registry. */
 269 # if !defined(HAVE_GETRUSAGE) || irix_HOST_OS || defined(mingw32_HOST_OS) || defined(cygwin32_HOST_OS)
 270     return 0;
 271 # else
 272     struct rusage t;
 273
 274     getrusage(RUSAGE_SELF, &t);
 275     return(t.ru_majflt);
 276 # endif
 277 }
 278
 279 void
 280 initStats(void)
 281 {
 282     nat i;
 283
 284     if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) {
 285         statsPrintf("    Alloc    Collect    Live    GC    GC     TOT     TOT  Page Flts\n");
 286         statsPrintf("    bytes     bytes     bytes  user  elap    user    elap\n");
 287     }
 288     GC_coll_times =
 289         (TICK_TYPE *)stgMallocBytes(
 290             sizeof(TICK_TYPE)*RtsFlags.GcFlags.generations,
 291             "initStats");
 292     for (i = 0; i < RtsFlags.GcFlags.generations; i++) {
 293         GC_coll_times[i] = 0;
 294     }
 295 }
 296
 297 /* -----------------------------------------------------------------------------
 298    Initialisation time...
 299    -------------------------------------------------------------------------- */
 300
 301 void
 302 stat_startInit(void)
 303 {
 304     /* Determine TicksPerSecond ... */
 305 #if defined(CLK_TCK)            /* defined by POSIX */
 306     TicksPerSecond = CLK_TCK;
 307
 308 #elif defined(HAVE_SYSCONF)
 309     long ticks;
 310
 311     ticks = sysconf(_SC_CLK_TCK);
 312     if ( ticks == -1 ) {
 313         debugBelch("stat_init: bad call to 'sysconf'!\n");
 314         stg_exit(EXIT_FAILURE);
 315     }
 316     TicksPerSecond = ticks;
 317
 318 /* no "sysconf" or CLK_TCK; had better guess */
 319 #elif defined(HZ)
 320     TicksPerSecond = HZ;
 321
 322 #elif defined(CLOCKS_PER_SEC)
 323     TicksPerSecond = CLOCKS_PER_SEC;
 324
 325 #else /* had better guess wildly */
 326     /* We will #ifdef around the fprintf for machines
 327        we *know* are unsupported. (WDP 94/05)
 328     */
 329     debugBelch("NOTE: Guessing `TicksPerSecond = 60'!\n");
 330     TicksPerSecond = 60;
 331 #endif
 332
 333     getTimes();
 334     ElapsedTimeStart = CurrentElapsedTime;
 335 }
 336
 337 void
 338 stat_endInit(void)
 339 {
 340     getTimes();
 341     InitUserTime = CurrentUserTime;
 342     InitElapsedStamp = CurrentElapsedTime;
 343     if (ElapsedTimeStart > CurrentElapsedTime) {
 344         InitElapsedTime = 0;
 345     } else {
 346         InitElapsedTime = CurrentElapsedTime - ElapsedTimeStart;
 347     }
 348 }
 349
 350 /* -----------------------------------------------------------------------------
 351    stat_startExit and stat_endExit
 352
 353    These two measure the time taken in shutdownHaskell().
 354    -------------------------------------------------------------------------- */
 355
 356 void
 357 stat_startExit(void)
 358 {
 359     getTimes();
 360     MutElapsedStamp = CurrentElapsedTime;
 361     MutElapsedTime = CurrentElapsedTime - GCe_tot_time -
 362         PROF_VAL(RPe_tot_time + HCe_tot_time) - InitElapsedStamp;
 363     if (MutElapsedTime < 0) { MutElapsedTime = 0; }     /* sometimes -0.00 */
 364
 365     /* for SMP, we don't know the mutator time yet, we have to inspect
 366      * all the running threads to find out, and they haven't stopped
 367      * yet.  So we just timestamp MutUserTime at this point so we can
 368      * calculate the EXIT time.  The real MutUserTime is calculated
 369      * in stat_exit below.
 370      */
 371 #ifdef SMP
 372     MutUserTime = CurrentUserTime;
 373 #else
 374     MutUserTime = CurrentUserTime - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime;
 375     if (MutUserTime < 0) { MutUserTime = 0; }
 376 #endif
 377 }
 378
 379 void
 380 stat_endExit(void)
 381 {
 382     getTimes();
 383 #ifdef SMP
 384     ExitUserTime = CurrentUserTime - MutUserTime;
 385 #else
 386     ExitUserTime = CurrentUserTime - MutUserTime - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime;
 387 #endif
 388     ExitElapsedTime = CurrentElapsedTime - MutElapsedStamp;
 389     if (ExitUserTime < 0) {
 390         ExitUserTime = 0;
 391     }
 392     if (ExitElapsedTime < 0) {
 393         ExitElapsedTime = 0;
 394     }
 395 }
 396
 397 /* -----------------------------------------------------------------------------
 398    Called at the beginning of each GC
 399    -------------------------------------------------------------------------- */
 400
 401 static nat rub_bell = 0;
 402
 403 /*  initialise global variables needed during GC
 404  *
 405  *  * GC_start_time is read in mut_user_time_during_GC(), which in turn is
 406  *    needed if either PROFILING or DEBUGing is enabled
 407  */
 408 void
 409 stat_startGC(void)
 410 {
 411     nat bell = RtsFlags.GcFlags.ringBell;
 412
 413     if (bell) {
 414         if (bell > 1) {
 415             debugBelch(" GC ");
 416             rub_bell = 1;
 417         } else {
 418             debugBelch("\007");
 419         }
 420     }
 421
 422 #if defined(PROFILING) || defined(DEBUG)
 423     getTimes();
 424     GC_start_time = CurrentUserTime;  /* needed in mut_user_time_during_GC() */
 425 #endif
 426
 427     if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
 428 #if !defined(PROFILING) && !defined(DEBUG)
 429         getTimes();
 430         GC_start_time = CurrentUserTime;
 431 #endif
 432         GCe_start_time = CurrentElapsedTime;
 433         if (RtsFlags.GcFlags.giveStats) {
 434             GC_start_faults = pageFaults();
 435         }
 436     }
 437 }
 438
 439 /* -----------------------------------------------------------------------------
 440    Called at the end of each GC
 441    -------------------------------------------------------------------------- */
 442
 443 void
 444 stat_endGC(lnat alloc, lnat collect, lnat live, lnat copied, lnat gen)
 445 {
 446     if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
 447         TICK_TYPE time, etime, gc_time, gc_etime;
 448
 449         getTimes();
 450         time     = CurrentUserTime;
 451         etime    = CurrentElapsedTime;
 452         gc_time  = time - GC_start_time;
 453         gc_etime = etime - GCe_start_time;
 454
 455         if (RtsFlags.GcFlags.giveStats == VERBOSE_GC_STATS) {
 456             nat faults = pageFaults();
 457
 458             statsPrintf("%9ld %9ld %9ld",
 459                     alloc*sizeof(W_), collect*sizeof(W_), live*sizeof(W_));
 460             statsPrintf(" %5.2f %5.2f %7.2f %7.2f %4ld %4ld  (Gen: %2ld)\n",
 461                     TICK_TO_DBL(gc_time),
 462                     TICK_TO_DBL(gc_etime),
 463                     TICK_TO_DBL(time),
 464                     TICK_TO_DBL(etime - ElapsedTimeStart),
 465                     faults - GC_start_faults,
 466                     GC_start_faults - GC_end_faults,
 467                     gen);
 468
 469             GC_end_faults = faults;
 470             statsFlush();
 471         }
 472
 473         GC_coll_times[gen] += gc_time;
 474
 475         GC_tot_copied += (ullong) copied;
 476         GC_tot_alloc  += (ullong) alloc;
 477         GC_tot_time   += gc_time;
 478         GCe_tot_time  += gc_etime;
 479
 480 #ifdef SMP
 481         {
 482             nat i;
 483             pthread_t me = pthread_self();
 484
 485             for (i = 0; i < RtsFlags.ParFlags.nNodes; i++) {
 486                 if (me == task_ids[i].id) {
 487                     task_ids[i].gc_time += gc_time;
 488                     task_ids[i].gc_etime += gc_etime;
 489                     break;
 490                 }
 491             }
 492         }
 493 #endif
 494
 495         if (gen == RtsFlags.GcFlags.generations-1) { /* major GC? */
 496             if (live > MaxResidency) {
 497                 MaxResidency = live;
 498             }
 499             ResidencySamples++;
 500             AvgResidency += live;
 501         }
 502     }
 503
 504     if (rub_bell) {
 505         debugBelch("\b\b\b  \b\b\b");
 506         rub_bell = 0;
 507     }
 508 }
 509
 510 /* -----------------------------------------------------------------------------
 511    Called at the beginning of each Retainer Profiliing
 512    -------------------------------------------------------------------------- */
 513 #ifdef PROFILING
 514 void
 515 stat_startRP(void)
 516 {
 517   getTimes();
 518   RP_start_time = CurrentUserTime;
 519   RPe_start_time = CurrentElapsedTime;
 520 }
 521 #endif /* PROFILING */
 522
 523 /* -----------------------------------------------------------------------------
 524    Called at the end of each Retainer Profiliing
 525    -------------------------------------------------------------------------- */
 526
 527 #ifdef PROFILING
 528 void
 529 stat_endRP(
 530   nat retainerGeneration,
 531 #ifdef DEBUG_RETAINER
 532   nat maxCStackSize,
 533   int maxStackSize,
 534 #endif
 535   double averageNumVisit)
 536 {
 537   getTimes();
 538   RP_tot_time += CurrentUserTime - RP_start_time;
 539   RPe_tot_time += CurrentElapsedTime - RPe_start_time;
 540
 541   fprintf(prof_file, "Retainer Profiling: %d, at %f seconds\n",
 542     retainerGeneration, mut_user_time_during_RP());
 543 #ifdef DEBUG_RETAINER
 544   fprintf(prof_file, "\tMax C stack size = %u\n", maxCStackSize);
 545   fprintf(prof_file, "\tMax auxiliary stack size = %u\n", maxStackSize);
 546 #endif
 547   fprintf(prof_file, "\tAverage number of visits per object = %f\n", averageNumVisit);
 548 }
 549 #endif /* PROFILING */
 550
 551 /* -----------------------------------------------------------------------------
 552    Called at the beginning of each heap census
 553    -------------------------------------------------------------------------- */
 554 #ifdef PROFILING
 555 void
 556 stat_startHeapCensus(void)
 557 {
 558   getTimes();
 559   HC_start_time = CurrentUserTime;
 560   HCe_start_time = CurrentElapsedTime;
 561 }
 562 #endif /* PROFILING */
 563
 564 /* -----------------------------------------------------------------------------
 565    Called at the end of each heap census
 566    -------------------------------------------------------------------------- */
 567 #ifdef PROFILING
 568 void
 569 stat_endHeapCensus(void)
 570 {
 571   getTimes();
 572   HC_tot_time += CurrentUserTime - HC_start_time;
 573   HCe_tot_time += CurrentElapsedTime - HCe_start_time;
 574 }
 575 #endif /* PROFILING */
 576
 577 /* -----------------------------------------------------------------------------
 578    stat_workerStop
 579
 580    Called under SMP when a worker thread finishes.  We drop the timing
 581    stats for this thread into the task_ids struct for that thread.
 582    -------------------------------------------------------------------------- */
 583
 584 #if defined(SMP)
 585 void
 586 stat_workerStop(void)
 587 {
 588     nat i;
 589     pthread_t me = pthread_self();
 590
 591     getTimes();
 592
 593     for (i = 0; i < RtsFlags.ParFlags.nNodes; i++) {
 594         if (task_ids[i].id == me) {
 595             task_ids[i].mut_time = CurrentUserTime - task_ids[i].gc_time;
 596             task_ids[i].mut_etime = CurrentElapsedTime
 597                 - GCe_tot_time
 598                 - task_ids[i].elapsedtimestart;
 599             if (task_ids[i].mut_time < 0.0)  { task_ids[i].mut_time = 0.0;  }
 600             if (task_ids[i].mut_etime < 0.0) { task_ids[i].mut_etime = 0.0; }
 601         }
 602     }
 603 }
 604 #endif
 605
 606 #if defined(SMP)
 607 long int stat_getElapsedTime ()
 608 {
 609   getTimes();
 610   return CurrentElapsedTime;
 611 }
 612 #endif
 613
 614 /* -----------------------------------------------------------------------------
 615    Called at the end of execution
 616
 617    NOTE: number of allocations is not entirely accurate: it doesn't
 618    take into account the few bytes at the end of the heap that
 619    were left unused when the heap-check failed.
 620    -------------------------------------------------------------------------- */
 621
 622 void
 623 stat_exit(int alloc)
 624 {
 625     if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
 626
 627         char temp[BIG_STRING_LEN];
 628         TICK_TYPE time;
 629         TICK_TYPE etime;
 630         nat g, total_collections = 0;
 631
 632         getTimes();
 633         time = CurrentUserTime;
 634         etime = CurrentElapsedTime - ElapsedTimeStart;
 635
 636         GC_tot_alloc += alloc;
 637
 638         /* avoid divide by zero if time is measured as 0.00 seconds -- SDM */
 639         if (time  == 0.0)  time = 1;
 640         if (etime == 0.0) etime = 1;
 641
 642         /* Count total garbage collections */
 643         for (g = 0; g < RtsFlags.GcFlags.generations; g++)
 644             total_collections += generations[g].collections;
 645
 646         /* For SMP, we have to get the user time from each thread
 647          * and try to work out the total time.
 648          */
 649 #ifdef SMP
 650         {   nat i;
 651             MutUserTime = 0.0;
 652             for (i = 0; i < RtsFlags.ParFlags.nNodes; i++) {
 653                 MutUserTime += task_ids[i].mut_time;
 654             }
 655         }
 656         time = MutUserTime + GC_tot_time + InitUserTime + ExitUserTime;
 657         if (MutUserTime < 0) { MutUserTime = 0; }
 658 #endif
 659
 660         if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) {
 661             statsPrintf("%9ld %9.9s %9.9s", (lnat)alloc*sizeof(W_), "", "");
 662             statsPrintf(" %5.2f %5.2f\n\n", 0.0, 0.0);
 663         }
 664
 665         if (RtsFlags.GcFlags.giveStats >= SUMMARY_GC_STATS) {
 666             ullong_format_string(GC_tot_alloc*sizeof(W_),
 667                                  temp, rtsTrue/*commas*/);
 668             statsPrintf("%11s bytes allocated in the heap\n", temp);
 669
 670             ullong_format_string(GC_tot_copied*sizeof(W_),
 671                                  temp, rtsTrue/*commas*/);
 672             statsPrintf("%11s bytes copied during GC\n", temp);
 673
 674             if ( ResidencySamples > 0 ) {
 675                 ullong_format_string(MaxResidency*sizeof(W_),
 676                                      temp, rtsTrue/*commas*/);
 677                 statsPrintf("%11s bytes maximum residency (%ld sample(s))\n",
 678                         temp, ResidencySamples);
 679             }
 680             statsPrintf("\n");
 681
 682             /* Print garbage collections in each gen */
 683             for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
 684                 statsPrintf("%11d collections in generation %d (%6.2fs)\n",
 685                         generations[g].collections, g,
 686                         TICK_TO_DBL(GC_coll_times[g]));
 687             }
 688
 689             statsPrintf("\n%11ld Mb total memory in use\n\n",
 690                     mblocks_allocated * MBLOCK_SIZE / (1024 * 1024));
 691
 692 #ifdef SMP
 693             {
 694                 nat i;
 695                 for (i = 0; i < RtsFlags.ParFlags.nNodes; i++) {
 696                     statsPrintf("  Task %2d:  MUT time: %6.2fs  (%6.2fs elapsed)\n"
 697                             "            GC  time: %6.2fs  (%6.2fs elapsed)\n\n",
 698                             i,
 699                             TICK_TO_DBL(task_ids[i].mut_time),
 700                             TICK_TO_DBL(task_ids[i].mut_etime),
 701                             TICK_TO_DBL(task_ids[i].gc_time),
 702                             TICK_TO_DBL(task_ids[i].gc_etime));
 703                 }
 704             }
 705 #endif
 706
 707             statsPrintf("  INIT  time  %6.2fs  (%6.2fs elapsed)\n",
 708                     TICK_TO_DBL(InitUserTime), TICK_TO_DBL(InitElapsedTime));
 709             statsPrintf("  MUT   time  %6.2fs  (%6.2fs elapsed)\n",
 710                     TICK_TO_DBL(MutUserTime), TICK_TO_DBL(MutElapsedTime));
 711             statsPrintf("  GC    time  %6.2fs  (%6.2fs elapsed)\n",
 712                     TICK_TO_DBL(GC_tot_time), TICK_TO_DBL(GCe_tot_time));
 713 #ifdef PROFILING
 714             statsPrintf("  RP    time  %6.2fs  (%6.2fs elapsed)\n",
 715                     TICK_TO_DBL(RP_tot_time), TICK_TO_DBL(RPe_tot_time));
 716             statsPrintf("  PROF  time  %6.2fs  (%6.2fs elapsed)\n",
 717                     TICK_TO_DBL(HC_tot_time), TICK_TO_DBL(HCe_tot_time));
 718 #endif
 719             statsPrintf("  EXIT  time  %6.2fs  (%6.2fs elapsed)\n",
 720                     TICK_TO_DBL(ExitUserTime), TICK_TO_DBL(ExitElapsedTime));
 721             statsPrintf("  Total time  %6.2fs  (%6.2fs elapsed)\n\n",
 722                     TICK_TO_DBL(time), TICK_TO_DBL(etime));
 723             statsPrintf("  %%GC time     %5.1f%%  (%.1f%% elapsed)\n\n",
 724                     TICK_TO_DBL(GC_tot_time)*100/TICK_TO_DBL(time),
 725                     TICK_TO_DBL(GCe_tot_time)*100/TICK_TO_DBL(etime));
 726
 727             if (time - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time) == 0)
 728                 ullong_format_string(0, temp, rtsTrue/*commas*/);
 729             else
 730                 ullong_format_string(
 731                     (ullong)((GC_tot_alloc*sizeof(W_))/
 732                              TICK_TO_DBL(time - GC_tot_time -
 733                                          PROF_VAL(RP_tot_time + HC_tot_time))),
 734                     temp, rtsTrue/*commas*/);
 735
 736             statsPrintf("  Alloc rate    %s bytes per MUT second\n\n", temp);
 737
 738             statsPrintf("  Productivity %5.1f%% of total user, %.1f%% of total elapsed\n\n",
 739                     TICK_TO_DBL(time - GC_tot_time -
 740                                 PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime) * 100
 741                     / TICK_TO_DBL(time),
 742                     TICK_TO_DBL(time - GC_tot_time -
 743                                 PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime) * 100
 744                     / TICK_TO_DBL(etime));
 745         }
 746
 747         if (RtsFlags.GcFlags.giveStats == ONELINE_GC_STATS) {
 748           /* print the long long separately to avoid bugginess on mingwin (2001-07-02, mingw-0.5) */
 749           statsPrintf("<<ghc: %llu bytes, ", GC_tot_alloc*sizeof(W_));
 750           statsPrintf("%d GCs, %ld/%ld avg/max bytes residency (%ld samples), %luM in use, %.2f INIT (%.2f elapsed), %.2f MUT (%.2f elapsed), %.2f GC (%.2f elapsed) :ghc>>\n",
 751                     total_collections,
 752                     ResidencySamples == 0 ? 0 :
 753                         AvgResidency*sizeof(W_)/ResidencySamples,
 754                     MaxResidency*sizeof(W_),
 755                     ResidencySamples,
 756                     (unsigned long)(mblocks_allocated * MBLOCK_SIZE / (1024L * 1024L)),
 757                     TICK_TO_DBL(InitUserTime), TICK_TO_DBL(InitElapsedTime),
 758                     TICK_TO_DBL(MutUserTime), TICK_TO_DBL(MutElapsedTime),
 759                     TICK_TO_DBL(GC_tot_time), TICK_TO_DBL(GCe_tot_time));
 760         }
 761
 762         statsFlush();
 763         statsClose();
 764     }
 765 }
 766
 767 /* -----------------------------------------------------------------------------
 768    stat_describe_gens
 769
 770    Produce some detailed info on the state of the generational GC.
 771    -------------------------------------------------------------------------- */
 772 #ifdef DEBUG
 773 void
 774 statDescribeGens(void)
 775 {
 776   nat g, s, mut, lge, live;
 777   bdescr *bd;
 778   step *step;
 779
 780   debugBelch("     Gen    Steps      Max   Mutable  Step   Blocks     Live    Large\n                    Blocks  Closures  Closures                          Objects\n");
 781
 782   mut = 0;
 783   for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
 784       for (bd = generations[g].mut_list; bd != NULL; bd = bd->link) {
 785           mut += bd->free - bd->start;
 786       }
 787
 788     debugBelch("%8d %8d %8d %9d", g, generations[g].n_steps,
 789             generations[g].max_blocks, mut);
 790
 791     for (s = 0; s < generations[g].n_steps; s++) {
 792       step = &generations[g].steps[s];
 793       for (bd = step->large_objects, lge = 0; bd; bd = bd->link)
 794         lge++;
 795       live = 0;
 796       if (RtsFlags.GcFlags.generations == 1) {
 797         bd = step->to_blocks;
 798       } else {
 799         bd = step->blocks;
 800       }
 801       for (; bd; bd = bd->link) {
 802         live += (bd->free - bd->start) * sizeof(W_);
 803       }
 804       if (s != 0) {
 805         debugBelch("%46s","");
 806       }
 807       debugBelch("%6d %8d %8d %8d\n", s, step->n_blocks,
 808               live, lge);
 809     }
 810   }
 811   debugBelch("\n");
 812 }
 813 #endif
 814
 815 /* -----------------------------------------------------------------------------
 816    Stats available via a programmatic interface, so eg. GHCi can time
 817    each compilation and expression evaluation.
 818    -------------------------------------------------------------------------- */
 819
 820 extern HsInt64 getAllocations( void )
 821 { return (HsInt64)total_allocated * sizeof(W_); }
 822
 823 /* -----------------------------------------------------------------------------
 824    Dumping stuff in the stats file, or via the debug message interface
 825    -------------------------------------------------------------------------- */
 826
 827 static void
 828 statsPrintf( char *s, ... )
 829 {
 830     FILE *sf = RtsFlags.GcFlags.statsFile;
 831     va_list ap;
 832
 833     va_start(ap,s);
 834     if (sf == NULL) {
 835         vdebugBelch(s,ap);
 836     } else {
 837         vfprintf(sf, s, ap);
 838     }
 839     va_end(ap);
 840 }
 841
 842 static void
 843 statsFlush( void )
 844 {
 845     FILE *sf = RtsFlags.GcFlags.statsFile;
 846     if (sf != NULL) {
 847         fflush(sf);
 848     }
 849 }
 850
 851 static void
 852 statsClose( void )
 853 {
 854     FILE *sf = RtsFlags.GcFlags.statsFile;
 855     if (sf != NULL) {
 856         fclose(sf);
 857     }
 858 }