ghc/rts/Stats.c

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