Stats.c 32 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

Simon Marlow's avatar
Simon Marlow committed
23
#define TimeToSecondsDbl(t) ((double)(t) / TIME_RESOLUTION)
24

Simon Marlow's avatar
Simon Marlow committed
25
static Time
Simon Marlow's avatar
Simon Marlow committed
26 27 28
    start_init_cpu, start_init_elapsed,
    end_init_cpu,   end_init_elapsed,
    start_exit_cpu, start_exit_elapsed,
Simon Marlow's avatar
Simon Marlow committed
29
    start_exit_gc_elapsed, start_exit_gc_cpu,
Simon Marlow's avatar
Simon Marlow committed
30
    end_exit_cpu,   end_exit_elapsed;
31

sof's avatar
sof committed
32
#ifdef PROFILING
Simon Marlow's avatar
Simon Marlow committed
33 34
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
35

Simon Marlow's avatar
Simon Marlow committed
36 37
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
38
#endif
39

sof's avatar
sof committed
40
#ifdef PROFILING
41
#define PROF_VAL(x)   (x)
sof's avatar
sof committed
42 43 44
#else
#define PROF_VAL(x)   0
#endif
45

Simon Marlow's avatar
Simon Marlow committed
46 47 48 49 50 51 52
//
// All the stats!
//
// This is where we accumulate all the stats during execution, and it's also
// in a convenient form that we can copy over to a caller of getRTSStats().
//
static RTSStats stats;
53

54
static W_ GC_end_faults = 0;
55

Simon Marlow's avatar
Simon Marlow committed
56 57 58
static Time *GC_coll_cpu = NULL;
static Time *GC_coll_elapsed = NULL;
static Time *GC_coll_max_pause = NULL;
59

Ben Gamari's avatar
Ben Gamari committed
60
static void statsPrintf( char *s, ... ) GNUC3_ATTRIBUTE(format (PRINTF, 1, 2));
61 62 63
static void statsFlush( void );
static void statsClose( void );

Simon Marlow's avatar
Simon Marlow committed
64 65 66
/* -----------------------------------------------------------------------------
   Current elapsed time
   ------------------------------------------------------------------------- */
sof's avatar
sof committed
67

Simon Marlow's avatar
Simon Marlow committed
68
Time stat_getElapsedTime(void)
Simon Marlow's avatar
Simon Marlow committed
69
{
Simon Marlow's avatar
Simon Marlow committed
70
    return getProcessElapsedTime() - start_init_elapsed;
Simon Marlow's avatar
Simon Marlow committed
71 72
}

Simon Marlow's avatar
Simon Marlow committed
73 74 75
/* ---------------------------------------------------------------------------
   Measure the current MUT time, for profiling
   ------------------------------------------------------------------------ */
76

Ian Lynagh's avatar
Ian Lynagh committed
77
double
Simon Marlow's avatar
Simon Marlow committed
78
mut_user_time_until( Time t )
Ian Lynagh's avatar
Ian Lynagh committed
79
{
Simon Marlow's avatar
Simon Marlow committed
80
    return TimeToSecondsDbl(t - stats.gc_cpu_ns);
81 82
    // heapCensus() time is included in GC_tot_cpu, so we don't need
    // to subtract it here.
Ian Lynagh's avatar
Ian Lynagh committed
83 84
}

85
double
86
mut_user_time( void )
87
{
Simon Marlow's avatar
Simon Marlow committed
88
    Time cpu;
Simon Marlow's avatar
Simon Marlow committed
89
    cpu = getProcessCPUTime();
Ian Lynagh's avatar
Ian Lynagh committed
90
    return mut_user_time_until(cpu);
91 92
}

93
#ifdef PROFILING
94
/*
Simon Marlow's avatar
Simon Marlow committed
95
  mut_user_time_during_RP() returns the MUT time during retainer profiling.
96
  The same is for mut_user_time_during_HC();
97
 */
98
static double
99 100
mut_user_time_during_RP( void )
{
Simon Marlow's avatar
Simon Marlow committed
101
    return TimeToSecondsDbl(RP_start_time - stats.gc_cpu_ns - RP_tot_time);
102 103
}

sof's avatar
sof committed
104
#endif /* PROFILING */
105

Simon Marlow's avatar
Simon Marlow committed
106 107 108 109
/* ---------------------------------------------------------------------------
   initStats0() has no dependencies, it can be called right at the beginning
   ------------------------------------------------------------------------ */

110
void
111 112
initStats0(void)
{
Simon Marlow's avatar
Simon Marlow committed
113 114 115 116
    start_init_cpu    = 0;
    start_init_elapsed = 0;
    end_init_cpu     = 0;
    end_init_elapsed  = 0;
117

Simon Marlow's avatar
Simon Marlow committed
118 119
    start_exit_cpu    = 0;
    start_exit_elapsed = 0;
Simon Marlow's avatar
Simon Marlow committed
120 121
    start_exit_gc_cpu    = 0;
    start_exit_gc_elapsed = 0;
Simon Marlow's avatar
Simon Marlow committed
122 123
    end_exit_cpu     = 0;
    end_exit_elapsed  = 0;
124 125 126 127 128 129 130 131 132 133 134 135 136 137

#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

    GC_end_faults = 0;
Simon Marlow's avatar
Simon Marlow committed
138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173

    stats = (RTSStats) {
        .gcs = 0,
        .major_gcs = 0,
        .allocated_bytes = 0,
        .max_live_bytes = 0,
        .max_large_objects_bytes = 0,
        .max_compact_bytes = 0,
        .max_slop_bytes = 0,
        .max_mem_in_use_bytes = 0,
        .cumulative_live_bytes = 0,
        .copied_bytes = 0,
        .par_copied_bytes = 0,
        .cumulative_par_max_copied_bytes = 0,
        .mutator_cpu_ns = 0,
        .mutator_elapsed_ns = 0,
        .gc_cpu_ns = 0,
        .gc_elapsed_ns = 0,
        .cpu_ns = 0,
        .elapsed_ns = 0,
        .gc = {
            .gen = 0,
            .threads = 0,
            .allocated_bytes = 0,
            .live_bytes = 0,
            .large_objects_bytes = 0,
            .compact_bytes = 0,
            .slop_bytes = 0,
            .mem_in_use_bytes = 0,
            .copied_bytes = 0,
            .par_max_copied_bytes = 0,
            .sync_elapsed_ns = 0,
            .cpu_ns = 0,
            .elapsed_ns = 0
        }
    };
Austin Seipp's avatar
Austin Seipp committed
174
}
175

Simon Marlow's avatar
Simon Marlow committed
176 177 178 179
/* ---------------------------------------------------------------------------
   initStats1() can be called after setupRtsFlags()
   ------------------------------------------------------------------------ */

180 181
void
initStats1 (void)
182
{
183
    uint32_t i;
Austin Seipp's avatar
Austin Seipp committed
184

185
    if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) {
186 187
        statsPrintf("    Alloc    Copied     Live     GC     GC      TOT      TOT  Page Flts\n");
        statsPrintf("    bytes     bytes     bytes   user   elap     user     elap\n");
188
    }
Austin Seipp's avatar
Austin Seipp committed
189 190
    GC_coll_cpu =
        (Time *)stgMallocBytes(
Simon Marlow's avatar
Simon Marlow committed
191
            sizeof(Time)*RtsFlags.GcFlags.generations,
Austin Seipp's avatar
Austin Seipp committed
192 193 194 195 196
            "initStats");
    GC_coll_elapsed =
        (Time *)stgMallocBytes(
            sizeof(Time)*RtsFlags.GcFlags.generations,
            "initStats");
Simon Marlow's avatar
Simon Marlow committed
197
    GC_coll_max_pause =
Austin Seipp's avatar
Austin Seipp committed
198 199 200
        (Time *)stgMallocBytes(
            sizeof(Time)*RtsFlags.GcFlags.generations,
            "initStats");
201
    for (i = 0; i < RtsFlags.GcFlags.generations; i++) {
Austin Seipp's avatar
Austin Seipp committed
202
        GC_coll_cpu[i] = 0;
Simon Marlow's avatar
Simon Marlow committed
203 204
        GC_coll_elapsed[i] = 0;
        GC_coll_max_pause[i] = 0;
205
    }
206
}
207 208 209 210

/* -----------------------------------------------------------------------------
   Initialisation time...
   -------------------------------------------------------------------------- */
211 212

void
213
stat_startInit(void)
214
{
Simon Marlow's avatar
Simon Marlow committed
215
    getProcessTimes(&start_init_cpu, &start_init_elapsed);
216 217
}

Austin Seipp's avatar
Austin Seipp committed
218
void
219
stat_endInit(void)
220
{
Simon Marlow's avatar
Simon Marlow committed
221
    getProcessTimes(&end_init_cpu, &end_init_elapsed);
222 223
}

224 225
/* -----------------------------------------------------------------------------
   stat_startExit and stat_endExit
Austin Seipp's avatar
Austin Seipp committed
226

227 228 229
   These two measure the time taken in shutdownHaskell().
   -------------------------------------------------------------------------- */

230 231 232
void
stat_startExit(void)
{
Simon Marlow's avatar
Simon Marlow committed
233
    getProcessTimes(&start_exit_cpu, &start_exit_elapsed);
Simon Marlow's avatar
Simon Marlow committed
234 235
    start_exit_gc_elapsed = stats.gc_elapsed_ns;
    start_exit_gc_cpu = stats.gc_cpu_ns;
236 237 238 239 240
}

void
stat_endExit(void)
{
Simon Marlow's avatar
Simon Marlow committed
241
    getProcessTimes(&end_exit_cpu, &end_exit_elapsed);
242 243
}

244 245 246 247 248 249
void
stat_startGCSync (gc_thread *gct)
{
    gct->gc_sync_start_elapsed = getProcessElapsedTime();
}

250 251 252 253 254
/* -----------------------------------------------------------------------------
   Called at the beginning of each GC
   -------------------------------------------------------------------------- */

void
255
stat_startGC (Capability *cap, gc_thread *gct)
256
{
Ben Gamari's avatar
Ben Gamari committed
257 258
    if (RtsFlags.GcFlags.ringBell) {
        debugBelch("\007");
259 260
    }

Simon Marlow's avatar
Simon Marlow committed
261
    getProcessTimes(&gct->gc_start_cpu, &gct->gc_start_elapsed);
262 263 264 265 266 267 268 269 270

    // 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
271 272 273 274
    if (RtsFlags.GcFlags.giveStats != NO_GC_STATS)
    {
        gct->gc_start_faults = getPageFaults();
    }
275

Simon Marlow's avatar
Simon Marlow committed
276
    updateNurseriesStats();
277 278
}

279 280 281 282 283
/* -----------------------------------------------------------------------------
   Called at the end of each GC
   -------------------------------------------------------------------------- */

void
284
stat_endGC (Capability *cap, gc_thread *gct,
285
            W_ live, W_ copied, W_ slop, uint32_t gen,
Simon Marlow's avatar
Simon Marlow committed
286
            uint32_t par_n_threads, W_ par_max_copied)
287
{
288
    if (RtsFlags.GcFlags.giveStats != NO_GC_STATS ||
289
        rtsConfig.gcDoneHook != NULL ||
Simon Marlow's avatar
Simon Marlow committed
290
        RtsFlags.ProfFlags.doHeapProfile) // heap profiling needs GC_tot_time
291
    {
Simon Marlow's avatar
Simon Marlow committed
292 293 294 295 296 297 298 299 300 301 302 303 304 305 306 307 308 309 310 311 312 313 314 315 316 317 318 319 320 321 322 323 324 325 326 327 328 329 330 331 332 333 334 335 336 337 338 339 340 341 342 343 344 345 346 347 348 349 350 351 352 353 354 355 356 357 358 359 360 361
        // -------------------------------------------------
        // Collect all the stats about this GC in stats.gc

        stats.gc.gen = gen;
        stats.gc.threads = par_n_threads;

        uint64_t tot_alloc_bytes = calcTotalAllocated() * sizeof(W_);

        // allocated since the last GC
        stats.gc.allocated_bytes = tot_alloc_bytes - stats.allocated_bytes;

        stats.gc.live_bytes = live * sizeof(W_);
        stats.gc.large_objects_bytes = calcTotalLargeObjectsW() * sizeof(W_);
        stats.gc.compact_bytes = calcTotalCompactW() * sizeof(W_);
        stats.gc.slop_bytes = slop * sizeof(W_);
        stats.gc.mem_in_use_bytes = mblocks_allocated * MBLOCK_SIZE;
        stats.gc.copied_bytes = copied * sizeof(W_);
        stats.gc.par_max_copied_bytes = par_max_copied * sizeof(W_);

        Time current_cpu, current_elapsed;
        getProcessTimes(&current_cpu, &current_elapsed);
        stats.cpu_ns = current_cpu - start_init_cpu;
        stats.elapsed_ns = current_elapsed - start_init_elapsed;

        stats.gc.sync_elapsed_ns =
          gct->gc_start_elapsed - gct->gc_sync_start_elapsed;
        stats.gc.elapsed_ns = current_elapsed - gct->gc_start_elapsed;
        stats.gc.cpu_ns = current_cpu - gct->gc_start_cpu;

        // -------------------------------------------------
        // Update the cumulative stats

        stats.gcs++;
        stats.allocated_bytes = tot_alloc_bytes;
        stats.max_mem_in_use_bytes = peak_mblocks_allocated * MBLOCK_SIZE;

        GC_coll_cpu[gen] += stats.gc.cpu_ns;
        GC_coll_elapsed[gen] += stats.gc.elapsed_ns;
        if (GC_coll_max_pause[gen] < stats.gc.elapsed_ns) {
            GC_coll_max_pause[gen] = stats.gc.elapsed_ns;
        }

        stats.copied_bytes += stats.gc.copied_bytes;
        if (par_n_threads > 1) {
            stats.par_copied_bytes += stats.gc.copied_bytes;
            stats.cumulative_par_max_copied_bytes +=
                stats.gc.par_max_copied_bytes;
        }
        stats.gc_cpu_ns += stats.gc.cpu_ns;
        stats.gc_elapsed_ns += stats.gc.elapsed_ns;

        if (gen == RtsFlags.GcFlags.generations-1) { // major GC?
            stats.major_gcs++;
            if (stats.gc.live_bytes > stats.max_live_bytes) {
                stats.max_live_bytes = stats.gc.live_bytes;
            }
            if (stats.gc.large_objects_bytes > stats.max_large_objects_bytes) {
                stats.max_large_objects_bytes = stats.gc.large_objects_bytes;
            }
            if (stats.gc.compact_bytes > stats.max_compact_bytes) {
                stats.max_compact_bytes = stats.gc.compact_bytes;
            }
            if (stats.gc.slop_bytes > stats.max_slop_bytes) {
                stats.max_slop_bytes = stats.gc.slop_bytes;
            }
            stats.cumulative_live_bytes += stats.gc.live_bytes;
        }

        // -------------------------------------------------
        // Emit events to the event log
362

363 364 365 366 367
        // 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
368

369
        // Emitted before GC_END on all caps, which simplifies tools code.
370 371
        traceEventGcStats(cap,
                          CAPSET_HEAP_DEFAULT,
Simon Marlow's avatar
Simon Marlow committed
372 373 374
                          stats.gc.gen,
                          stats.gc.copied_bytes,
                          stats.gc.slop_bytes,
375 376
                          /* current loss due to fragmentation */
                          (mblocks_allocated * BLOCKS_PER_MBLOCK - n_alloc_blocks)
377
                                 * BLOCK_SIZE,
378
                          par_n_threads,
Simon Marlow's avatar
Simon Marlow committed
379 380
                          stats.gc.par_max_copied_bytes,
                          stats.gc.copied_bytes);
Simon Marlow's avatar
Simon Marlow committed
381

382 383 384 385 386
        // 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.
Simon Marlow's avatar
Simon Marlow committed
387
        traceEventGcEndAtT(cap, TimeToNS(stats.elapsed_ns));
Simon Marlow's avatar
Simon Marlow committed
388

Simon Marlow's avatar
Simon Marlow committed
389 390 391 392 393
        if (gen == RtsFlags.GcFlags.generations-1) { // major GC?
            traceEventHeapLive(cap,
                               CAPSET_HEAP_DEFAULT,
                               stats.gc.live_bytes);
        }
394

Simon Marlow's avatar
Simon Marlow committed
395 396
        // -------------------------------------------------
        // Print GC stats to stdout or a file (+RTS -S/-s)
397

Simon Marlow's avatar
Simon Marlow committed
398
        if (RtsFlags.GcFlags.giveStats == VERBOSE_GC_STATS) {
Austin Seipp's avatar
Austin Seipp committed
399 400
            W_ faults = getPageFaults();

401
            statsPrintf("%9" FMT_Word " %9" FMT_Word " %9" FMT_Word,
Simon Marlow's avatar
Simon Marlow committed
402 403 404 405 406 407 408 409 410
                        stats.gc.allocated_bytes, stats.gc.copied_bytes,
                        stats.gc.live_bytes);

            statsPrintf(" %6.3f %6.3f %8.3f %8.3f %4"
                        FMT_Word " %4" FMT_Word "  (Gen: %2d)\n",
                    TimeToSecondsDbl(stats.gc.cpu_ns),
                    TimeToSecondsDbl(stats.gc.elapsed_ns),
                    TimeToSecondsDbl(stats.cpu_ns),
                    TimeToSecondsDbl(stats.elapsed_ns),
Austin Seipp's avatar
Austin Seipp committed
411
                    faults - gct->gc_start_faults,
Simon Marlow's avatar
Simon Marlow committed
412 413 414 415
                        gct->gc_start_faults - GC_end_faults,
                    gen);

            GC_end_faults = faults;
Austin Seipp's avatar
Austin Seipp committed
416 417
            statsFlush();
        }
418

419 420

        if (rtsConfig.gcDoneHook != NULL) {
Simon Marlow's avatar
Simon Marlow committed
421
            rtsConfig.gcDoneHook(&stats.gc);
Simon Marlow's avatar
Simon Marlow committed
422
        }
423

424
        traceEventHeapSize(cap,
Austin Seipp's avatar
Austin Seipp committed
425
                           CAPSET_HEAP_DEFAULT,
Simon Marlow's avatar
Simon Marlow committed
426
                           mblocks_allocated * MBLOCK_SIZE);
427 428 429
    }
}

430 431 432
/* -----------------------------------------------------------------------------
   Called at the beginning of each Retainer Profiliing
   -------------------------------------------------------------------------- */
433 434 435
#ifdef PROFILING
void
stat_startRP(void)
436
{
Simon Marlow's avatar
Simon Marlow committed
437
    Time user, elapsed;
438
    getProcessTimes( &user, &elapsed );
439 440 441

    RP_start_time = user;
    RPe_start_time = elapsed;
442
}
sof's avatar
sof committed
443
#endif /* PROFILING */
444 445 446 447

/* -----------------------------------------------------------------------------
   Called at the end of each Retainer Profiliing
   -------------------------------------------------------------------------- */
448 449 450 451

#ifdef PROFILING
void
stat_endRP(
452
  uint32_t retainerGeneration,
453
#ifdef DEBUG_RETAINER
454
  uint32_t maxCStackSize,
455 456
  int maxStackSize,
#endif
457
  double averageNumVisit)
458
{
Simon Marlow's avatar
Simon Marlow committed
459
    Time user, elapsed;
460
    getProcessTimes( &user, &elapsed );
461 462 463

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

Austin Seipp's avatar
Austin Seipp committed
465
  fprintf(prof_file, "Retainer Profiling: %d, at %f seconds\n",
466 467 468 469 470 471 472
    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
473
#endif /* PROFILING */
474 475

/* -----------------------------------------------------------------------------
476
   Called at the beginning of each heap census
477
   -------------------------------------------------------------------------- */
478 479
#ifdef PROFILING
void
480
stat_startHeapCensus(void)
481
{
Simon Marlow's avatar
Simon Marlow committed
482
    Time user, elapsed;
483
    getProcessTimes( &user, &elapsed );
484 485 486

    HC_start_time = user;
    HCe_start_time = elapsed;
487
}
sof's avatar
sof committed
488
#endif /* PROFILING */
489 490

/* -----------------------------------------------------------------------------
491
   Called at the end of each heap census
492
   -------------------------------------------------------------------------- */
493 494
#ifdef PROFILING
void
Austin Seipp's avatar
Austin Seipp committed
495
stat_endHeapCensus(void)
496
{
Simon Marlow's avatar
Simon Marlow committed
497
    Time user, elapsed;
498
    getProcessTimes( &user, &elapsed );
499 500 501

    HC_tot_time += user - HC_start_time;
    HCe_tot_time += elapsed - HCe_start_time;
502
}
sof's avatar
sof committed
503
#endif /* PROFILING */
504

505 506 507 508 509 510 511 512
/* -----------------------------------------------------------------------------
   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
513 514 515 516 517 518 519 520 521 522 523 524 525 526 527
#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) \
  { \
Ben Gamari's avatar
Ben Gamari committed
528
    showStgWord64(counter,temp,true/*commas*/); \
Austin Seipp's avatar
Austin Seipp committed
529
    statsPrintf("  (" #counter ")  : %s\n",temp);                               \
Simon Marlow's avatar
Simon Marlow committed
530 531 532 533 534
  }

/* 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
535
              counter*100.0/countertot)
Simon Marlow's avatar
Simon Marlow committed
536 537 538 539 540 541 542 543 544 545

#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
546
              SLOW_CALLS_##arity * 100.0/TOTAL_CALLS)
Simon Marlow's avatar
Simon Marlow committed
547

Simon Marlow's avatar
Simon Marlow committed
548 549 550 551 552 553 554
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;
}
555

556

557
void
558
stat_exit (void)
559
{
Simon Marlow's avatar
Simon Marlow committed
560
    generation *gen;
Simon Marlow's avatar
Simon Marlow committed
561 562 563 564 565 566 567 568
    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;
Simon Marlow's avatar
Simon Marlow committed
569 570
    Time exit_gc_cpu = 0;
    Time exit_gc_elapsed = 0;
Simon Marlow's avatar
Simon Marlow committed
571

572
    if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
573

Simon Marlow's avatar
Simon Marlow committed
574
        char temp[512];
Austin Seipp's avatar
Austin Seipp committed
575 576
        Time tot_cpu;
        Time tot_elapsed;
Simon Marlow's avatar
Simon Marlow committed
577
        uint32_t g;
578

Austin Seipp's avatar
Austin Seipp committed
579
        getProcessTimes( &tot_cpu, &tot_elapsed );
Simon Marlow's avatar
Simon Marlow committed
580
        tot_cpu -= start_init_cpu;
Austin Seipp's avatar
Austin Seipp committed
581
        tot_elapsed -= start_init_elapsed;
582

Simon Marlow's avatar
Simon Marlow committed
583
        uint64_t tot_alloc_bytes = calcTotalAllocated() * sizeof(W_);
584

585
        // allocated since the last GC
Simon Marlow's avatar
Simon Marlow committed
586 587
        stats.gc.allocated_bytes = tot_alloc_bytes - stats.allocated_bytes;
        stats.allocated_bytes = tot_alloc_bytes;
588

Austin Seipp's avatar
Austin Seipp committed
589
        /* avoid divide by zero if tot_cpu is measured as 0.00 seconds -- SDM */
Simon Marlow's avatar
Simon Marlow committed
590 591
        if (tot_cpu <= 0)  tot_cpu = 1;
        if (tot_elapsed <= 0) tot_elapsed = 1;
Austin Seipp's avatar
Austin Seipp committed
592 593

        if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) {
Simon Marlow's avatar
Simon Marlow committed
594 595
            statsPrintf("%9" FMT_Word " %9.9s %9.9s",
                        (W_)stats.gc.allocated_bytes, "", "");
Austin Seipp's avatar
Austin Seipp committed
596 597
            statsPrintf(" %6.3f %6.3f\n\n", 0.0, 0.0);
        }
598

599 600
        // 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
601
        // obtain the actual GC cpu time.
Simon Marlow's avatar
Simon Marlow committed
602 603
        gc_cpu     = stats.gc_cpu_ns - PROF_VAL(RP_tot_time + HC_tot_time);
        gc_elapsed = stats.gc_elapsed_ns - PROF_VAL(RPe_tot_time + HCe_tot_time);
604

605 606
        init_cpu     = get_init_cpu();
        init_elapsed = get_init_elapsed();
dmp's avatar
dmp committed
607

Simon Marlow's avatar
Simon Marlow committed
608 609 610 611 612 613
        // We do a GC during the EXIT phase.  We'll attribute the cost of that
        // to GC instead of EXIT, so carefully subtract it from the EXIT time.
        exit_gc_cpu  = stats.gc_cpu_ns - start_exit_gc_cpu;
        exit_gc_elapsed = stats.gc_elapsed_ns - start_exit_gc_elapsed;
        exit_cpu     = end_exit_cpu - start_exit_cpu - exit_gc_cpu;
        exit_elapsed = end_exit_elapsed - start_exit_elapsed - exit_gc_elapsed;
dmp's avatar
dmp committed
614

Simon Marlow's avatar
Simon Marlow committed
615 616
        mut_elapsed = start_exit_elapsed - end_init_elapsed -
            (gc_elapsed - exit_gc_elapsed);
dmp's avatar
dmp committed
617

Simon Marlow's avatar
Simon Marlow committed
618
        mut_cpu = start_exit_cpu - end_init_cpu - (gc_cpu - exit_gc_cpu)
dmp's avatar
dmp committed
619 620 621
            - PROF_VAL(RP_tot_time + HC_tot_time);
        if (mut_cpu < 0) { mut_cpu = 0; }

Simon Marlow's avatar
Simon Marlow committed
622 623 624 625 626 627 628 629
        // The subdivision of runtime into INIT/EXIT/GC/MUT is just adding and
        // subtracting, so the parts should add up to the total exactly.  Note
        // that tot_elapsed is captured a tiny bit later than end_exit_elapsed,
        // so we don't use it here.
        ASSERT(init_elapsed + mut_elapsed + gc_elapsed + exit_elapsed
               == end_exit_elapsed - start_init_elapsed);


Austin Seipp's avatar
Austin Seipp committed
630
        if (RtsFlags.GcFlags.giveStats >= SUMMARY_GC_STATS) {
Simon Marlow's avatar
Simon Marlow committed
631
            showStgWord64(stats.allocated_bytes, temp, true/*commas*/);
Austin Seipp's avatar
Austin Seipp committed
632
            statsPrintf("%16s bytes allocated in the heap\n", temp);
633

Simon Marlow's avatar
Simon Marlow committed
634
            showStgWord64(stats.copied_bytes, temp, true/*commas*/);
Austin Seipp's avatar
Austin Seipp committed
635
            statsPrintf("%16s bytes copied during GC\n", temp);
636

Simon Marlow's avatar
Simon Marlow committed
637 638 639 640 641
            if ( stats.major_gcs > 0 ) {
                showStgWord64(stats.max_live_bytes, temp, true/*commas*/);
                statsPrintf("%16s bytes maximum residency (%" FMT_Word32
                            " sample(s))\n",
                            temp, stats.major_gcs);
Austin Seipp's avatar
Austin Seipp committed
642
            }
643

Simon Marlow's avatar
Simon Marlow committed
644
            showStgWord64(stats.max_slop_bytes, temp, true/*commas*/);
Austin Seipp's avatar
Austin Seipp committed
645
            statsPrintf("%16s bytes maximum slop\n", temp);
646

Simon Marlow's avatar
Simon Marlow committed
647 648
            statsPrintf("%16" FMT_SizeT " MB total memory in use (%"
                        FMT_SizeT " MB lost due to fragmentation)\n\n",
649 650
                        (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_)));
651

Austin Seipp's avatar
Austin Seipp committed
652
            /* Print garbage collections in each gen */
653
            statsPrintf("                                     Tot time (elapsed)  Avg pause  Max pause\n");
Simon Marlow's avatar
Simon Marlow committed
654 655
            for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
                gen = &generations[g];
656
                statsPrintf("  Gen %2d     %5d colls, %5d par   %6.3fs  %6.3fs     %3.4fs    %3.4fs\n",
Simon Marlow's avatar
Simon Marlow committed
657 658 659
                            gen->no,
                            gen->collections,
                            gen->par_collections,
Simon Marlow's avatar
Simon Marlow committed
660 661 662 663
                            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
664
            }
665

666
#if defined(THREADED_RTS)
667
            if (RtsFlags.ParFlags.parGcEnabled && n_capabilities > 1) {
Austin Seipp's avatar
Austin Seipp committed
668
                statsPrintf("\n  Parallel GC work balance: %.2f%% (serial 0%%, perfect 100%%)\n",
Simon Marlow's avatar
Simon Marlow committed
669
                            100 * (((double)stats.par_copied_bytes / (double)stats.cumulative_par_max_copied_bytes) - 1)
670
                                / (n_capabilities - 1)
671 672 673
                    );
            }
#endif
Simon Marlow's avatar
Simon Marlow committed
674
            statsPrintf("\n");
675

676
#if defined(THREADED_RTS)
677 678 679 680
            statsPrintf("  TASKS: %d (%d bound, %d peak workers (%d total), using -N%d)\n",
                        taskCount, taskCount - workerCount,
                        peakWorkerCount, workerCount,
                        n_capabilities);
681

Austin Seipp's avatar
Austin Seipp committed
682
            statsPrintf("\n");
683

684
            {
685
                uint32_t i;
686
                SparkCounters sparks = { 0, 0, 0, 0, 0, 0};
687
                for (i = 0; i < n_capabilities; i++) {
688 689 690 691 692 693
                    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;
694 695
                }

Ian Lynagh's avatar
Ian Lynagh committed
696
                statsPrintf("  SPARKS: %" FMT_Word " (%" FMT_Word " converted, %" FMT_Word " overflowed, %" FMT_Word " dud, %" FMT_Word " GC'd, %" FMT_Word " fizzled)\n\n",
697 698
                            sparks.created + sparks.dud + sparks.overflowed,
                            sparks.converted, sparks.overflowed, sparks.dud,
699
                            sparks.gcd, sparks.fizzled);
700
            }
701 702
#endif

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

706
            statsPrintf("  MUT     time  %7.3fs  (%7.3fs elapsed)\n",
Simon Marlow's avatar
Simon Marlow committed
707
                        TimeToSecondsDbl(mut_cpu), TimeToSecondsDbl(mut_elapsed));
708
            statsPrintf("  GC      time  %7.3fs  (%7.3fs elapsed)\n",
Simon Marlow's avatar
Simon Marlow committed
709
                        TimeToSecondsDbl(gc_cpu), TimeToSecondsDbl(gc_elapsed));
Simon Marlow's avatar
Simon Marlow committed
710

711
#ifdef PROFILING
Austin Seipp's avatar
Austin Seipp committed
712 713 714 715 716 717 718 719 720
            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
721
#ifndef THREADED_RTS
Austin Seipp's avatar
Austin Seipp committed
722 723 724
            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
725 726
#endif

Simon Marlow's avatar
Simon Marlow committed
727
            if (mut_cpu == 0) {
Ben Gamari's avatar
Ben Gamari committed
728
                showStgWord64(0, temp, true/*commas*/);
Simon Marlow's avatar
Simon Marlow committed
729
            } else {
Austin Seipp's avatar
Austin Seipp committed
730
                showStgWord64(
Simon Marlow's avatar
Simon Marlow committed
731 732
                    (StgWord64)((double)stats.allocated_bytes /
                                TimeToSecondsDbl(mut_cpu)),
Ben Gamari's avatar
Ben Gamari committed
733
                    temp, true/*commas*/);
Simon Marlow's avatar
Simon Marlow committed
734 735
            }

Austin Seipp's avatar
Austin Seipp committed
736 737 738
            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
739
                    TimeToSecondsDbl(tot_cpu - gc_cpu -
Austin Seipp's avatar
Austin Seipp committed
740 741
                                PROF_VAL(RP_tot_time + HC_tot_time) - init_cpu) * 100
                    / TimeToSecondsDbl(tot_cpu),
742 743
                    TimeToSecondsDbl(tot_elapsed - gc_elapsed -
                                PROF_VAL(RPe_tot_time + HCe_tot_time) - init_elapsed) * 100
Simon Marlow's avatar
Simon Marlow committed
744
                    / TimeToSecondsDbl(tot_elapsed));
Simon Marlow's avatar
Simon Marlow committed
745

746 747
#if defined(THREADED_RTS) && defined(PROF_SPIN)
            {
748
                uint32_t g;
Austin Seipp's avatar
Austin Seipp committed
749

750
                statsPrintf("gc_alloc_block_sync: %"FMT_Word64"\n", gc_alloc_block_sync.spin);
751
                statsPrintf("whitehole_spin: %"FMT_Word64"\n", whitehole_spin);
752
                for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
Simon Marlow's avatar
Simon Marlow committed
753
                    statsPrintf("gen[%d].sync: %"FMT_Word64"\n", g, generations[g].sync.spin);
754 755
                }
            }
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
756
#endif
Austin Seipp's avatar
Austin Seipp committed
757
        }
758

Austin Seipp's avatar
Austin Seipp committed
759
        if (RtsFlags.GcFlags.giveStats == ONELINE_GC_STATS) {
Ian Lynagh's avatar
Ian Lynagh committed
760 761 762 763 764 765 766 767
      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"
768 769 770 771 772 773
                 " ,(\"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
774 775 776 777
                 " ]\n";
      }
      else {
          fmt1 = "<<ghc: %llu bytes, ";
778
          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
779
      }
Austin Seipp's avatar
Austin Seipp committed
780
          /* print the long long separately to avoid bugginess on mingwin (2001-07-02, mingw-0.5) */
Simon Marlow's avatar
Simon Marlow committed
781
          statsPrintf(fmt1, stats.allocated_bytes);
Austin Seipp's avatar
Austin Seipp committed
782
          statsPrintf(fmt2,
Simon Marlow's avatar
Simon Marlow committed
783 784 785 786 787
                    stats.gcs,
                    stats.major_gcs == 0 ? 0 :
                        stats.cumulative_live_bytes/stats.major_gcs,
                    stats.max_live_bytes,
                    stats.major_gcs,
Austin Seipp's avatar
Austin Seipp committed
788 789 790 791 792 793 794 795
                    (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();
796
    }
simonmarhaskell@gmail.com's avatar
simonmarhaskell@gmail.com committed
797

Simon Marlow's avatar
Simon Marlow committed
798
    if (GC_coll_cpu) {
Simon Marlow's avatar
Simon Marlow committed
799
      stgFree(GC_coll_cpu);
Simon Marlow's avatar
Simon Marlow committed
800 801 802
      GC_coll_cpu = NULL;
    }
    if (GC_coll_elapsed) {
Simon Marlow's avatar
Simon Marlow committed
803
      stgFree(GC_coll_elapsed);
Simon Marlow's avatar
Simon Marlow committed
804 805 806 807 808 809
      GC_coll_elapsed = NULL;
    }
    if (GC_coll_max_pause) {
      stgFree(GC_coll_max_pause);
      GC_coll_max_pause = NULL;
    }
810
}
811 812 813 814 815 816 817

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

   Produce some detailed info on the state of the generational GC.
   -------------------------------------------------------------------------- */
void
818
statDescribeGens(void)
819
{
820
  uint32_t g, mut, lge, i;
821 822 823
  W_ gen_slop;
  W_ tot_live, tot_slop;
  W_ gen_live, gen_blocks;
824
  bdescr *bd;
Simon Marlow's avatar
Simon Marlow committed
825
  generation *gen;
Austin Seipp's avatar
Austin Seipp committed
826

827
  debugBelch(
Simon Marlow's avatar
Simon Marlow committed
828 829 830 831
"----------------------------------------------------------\n"
"  Gen     Max  Mut-list  Blocks    Large     Live     Slop\n"
"       Blocks     Bytes          Objects                  \n"
"----------------------------------------------------------\n");
832

833 834
  tot_live = 0;
  tot_slop = 0;
Simon Marlow's avatar
Simon Marlow committed
835

836
  for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
Simon Marlow's avatar
Simon Marlow committed
837 838 839 840 841 842 843 844 845
      gen = &generations[g];

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

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

846
      mut = 0;
847
      for (i = 0; i < n_capabilities; i++) {
848
          mut += countOccupied(capabilities[i]->mut_lists[g]);
849 850

          // Add the pinned object block.
851
          bd = capabilities[i]->pinned_object_block;
852 853 854 855 856
          if (bd != NULL) {
              gen_live   += bd->free - bd->start;
              gen_blocks += bd->blocks;
          }