Stats.c 32.5 KB
Newer Older
1
/* -----------------------------------------------------------------------------
2
 *
3
 * (c) The GHC Team, 1998-2005
4 5 6 7 8
 *
 * Statistics and timing-related functions.
 *
 * ---------------------------------------------------------------------------*/

Simon Marlow's avatar
Simon Marlow committed
9
#include "PosixSource.h"
10
#include "Rts.h"
Simon Marlow's avatar
Simon Marlow committed
11

12
#include "RtsFlags.h"
13
#include "RtsUtils.h"
14
#include "Schedule.h"
15
#include "Stats.h"
16
#include "Profiling.h"
17
#include "GetTime.h"
Simon Marlow's avatar
Simon Marlow committed
18
#include "sm/Storage.h"
19
#include "sm/GC.h" // gc_alloc_block_sync, whitehole_spin
Simon Marlow's avatar
Simon Marlow committed
20 21
#include "sm/GCThread.h"
#include "sm/BlockAlloc.h"
22

23 24 25
/* huh? */
#define BIG_STRING_LEN              512

Simon Marlow's avatar
Simon Marlow committed
26
#define TimeToSecondsDbl(t) ((double)(t) / TIME_RESOLUTION)
27

Simon Marlow's avatar
Simon Marlow committed
28
static Time
Simon Marlow's avatar
Simon Marlow committed
29 30 31 32
    start_init_cpu, start_init_elapsed,
    end_init_cpu,   end_init_elapsed,
    start_exit_cpu, start_exit_elapsed,
    end_exit_cpu,   end_exit_elapsed;
33

Simon Marlow's avatar
Simon Marlow committed
34
static Time GC_tot_cpu  = 0;
35

Simon Marlow's avatar
Simon Marlow committed
36 37
static StgWord64 GC_tot_alloc      = 0;
static StgWord64 GC_tot_copied     = 0;
38

Ian Lynagh's avatar
Ian Lynagh committed
39
static StgWord64 GC_par_max_copied = 0;
40
static StgWord64 GC_par_tot_copied = 0;
41

sof's avatar
sof committed
42
#ifdef PROFILING
Simon Marlow's avatar
Simon Marlow committed
43 44
static Time RP_start_time  = 0, RP_tot_time  = 0;  // retainer prof user time
static Time RPe_start_time = 0, RPe_tot_time = 0;  // retainer prof elap time
sof's avatar
sof committed
45

Simon Marlow's avatar
Simon Marlow committed
46 47
static Time HC_start_time, HC_tot_time = 0;     // heap census prof user time
static Time HCe_start_time, HCe_tot_time = 0;   // heap census prof elap time
sof's avatar
sof committed
48
#endif
49

sof's avatar
sof committed
50
#ifdef PROFILING
51
#define PROF_VAL(x)   (x)
sof's avatar
sof committed
52 53 54
#else
#define PROF_VAL(x)   0
#endif
55

56
// current = current as of last GC
57 58 59 60 61 62
static W_ current_residency = 0; // in words; for stats only
static W_ max_residency     = 0;
static W_ cumulative_residency = 0;
static W_ residency_samples = 0; // for stats only
static W_ current_slop      = 0;
static W_ max_slop          = 0;
63

64
static W_ GC_end_faults = 0;
65

Simon Marlow's avatar
Simon Marlow committed
66 67 68
static Time *GC_coll_cpu = NULL;
static Time *GC_coll_elapsed = NULL;
static Time *GC_coll_max_pause = NULL;
69

Ben Gamari's avatar
Ben Gamari committed
70
static void statsPrintf( char *s, ... ) GNUC3_ATTRIBUTE(format (PRINTF, 1, 2));
71 72 73
static void statsFlush( void );
static void statsClose( void );

Simon Marlow's avatar
Simon Marlow committed
74 75 76
/* -----------------------------------------------------------------------------
   Current elapsed time
   ------------------------------------------------------------------------- */
sof's avatar
sof committed
77

Simon Marlow's avatar
Simon Marlow committed
78
Time stat_getElapsedTime(void)
Simon Marlow's avatar
Simon Marlow committed
79
{
Simon Marlow's avatar
Simon Marlow committed
80
    return getProcessElapsedTime() - start_init_elapsed;
Simon Marlow's avatar
Simon Marlow committed
81 82
}

Simon Marlow's avatar
Simon Marlow committed
83 84 85
/* ---------------------------------------------------------------------------
   Measure the current MUT time, for profiling
   ------------------------------------------------------------------------ */
86

Ian Lynagh's avatar
Ian Lynagh committed
87
double
Simon Marlow's avatar
Simon Marlow committed
88
mut_user_time_until( Time t )
Ian Lynagh's avatar
Ian Lynagh committed
89
{
Simon Marlow's avatar
Simon Marlow committed
90
    return TimeToSecondsDbl(t - GC_tot_cpu);
91 92
    // heapCensus() time is included in GC_tot_cpu, so we don't need
    // to subtract it here.
Ian Lynagh's avatar
Ian Lynagh committed
93 94
}

95
double
96
mut_user_time( void )
97
{
Simon Marlow's avatar
Simon Marlow committed
98
    Time cpu;
Simon Marlow's avatar
Simon Marlow committed
99
    cpu = getProcessCPUTime();
Ian Lynagh's avatar
Ian Lynagh committed
100
    return mut_user_time_until(cpu);
101 102
}

103
#ifdef PROFILING
104
/*
Simon Marlow's avatar
Simon Marlow committed
105
  mut_user_time_during_RP() returns the MUT time during retainer profiling.
106
  The same is for mut_user_time_during_HC();
107
 */
108
static double
109 110
mut_user_time_during_RP( void )
{
Simon Marlow's avatar
Simon Marlow committed
111
    return TimeToSecondsDbl(RP_start_time - GC_tot_cpu - RP_tot_time);
112 113
}

sof's avatar
sof committed
114
#endif /* PROFILING */
115

Simon Marlow's avatar
Simon Marlow committed
116 117 118 119
/* ---------------------------------------------------------------------------
   initStats0() has no dependencies, it can be called right at the beginning
   ------------------------------------------------------------------------ */

120
void
121 122
initStats0(void)
{
Simon Marlow's avatar
Simon Marlow committed
123 124 125 126
    start_init_cpu    = 0;
    start_init_elapsed = 0;
    end_init_cpu     = 0;
    end_init_elapsed  = 0;
127

Simon Marlow's avatar
Simon Marlow committed
128 129 130 131
    start_exit_cpu    = 0;
    start_exit_elapsed = 0;
    end_exit_cpu     = 0;
    end_exit_elapsed  = 0;
132 133 134 135

    GC_tot_alloc     = 0;
    GC_tot_copied    = 0;
    GC_par_max_copied = 0;
136
    GC_par_tot_copied = 0;
Simon Marlow's avatar
Simon Marlow committed
137
    GC_tot_cpu  = 0;
138 139 140 141 142 143 144 145 146 147 148 149 150

#ifdef PROFILING
    RP_start_time  = 0;
    RP_tot_time  = 0;
    RPe_start_time = 0;
    RPe_tot_time = 0;

    HC_start_time = 0;
    HC_tot_time = 0;
    HCe_start_time = 0;
    HCe_tot_time = 0;
#endif

Simon Marlow's avatar
Simon Marlow committed
151
    max_residency = 0;
152
    cumulative_residency = 0;
Simon Marlow's avatar
Simon Marlow committed
153 154
    residency_samples = 0;
    max_slop = 0;
155 156

    GC_end_faults = 0;
Austin Seipp's avatar
Austin Seipp committed
157
}
158

Simon Marlow's avatar
Simon Marlow committed
159 160 161 162
/* ---------------------------------------------------------------------------
   initStats1() can be called after setupRtsFlags()
   ------------------------------------------------------------------------ */

163 164
void
initStats1 (void)
165
{
166
    uint32_t i;
Austin Seipp's avatar
Austin Seipp committed
167

168
    if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) {
169 170
        statsPrintf("    Alloc    Copied     Live     GC     GC      TOT      TOT  Page Flts\n");
        statsPrintf("    bytes     bytes     bytes   user   elap     user     elap\n");
171
    }
Austin Seipp's avatar
Austin Seipp committed
172 173
    GC_coll_cpu =
        (Time *)stgMallocBytes(
Simon Marlow's avatar
Simon Marlow committed
174
            sizeof(Time)*RtsFlags.GcFlags.generations,
Austin Seipp's avatar
Austin Seipp committed
175 176 177 178 179
            "initStats");
    GC_coll_elapsed =
        (Time *)stgMallocBytes(
            sizeof(Time)*RtsFlags.GcFlags.generations,
            "initStats");
Simon Marlow's avatar
Simon Marlow committed
180
    GC_coll_max_pause =
Austin Seipp's avatar
Austin Seipp committed
181 182 183
        (Time *)stgMallocBytes(
            sizeof(Time)*RtsFlags.GcFlags.generations,
            "initStats");
184
    for (i = 0; i < RtsFlags.GcFlags.generations; i++) {
Austin Seipp's avatar
Austin Seipp committed
185
        GC_coll_cpu[i] = 0;
Simon Marlow's avatar
Simon Marlow committed
186 187
        GC_coll_elapsed[i] = 0;
        GC_coll_max_pause[i] = 0;
188
    }
189
}
190 191 192 193

/* -----------------------------------------------------------------------------
   Initialisation time...
   -------------------------------------------------------------------------- */
194 195

void
196
stat_startInit(void)
197
{
Simon Marlow's avatar
Simon Marlow committed
198
    getProcessTimes(&start_init_cpu, &start_init_elapsed);
199 200
}

Austin Seipp's avatar
Austin Seipp committed
201
void
202
stat_endInit(void)
203
{
Simon Marlow's avatar
Simon Marlow committed
204
    getProcessTimes(&end_init_cpu, &end_init_elapsed);
205 206
}

207 208
/* -----------------------------------------------------------------------------
   stat_startExit and stat_endExit
Austin Seipp's avatar
Austin Seipp committed
209

210 211 212
   These two measure the time taken in shutdownHaskell().
   -------------------------------------------------------------------------- */

213 214 215
void
stat_startExit(void)
{
Simon Marlow's avatar
Simon Marlow committed
216
    getProcessTimes(&start_exit_cpu, &start_exit_elapsed);
217 218 219 220 221
}

void
stat_endExit(void)
{
Simon Marlow's avatar
Simon Marlow committed
222
    getProcessTimes(&end_exit_cpu, &end_exit_elapsed);
223 224
}

225 226 227 228 229 230
void
stat_startGCSync (gc_thread *gct)
{
    gct->gc_sync_start_elapsed = getProcessElapsedTime();
}

231 232 233 234
/* -----------------------------------------------------------------------------
   Called at the beginning of each GC
   -------------------------------------------------------------------------- */

235
static uint32_t rub_bell = 0;
236 237

void
238
stat_startGC (Capability *cap, gc_thread *gct)
239
{
240
    uint32_t bell = RtsFlags.GcFlags.ringBell;
241 242

    if (bell) {
Austin Seipp's avatar
Austin Seipp committed
243 244 245 246 247 248
        if (bell > 1) {
            debugBelch(" GC ");
            rub_bell = 1;
        } else {
            debugBelch("\007");
        }
249 250
    }

Simon Marlow's avatar
Simon Marlow committed
251
    getProcessTimes(&gct->gc_start_cpu, &gct->gc_start_elapsed);
252 253 254 255 256 257 258 259 260

    // Post EVENT_GC_START with the same timestamp as used for stats
    // (though converted from Time=StgInt64 to EventTimestamp=StgWord64).
    // Here, as opposed to other places, the event is emitted on the cap
    // that initiates the GC and external tools expect it to have the same
    // timestamp as used in +RTS -s calculcations.
    traceEventGcStartAtT(cap,
                         TimeToNS(gct->gc_start_elapsed - start_init_elapsed));

Simon Marlow's avatar
Simon Marlow committed
261 262 263 264
    if (RtsFlags.GcFlags.giveStats != NO_GC_STATS)
    {
        gct->gc_start_faults = getPageFaults();
    }
265

Simon Marlow's avatar
Simon Marlow committed
266
    updateNurseriesStats();
267 268
}

269 270 271 272 273
/* -----------------------------------------------------------------------------
   Called at the end of each GC
   -------------------------------------------------------------------------- */

void
274
stat_endGC (Capability *cap, gc_thread *gct,
275 276
            W_ live, W_ copied, W_ slop, uint32_t gen,
            uint32_t par_n_threads, W_ par_max_copied, W_ par_tot_copied)
277
{
278 279 280
    W_ tot_alloc;
    W_ alloc;

281
    if (RtsFlags.GcFlags.giveStats != NO_GC_STATS ||
282
        rtsConfig.gcDoneHook != NULL ||
283 284 285
        RtsFlags.ProfFlags.doHeapProfile)
        // heap profiling needs GC_tot_time
    {
286
        Time cpu, elapsed, gc_cpu, gc_elapsed, gc_sync_elapsed;
287

288 289 290 291 292
        // Has to be emitted while all caps stopped for GC, but before GC_END.
        // See trac.haskell.org/ThreadScope/wiki/RTSsummaryEvents
        // for a detailed design rationale of the current setup
        // of GC eventlog events.
        traceEventGcGlobalSync(cap);
Austin Seipp's avatar
Austin Seipp committed
293

294
        // Emitted before GC_END on all caps, which simplifies tools code.
295 296 297 298 299 300 301
        traceEventGcStats(cap,
                          CAPSET_HEAP_DEFAULT,
                          gen,
                          copied * sizeof(W_),
                          slop   * sizeof(W_),
                          /* current loss due to fragmentation */
                          (mblocks_allocated * BLOCKS_PER_MBLOCK - n_alloc_blocks)
302
                                 * BLOCK_SIZE,
303 304 305
                          par_n_threads,
                          par_max_copied * sizeof(W_),
                          par_tot_copied * sizeof(W_));
306

Simon Marlow's avatar
Simon Marlow committed
307 308
        getProcessTimes(&cpu, &elapsed);

309 310 311 312 313 314 315
        // Post EVENT_GC_END with the same timestamp as used for stats
        // (though converted from Time=StgInt64 to EventTimestamp=StgWord64).
        // Here, as opposed to other places, the event is emitted on the cap
        // that initiates the GC and external tools expect it to have the same
        // timestamp as used in +RTS -s calculcations.
        traceEventGcEndAtT(cap, TimeToNS(elapsed - start_init_elapsed));

316
        gc_sync_elapsed = gct->gc_start_elapsed - gct->gc_sync_start_elapsed;
317
        gc_elapsed = elapsed - gct->gc_start_elapsed;
Simon Marlow's avatar
Simon Marlow committed
318 319
        gc_cpu = cpu - gct->gc_start_cpu;

320
        /* For the moment we calculate both per-HEC and total allocation.
Austin Seipp's avatar
Austin Seipp committed
321 322 323
         * There is thus redundancy here, but for the moment we will calculate
         * it both the old and new way and assert they're the same.
         * When we're sure it's working OK then we can simplify things.
324 325 326 327 328 329 330
         */
        tot_alloc = calcTotalAllocated();

        // allocated since the last GC
        alloc = tot_alloc - GC_tot_alloc;
        GC_tot_alloc = tot_alloc;

Simon Marlow's avatar
Simon Marlow committed
331
        if (RtsFlags.GcFlags.giveStats == VERBOSE_GC_STATS) {
Austin Seipp's avatar
Austin Seipp committed
332 333
            W_ faults = getPageFaults();

334
            statsPrintf("%9" FMT_Word " %9" FMT_Word " %9" FMT_Word,
Austin Seipp's avatar
Austin Seipp committed
335 336
                    alloc*sizeof(W_), copied*sizeof(W_),
                        live*sizeof(W_));
337
            statsPrintf(" %6.3f %6.3f %8.3f %8.3f %4" FMT_Word " %4" FMT_Word "  (Gen: %2d)\n",
Simon Marlow's avatar
Simon Marlow committed
338
                    TimeToSecondsDbl(gc_cpu),
Austin Seipp's avatar
Austin Seipp committed
339 340 341 342
                    TimeToSecondsDbl(gc_elapsed),
                    TimeToSecondsDbl(cpu),
                    TimeToSecondsDbl(elapsed - start_init_elapsed),
                    faults - gct->gc_start_faults,
Simon Marlow's avatar
Simon Marlow committed
343 344 345 346
                        gct->gc_start_faults - GC_end_faults,
                    gen);

            GC_end_faults = faults;
Austin Seipp's avatar
Austin Seipp committed
347 348
            statsFlush();
        }
349

350 351 352 353 354 355 356 357

        if (rtsConfig.gcDoneHook != NULL) {
            rtsConfig.gcDoneHook(gen,
                                 alloc*sizeof(W_),
                                 live*sizeof(W_),
                                 copied*sizeof(W_),
                                 par_max_copied * sizeof(W_),
                                 mblocks_allocated * BLOCKS_PER_MBLOCK
358
                                   * BLOCK_SIZE,
359 360 361 362 363 364
                                 slop   * sizeof(W_),
                                 TimeToNS(gc_sync_elapsed),
                                 TimeToNS(gc_elapsed),
                                 TimeToNS(gc_cpu));
        }

Simon Marlow's avatar
Simon Marlow committed
365 366 367 368 369
        GC_coll_cpu[gen] += gc_cpu;
        GC_coll_elapsed[gen] += gc_elapsed;
        if (GC_coll_max_pause[gen] < gc_elapsed) {
            GC_coll_max_pause[gen] = gc_elapsed;
        }
370

Austin Seipp's avatar
Austin Seipp committed
371
        GC_tot_copied += (StgWord64) copied;
372 373
        GC_par_max_copied += (StgWord64) par_max_copied;
        GC_par_tot_copied += (StgWord64) par_tot_copied;
Austin Seipp's avatar
Austin Seipp committed
374 375
        GC_tot_cpu   += gc_cpu;

376
        traceEventHeapSize(cap,
Austin Seipp's avatar
Austin Seipp committed
377 378
                           CAPSET_HEAP_DEFAULT,
                           mblocks_allocated * MBLOCK_SIZE_W * sizeof(W_));
379

Austin Seipp's avatar
Austin Seipp committed
380 381 382 383
        if (gen == RtsFlags.GcFlags.generations-1) { /* major GC? */
            if (live > max_residency) {
                max_residency = live;
            }
384
            current_residency = live;
Austin Seipp's avatar
Austin Seipp committed
385 386 387 388 389 390
            residency_samples++;
            cumulative_residency += live;
            traceEventHeapLive(cap,
                               CAPSET_HEAP_DEFAULT,
                               live * sizeof(W_));
        }
391

Simon Marlow's avatar
Simon Marlow committed
392
        if (slop > max_slop) max_slop = slop;
393 394 395
    }

    if (rub_bell) {
Austin Seipp's avatar
Austin Seipp committed
396 397
        debugBelch("\b\b\b  \b\b\b");
        rub_bell = 0;
398 399 400
    }
}

401 402 403
/* -----------------------------------------------------------------------------
   Called at the beginning of each Retainer Profiliing
   -------------------------------------------------------------------------- */
404 405 406
#ifdef PROFILING
void
stat_startRP(void)
407
{
Simon Marlow's avatar
Simon Marlow committed
408
    Time user, elapsed;
409
    getProcessTimes( &user, &elapsed );
410 411 412

    RP_start_time = user;
    RPe_start_time = elapsed;
413
}
sof's avatar
sof committed
414
#endif /* PROFILING */
415 416 417 418

/* -----------------------------------------------------------------------------
   Called at the end of each Retainer Profiliing
   -------------------------------------------------------------------------- */
419 420 421 422

#ifdef PROFILING
void
stat_endRP(
423
  uint32_t retainerGeneration,
424
#ifdef DEBUG_RETAINER
425
  uint32_t maxCStackSize,
426 427
  int maxStackSize,
#endif
428
  double averageNumVisit)
429
{
Simon Marlow's avatar
Simon Marlow committed
430
    Time user, elapsed;
431
    getProcessTimes( &user, &elapsed );
432 433 434

    RP_tot_time += user - RP_start_time;
    RPe_tot_time += elapsed - RPe_start_time;
435

Austin Seipp's avatar
Austin Seipp committed
436
  fprintf(prof_file, "Retainer Profiling: %d, at %f seconds\n",
437 438 439 440 441 442 443
    retainerGeneration, mut_user_time_during_RP());
#ifdef DEBUG_RETAINER
  fprintf(prof_file, "\tMax C stack size = %u\n", maxCStackSize);
  fprintf(prof_file, "\tMax auxiliary stack size = %u\n", maxStackSize);
#endif
  fprintf(prof_file, "\tAverage number of visits per object = %f\n", averageNumVisit);
}
sof's avatar
sof committed
444
#endif /* PROFILING */
445 446

/* -----------------------------------------------------------------------------
447
   Called at the beginning of each heap census
448
   -------------------------------------------------------------------------- */
449 450
#ifdef PROFILING
void
451
stat_startHeapCensus(void)
452
{
Simon Marlow's avatar
Simon Marlow committed
453
    Time user, elapsed;
454
    getProcessTimes( &user, &elapsed );
455 456 457

    HC_start_time = user;
    HCe_start_time = elapsed;
458
}
sof's avatar
sof committed
459
#endif /* PROFILING */
460 461

/* -----------------------------------------------------------------------------
462
   Called at the end of each heap census
463
   -------------------------------------------------------------------------- */
464 465
#ifdef PROFILING
void
Austin Seipp's avatar
Austin Seipp committed
466
stat_endHeapCensus(void)
467
{
Simon Marlow's avatar
Simon Marlow committed
468
    Time user, elapsed;
469
    getProcessTimes( &user, &elapsed );
470 471 472

    HC_tot_time += user - HC_start_time;
    HCe_tot_time += elapsed - HCe_start_time;
473
}
sof's avatar
sof committed
474
#endif /* PROFILING */
475

476 477 478 479 480 481 482 483
/* -----------------------------------------------------------------------------
   Called at the end of execution

   NOTE: number of allocations is not entirely accurate: it doesn't
   take into account the few bytes at the end of the heap that
   were left unused when the heap-check failed.
   -------------------------------------------------------------------------- */

Simon Marlow's avatar
Simon Marlow committed
484 485 486 487 488 489 490 491 492 493 494 495 496 497 498
#ifdef DEBUG
#define TICK_VAR_INI(arity) \
  StgInt SLOW_CALLS_##arity = 1; \
  StgInt RIGHT_ARITY_##arity = 1; \
  StgInt TAGGED_PTR_##arity = 0;

TICK_VAR_INI(1)
TICK_VAR_INI(2)

StgInt TOTAL_CALLS=1;
#endif

/* Report the value of a counter */
#define REPORT(counter) \
  { \
Ian Lynagh's avatar
Ian Lynagh committed
499
    showStgWord64(counter,temp,rtsTrue/*commas*/); \
Austin Seipp's avatar
Austin Seipp committed
500
    statsPrintf("  (" #counter ")  : %s\n",temp);                               \
Simon Marlow's avatar
Simon Marlow committed
501 502 503 504 505
  }

/* Report the value of a counter as a percentage of another counter */
#define REPORT_PCT(counter,countertot) \
  statsPrintf("  (" #counter ") %% of (" #countertot ") : %.1f%%\n", \
Austin Seipp's avatar
Austin Seipp committed
506
              counter*100.0/countertot)
Simon Marlow's avatar
Simon Marlow committed
507 508 509 510 511 512 513 514 515 516

#define TICK_PRINT(arity) \
  REPORT(SLOW_CALLS_##arity); \
  REPORT_PCT(RIGHT_ARITY_##arity,SLOW_CALLS_##arity); \
  REPORT_PCT(TAGGED_PTR_##arity,RIGHT_ARITY_##arity); \
  REPORT(RIGHT_ARITY_##arity); \
  REPORT(TAGGED_PTR_##arity)

#define TICK_PRINT_TOT(arity) \
  statsPrintf("  (SLOW_CALLS_" #arity ") %% of (TOTAL_CALLS) : %.1f%%\n", \
Austin Seipp's avatar
Austin Seipp committed
517
              SLOW_CALLS_##arity * 100.0/TOTAL_CALLS)
Simon Marlow's avatar
Simon Marlow committed
518

Simon Marlow's avatar
Simon Marlow committed
519 520
static inline Time get_init_cpu(void) { return end_init_cpu - start_init_cpu; }
static inline Time get_init_elapsed(void) { return end_init_elapsed - start_init_elapsed; }
521

522

523
void
524
stat_exit (void)
525
{
Simon Marlow's avatar
Simon Marlow committed
526
    generation *gen;
Simon Marlow's avatar
Simon Marlow committed
527 528 529 530 531 532 533 534
    Time gc_cpu = 0;
    Time gc_elapsed = 0;
    Time init_cpu = 0;
    Time init_elapsed = 0;
    Time mut_cpu = 0;
    Time mut_elapsed = 0;
    Time exit_cpu = 0;
    Time exit_elapsed = 0;
535 536
    W_ tot_alloc;
    W_ alloc;
Simon Marlow's avatar
Simon Marlow committed
537

538
    if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
539

Austin Seipp's avatar
Austin Seipp committed
540 541 542
        char temp[BIG_STRING_LEN];
        Time tot_cpu;
        Time tot_elapsed;
543
        uint32_t i, g, total_collections = 0;
544

Austin Seipp's avatar
Austin Seipp committed
545 546
        getProcessTimes( &tot_cpu, &tot_elapsed );
        tot_elapsed -= start_init_elapsed;
547

548
        tot_alloc = calcTotalAllocated();
549

550 551 552
        // allocated since the last GC
        alloc = tot_alloc - GC_tot_alloc;
        GC_tot_alloc = tot_alloc;
553

Austin Seipp's avatar
Austin Seipp committed
554 555 556
        /* Count total garbage collections */
        for (g = 0; g < RtsFlags.GcFlags.generations; g++)
            total_collections += generations[g].collections;
557

Austin Seipp's avatar
Austin Seipp committed
558 559 560 561 562
        /* avoid divide by zero if tot_cpu is measured as 0.00 seconds -- SDM */
        if (tot_cpu  == 0.0)  tot_cpu = 1;
        if (tot_elapsed == 0.0) tot_elapsed = 1;

        if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) {
563
            statsPrintf("%9" FMT_Word " %9.9s %9.9s", (W_)alloc*sizeof(W_), "", "");
Austin Seipp's avatar
Austin Seipp committed
564 565
            statsPrintf(" %6.3f %6.3f\n\n", 0.0, 0.0);
        }
566

Simon Marlow's avatar
Simon Marlow committed
567 568 569 570 571
        for (i = 0; i < RtsFlags.GcFlags.generations; i++) {
            gc_cpu     += GC_coll_cpu[i];
            gc_elapsed += GC_coll_elapsed[i];
        }

572 573
        // heapCensus() is called by the GC, so RP and HC time are
        // included in the GC stats.  We therefore subtract them to
Ian Lynagh's avatar
Ian Lynagh committed
574
        // obtain the actual GC cpu time.
575 576
        gc_cpu     -= PROF_VAL(RP_tot_time + HC_tot_time);
        gc_elapsed -= PROF_VAL(RPe_tot_time + HCe_tot_time);
577

578 579
        init_cpu     = get_init_cpu();
        init_elapsed = get_init_elapsed();
dmp's avatar
dmp committed
580 581 582 583 584 585 586 587 588 589

        exit_cpu     = end_exit_cpu - start_exit_cpu;
        exit_elapsed = end_exit_elapsed - start_exit_elapsed;

        mut_elapsed = start_exit_elapsed - end_init_elapsed - gc_elapsed;

        mut_cpu = start_exit_cpu - end_init_cpu - gc_cpu
            - PROF_VAL(RP_tot_time + HC_tot_time);
        if (mut_cpu < 0) { mut_cpu = 0; }

Austin Seipp's avatar
Austin Seipp committed
590 591 592 593
        if (RtsFlags.GcFlags.giveStats >= SUMMARY_GC_STATS) {
            showStgWord64(GC_tot_alloc*sizeof(W_),
                                 temp, rtsTrue/*commas*/);
            statsPrintf("%16s bytes allocated in the heap\n", temp);
594

Austin Seipp's avatar
Austin Seipp committed
595 596 597
            showStgWord64(GC_tot_copied*sizeof(W_),
                                 temp, rtsTrue/*commas*/);
            statsPrintf("%16s bytes copied during GC\n", temp);
598

Simon Marlow's avatar
Simon Marlow committed
599
            if ( residency_samples > 0 ) {
Austin Seipp's avatar
Austin Seipp committed
600 601 602 603 604
                showStgWord64(max_residency*sizeof(W_),
                                     temp, rtsTrue/*commas*/);
                statsPrintf("%16s bytes maximum residency (%" FMT_Word " sample(s))\n",
                        temp, residency_samples);
            }
605

Austin Seipp's avatar
Austin Seipp committed
606 607
            showStgWord64(max_slop*sizeof(W_), temp, rtsTrue/*commas*/);
            statsPrintf("%16s bytes maximum slop\n", temp);
608

Austin Seipp's avatar
Austin Seipp committed
609
            statsPrintf("%16" FMT_SizeT " MB total memory in use (%" FMT_SizeT " MB lost due to fragmentation)\n\n",
610 611
                        (size_t)(peak_mblocks_allocated * MBLOCK_SIZE_W) / (1024 * 1024 / sizeof(W_)),
                        (size_t)(peak_mblocks_allocated * BLOCKS_PER_MBLOCK * BLOCK_SIZE_W - hw_alloc_blocks * BLOCK_SIZE_W) / (1024 * 1024 / sizeof(W_)));
612

Austin Seipp's avatar
Austin Seipp committed
613
            /* Print garbage collections in each gen */
614
            statsPrintf("                                     Tot time (elapsed)  Avg pause  Max pause\n");
Simon Marlow's avatar
Simon Marlow committed
615 616
            for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
                gen = &generations[g];
617
                statsPrintf("  Gen %2d     %5d colls, %5d par   %6.3fs  %6.3fs     %3.4fs    %3.4fs\n",
Simon Marlow's avatar
Simon Marlow committed
618 619 620
                            gen->no,
                            gen->collections,
                            gen->par_collections,
Simon Marlow's avatar
Simon Marlow committed
621 622 623 624
                            TimeToSecondsDbl(GC_coll_cpu[g]),
                            TimeToSecondsDbl(GC_coll_elapsed[g]),
                            gen->collections == 0 ? 0 : TimeToSecondsDbl(GC_coll_elapsed[g] / gen->collections),
                            TimeToSecondsDbl(GC_coll_max_pause[g]));
Simon Marlow's avatar
Simon Marlow committed
625
            }
626

627
#if defined(THREADED_RTS)
628
            if (RtsFlags.ParFlags.parGcEnabled && n_capabilities > 1) {
Austin Seipp's avatar
Austin Seipp committed
629
                statsPrintf("\n  Parallel GC work balance: %.2f%% (serial 0%%, perfect 100%%)\n",
630 631
                            100 * (((double)GC_par_tot_copied / (double)GC_par_max_copied) - 1)
                                / (n_capabilities - 1)
632 633 634
                    );
            }
#endif
Simon Marlow's avatar
Simon Marlow committed
635
            statsPrintf("\n");
636

637
#if defined(THREADED_RTS)
638 639 640 641
            statsPrintf("  TASKS: %d (%d bound, %d peak workers (%d total), using -N%d)\n",
                        taskCount, taskCount - workerCount,
                        peakWorkerCount, workerCount,
                        n_capabilities);
642

Austin Seipp's avatar
Austin Seipp committed
643
            statsPrintf("\n");
644

645
            {
646
                uint32_t i;
647
                SparkCounters sparks = { 0, 0, 0, 0, 0, 0};
648
                for (i = 0; i < n_capabilities; i++) {
649 650 651 652 653 654
                    sparks.created   += capabilities[i]->spark_stats.created;
                    sparks.dud       += capabilities[i]->spark_stats.dud;
                    sparks.overflowed+= capabilities[i]->spark_stats.overflowed;
                    sparks.converted += capabilities[i]->spark_stats.converted;
                    sparks.gcd       += capabilities[i]->spark_stats.gcd;
                    sparks.fizzled   += capabilities[i]->spark_stats.fizzled;
655 656
                }

Ian Lynagh's avatar
Ian Lynagh committed
657
                statsPrintf("  SPARKS: %" FMT_Word " (%" FMT_Word " converted, %" FMT_Word " overflowed, %" FMT_Word " dud, %" FMT_Word " GC'd, %" FMT_Word " fizzled)\n\n",
658 659
                            sparks.created + sparks.dud + sparks.overflowed,
                            sparks.converted, sparks.overflowed, sparks.dud,
660
                            sparks.gcd, sparks.fizzled);
661
            }
662 663
#endif

Austin Seipp's avatar
Austin Seipp committed
664
            statsPrintf("  INIT    time  %7.3fs  (%7.3fs elapsed)\n",
Simon Marlow's avatar
Simon Marlow committed
665
                        TimeToSecondsDbl(init_cpu), TimeToSecondsDbl(init_elapsed));
Simon Marlow's avatar
Simon Marlow committed
666

667
            statsPrintf("  MUT     time  %7.3fs  (%7.3fs elapsed)\n",
Simon Marlow's avatar
Simon Marlow committed
668
                        TimeToSecondsDbl(mut_cpu), TimeToSecondsDbl(mut_elapsed));
669
            statsPrintf("  GC      time  %7.3fs  (%7.3fs elapsed)\n",
Simon Marlow's avatar
Simon Marlow committed
670
                        TimeToSecondsDbl(gc_cpu), TimeToSecondsDbl(gc_elapsed));
Simon Marlow's avatar
Simon Marlow committed
671

672
#ifdef PROFILING
Austin Seipp's avatar
Austin Seipp committed
673 674 675 676 677 678 679 680 681
            statsPrintf("  RP      time  %7.3fs  (%7.3fs elapsed)\n",
                    TimeToSecondsDbl(RP_tot_time), TimeToSecondsDbl(RPe_tot_time));
            statsPrintf("  PROF    time  %7.3fs  (%7.3fs elapsed)\n",
                    TimeToSecondsDbl(HC_tot_time), TimeToSecondsDbl(HCe_tot_time));
#endif
            statsPrintf("  EXIT    time  %7.3fs  (%7.3fs elapsed)\n",
                    TimeToSecondsDbl(exit_cpu), TimeToSecondsDbl(exit_elapsed));
            statsPrintf("  Total   time  %7.3fs  (%7.3fs elapsed)\n\n",
                    TimeToSecondsDbl(tot_cpu), TimeToSecondsDbl(tot_elapsed));
Simon Marlow's avatar
Simon Marlow committed
682
#ifndef THREADED_RTS
Austin Seipp's avatar
Austin Seipp committed
683 684 685
            statsPrintf("  %%GC     time     %5.1f%%  (%.1f%% elapsed)\n\n",
                    TimeToSecondsDbl(gc_cpu)*100/TimeToSecondsDbl(tot_cpu),
                    TimeToSecondsDbl(gc_elapsed)*100/TimeToSecondsDbl(tot_elapsed));
Simon Marlow's avatar
Simon Marlow committed
686 687
#endif

Simon Marlow's avatar
Simon Marlow committed
688
            if (mut_cpu == 0) {
Austin Seipp's avatar
Austin Seipp committed
689
                showStgWord64(0, temp, rtsTrue/*commas*/);
Simon Marlow's avatar
Simon Marlow committed
690
            } else {
Austin Seipp's avatar
Austin Seipp committed
691
                showStgWord64(
Simon Marlow's avatar
Simon Marlow committed
692 693 694 695
                    (StgWord64)((GC_tot_alloc*sizeof(W_)) / TimeToSecondsDbl(mut_cpu)),
                    temp, rtsTrue/*commas*/);
            }

Austin Seipp's avatar
Austin Seipp committed
696 697 698
            statsPrintf("  Alloc rate    %s bytes per MUT second\n\n", temp);

            statsPrintf("  Productivity %5.1f%% of total user, %.1f%% of total elapsed\n\n",
Simon Marlow's avatar
Simon Marlow committed
699
                    TimeToSecondsDbl(tot_cpu - gc_cpu -
Austin Seipp's avatar
Austin Seipp committed
700 701
                                PROF_VAL(RP_tot_time + HC_tot_time) - init_cpu) * 100
                    / TimeToSecondsDbl(tot_cpu),
702 703
                    TimeToSecondsDbl(tot_elapsed - gc_elapsed -
                                PROF_VAL(RPe_tot_time + HCe_tot_time) - init_elapsed) * 100
Simon Marlow's avatar
Simon Marlow committed
704
                    / TimeToSecondsDbl(tot_elapsed));
Simon Marlow's avatar
Simon Marlow committed
705 706 707 708

            /*
            TICK_PRINT(1);
            TICK_PRINT(2);
Austin Seipp's avatar
Austin Seipp committed
709
            REPORT(TOTAL_CALLS);
Simon Marlow's avatar
Simon Marlow committed
710 711 712 713
            TICK_PRINT_TOT(1);
            TICK_PRINT_TOT(2);
            */

714 715
#if defined(THREADED_RTS) && defined(PROF_SPIN)
            {
716
                uint32_t g;
Austin Seipp's avatar
Austin Seipp committed
717

718
                statsPrintf("gc_alloc_block_sync: %"FMT_Word64"\n", gc_alloc_block_sync.spin);
719
                statsPrintf("whitehole_spin: %"FMT_Word64"\n", whitehole_spin);
720
                for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
Simon Marlow's avatar
Simon Marlow committed
721
                    statsPrintf("gen[%d].sync: %"FMT_Word64"\n", g, generations[g].sync.spin);
722 723
                }
            }
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
724
#endif
Austin Seipp's avatar
Austin Seipp committed
725
        }
726

Austin Seipp's avatar
Austin Seipp committed
727
        if (RtsFlags.GcFlags.giveStats == ONELINE_GC_STATS) {
Ian Lynagh's avatar
Ian Lynagh committed
728 729 730 731 732 733 734 735
      char *fmt1, *fmt2;
      if (RtsFlags.MiscFlags.machineReadable) {
          fmt1 = " [(\"bytes allocated\", \"%llu\")\n";
          fmt2 = " ,(\"num_GCs\", \"%d\")\n"
                 " ,(\"average_bytes_used\", \"%ld\")\n"
                 " ,(\"max_bytes_used\", \"%ld\")\n"
                 " ,(\"num_byte_usage_samples\", \"%ld\")\n"
                 " ,(\"peak_megabytes_allocated\", \"%lu\")\n"
736 737 738 739 740 741
                 " ,(\"init_cpu_seconds\", \"%.3f\")\n"
                 " ,(\"init_wall_seconds\", \"%.3f\")\n"
                 " ,(\"mutator_cpu_seconds\", \"%.3f\")\n"
                 " ,(\"mutator_wall_seconds\", \"%.3f\")\n"
                 " ,(\"GC_cpu_seconds\", \"%.3f\")\n"
                 " ,(\"GC_wall_seconds\", \"%.3f\")\n"
Ian Lynagh's avatar
Ian Lynagh committed
742 743 744 745
                 " ]\n";
      }
      else {
          fmt1 = "<<ghc: %llu bytes, ";
746
          fmt2 = "%d GCs, %ld/%ld avg/max bytes residency (%ld samples), %luM in use, %.3f INIT (%.3f elapsed), %.3f MUT (%.3f elapsed), %.3f GC (%.3f elapsed) :ghc>>\n";
Ian Lynagh's avatar
Ian Lynagh committed
747
      }
Austin Seipp's avatar
Austin Seipp committed
748 749 750 751 752 753 754 755 756 757 758 759 760 761 762 763
          /* print the long long separately to avoid bugginess on mingwin (2001-07-02, mingw-0.5) */
          statsPrintf(fmt1, GC_tot_alloc*(StgWord64)sizeof(W_));
          statsPrintf(fmt2,
                    total_collections,
                    residency_samples == 0 ? 0 :
                        cumulative_residency*sizeof(W_)/residency_samples,
                    max_residency*sizeof(W_),
                    residency_samples,
                    (unsigned long)(peak_mblocks_allocated * MBLOCK_SIZE / (1024L * 1024L)),
                    TimeToSecondsDbl(init_cpu), TimeToSecondsDbl(init_elapsed),
                    TimeToSecondsDbl(mut_cpu), TimeToSecondsDbl(mut_elapsed),
                    TimeToSecondsDbl(gc_cpu), TimeToSecondsDbl(gc_elapsed));
        }

        statsFlush();
        statsClose();
764
    }
simonmarhaskell@gmail.com's avatar
simonmarhaskell@gmail.com committed
765

Simon Marlow's avatar
Simon Marlow committed
766
    if (GC_coll_cpu) {
Simon Marlow's avatar
Simon Marlow committed
767
      stgFree(GC_coll_cpu);
Simon Marlow's avatar
Simon Marlow committed
768 769 770
      GC_coll_cpu = NULL;
    }
    if (GC_coll_elapsed) {
Simon Marlow's avatar
Simon Marlow committed
771
      stgFree(GC_coll_elapsed);
Simon Marlow's avatar
Simon Marlow committed
772 773 774 775 776 777
      GC_coll_elapsed = NULL;
    }
    if (GC_coll_max_pause) {
      stgFree(GC_coll_max_pause);
      GC_coll_max_pause = NULL;
    }
778
}
779 780 781 782 783 784 785

/* -----------------------------------------------------------------------------
   stat_describe_gens

   Produce some detailed info on the state of the generational GC.
   -------------------------------------------------------------------------- */
void
786
statDescribeGens(void)
787
{
788
  uint32_t g, mut, lge, i;
789 790 791
  W_ gen_slop;
  W_ tot_live, tot_slop;
  W_ gen_live, gen_blocks;
792
  bdescr *bd;
Simon Marlow's avatar
Simon Marlow committed
793
  generation *gen;
Austin Seipp's avatar
Austin Seipp committed
794

795
  debugBelch(
Simon Marlow's avatar
Simon Marlow committed
796 797 798 799
"----------------------------------------------------------\n"
"  Gen     Max  Mut-list  Blocks    Large     Live     Slop\n"
"       Blocks     Bytes          Objects                  \n"
"----------------------------------------------------------\n");
800

801 802
  tot_live = 0;
  tot_slop = 0;
Simon Marlow's avatar
Simon Marlow committed
803

804
  for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
Simon Marlow's avatar
Simon Marlow committed
805 806 807 808 809 810 811 812 813
      gen = &generations[g];

      for (bd = gen->large_objects, lge = 0; bd; bd = bd->link) {
          lge++;
      }

      gen_live   = genLiveWords(gen);
      gen_blocks = genLiveBlocks(gen);

814
      mut = 0;
815
      for (i = 0; i < n_capabilities; i++) {
816
          mut += countOccupied(capabilities[i]->mut_lists[g]);
817 818

          // Add the pinned object block.
819
          bd = capabilities[i]->pinned_object_block;
820 821 822 823 824
          if (bd != NULL) {
              gen_live   += bd->free - bd->start;
              gen_blocks += bd->blocks;
          }

Simon Marlow's avatar
Simon Marlow committed
825 826
          gen_live   += gcThreadLiveWords(i,g);
          gen_blocks += gcThreadLiveBlocks(i,g);
827 828
      }

Ian Lynagh's avatar
Ian Lynagh committed
829
      debugBelch("%5d %7" FMT_Word " %9d", g, (W_)gen->max_blocks, mut);
Simon Marlow's avatar
Simon Marlow committed
830

Simon Marlow's avatar
Simon Marlow committed
831 832
      gen_slop = gen_blocks * BLOCK_SIZE_W - gen_live;

Ian Lynagh's avatar
Ian Lynagh committed
833 834
      debugBelch("%8" FMT_Word " %8d %8" FMT_Word " %8" FMT_Word "\n", gen_blocks, lge,
                 gen_live*(W_)sizeof(W_), gen_slop*(W_)sizeof(W_));
Simon Marlow's avatar
Simon Marlow committed
835 836
      tot_live += gen_live;
      tot_slop += gen_slop;
837
  }
Simon Marlow's avatar
Simon Marlow committed
838
  debugBelch("----------------------------------------------------------\n");
839
  debugBelch("%41s%8" FMT_Word " %8" FMT_Word "\n",
Ian Lynagh's avatar
Ian Lynagh committed
840
             "",tot_live*sizeof(W_),tot_slop*sizeof(W_));
Simon Marlow's avatar
Simon Marlow committed
841
  debugBelch("----------------------------------------------------------\n");
842
  debugBelch("\n");
843
}
844 845 846 847 848 849

/* -----------------------------------------------------------------------------
   Stats available via a programmatic interface, so eg. GHCi can time
   each compilation and expression evaluation.
   -------------------------------------------------------------------------- */

Austin Seipp's avatar
Austin Seipp committed
850
extern HsInt64 getAllocations( void )
851
{ return (HsInt64)GC_tot_alloc * sizeof(W_); }
852

853 854
/* EZY: I'm not convinced I got all the casting right. */

pcapriotti's avatar
pcapriotti committed
855 856 857 858 859
extern rtsBool getGCStatsEnabled( void )
{
    return RtsFlags.GcFlags.giveStats != NO_GC_STATS;
}

860 861
extern void getGCStats( GCStats *s )
{
862 863
    uint32_t total_collections = 0;
    uint32_t g;
Simon Marlow's avatar
Simon Marlow committed
864 865 866 867
    Time gc_cpu = 0;
    Time gc_elapsed = 0;
    Time current_elapsed = 0;
    Time current_cpu = 0;
868 869 870 871 872 873 874 875 876 877 878 879 880 881 882 883 884 885

    getProcessTimes(&current_cpu, &current_elapsed);

    /* EZY: static inline'ify these */
    for (g = 0; g < RtsFlags.GcFlags.generations; g++)
        total_collections += generations[g].collections;

    for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
        gc_cpu     += GC_coll_cpu[g];
        gc_elapsed += GC_coll_elapsed[g];
    }

    s->bytes_allocated = GC_tot_alloc*(StgWord64)sizeof(W_);
    s->num_gcs = total_collections;
    s->num_byte_usage_samples = residency_samples;
    s->max_bytes_used = max_residency*sizeof(W_);
    s->cumulative_bytes_used = cumulative_residency*(StgWord64)sizeof(W_);
    s->peak_megabytes_allocated = (StgWord64)(peak_mblocks_allocated * MBLOCK_SIZE / (1024L * 1024L));
886
    s->mblocks_allocated = (StgWord64)mblocks_allocated;
887 888 889 890 891
    s->bytes_copied = GC_tot_copied*(StgWord64)sizeof(W_);
    s->max_bytes_slop = max_slop*(StgWord64)sizeof(W_);
    s->current_bytes_used = current_residency*(StgWord64)sizeof(W_);
    s->current_bytes_slop = current_slop*(StgWord64)sizeof(W_);
    /*
Simon Marlow's avatar
Simon Marlow committed
892 893
    s->init_cpu_seconds = TimeToSecondsDbl(get_init_cpu());
    s->init_wall_seconds = TimeToSecondsDbl(get_init_elapsed());
894
    */
Simon Marlow's avatar
Simon Marlow committed
895 896 897 898
    s->mutator_cpu_seconds = TimeToSecondsDbl(current_cpu - end_init_cpu - gc_cpu - PROF_VAL(RP_tot_time + HC_tot_time));
    s->mutator_wall_seconds = TimeToSecondsDbl(current_elapsed- end_init_elapsed - gc_elapsed);
    s->gc_cpu_seconds = TimeToSecondsDbl(gc_cpu);
    s->gc_wall_seconds = TimeToSecondsDbl(gc_elapsed);
899
    /* EZY: Being consistent with incremental output, but maybe should also discount init */
Simon Marlow's avatar
Simon Marlow committed
900 901
    s->cpu_seconds = TimeToSecondsDbl(current_cpu);
    s->wall_seconds = TimeToSecondsDbl(current_elapsed - end_init_elapsed);
902
    s->par_tot_bytes_copied = GC_par_tot_copied*(StgWord64)sizeof(W_);
903