ghc/rts/Stats.c

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