Stats.c 26.1 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 "RtsUtils.h"
13
#include "Schedule.h"
14
#include "Stats.h"
15
#include "Profiling.h"
16
#include "GetTime.h"
Simon Marlow's avatar
Simon Marlow committed
17
#include "sm/Storage.h"
18
#include "sm/GC.h" // gc_alloc_block_sync, whitehole_spin
Simon Marlow's avatar
Simon Marlow committed
19 20
#include "sm/GCThread.h"
#include "sm/BlockAlloc.h"
21

mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
22 23 24 25
#if USE_PAPI
#include "Papi.h"
#endif

26 27 28
/* huh? */
#define BIG_STRING_LEN              512

29
#define TICK_TO_DBL(t) ((double)(t) / TICKS_PER_SECOND)
30

Simon Marlow's avatar
Simon Marlow committed
31 32 33 34 35
static Ticks
    start_init_cpu, start_init_elapsed,
    end_init_cpu,   end_init_elapsed,
    start_exit_cpu, start_exit_elapsed,
    end_exit_cpu,   end_exit_elapsed;
36

Simon Marlow's avatar
Simon Marlow committed
37
static Ticks GC_tot_cpu  = 0;
38

Simon Marlow's avatar
Simon Marlow committed
39 40
static StgWord64 GC_tot_alloc      = 0;
static StgWord64 GC_tot_copied     = 0;
41

Ian Lynagh's avatar
Ian Lynagh committed
42 43
static StgWord64 GC_par_max_copied = 0;
static StgWord64 GC_par_avg_copied = 0;
44

sof's avatar
sof committed
45
#ifdef PROFILING
Simon Marlow's avatar
Simon Marlow committed
46 47
static Ticks RP_start_time  = 0, RP_tot_time  = 0;  // retainer prof user time
static Ticks RPe_start_time = 0, RPe_tot_time = 0;  // retainer prof elap time
sof's avatar
sof committed
48

49 50
static Ticks HC_start_time, HC_tot_time = 0;     // heap census prof user time
static Ticks HCe_start_time, HCe_tot_time = 0;   // heap census prof elap time
sof's avatar
sof committed
51
#endif
52

sof's avatar
sof committed
53
#ifdef PROFILING
54
#define PROF_VAL(x)   (x)
sof's avatar
sof committed
55 56 57
#else
#define PROF_VAL(x)   0
#endif
58

Simon Marlow's avatar
Simon Marlow committed
59
static lnat max_residency     = 0; // in words; for stats only
60
static lnat cumulative_residency = 0;
Simon Marlow's avatar
Simon Marlow committed
61 62
static lnat residency_samples = 0; // for stats only
static lnat max_slop          = 0;
63

Simon Marlow's avatar
Simon Marlow committed
64
static lnat GC_end_faults = 0;
65

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

70 71 72
static void statsFlush( void );
static void statsClose( void );

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

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

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

Ian Lynagh's avatar
Ian Lynagh committed
86 87 88
double
mut_user_time_until( Ticks t )
{
89
    return TICK_TO_DBL(t - GC_tot_cpu - PROF_VAL(RP_tot_time));
Ian Lynagh's avatar
Ian Lynagh committed
90 91
}

92
double
93
mut_user_time( void )
94
{
Simon Marlow's avatar
Simon Marlow committed
95 96
    Ticks cpu;
    cpu = getProcessCPUTime();
Ian Lynagh's avatar
Ian Lynagh committed
97
    return mut_user_time_until(cpu);
98 99
}

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

double
112
mut_user_time_during_heap_census( void )
113
{
114
  return TICK_TO_DBL(HC_start_time - GC_tot_cpu - RP_tot_time);
115
}
sof's avatar
sof committed
116
#endif /* PROFILING */
117

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

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

Simon Marlow's avatar
Simon Marlow committed
130 131 132 133
    start_exit_cpu    = 0;
    start_exit_elapsed = 0;
    end_exit_cpu     = 0;
    end_exit_elapsed  = 0;
134 135 136 137 138

    GC_tot_alloc     = 0;
    GC_tot_copied    = 0;
    GC_par_max_copied = 0;
    GC_par_avg_copied = 0;
Simon Marlow's avatar
Simon Marlow committed
139
    GC_tot_cpu  = 0;
140 141 142 143 144 145 146 147 148 149 150 151 152

#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
153
    max_residency = 0;
154
    cumulative_residency = 0;
Simon Marlow's avatar
Simon Marlow committed
155 156
    residency_samples = 0;
    max_slop = 0;
157 158 159 160

    GC_end_faults = 0;
}    

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

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

/* -----------------------------------------------------------------------------
   Initialisation time...
   -------------------------------------------------------------------------- */
196 197

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

void 
204
stat_endInit(void)
205
{
Simon Marlow's avatar
Simon Marlow committed
206
    getProcessTimes(&end_init_cpu, &end_init_elapsed);
207

mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
208 209 210 211 212 213 214 215 216 217
#if USE_PAPI
    /* We start counting events for the mutator
     * when garbage collection starts
     * we switch to the GC event set. */
    papi_start_mutator_count();

    /* This flag is needed to avoid counting the last GC */
    papi_is_reporting = 1;

#endif
218 219
}

220 221 222 223 224 225
/* -----------------------------------------------------------------------------
   stat_startExit and stat_endExit
   
   These two measure the time taken in shutdownHaskell().
   -------------------------------------------------------------------------- */

226 227 228
void
stat_startExit(void)
{
Simon Marlow's avatar
Simon Marlow committed
229
    getProcessTimes(&start_exit_cpu, &start_exit_elapsed);
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
230 231 232 233 234 235 236 237 238

#if USE_PAPI
    /* We stop counting mutator events
     * GC events are not being counted at this point */
    papi_stop_mutator_count();

    /* This flag is needed, because GC is run once more after this function */
    papi_is_reporting = 0;
#endif
239 240 241 242 243
}

void
stat_endExit(void)
{
Simon Marlow's avatar
Simon Marlow committed
244
    getProcessTimes(&end_exit_cpu, &end_exit_elapsed);
245 246
}

247 248 249 250 251 252 253
/* -----------------------------------------------------------------------------
   Called at the beginning of each GC
   -------------------------------------------------------------------------- */

static nat rub_bell = 0;

void
Simon Marlow's avatar
Simon Marlow committed
254
stat_startGC (gc_thread *gct)
255 256 257 258 259
{
    nat bell = RtsFlags.GcFlags.ringBell;

    if (bell) {
	if (bell > 1) {
260
	    debugBelch(" GC ");
261 262
	    rub_bell = 1;
	} else {
263
	    debugBelch("\007");
264 265 266
	}
    }

mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
267 268 269 270 271 272 273 274
#if USE_PAPI
    if(papi_is_reporting) {
      /* Switch to counting GC events */
      papi_stop_mutator_count();
      papi_start_gc_count();
    }
#endif

Simon Marlow's avatar
Simon Marlow committed
275 276 277 278 279 280 281 282 283 284 285 286 287 288 289 290 291 292 293 294 295 296 297 298 299 300 301 302 303 304 305 306 307 308
    getProcessTimes(&gct->gc_start_cpu, &gct->gc_start_elapsed);
    gct->gc_start_thread_cpu  = getThreadCPUTime();

    if (RtsFlags.GcFlags.giveStats != NO_GC_STATS)
    {
        gct->gc_start_faults = getPageFaults();
    }
}

void
stat_gcWorkerThreadStart (gc_thread *gct)
{
    if (RtsFlags.GcFlags.giveStats != NO_GC_STATS)
    {
        getProcessTimes(&gct->gc_start_cpu, &gct->gc_start_elapsed);
        gct->gc_start_thread_cpu  = getThreadCPUTime();
    }
}

void
stat_gcWorkerThreadDone (gc_thread *gct)
{
    Ticks thread_cpu, elapsed, gc_cpu, gc_elapsed;

    if (RtsFlags.GcFlags.giveStats != NO_GC_STATS)
    {
        elapsed    = getProcessElapsedTime();
        thread_cpu = getThreadCPUTime();

        gc_cpu     = thread_cpu - gct->gc_start_thread_cpu;
        gc_elapsed = elapsed    - gct->gc_start_elapsed;
    
        taskDoneGC(gct->cap->running_task, gc_cpu, gc_elapsed);
    }
309 310 311 312 313 314 315
}

/* -----------------------------------------------------------------------------
   Called at the end of each GC
   -------------------------------------------------------------------------- */

void
Simon Marlow's avatar
Simon Marlow committed
316 317
stat_endGC (gc_thread *gct,
            lnat alloc, lnat live, lnat copied, nat gen,
318
            lnat max_copied, lnat avg_copied, lnat slop)
319
{
320 321 322 323
    if (RtsFlags.GcFlags.giveStats != NO_GC_STATS ||
        RtsFlags.ProfFlags.doHeapProfile)
        // heap profiling needs GC_tot_time
    {
Simon Marlow's avatar
Simon Marlow committed
324
        Ticks cpu, elapsed, thread_gc_cpu, gc_cpu, gc_elapsed;
325
	
Simon Marlow's avatar
Simon Marlow committed
326 327 328 329 330 331 332 333 334 335
        getProcessTimes(&cpu, &elapsed);
        gc_elapsed    = elapsed - gct->gc_start_elapsed;

        thread_gc_cpu = getThreadCPUTime() - gct->gc_start_thread_cpu;

        gc_cpu = cpu - gct->gc_start_cpu;

        taskDoneGC(gct->cap->running_task, thread_gc_cpu, gc_elapsed);

        if (RtsFlags.GcFlags.giveStats == VERBOSE_GC_STATS) {
336
	    nat faults = getPageFaults();
337
	    
338
	    statsPrintf("%9ld %9ld %9ld",
339
		    alloc*sizeof(W_), copied*sizeof(W_), 
340
			live*sizeof(W_));
Simon Marlow's avatar
Simon Marlow committed
341 342 343 344 345 346 347 348 349 350
            statsPrintf(" %5.2f %5.2f %7.2f %7.2f %4ld %4ld  (Gen: %2d)\n",
                    TICK_TO_DBL(gc_cpu),
		    TICK_TO_DBL(gc_elapsed),
		    TICK_TO_DBL(cpu),
		    TICK_TO_DBL(elapsed - start_init_elapsed),
		    faults - gct->gc_start_faults,
                        gct->gc_start_faults - GC_end_faults,
                    gen);

            GC_end_faults = faults;
351
	    statsFlush();
352 353
	}

Simon Marlow's avatar
Simon Marlow committed
354 355 356 357 358
        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;
        }
359

Ian Lynagh's avatar
Ian Lynagh committed
360 361 362 363
	GC_tot_copied += (StgWord64) copied;
	GC_tot_alloc  += (StgWord64) alloc;
        GC_par_max_copied += (StgWord64) max_copied;
        GC_par_avg_copied += (StgWord64) avg_copied;
Simon Marlow's avatar
Simon Marlow committed
364
	GC_tot_cpu   += gc_cpu;
365

366
	if (gen == RtsFlags.GcFlags.generations-1) { /* major GC? */
Simon Marlow's avatar
Simon Marlow committed
367 368
	    if (live > max_residency) {
		max_residency = live;
369
	    }
Simon Marlow's avatar
Simon Marlow committed
370
	    residency_samples++;
371
	    cumulative_residency += live;
372
	}
373

Simon Marlow's avatar
Simon Marlow committed
374
        if (slop > max_slop) max_slop = slop;
375 376 377
    }

    if (rub_bell) {
378
	debugBelch("\b\b\b  \b\b\b");
379 380
	rub_bell = 0;
    }
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
381 382 383 384

#if USE_PAPI
    if(papi_is_reporting) {
      /* Switch to counting mutator events */
385 386 387 388 389
      if (gen == 0) {
          papi_stop_gc0_count();
      } else {
          papi_stop_gc1_count();
      }
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
390 391 392
      papi_start_mutator_count();
    }
#endif
393 394
}

395 396 397
/* -----------------------------------------------------------------------------
   Called at the beginning of each Retainer Profiliing
   -------------------------------------------------------------------------- */
398 399 400
#ifdef PROFILING
void
stat_startRP(void)
401
{
402 403
    Ticks user, elapsed;
    getProcessTimes( &user, &elapsed );
404 405 406

    RP_start_time = user;
    RPe_start_time = elapsed;
407
}
sof's avatar
sof committed
408
#endif /* PROFILING */
409 410 411 412

/* -----------------------------------------------------------------------------
   Called at the end of each Retainer Profiliing
   -------------------------------------------------------------------------- */
413 414 415 416

#ifdef PROFILING
void
stat_endRP(
417 418 419 420 421
  nat retainerGeneration,
#ifdef DEBUG_RETAINER
  nat maxCStackSize,
  int maxStackSize,
#endif
422
  double averageNumVisit)
423
{
424 425
    Ticks user, elapsed;
    getProcessTimes( &user, &elapsed );
426 427 428

    RP_tot_time += user - RP_start_time;
    RPe_tot_time += elapsed - RPe_start_time;
429 430 431 432 433 434 435 436 437

  fprintf(prof_file, "Retainer Profiling: %d, at %f seconds\n", 
    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
438
#endif /* PROFILING */
439 440

/* -----------------------------------------------------------------------------
441
   Called at the beginning of each heap census
442
   -------------------------------------------------------------------------- */
443 444
#ifdef PROFILING
void
445
stat_startHeapCensus(void)
446
{
447 448
    Ticks user, elapsed;
    getProcessTimes( &user, &elapsed );
449 450 451

    HC_start_time = user;
    HCe_start_time = elapsed;
452
}
sof's avatar
sof committed
453
#endif /* PROFILING */
454 455

/* -----------------------------------------------------------------------------
456
   Called at the end of each heap census
457
   -------------------------------------------------------------------------- */
458 459
#ifdef PROFILING
void
460
stat_endHeapCensus(void) 
461
{
462 463
    Ticks user, elapsed;
    getProcessTimes( &user, &elapsed );
464 465 466

    HC_tot_time += user - HC_start_time;
    HCe_tot_time += elapsed - HCe_start_time;
467
}
sof's avatar
sof committed
468
#endif /* PROFILING */
469

470 471 472 473 474 475 476 477
/* -----------------------------------------------------------------------------
   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
478 479 480 481 482 483 484 485 486 487 488 489 490 491 492
#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
493
    showStgWord64(counter,temp,rtsTrue/*commas*/); \
Simon Marlow's avatar
Simon Marlow committed
494 495 496 497 498 499 500 501 502 503 504 505 506 507 508 509 510 511 512
    statsPrintf("  (" #counter ")  : %s\n",temp);				\
  }

/* Report the value of a counter as a percentage of another counter */
#define REPORT_PCT(counter,countertot) \
  statsPrintf("  (" #counter ") %% of (" #countertot ") : %.1f%%\n", \
	      counter*100.0/countertot)

#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", \
	      SLOW_CALLS_##arity * 100.0/TOTAL_CALLS)

513 514 515
void
stat_exit(int alloc)
{
Simon Marlow's avatar
Simon Marlow committed
516 517 518 519 520 521 522 523 524 525
    generation *gen;
    Ticks gc_cpu = 0;
    Ticks gc_elapsed = 0;
    Ticks init_cpu = 0;
    Ticks init_elapsed = 0;
    Ticks mut_cpu = 0;
    Ticks mut_elapsed = 0;
    Ticks exit_cpu = 0;
    Ticks exit_elapsed = 0;

526
    if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
527 528

	char temp[BIG_STRING_LEN];
Simon Marlow's avatar
Simon Marlow committed
529 530 531
	Ticks tot_cpu;
	Ticks tot_elapsed;
	nat i, g, total_collections = 0;
532

Simon Marlow's avatar
Simon Marlow committed
533 534
	getProcessTimes( &tot_cpu, &tot_elapsed );
	tot_elapsed -= start_init_elapsed;
535 536

	GC_tot_alloc += alloc;
537

538 539 540
	/* Count total garbage collections */
	for (g = 0; g < RtsFlags.GcFlags.generations; g++)
	    total_collections += generations[g].collections;
541

Simon Marlow's avatar
Simon Marlow committed
542 543 544
	/* 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;
545
	
546 547 548
	if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) {
	    statsPrintf("%9ld %9.9s %9.9s", (lnat)alloc*sizeof(W_), "", "");
	    statsPrintf(" %5.2f %5.2f\n\n", 0.0, 0.0);
549 550
	}

Simon Marlow's avatar
Simon Marlow committed
551 552 553 554 555
        for (i = 0; i < RtsFlags.GcFlags.generations; i++) {
            gc_cpu     += GC_coll_cpu[i];
            gc_elapsed += GC_coll_elapsed[i];
        }

dmp's avatar
dmp committed
556 557 558 559 560 561 562 563 564 565 566 567
        init_cpu     = end_init_cpu - start_init_cpu;
        init_elapsed = end_init_elapsed - start_init_elapsed;

        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; }

568
	if (RtsFlags.GcFlags.giveStats >= SUMMARY_GC_STATS) {
Ian Lynagh's avatar
Ian Lynagh committed
569
	    showStgWord64(GC_tot_alloc*sizeof(W_), 
570
				 temp, rtsTrue/*commas*/);
571
	    statsPrintf("%16s bytes allocated in the heap\n", temp);
572

Ian Lynagh's avatar
Ian Lynagh committed
573
	    showStgWord64(GC_tot_copied*sizeof(W_), 
574
				 temp, rtsTrue/*commas*/);
575
	    statsPrintf("%16s bytes copied during GC\n", temp);
576

Simon Marlow's avatar
Simon Marlow committed
577 578
            if ( residency_samples > 0 ) {
		showStgWord64(max_residency*sizeof(W_), 
579
				     temp, rtsTrue/*commas*/);
580
		statsPrintf("%16s bytes maximum residency (%ld sample(s))\n",
Simon Marlow's avatar
Simon Marlow committed
581
			temp, residency_samples);
582
	    }
583

Simon Marlow's avatar
Simon Marlow committed
584
	    showStgWord64(max_slop*sizeof(W_), temp, rtsTrue/*commas*/);
585 586
	    statsPrintf("%16s bytes maximum slop\n", temp);

587
	    statsPrintf("%16ld MB total memory in use (%ld MB lost due to fragmentation)\n\n", 
588
                        peak_mblocks_allocated * MBLOCK_SIZE_W / (1024 * 1024 / sizeof(W_)),
589
                        (peak_mblocks_allocated * BLOCKS_PER_MBLOCK * BLOCK_SIZE_W - hw_alloc_blocks * BLOCK_SIZE_W) / (1024 * 1024 / sizeof(W_)));
590 591

	    /* Print garbage collections in each gen */
Simon Marlow's avatar
Simon Marlow committed
592 593 594 595 596 597 598 599 600 601 602 603
            statsPrintf("                                    Tot time (elapsed)  Avg pause  Max pause\n");
            for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
                gen = &generations[g];
                statsPrintf("  Gen %2d     %5d colls, %5d par   %5.2fs   %5.2fs     %3.4fs    %3.4fs\n",
                            gen->no,
                            gen->collections,
                            gen->par_collections,
                            TICK_TO_DBL(GC_coll_cpu[g]),
                            TICK_TO_DBL(GC_coll_elapsed[g]),
                            gen->collections == 0 ? 0 : TICK_TO_DBL(GC_coll_elapsed[g] / gen->collections),
                            TICK_TO_DBL(GC_coll_max_pause[g]));
            }
604

605
#if defined(THREADED_RTS)
606
            if (RtsFlags.ParFlags.parGcEnabled) {
607 608 609
                statsPrintf("\n  Parallel GC work balance: %.2f (%ld / %ld, ideal %d)\n", 
                            (double)GC_par_avg_copied / (double)GC_par_max_copied,
                            (lnat)GC_par_avg_copied, (lnat)GC_par_max_copied,
610
                            RtsFlags.ParFlags.nNodes
611 612 613
                    );
            }
#endif
Simon Marlow's avatar
Simon Marlow committed
614
            statsPrintf("\n");
615

616
#if defined(THREADED_RTS)
617 618
	    {
		nat i;
619
		Task *task;
620
                statsPrintf("                        MUT time (elapsed)       GC time  (elapsed)\n");
621 622 623
		for (i = 0, task = all_tasks; 
		     task != NULL; 
		     i++, task = task->all_link) {
624
		    statsPrintf("  Task %2d %-8s :  %6.2fs    (%6.2fs)     %6.2fs    (%6.2fs)\n",
625
				i,
626
				(task->worker) ? "(worker)" : "(bound)",
627 628 629 630
				TICK_TO_DBL(task->mut_time),
				TICK_TO_DBL(task->mut_etime),
				TICK_TO_DBL(task->gc_time),
				TICK_TO_DBL(task->gc_etime));
631 632
		}
	    }
633

634 635
	    statsPrintf("\n");

636 637
            {
                nat i;
638
                SparkCounters sparks = { 0, 0, 0, 0, 0, 0};
639
                for (i = 0; i < n_capabilities; i++) {
640 641
                    sparks.created   += capabilities[i].spark_stats.created;
                    sparks.dud       += capabilities[i].spark_stats.dud;
642
                    sparks.overflowed+= capabilities[i].spark_stats.overflowed;
643 644 645
                    sparks.converted += capabilities[i].spark_stats.converted;
                    sparks.gcd       += capabilities[i].spark_stats.gcd;
                    sparks.fizzled   += capabilities[i].spark_stats.fizzled;
646 647
                }

648 649 650
                statsPrintf("  SPARKS: %ld (%ld converted, %ld overflowed, %ld dud, %ld GC'd, %ld fizzled)\n\n",
                            sparks.created + sparks.dud + sparks.overflowed,
                            sparks.converted, sparks.overflowed, sparks.dud,
651
                            sparks.gcd, sparks.fizzled);
652
            }
653 654
#endif

Simon Marlow's avatar
Simon Marlow committed
655 656 657 658 659 660 661 662
	    statsPrintf("  INIT    time  %6.2fs  (%6.2fs elapsed)\n",
                        TICK_TO_DBL(init_cpu), TICK_TO_DBL(init_elapsed));

            statsPrintf("  MUT     time  %6.2fs  (%6.2fs elapsed)\n",
                        TICK_TO_DBL(mut_cpu), TICK_TO_DBL(mut_elapsed));
            statsPrintf("  GC      time  %6.2fs  (%6.2fs elapsed)\n",
                        TICK_TO_DBL(gc_cpu), TICK_TO_DBL(gc_elapsed));

663
#ifdef PROFILING
Simon Marlow's avatar
Simon Marlow committed
664
	    statsPrintf("  RP      time  %6.2fs  (%6.2fs elapsed)\n",
665
		    TICK_TO_DBL(RP_tot_time), TICK_TO_DBL(RPe_tot_time));
Simon Marlow's avatar
Simon Marlow committed
666
	    statsPrintf("  PROF    time  %6.2fs  (%6.2fs elapsed)\n",
667
		    TICK_TO_DBL(HC_tot_time), TICK_TO_DBL(HCe_tot_time));
668
#endif 
Simon Marlow's avatar
Simon Marlow committed
669 670 671 672 673 674 675 676 677 678 679
	    statsPrintf("  EXIT    time  %6.2fs  (%6.2fs elapsed)\n",
		    TICK_TO_DBL(exit_cpu), TICK_TO_DBL(exit_elapsed));
	    statsPrintf("  Total   time  %6.2fs  (%6.2fs elapsed)\n\n",
		    TICK_TO_DBL(tot_cpu), TICK_TO_DBL(tot_elapsed));
#ifndef THREADED_RTS
	    statsPrintf("  %%GC     time     %5.1f%%  (%.1f%% elapsed)\n\n",
		    TICK_TO_DBL(gc_cpu)*100/TICK_TO_DBL(tot_cpu),
		    TICK_TO_DBL(gc_elapsed)*100/TICK_TO_DBL(tot_elapsed));
#endif

	    if (tot_cpu - GC_tot_cpu - PROF_VAL(RP_tot_time + HC_tot_time) == 0)
Ian Lynagh's avatar
Ian Lynagh committed
680
		showStgWord64(0, temp, rtsTrue/*commas*/);
681
	    else
Ian Lynagh's avatar
Ian Lynagh committed
682 683
		showStgWord64(
		    (StgWord64)((GC_tot_alloc*sizeof(W_))/
Simon Marlow's avatar
Simon Marlow committed
684
			     TICK_TO_DBL(tot_cpu - GC_tot_cpu - 
685
					 PROF_VAL(RP_tot_time + HC_tot_time))),
686 687
		    temp, rtsTrue/*commas*/);
	    
688
	    statsPrintf("  Alloc rate    %s bytes per MUT second\n\n", temp);
689
	
690
	    statsPrintf("  Productivity %5.1f%% of total user, %.1f%% of total elapsed\n\n",
Simon Marlow's avatar
Simon Marlow committed
691 692 693 694 695 696
		    TICK_TO_DBL(tot_cpu - GC_tot_cpu - 
				PROF_VAL(RP_tot_time + HC_tot_time) - init_cpu) * 100 
		    / TICK_TO_DBL(tot_cpu), 
		    TICK_TO_DBL(tot_cpu - GC_tot_cpu - 
				PROF_VAL(RP_tot_time + HC_tot_time) - init_cpu) * 100 
		    / TICK_TO_DBL(tot_elapsed));
Simon Marlow's avatar
Simon Marlow committed
697 698 699 700 701 702 703 704 705

            /*
            TICK_PRINT(1);
            TICK_PRINT(2);
	    REPORT(TOTAL_CALLS);
            TICK_PRINT_TOT(1);
            TICK_PRINT_TOT(2);
            */

mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
706
#if USE_PAPI
707
            papi_stats_report();
708 709 710
#endif
#if defined(THREADED_RTS) && defined(PROF_SPIN)
            {
Simon Marlow's avatar
Simon Marlow committed
711
                nat g;
712 713
                
                statsPrintf("gc_alloc_block_sync: %"FMT_Word64"\n", gc_alloc_block_sync.spin);
714
                statsPrintf("whitehole_spin: %"FMT_Word64"\n", whitehole_spin);
715
                for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
Simon Marlow's avatar
Simon Marlow committed
716
                    statsPrintf("gen[%d].sync: %"FMT_Word64"\n", g, generations[g].sync.spin);
717 718
                }
            }
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
719
#endif
720 721
	}

722
	if (RtsFlags.GcFlags.giveStats == ONELINE_GC_STATS) {
Ian Lynagh's avatar
Ian Lynagh committed
723 724 725 726 727 728 729 730 731 732 733 734 735 736 737 738 739 740 741 742
      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"
                 " ,(\"init_cpu_seconds\", \"%.2f\")\n"
                 " ,(\"init_wall_seconds\", \"%.2f\")\n"
                 " ,(\"mutator_cpu_seconds\", \"%.2f\")\n"
                 " ,(\"mutator_wall_seconds\", \"%.2f\")\n"
                 " ,(\"GC_cpu_seconds\", \"%.2f\")\n"
                 " ,(\"GC_wall_seconds\", \"%.2f\")\n"
                 " ]\n";
      }
      else {
          fmt1 = "<<ghc: %llu bytes, ";
          fmt2 = "%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";
      }
rrt's avatar
rrt committed
743
	  /* print the long long separately to avoid bugginess on mingwin (2001-07-02, mingw-0.5) */
Ian Lynagh's avatar
Ian Lynagh committed
744
	  statsPrintf(fmt1, GC_tot_alloc*(StgWord64)sizeof(W_));
Ian Lynagh's avatar
Ian Lynagh committed
745
	  statsPrintf(fmt2,
rrt's avatar
rrt committed
746
		    total_collections,
Simon Marlow's avatar
Simon Marlow committed
747
		    residency_samples == 0 ? 0 : 
748
		        cumulative_residency*sizeof(W_)/residency_samples, 
Simon Marlow's avatar
Simon Marlow committed
749 750
		    max_residency*sizeof(W_), 
		    residency_samples,
751
		    (unsigned long)(peak_mblocks_allocated * MBLOCK_SIZE / (1024L * 1024L)),
Simon Marlow's avatar
Simon Marlow committed
752 753 754
		    TICK_TO_DBL(init_cpu), TICK_TO_DBL(init_elapsed),
		    TICK_TO_DBL(mut_cpu), TICK_TO_DBL(mut_elapsed),
		    TICK_TO_DBL(gc_cpu), TICK_TO_DBL(gc_elapsed));
755
	}
756

757 758
	statsFlush();
	statsClose();
759
    }
simonmarhaskell@gmail.com's avatar
simonmarhaskell@gmail.com committed
760

Simon Marlow's avatar
Simon Marlow committed
761
    if (GC_coll_cpu) {
Simon Marlow's avatar
Simon Marlow committed
762
      stgFree(GC_coll_cpu);
Simon Marlow's avatar
Simon Marlow committed
763 764 765
      GC_coll_cpu = NULL;
    }
    if (GC_coll_elapsed) {
Simon Marlow's avatar
Simon Marlow committed
766
      stgFree(GC_coll_elapsed);
Simon Marlow's avatar
Simon Marlow committed
767 768 769 770 771 772
      GC_coll_elapsed = NULL;
    }
    if (GC_coll_max_pause) {
      stgFree(GC_coll_max_pause);
      GC_coll_max_pause = NULL;
    }
773
}
774 775 776 777 778 779 780

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

   Produce some detailed info on the state of the generational GC.
   -------------------------------------------------------------------------- */
void
781
statDescribeGens(void)
782
{
783
  nat g, mut, lge, i;
Simon Marlow's avatar
Simon Marlow committed
784
  lnat gen_slop;
785
  lnat tot_live, tot_slop;
Simon Marlow's avatar
Simon Marlow committed
786
  lnat gen_live, gen_blocks;
787
  bdescr *bd;
Simon Marlow's avatar
Simon Marlow committed
788 789
  generation *gen;
  
790
  debugBelch(
Simon Marlow's avatar
Simon Marlow committed
791 792 793 794
"----------------------------------------------------------\n"
"  Gen     Max  Mut-list  Blocks    Large     Live     Slop\n"
"       Blocks     Bytes          Objects                  \n"
"----------------------------------------------------------\n");
795

796 797
  tot_live = 0;
  tot_slop = 0;
Simon Marlow's avatar
Simon Marlow committed
798

799
  for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
Simon Marlow's avatar
Simon Marlow committed
800 801 802 803 804 805 806 807 808
      gen = &generations[g];

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

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

809
      mut = 0;
810 811
      for (i = 0; i < n_capabilities; i++) {
          mut += countOccupied(capabilities[i].mut_lists[g]);
812 813 814 815 816 817 818 819

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

Simon Marlow's avatar
Simon Marlow committed
820 821
          gen_live   += gcThreadLiveWords(i,g);
          gen_blocks += gcThreadLiveBlocks(i,g);
822 823
      }

824
      debugBelch("%5d %7ld %9d", g, (lnat)gen->max_blocks, mut);
Simon Marlow's avatar
Simon Marlow committed
825

Simon Marlow's avatar
Simon Marlow committed
826 827 828 829 830 831
      gen_slop = gen_blocks * BLOCK_SIZE_W - gen_live;

      debugBelch("%8ld %8d %8ld %8ld\n", gen_blocks, lge,
                 gen_live*sizeof(W_), gen_slop*sizeof(W_));
      tot_live += gen_live;
      tot_slop += gen_slop;
832
  }
Simon Marlow's avatar
Simon Marlow committed
833 834 835
  debugBelch("----------------------------------------------------------\n");
  debugBelch("%41s%8ld %8ld\n","",tot_live*sizeof(W_),tot_slop*sizeof(W_));
  debugBelch("----------------------------------------------------------\n");
836
  debugBelch("\n");
837
}
838 839 840 841 842 843

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

844
extern HsInt64 getAllocations( void ) 
845
{ return (HsInt64)GC_tot_alloc * sizeof(W_); }
846 847 848 849 850

/* -----------------------------------------------------------------------------
   Dumping stuff in the stats file, or via the debug message interface
   -------------------------------------------------------------------------- */

mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
851
void
852 853 854 855 856 857 858 859 860 861 862 863 864 865 866 867 868 869 870 871 872 873 874 875 876 877 878 879 880 881 882
statsPrintf( char *s, ... )
{
    FILE *sf = RtsFlags.GcFlags.statsFile;
    va_list ap;
    
    va_start(ap,s);
    if (sf == NULL) {
	vdebugBelch(s,ap);
    } else {
	vfprintf(sf, s, ap);
    }
    va_end(ap);
}

static void
statsFlush( void )
{
    FILE *sf = RtsFlags.GcFlags.statsFile;
    if (sf != NULL) {
	fflush(sf);
    }
}

static void
statsClose( void )
{
    FILE *sf = RtsFlags.GcFlags.statsFile;
    if (sf != NULL) {
	fclose(sf);
    }
}