ghc/rts/Stats.c

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