Stats.c 26 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 60 61 62
static lnat max_residency     = 0; // in words; for stats only
static lnat avg_residency     = 0;
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 86

double
87
mut_user_time( void )
88
{
Simon Marlow's avatar
Simon Marlow committed
89 90 91
    Ticks cpu;
    cpu = getProcessCPUTime();
    return TICK_TO_DBL(cpu - GC_tot_cpu - PROF_VAL(RP_tot_time + HC_tot_time));
92 93
}

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

double
106
mut_user_time_during_heap_census( void )
107
{
Simon Marlow's avatar
Simon Marlow committed
108
  return TICK_TO_DBL(HC_start_time - GC_tot_cpu - RP_tot_time - HC_tot_time);
109
}
sof's avatar
sof committed
110
#endif /* PROFILING */
111

Simon Marlow's avatar
Simon Marlow committed
112 113 114 115
/* ---------------------------------------------------------------------------
   initStats0() has no dependencies, it can be called right at the beginning
   ------------------------------------------------------------------------ */

116
void
117 118
initStats0(void)
{
Simon Marlow's avatar
Simon Marlow committed
119 120 121 122
    start_init_cpu    = 0;
    start_init_elapsed = 0;
    end_init_cpu     = 0;
    end_init_elapsed  = 0;
123

Simon Marlow's avatar
Simon Marlow committed
124 125 126 127
    start_exit_cpu    = 0;
    start_exit_elapsed = 0;
    end_exit_cpu     = 0;
    end_exit_elapsed  = 0;
128 129 130 131 132

    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
133
    GC_tot_cpu  = 0;
134 135 136 137 138 139 140 141 142 143 144 145 146

#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
147 148 149 150
    max_residency = 0;
    avg_residency = 0;
    residency_samples = 0;
    max_slop = 0;
151 152 153 154

    GC_end_faults = 0;
}    

Simon Marlow's avatar
Simon Marlow committed
155 156 157 158
/* ---------------------------------------------------------------------------
   initStats1() can be called after setupRtsFlags()
   ------------------------------------------------------------------------ */

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

/* -----------------------------------------------------------------------------
   Initialisation time...
   -------------------------------------------------------------------------- */
190 191

void
192
stat_startInit(void)
193
{
Simon Marlow's avatar
Simon Marlow committed
194
    getProcessTimes(&start_init_cpu, &start_init_elapsed);
195 196 197
}

void 
198
stat_endInit(void)
199
{
Simon Marlow's avatar
Simon Marlow committed
200
    getProcessTimes(&end_init_cpu, &end_init_elapsed);
201

mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
202 203 204 205 206 207 208 209 210 211
#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
212 213
}

214 215 216 217 218 219
/* -----------------------------------------------------------------------------
   stat_startExit and stat_endExit
   
   These two measure the time taken in shutdownHaskell().
   -------------------------------------------------------------------------- */

220 221 222
void
stat_startExit(void)
{
Simon Marlow's avatar
Simon Marlow committed
223
    getProcessTimes(&start_exit_cpu, &start_exit_elapsed);
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
224 225 226 227 228 229 230 231 232

#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
233 234 235 236 237
}

void
stat_endExit(void)
{
Simon Marlow's avatar
Simon Marlow committed
238
    getProcessTimes(&end_exit_cpu, &end_exit_elapsed);
239 240
}

241 242 243 244 245 246 247
/* -----------------------------------------------------------------------------
   Called at the beginning of each GC
   -------------------------------------------------------------------------- */

static nat rub_bell = 0;

void
Simon Marlow's avatar
Simon Marlow committed
248
stat_startGC (gc_thread *gct)
249 250 251 252 253
{
    nat bell = RtsFlags.GcFlags.ringBell;

    if (bell) {
	if (bell > 1) {
254
	    debugBelch(" GC ");
255 256
	    rub_bell = 1;
	} else {
257
	    debugBelch("\007");
258 259 260
	}
    }

mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
261 262 263 264 265 266 267 268
#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
269 270 271 272 273 274 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
    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);
    }
303 304 305 306 307 308 309
}

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

void
Simon Marlow's avatar
Simon Marlow committed
310 311
stat_endGC (gc_thread *gct,
            lnat alloc, lnat live, lnat copied, nat gen,
312
            lnat max_copied, lnat avg_copied, lnat slop)
313
{
314 315 316 317
    if (RtsFlags.GcFlags.giveStats != NO_GC_STATS ||
        RtsFlags.ProfFlags.doHeapProfile)
        // heap profiling needs GC_tot_time
    {
Simon Marlow's avatar
Simon Marlow committed
318
        Ticks cpu, elapsed, thread_gc_cpu, gc_cpu, gc_elapsed;
319
	
Simon Marlow's avatar
Simon Marlow committed
320 321 322 323 324 325 326 327 328 329
        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) {
330
	    nat faults = getPageFaults();
331
	    
332
	    statsPrintf("%9ld %9ld %9ld",
333
		    alloc*sizeof(W_), copied*sizeof(W_), 
334
			live*sizeof(W_));
Simon Marlow's avatar
Simon Marlow committed
335 336 337 338 339 340 341 342 343 344
            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;
345
	    statsFlush();
346 347
	}

Simon Marlow's avatar
Simon Marlow committed
348 349 350 351 352
        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;
        }
353

Ian Lynagh's avatar
Ian Lynagh committed
354 355 356 357
	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
358
	GC_tot_cpu   += gc_cpu;
359

360
	if (gen == RtsFlags.GcFlags.generations-1) { /* major GC? */
Simon Marlow's avatar
Simon Marlow committed
361 362
	    if (live > max_residency) {
		max_residency = live;
363
	    }
Simon Marlow's avatar
Simon Marlow committed
364 365
	    residency_samples++;
	    avg_residency += live;
366
	}
367

Simon Marlow's avatar
Simon Marlow committed
368
        if (slop > max_slop) max_slop = slop;
369 370 371
    }

    if (rub_bell) {
372
	debugBelch("\b\b\b  \b\b\b");
373 374
	rub_bell = 0;
    }
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
375 376 377 378

#if USE_PAPI
    if(papi_is_reporting) {
      /* Switch to counting mutator events */
379 380 381 382 383
      if (gen == 0) {
          papi_stop_gc0_count();
      } else {
          papi_stop_gc1_count();
      }
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
384 385 386
      papi_start_mutator_count();
    }
#endif
387 388
}

389 390 391
/* -----------------------------------------------------------------------------
   Called at the beginning of each Retainer Profiliing
   -------------------------------------------------------------------------- */
392 393 394
#ifdef PROFILING
void
stat_startRP(void)
395
{
396 397
    Ticks user, elapsed;
    getProcessTimes( &user, &elapsed );
398 399 400

    RP_start_time = user;
    RPe_start_time = elapsed;
401
}
sof's avatar
sof committed
402
#endif /* PROFILING */
403 404 405 406

/* -----------------------------------------------------------------------------
   Called at the end of each Retainer Profiliing
   -------------------------------------------------------------------------- */
407 408 409 410

#ifdef PROFILING
void
stat_endRP(
411 412 413 414 415
  nat retainerGeneration,
#ifdef DEBUG_RETAINER
  nat maxCStackSize,
  int maxStackSize,
#endif
416
  double averageNumVisit)
417
{
418 419
    Ticks user, elapsed;
    getProcessTimes( &user, &elapsed );
420 421 422

    RP_tot_time += user - RP_start_time;
    RPe_tot_time += elapsed - RPe_start_time;
423 424 425 426 427 428 429 430 431

  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
432
#endif /* PROFILING */
433 434

/* -----------------------------------------------------------------------------
435
   Called at the beginning of each heap census
436
   -------------------------------------------------------------------------- */
437 438
#ifdef PROFILING
void
439
stat_startHeapCensus(void)
440
{
441 442
    Ticks user, elapsed;
    getProcessTimes( &user, &elapsed );
443 444 445

    HC_start_time = user;
    HCe_start_time = elapsed;
446
}
sof's avatar
sof committed
447
#endif /* PROFILING */
448 449

/* -----------------------------------------------------------------------------
450
   Called at the end of each heap census
451
   -------------------------------------------------------------------------- */
452 453
#ifdef PROFILING
void
454
stat_endHeapCensus(void) 
455
{
456 457
    Ticks user, elapsed;
    getProcessTimes( &user, &elapsed );
458 459 460

    HC_tot_time += user - HC_start_time;
    HCe_tot_time += elapsed - HCe_start_time;
461
}
sof's avatar
sof committed
462
#endif /* PROFILING */
463

464 465 466 467 468 469 470 471
/* -----------------------------------------------------------------------------
   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
472 473 474 475 476 477 478 479 480 481 482 483 484 485 486
#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
487
    showStgWord64(counter,temp,rtsTrue/*commas*/); \
Simon Marlow's avatar
Simon Marlow committed
488 489 490 491 492 493 494 495 496 497 498 499 500 501 502 503 504 505 506
    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)

507 508 509
void
stat_exit(int alloc)
{
Simon Marlow's avatar
Simon Marlow committed
510 511 512 513 514 515 516 517 518 519
    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;

520
    if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
521 522

	char temp[BIG_STRING_LEN];
Simon Marlow's avatar
Simon Marlow committed
523 524 525
	Ticks tot_cpu;
	Ticks tot_elapsed;
	nat i, g, total_collections = 0;
526

Simon Marlow's avatar
Simon Marlow committed
527 528
	getProcessTimes( &tot_cpu, &tot_elapsed );
	tot_elapsed -= start_init_elapsed;
529 530

	GC_tot_alloc += alloc;
531

532 533 534
	/* Count total garbage collections */
	for (g = 0; g < RtsFlags.GcFlags.generations; g++)
	    total_collections += generations[g].collections;
535

Simon Marlow's avatar
Simon Marlow committed
536 537 538
	/* 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;
539
	
540 541 542
	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);
543 544
	}

Simon Marlow's avatar
Simon Marlow committed
545 546 547 548 549
        for (i = 0; i < RtsFlags.GcFlags.generations; i++) {
            gc_cpu     += GC_coll_cpu[i];
            gc_elapsed += GC_coll_elapsed[i];
        }

550
	if (RtsFlags.GcFlags.giveStats >= SUMMARY_GC_STATS) {
Ian Lynagh's avatar
Ian Lynagh committed
551
	    showStgWord64(GC_tot_alloc*sizeof(W_), 
552
				 temp, rtsTrue/*commas*/);
553
	    statsPrintf("%16s bytes allocated in the heap\n", temp);
554

Ian Lynagh's avatar
Ian Lynagh committed
555
	    showStgWord64(GC_tot_copied*sizeof(W_), 
556
				 temp, rtsTrue/*commas*/);
557
	    statsPrintf("%16s bytes copied during GC\n", temp);
558

Simon Marlow's avatar
Simon Marlow committed
559 560
            if ( residency_samples > 0 ) {
		showStgWord64(max_residency*sizeof(W_), 
561
				     temp, rtsTrue/*commas*/);
562
		statsPrintf("%16s bytes maximum residency (%ld sample(s))\n",
Simon Marlow's avatar
Simon Marlow committed
563
			temp, residency_samples);
564
	    }
565

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

569
	    statsPrintf("%16ld MB total memory in use (%ld MB lost due to fragmentation)\n\n", 
570
                        peak_mblocks_allocated * MBLOCK_SIZE_W / (1024 * 1024 / sizeof(W_)),
571
                        (peak_mblocks_allocated * BLOCKS_PER_MBLOCK * BLOCK_SIZE_W - hw_alloc_blocks * BLOCK_SIZE_W) / (1024 * 1024 / sizeof(W_)));
572 573

	    /* Print garbage collections in each gen */
Simon Marlow's avatar
Simon Marlow committed
574 575 576 577 578 579 580 581 582 583 584 585
            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]));
            }
586

587
#if defined(THREADED_RTS)
588
            if (RtsFlags.ParFlags.parGcEnabled) {
589 590 591
                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,
592
                            RtsFlags.ParFlags.nNodes
593 594 595
                    );
            }
#endif
Simon Marlow's avatar
Simon Marlow committed
596
            statsPrintf("\n");
597

598
#if defined(THREADED_RTS)
599 600
	    {
		nat i;
601
		Task *task;
602
                statsPrintf("                        MUT time (elapsed)       GC time  (elapsed)\n");
603 604 605
		for (i = 0, task = all_tasks; 
		     task != NULL; 
		     i++, task = task->all_link) {
606
		    statsPrintf("  Task %2d %-8s :  %6.2fs    (%6.2fs)     %6.2fs    (%6.2fs)\n",
607
				i,
608
				(task->worker) ? "(worker)" : "(bound)",
609 610 611 612
				TICK_TO_DBL(task->mut_time),
				TICK_TO_DBL(task->mut_etime),
				TICK_TO_DBL(task->gc_time),
				TICK_TO_DBL(task->gc_etime));
613 614
		}
	    }
615

616 617
	    statsPrintf("\n");

618 619 620
            {
                nat i;
                lnat sparks_created   = 0;
621
                lnat sparks_dud       = 0;
622
                lnat sparks_converted = 0;
623 624
                lnat sparks_gcd       = 0;
                lnat sparks_fizzled   = 0;
625 626
                for (i = 0; i < n_capabilities; i++) {
                    sparks_created   += capabilities[i].sparks_created;
627
                    sparks_dud       += capabilities[i].sparks_dud;
628
                    sparks_converted += capabilities[i].sparks_converted;
629 630
                    sparks_gcd       += capabilities[i].sparks_gcd;
                    sparks_fizzled   += capabilities[i].sparks_fizzled;
631 632
                }

633 634
                statsPrintf("  SPARKS: %ld (%ld converted, %ld dud, %ld GC'd, %ld fizzled)\n\n",
                            sparks_created + sparks_dud, sparks_converted, sparks_dud, sparks_gcd, sparks_fizzled);
635
            }
636 637
#endif

Simon Marlow's avatar
Simon Marlow committed
638 639 640 641 642 643 644 645 646 647 648 649 650 651 652 653 654 655 656 657
            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;

	    statsPrintf("  INIT    time  %6.2fs  (%6.2fs elapsed)\n",
                        TICK_TO_DBL(init_cpu), TICK_TO_DBL(init_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; }

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

658
#ifdef PROFILING
Simon Marlow's avatar
Simon Marlow committed
659
	    statsPrintf("  RP      time  %6.2fs  (%6.2fs elapsed)\n",
660
		    TICK_TO_DBL(RP_tot_time), TICK_TO_DBL(RPe_tot_time));
Simon Marlow's avatar
Simon Marlow committed
661
	    statsPrintf("  PROF    time  %6.2fs  (%6.2fs elapsed)\n",
662
		    TICK_TO_DBL(HC_tot_time), TICK_TO_DBL(HCe_tot_time));
663
#endif 
Simon Marlow's avatar
Simon Marlow committed
664 665 666 667 668 669 670 671 672 673 674
	    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
675
		showStgWord64(0, temp, rtsTrue/*commas*/);
676
	    else
Ian Lynagh's avatar
Ian Lynagh committed
677 678
		showStgWord64(
		    (StgWord64)((GC_tot_alloc*sizeof(W_))/
Simon Marlow's avatar
Simon Marlow committed
679
			     TICK_TO_DBL(tot_cpu - GC_tot_cpu - 
680
					 PROF_VAL(RP_tot_time + HC_tot_time))),
681 682
		    temp, rtsTrue/*commas*/);
	    
683
	    statsPrintf("  Alloc rate    %s bytes per MUT second\n\n", temp);
684
	
685
	    statsPrintf("  Productivity %5.1f%% of total user, %.1f%% of total elapsed\n\n",
Simon Marlow's avatar
Simon Marlow committed
686 687 688 689 690 691
		    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
692 693 694 695 696 697 698 699 700

            /*
            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
701
#if USE_PAPI
702
            papi_stats_report();
703 704 705
#endif
#if defined(THREADED_RTS) && defined(PROF_SPIN)
            {
Simon Marlow's avatar
Simon Marlow committed
706
                nat g;
707 708
                
                statsPrintf("gc_alloc_block_sync: %"FMT_Word64"\n", gc_alloc_block_sync.spin);
709
                statsPrintf("whitehole_spin: %"FMT_Word64"\n", whitehole_spin);
710
                for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
Simon Marlow's avatar
Simon Marlow committed
711
                    statsPrintf("gen[%d].sync: %"FMT_Word64"\n", g, generations[g].sync.spin);
712 713
                }
            }
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
714
#endif
715 716
	}

717
	if (RtsFlags.GcFlags.giveStats == ONELINE_GC_STATS) {
Ian Lynagh's avatar
Ian Lynagh committed
718 719 720 721 722 723 724 725 726 727 728 729 730 731 732 733 734 735 736 737
      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
738
	  /* print the long long separately to avoid bugginess on mingwin (2001-07-02, mingw-0.5) */
Ian Lynagh's avatar
Ian Lynagh committed
739
	  statsPrintf(fmt1, GC_tot_alloc*(StgWord64)sizeof(W_));
Ian Lynagh's avatar
Ian Lynagh committed
740
	  statsPrintf(fmt2,
rrt's avatar
rrt committed
741
		    total_collections,
Simon Marlow's avatar
Simon Marlow committed
742 743 744 745
		    residency_samples == 0 ? 0 : 
		        avg_residency*sizeof(W_)/residency_samples, 
		    max_residency*sizeof(W_), 
		    residency_samples,
746
		    (unsigned long)(peak_mblocks_allocated * MBLOCK_SIZE / (1024L * 1024L)),
Simon Marlow's avatar
Simon Marlow committed
747 748 749
		    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));
750
	}
751

752 753
	statsFlush();
	statsClose();
754
    }
simonmarhaskell@gmail.com's avatar
simonmarhaskell@gmail.com committed
755

Simon Marlow's avatar
Simon Marlow committed
756
    if (GC_coll_cpu) {
Simon Marlow's avatar
Simon Marlow committed
757
      stgFree(GC_coll_cpu);
Simon Marlow's avatar
Simon Marlow committed
758 759 760
      GC_coll_cpu = NULL;
    }
    if (GC_coll_elapsed) {
Simon Marlow's avatar
Simon Marlow committed
761
      stgFree(GC_coll_elapsed);
Simon Marlow's avatar
Simon Marlow committed
762 763 764 765 766 767
      GC_coll_elapsed = NULL;
    }
    if (GC_coll_max_pause) {
      stgFree(GC_coll_max_pause);
      GC_coll_max_pause = NULL;
    }
768
}
769 770 771 772 773 774 775

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

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

791 792
  tot_live = 0;
  tot_slop = 0;
Simon Marlow's avatar
Simon Marlow committed
793

794
  for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
Simon Marlow's avatar
Simon Marlow committed
795 796 797 798 799 800 801 802 803
      gen = &generations[g];

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

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

804
      mut = 0;
805 806
      for (i = 0; i < n_capabilities; i++) {
          mut += countOccupied(capabilities[i].mut_lists[g]);
807 808 809 810 811 812 813 814 815

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

          gen_live   += gcThreadLiveWords(i,g);
Simon Marlow's avatar
Simon Marlow committed
816 817
          gen_live   += gcThreadLiveWords(i,g);
          gen_blocks += gcThreadLiveBlocks(i,g);
818 819
      }

Simon Marlow's avatar
Simon Marlow committed
820 821
      debugBelch("%5d %7d %9d", g, gen->max_blocks, mut);

Simon Marlow's avatar
Simon Marlow committed
822 823 824 825 826 827
      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;
828
  }
Simon Marlow's avatar
Simon Marlow committed
829 830 831
  debugBelch("----------------------------------------------------------\n");
  debugBelch("%41s%8ld %8ld\n","",tot_live*sizeof(W_),tot_slop*sizeof(W_));
  debugBelch("----------------------------------------------------------\n");
832
  debugBelch("\n");
833
}
834 835 836 837 838 839

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

840
extern HsInt64 getAllocations( void ) 
841
{ return (HsInt64)GC_tot_alloc * sizeof(W_); }
842 843 844 845 846

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

mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
847
void
848 849 850 851 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
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);
    }
}