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