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 #include "Task.h"
  23
  24 #ifdef HAVE_UNISTD_H
  25 #include <unistd.h>
  26 #endif
  27
  28 #ifndef mingw32_HOST_OS
  29 # ifdef HAVE_SYS_TIMES_H
  30 #  include <sys/times.h>
  31 # endif
  32 #endif
  33
  34 #ifdef HAVE_SYS_TIME_H
  35 #include <sys/time.h>
  36 #endif
  37
  38 #ifdef __CYGWIN32__
  39 # ifdef HAVE_TIME_H
  40 #  include <time.h>
  41 # endif
  42 #endif
  43
  44 #if ! irix_HOST_OS && ! defined(mingw32_HOST_OS)
  45 # if defined(HAVE_SYS_RESOURCE_H)
  46 #  include <sys/resource.h>
  47 # endif
  48 #endif
  49
  50 #ifdef HAVE_SYS_TIMEB_H
  51 #include <sys/timeb.h>
  52 #endif
  53
  54 #if HAVE_STDLIB_H
  55 #include <stdlib.h>
  56 #endif
  57
  58 #if HAVE_WINDOWS_H
  59 #include <windows.h>
  60 #endif
  61
  62 #if defined(PAR) || !(!defined(HAVE_GETRUSAGE) || irix_HOST_OS || defined(mingw32_HOST_OS) || defined(cygwin32_HOST_OS))
  63 #include <sys/resource.h>
  64 #endif
  65
  66 /* huh? */
  67 #define BIG_STRING_LEN              512
  68
  69 /* We're not trying to be terribly accurate here, using the
  70  * basic times() function to get a resolution of about 100ths of a
  71  * second, depending on the OS.  A long int will do fine for holding
  72  * these values.
  73  */
  74 #define TICK_TYPE long int
  75 #define TICK_TO_DBL(t) ((double)(t) / TicksPerSecond)
  76
  77 static int TicksPerSecond = 0;
  78
  79 static TICK_TYPE ElapsedTimeStart = 0;
  80
  81 static TICK_TYPE InitUserTime     = 0;
  82 static TICK_TYPE InitElapsedTime  = 0;
  83 static TICK_TYPE InitElapsedStamp = 0;
  84
  85 static TICK_TYPE MutUserTime      = 0;
  86 static TICK_TYPE MutElapsedTime   = 0;
  87 static TICK_TYPE MutElapsedStamp  = 0;
  88
  89 static TICK_TYPE ExitUserTime     = 0;
  90 static TICK_TYPE ExitElapsedTime  = 0;
  91
  92 static ullong GC_tot_alloc        = 0;
  93 static ullong GC_tot_copied       = 0;
  94 static ullong GC_tot_scavd_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( long *elapsed, long *user );
 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( TICK_TYPE *elapsed, TICK_TYPE *user )
 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         *elapsed = 0;
 178         *user = 0;
 179         return;
 180       }
 181     }
 182
 183     FT2longlong(kT,kernelTime);
 184     FT2longlong(uT,userTime);
 185     *elapsed = uT + kT;
 186     *user = uT;
 187
 188     if (is_win9x) {
 189       /* Adjust for the fact that we're using system time & not
 190          process time on Win9x. */
 191       *user    -= ElapsedTimeStart;
 192       *elapsed -= ElapsedTimeStart;
 193     }
 194 }
 195
 196 #else /* !win32 */
 197
 198 static void
 199 getTimes( TICK_TYPE *user, TICK_TYPE *elapsed )
 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     *elapsed = r;
 214     *user = t.tms_utime;
 215 #endif
 216 }
 217 #endif /* !win32 */
 218
 219 /* mut_user_time_during_GC() and mut_user_time()
 220  *
 221  * The former function can be used to get the current mutator time
 222  * *during* a GC, i.e. between stat_startGC and stat_endGC.  This is
 223  * used in the heap profiler for accurately time stamping the heap
 224  * sample.
 225  *
 226  * ATTENTION: mut_user_time_during_GC() relies on GC_start_time being
 227  *            defined in stat_startGC() - to minimise system calls,
 228  *            GC_start_time is, however, only defined when really needed (check
 229  *            stat_startGC() for details)
 230  */
 231 double
 232 mut_user_time_during_GC( void )
 233 {
 234   return TICK_TO_DBL(GC_start_time - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time));
 235 }
 236
 237 double
 238 mut_user_time( void )
 239 {
 240     TICK_TYPE user, elapsed;
 241     getTimes(&user, &elapsed);
 242     return TICK_TO_DBL(user - 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     TICK_TYPE user, elapsed;
 305
 306     /* Determine TicksPerSecond ... */
 307 #if defined(CLK_TCK)            /* defined by POSIX */
 308     TicksPerSecond = CLK_TCK;
 309
 310 #elif defined(HAVE_SYSCONF)
 311     long ticks;
 312
 313     ticks = sysconf(_SC_CLK_TCK);
 314     if ( ticks == -1 ) {
 315         debugBelch("stat_init: bad call to 'sysconf'!\n");
 316         stg_exit(EXIT_FAILURE);
 317     }
 318     TicksPerSecond = ticks;
 319
 320 /* no "sysconf" or CLK_TCK; had better guess */
 321 #elif defined(HZ)
 322     TicksPerSecond = HZ;
 323
 324 #elif defined(CLOCKS_PER_SEC)
 325     TicksPerSecond = CLOCKS_PER_SEC;
 326
 327 #else /* had better guess wildly */
 328     /* We will #ifdef around the fprintf for machines
 329        we *know* are unsupported. (WDP 94/05)
 330     */
 331     debugBelch("NOTE: Guessing `TicksPerSecond = 60'!\n");
 332     TicksPerSecond = 60;
 333 #endif
 334
 335     getTimes( &user, &elapsed );
 336     ElapsedTimeStart = elapsed;
 337 }
 338
 339 void
 340 stat_endInit(void)
 341 {
 342     TICK_TYPE user, elapsed;
 343     getTimes( &user, &elapsed );
 344     InitUserTime = user;
 345     InitElapsedStamp = elapsed;
 346     if (ElapsedTimeStart > elapsed) {
 347         InitElapsedTime = 0;
 348     } else {
 349         InitElapsedTime = elapsed - ElapsedTimeStart;
 350     }
 351 }
 352
 353 /* -----------------------------------------------------------------------------
 354    stat_startExit and stat_endExit
 355
 356    These two measure the time taken in shutdownHaskell().
 357    -------------------------------------------------------------------------- */
 358
 359 void
 360 stat_startExit(void)
 361 {
 362     TICK_TYPE user, elapsed;
 363     getTimes( &user, &elapsed );
 364
 365     MutElapsedStamp = elapsed;
 366     MutElapsedTime = elapsed - GCe_tot_time -
 367         PROF_VAL(RPe_tot_time + HCe_tot_time) - InitElapsedStamp;
 368     if (MutElapsedTime < 0) { MutElapsedTime = 0; }     /* sometimes -0.00 */
 369
 370     /* for threads, we don't know the mutator time yet, we have to inspect
 371      * all the running threads to find out, and they haven't stopped
 372      * yet.  So we just timestamp MutUserTime at this point so we can
 373      * calculate the EXIT time.  The real MutUserTime is calculated
 374      * in stat_exit below.
 375      */
 376 #if defined(RTS_SUPPORTS_THREADS)
 377     MutUserTime = user;
 378 #else
 379     MutUserTime = user - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime;
 380     if (MutUserTime < 0) { MutUserTime = 0; }
 381 #endif
 382 }
 383
 384 void
 385 stat_endExit(void)
 386 {
 387     TICK_TYPE user, elapsed;
 388     getTimes( &user, &elapsed );
 389
 390 #if defined(RTS_SUPPORTS_THREADS)
 391     ExitUserTime = user - MutUserTime;
 392 #else
 393     ExitUserTime = user - MutUserTime - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime;
 394 #endif
 395     ExitElapsedTime = elapsed - MutElapsedStamp;
 396     if (ExitUserTime < 0) {
 397         ExitUserTime = 0;
 398     }
 399     if (ExitElapsedTime < 0) {
 400         ExitElapsedTime = 0;
 401     }
 402 }
 403
 404 /* -----------------------------------------------------------------------------
 405    Called at the beginning of each GC
 406    -------------------------------------------------------------------------- */
 407
 408 static nat rub_bell = 0;
 409
 410 /*  initialise global variables needed during GC
 411  *
 412  *  * GC_start_time is read in mut_user_time_during_GC(), which in turn is
 413  *    needed if either PROFILING or DEBUGing is enabled
 414  */
 415 void
 416 stat_startGC(void)
 417 {
 418     nat bell = RtsFlags.GcFlags.ringBell;
 419     TICK_TYPE user, elapsed;
 420
 421
 422     if (bell) {
 423         if (bell > 1) {
 424             debugBelch(" GC ");
 425             rub_bell = 1;
 426         } else {
 427             debugBelch("\007");
 428         }
 429     }
 430
 431 #if defined(PROFILING) || defined(DEBUG)
 432     getTimes( &user, &elapsed );
 433     GC_start_time = user;  /* needed in mut_user_time_during_GC() */
 434 #endif
 435
 436     if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
 437 #if !defined(PROFILING) && !defined(DEBUG)
 438         getTimes( &user, &elapsed );
 439         GC_start_time = user;
 440 #endif
 441         GCe_start_time = elapsed;
 442         if (RtsFlags.GcFlags.giveStats) {
 443             GC_start_faults = pageFaults();
 444         }
 445     }
 446 }
 447
 448 /* -----------------------------------------------------------------------------
 449    Called at the end of each GC
 450    -------------------------------------------------------------------------- */
 451
 452 void
 453 stat_endGC(lnat alloc, lnat collect, lnat live, lnat copied, lnat scavd_copied, lnat gen)
 454 {
 455     TICK_TYPE user, elapsed;
 456
 457     if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
 458         TICK_TYPE time, etime, gc_time, gc_etime;
 459
 460         getTimes( &user, &elapsed );
 461         time     = user;
 462         etime    = elapsed;
 463         gc_time  = time - GC_start_time;
 464         gc_etime = etime - GCe_start_time;
 465
 466         if (RtsFlags.GcFlags.giveStats == VERBOSE_GC_STATS) {
 467             nat faults = pageFaults();
 468
 469             statsPrintf("%9ld %9ld %9ld",
 470                     alloc*sizeof(W_), collect*sizeof(W_), live*sizeof(W_));
 471             statsPrintf(" %5.2f %5.2f %7.2f %7.2f %4ld %4ld  (Gen: %2ld)\n",
 472                     TICK_TO_DBL(gc_time),
 473                     TICK_TO_DBL(gc_etime),
 474                     TICK_TO_DBL(time),
 475                     TICK_TO_DBL(etime - ElapsedTimeStart),
 476                     faults - GC_start_faults,
 477                     GC_start_faults - GC_end_faults,
 478                     gen);
 479
 480             GC_end_faults = faults;
 481             statsFlush();
 482         }
 483
 484         GC_coll_times[gen] += gc_time;
 485
 486         GC_tot_copied += (ullong) copied;
 487         GC_tot_scavd_copied += (ullong) scavd_copied;
 488         GC_tot_alloc  += (ullong) alloc;
 489         GC_tot_time   += gc_time;
 490         GCe_tot_time  += gc_etime;
 491
 492 #if defined(RTS_SUPPORTS_THREADS)
 493         {
 494             TaskInfo *task_info = taskOfId(osThreadId());
 495
 496             if (task_info != NULL) {
 497                 task_info->gc_time += gc_time;
 498                 task_info->gc_etime += gc_etime;
 499             }
 500         }
 501 #endif
 502
 503         if (gen == RtsFlags.GcFlags.generations-1) { /* major GC? */
 504             if (live > MaxResidency) {
 505                 MaxResidency = live;
 506             }
 507             ResidencySamples++;
 508             AvgResidency += live;
 509         }
 510     }
 511
 512     if (rub_bell) {
 513         debugBelch("\b\b\b  \b\b\b");
 514         rub_bell = 0;
 515     }
 516 }
 517
 518 /* -----------------------------------------------------------------------------
 519    Called at the beginning of each Retainer Profiliing
 520    -------------------------------------------------------------------------- */
 521 #ifdef PROFILING
 522 void
 523 stat_startRP(void)
 524 {
 525     TICK_TYPE user, elapsed;
 526     getTimes( &user, &elapsed );
 527
 528     RP_start_time = user;
 529     RPe_start_time = elapsed;
 530 }
 531 #endif /* PROFILING */
 532
 533 /* -----------------------------------------------------------------------------
 534    Called at the end of each Retainer Profiliing
 535    -------------------------------------------------------------------------- */
 536
 537 #ifdef PROFILING
 538 void
 539 stat_endRP(
 540   nat retainerGeneration,
 541 #ifdef DEBUG_RETAINER
 542   nat maxCStackSize,
 543   int maxStackSize,
 544 #endif
 545   double averageNumVisit)
 546 {
 547     TICK_TYPE user, elapsed;
 548     getTimes( &user, &elapsed );
 549
 550     RP_tot_time += user - RP_start_time;
 551     RPe_tot_time += elapsed - RPe_start_time;
 552
 553   fprintf(prof_file, "Retainer Profiling: %d, at %f seconds\n",
 554     retainerGeneration, mut_user_time_during_RP());
 555 #ifdef DEBUG_RETAINER
 556   fprintf(prof_file, "\tMax C stack size = %u\n", maxCStackSize);
 557   fprintf(prof_file, "\tMax auxiliary stack size = %u\n", maxStackSize);
 558 #endif
 559   fprintf(prof_file, "\tAverage number of visits per object = %f\n", averageNumVisit);
 560 }
 561 #endif /* PROFILING */
 562
 563 /* -----------------------------------------------------------------------------
 564    Called at the beginning of each heap census
 565    -------------------------------------------------------------------------- */
 566 #ifdef PROFILING
 567 void
 568 stat_startHeapCensus(void)
 569 {
 570     TICK_TYPE user, elapsed;
 571     getTimes( &user, &elapsed );
 572
 573     HC_start_time = user;
 574     HCe_start_time = elapsed;
 575 }
 576 #endif /* PROFILING */
 577
 578 /* -----------------------------------------------------------------------------
 579    Called at the end of each heap census
 580    -------------------------------------------------------------------------- */
 581 #ifdef PROFILING
 582 void
 583 stat_endHeapCensus(void)
 584 {
 585     TICK_TYPE user, elapsed;
 586     getTimes( &user, &elapsed );
 587
 588     HC_tot_time += user - HC_start_time;
 589     HCe_tot_time += elapsed - HCe_start_time;
 590 }
 591 #endif /* PROFILING */
 592
 593 /* -----------------------------------------------------------------------------
 594    stat_workerStop
 595
 596    Called under SMP when a worker thread finishes.  We drop the timing
 597    stats for this thread into the taskTable struct for that thread.
 598    -------------------------------------------------------------------------- */
 599
 600 void
 601 stat_getTimes ( long *currentElapsedTime,
 602                 long *currentUserTime,
 603                 long *elapsedGCTime )
 604 {
 605   getTimes(currentUserTime, currentElapsedTime);
 606   *elapsedGCTime = GCe_tot_time;
 607 }
 608
 609 /* -----------------------------------------------------------------------------
 610    Called at the end of execution
 611
 612    NOTE: number of allocations is not entirely accurate: it doesn't
 613    take into account the few bytes at the end of the heap that
 614    were left unused when the heap-check failed.
 615    -------------------------------------------------------------------------- */
 616
 617 void
 618 stat_exit(int alloc)
 619 {
 620     TICK_TYPE user, elapsed;
 621
 622     if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
 623
 624         char temp[BIG_STRING_LEN];
 625         TICK_TYPE time;
 626         TICK_TYPE etime;
 627         nat g, total_collections = 0;
 628
 629         getTimes( &user, &elapsed );
 630         etime = elapsed - ElapsedTimeStart;
 631
 632         GC_tot_alloc += alloc;
 633
 634         /* Count total garbage collections */
 635         for (g = 0; g < RtsFlags.GcFlags.generations; g++)
 636             total_collections += generations[g].collections;
 637
 638         /* For SMP, we have to get the user time from each thread
 639          * and try to work out the total time.
 640          */
 641 #if defined(RTS_SUPPORTS_THREADS)
 642         {
 643             nat i;
 644             MutUserTime = 0.0;
 645             for (i = 0; i < taskCount; i++) {
 646                 MutUserTime += taskTable[i].mut_time;
 647             }
 648         }
 649         time = MutUserTime + GC_tot_time + InitUserTime + ExitUserTime;
 650         if (MutUserTime < 0) { MutUserTime = 0; }
 651 #else
 652         time = user;
 653 #endif
 654
 655         /* avoid divide by zero if time is measured as 0.00 seconds -- SDM */
 656         if (time  == 0.0)  time = 1;
 657         if (etime == 0.0) etime = 1;
 658
 659         if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) {
 660             statsPrintf("%9ld %9.9s %9.9s", (lnat)alloc*sizeof(W_), "", "");
 661             statsPrintf(" %5.2f %5.2f\n\n", 0.0, 0.0);
 662         }
 663
 664         if (RtsFlags.GcFlags.giveStats >= SUMMARY_GC_STATS) {
 665             ullong_format_string(GC_tot_alloc*sizeof(W_),
 666                                  temp, rtsTrue/*commas*/);
 667             statsPrintf("%11s bytes allocated in the heap\n", temp);
 668
 669             ullong_format_string(GC_tot_copied*sizeof(W_),
 670                                  temp, rtsTrue/*commas*/);
 671             statsPrintf("%11s bytes copied during GC (scavenged)\n", temp);
 672
 673             ullong_format_string(GC_tot_scavd_copied*sizeof(W_),
 674                                  temp, rtsTrue/*commas*/);
 675             statsPrintf("%11s bytes copied during GC (not scavenged)\n", temp);
 676
 677             if ( ResidencySamples > 0 ) {
 678                 ullong_format_string(MaxResidency*sizeof(W_),
 679                                      temp, rtsTrue/*commas*/);
 680                 statsPrintf("%11s bytes maximum residency (%ld sample(s))\n",
 681                         temp, ResidencySamples);
 682             }
 683             statsPrintf("\n");
 684
 685             /* Print garbage collections in each gen */
 686             for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
 687                 statsPrintf("%11d collections in generation %d (%6.2fs)\n",
 688                         generations[g].collections, g,
 689                         TICK_TO_DBL(GC_coll_times[g]));
 690             }
 691
 692             statsPrintf("\n%11ld Mb total memory in use\n\n",
 693                     mblocks_allocated * MBLOCK_SIZE / (1024 * 1024));
 694
 695 #if defined(RTS_SUPPORTS_THREADS)
 696             {
 697                 nat i;
 698                 for (i = 0; i < taskCount; i++) {
 699                     statsPrintf("  Task %2d %-8s :  MUT time: %6.2fs  (%6.2fs elapsed)\n"
 700                             "                      GC  time: %6.2fs  (%6.2fs elapsed)\n\n",
 701                                 i,
 702                                 taskTable[i].is_worker ? "(worker)" : "(bound)",
 703                                 TICK_TO_DBL(taskTable[i].mut_time),
 704                                 TICK_TO_DBL(taskTable[i].mut_etime),
 705                                 TICK_TO_DBL(taskTable[i].gc_time),
 706                                 TICK_TO_DBL(taskTable[i].gc_etime));
 707                 }
 708             }
 709 #endif
 710
 711             statsPrintf("  INIT  time  %6.2fs  (%6.2fs elapsed)\n",
 712                     TICK_TO_DBL(InitUserTime), TICK_TO_DBL(InitElapsedTime));
 713             statsPrintf("  MUT   time  %6.2fs  (%6.2fs elapsed)\n",
 714                     TICK_TO_DBL(MutUserTime), TICK_TO_DBL(MutElapsedTime));
 715             statsPrintf("  GC    time  %6.2fs  (%6.2fs elapsed)\n",
 716                     TICK_TO_DBL(GC_tot_time), TICK_TO_DBL(GCe_tot_time));
 717 #ifdef PROFILING
 718             statsPrintf("  RP    time  %6.2fs  (%6.2fs elapsed)\n",
 719                     TICK_TO_DBL(RP_tot_time), TICK_TO_DBL(RPe_tot_time));
 720             statsPrintf("  PROF  time  %6.2fs  (%6.2fs elapsed)\n",
 721                     TICK_TO_DBL(HC_tot_time), TICK_TO_DBL(HCe_tot_time));
 722 #endif
 723             statsPrintf("  EXIT  time  %6.2fs  (%6.2fs elapsed)\n",
 724                     TICK_TO_DBL(ExitUserTime), TICK_TO_DBL(ExitElapsedTime));
 725             statsPrintf("  Total time  %6.2fs  (%6.2fs elapsed)\n\n",
 726                     TICK_TO_DBL(time), TICK_TO_DBL(etime));
 727             statsPrintf("  %%GC time     %5.1f%%  (%.1f%% elapsed)\n\n",
 728                     TICK_TO_DBL(GC_tot_time)*100/TICK_TO_DBL(time),
 729                     TICK_TO_DBL(GCe_tot_time)*100/TICK_TO_DBL(etime));
 730
 731             if (time - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time) == 0)
 732                 ullong_format_string(0, temp, rtsTrue/*commas*/);
 733             else
 734                 ullong_format_string(
 735                     (ullong)((GC_tot_alloc*sizeof(W_))/
 736                              TICK_TO_DBL(time - GC_tot_time -
 737                                          PROF_VAL(RP_tot_time + HC_tot_time))),
 738                     temp, rtsTrue/*commas*/);
 739
 740             statsPrintf("  Alloc rate    %s bytes per MUT second\n\n", temp);
 741
 742             statsPrintf("  Productivity %5.1f%% of total user, %.1f%% of total elapsed\n\n",
 743                     TICK_TO_DBL(time - GC_tot_time -
 744                                 PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime) * 100
 745                     / TICK_TO_DBL(time),
 746                     TICK_TO_DBL(time - GC_tot_time -
 747                                 PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime) * 100
 748                     / TICK_TO_DBL(etime));
 749         }
 750
 751         if (RtsFlags.GcFlags.giveStats == ONELINE_GC_STATS) {
 752           /* print the long long separately to avoid bugginess on mingwin (2001-07-02, mingw-0.5) */
 753           statsPrintf("<<ghc: %llu bytes, ", GC_tot_alloc*(ullong)sizeof(W_));
 754           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",
 755                     total_collections,
 756                     ResidencySamples == 0 ? 0 :
 757                         AvgResidency*sizeof(W_)/ResidencySamples,
 758                     MaxResidency*sizeof(W_),
 759                     ResidencySamples,
 760                     (unsigned long)(mblocks_allocated * MBLOCK_SIZE / (1024L * 1024L)),
 761                     TICK_TO_DBL(InitUserTime), TICK_TO_DBL(InitElapsedTime),
 762                     TICK_TO_DBL(MutUserTime), TICK_TO_DBL(MutElapsedTime),
 763                     TICK_TO_DBL(GC_tot_time), TICK_TO_DBL(GCe_tot_time));
 764         }
 765
 766         statsFlush();
 767         statsClose();
 768     }
 769 }
 770
 771 /* -----------------------------------------------------------------------------
 772    stat_describe_gens
 773
 774    Produce some detailed info on the state of the generational GC.
 775    -------------------------------------------------------------------------- */
 776 #ifdef DEBUG
 777 void
 778 statDescribeGens(void)
 779 {
 780   nat g, s, mut, lge, live;
 781   bdescr *bd;
 782   step *step;
 783
 784   debugBelch("     Gen    Steps      Max   Mutable  Step   Blocks     Live    Large\n                    Blocks  Closures  Closures                          Objects\n");
 785
 786   mut = 0;
 787   for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
 788       for (bd = generations[g].mut_list; bd != NULL; bd = bd->link) {
 789           mut += bd->free - bd->start;
 790       }
 791
 792     debugBelch("%8d %8d %8d %9d", g, generations[g].n_steps,
 793             generations[g].max_blocks, mut);
 794
 795     for (s = 0; s < generations[g].n_steps; s++) {
 796       step = &generations[g].steps[s];
 797       for (bd = step->large_objects, lge = 0; bd; bd = bd->link)
 798         lge++;
 799       live = 0;
 800       bd = step->blocks;
 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 }