Stats.c 25.9 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];
        }

dmp's avatar
dmp committed
550 551 552 553 554 555 556 557 558 559 560 561
        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; }

562
	if (RtsFlags.GcFlags.giveStats >= SUMMARY_GC_STATS) {
Ian Lynagh's avatar
Ian Lynagh committed
563
	    showStgWord64(GC_tot_alloc*sizeof(W_), 
564
				 temp, rtsTrue/*commas*/);
565
	    statsPrintf("%16s bytes allocated in the heap\n", temp);
566

Ian Lynagh's avatar
Ian Lynagh committed
567
	    showStgWord64(GC_tot_copied*sizeof(W_), 
568
				 temp, rtsTrue/*commas*/);
569
	    statsPrintf("%16s bytes copied during GC\n", temp);
570

Simon Marlow's avatar
Simon Marlow committed
571 572
            if ( residency_samples > 0 ) {
		showStgWord64(max_residency*sizeof(W_), 
573
				     temp, rtsTrue/*commas*/);
574
		statsPrintf("%16s bytes maximum residency (%ld sample(s))\n",
Simon Marlow's avatar
Simon Marlow committed
575
			temp, residency_samples);
576
	    }
577

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

581
	    statsPrintf("%16ld MB total memory in use (%ld MB lost due to fragmentation)\n\n", 
582
                        peak_mblocks_allocated * MBLOCK_SIZE_W / (1024 * 1024 / sizeof(W_)),
583
                        (peak_mblocks_allocated * BLOCKS_PER_MBLOCK * BLOCK_SIZE_W - hw_alloc_blocks * BLOCK_SIZE_W) / (1024 * 1024 / sizeof(W_)));
584 585

	    /* Print garbage collections in each gen */
Simon Marlow's avatar
Simon Marlow committed
586 587 588 589 590 591 592 593 594 595 596 597
            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]));
            }
598

599
#if defined(THREADED_RTS)
600
            if (RtsFlags.ParFlags.parGcEnabled) {
601 602 603
                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,
604
                            RtsFlags.ParFlags.nNodes
605 606 607
                    );
            }
#endif
Simon Marlow's avatar
Simon Marlow committed
608
            statsPrintf("\n");
609

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

628 629
	    statsPrintf("\n");

630 631
            {
                nat i;
632
                SparkCounters sparks = { 0, 0, 0, 0, 0};
633
                for (i = 0; i < n_capabilities; i++) {
634 635 636 637 638
                    sparks.created   += capabilities[i].spark_stats.created;
                    sparks.dud       += capabilities[i].spark_stats.dud;
                    sparks.converted += capabilities[i].spark_stats.converted;
                    sparks.gcd       += capabilities[i].spark_stats.gcd;
                    sparks.fizzled   += capabilities[i].spark_stats.fizzled;
639 640
                }

641
                statsPrintf("  SPARKS: %ld (%ld converted, %ld dud, %ld GC'd, %ld fizzled)\n\n",
642 643 644
                            sparks.created + sparks.dud,
                            sparks.converted, sparks.dud,
                            sparks.gcd, sparks.fizzled);
645
            }
646 647
#endif

Simon Marlow's avatar
Simon Marlow committed
648 649 650 651 652 653 654 655
	    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));

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

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

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

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

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

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

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

789 790
  tot_live = 0;
  tot_slop = 0;
Simon Marlow's avatar
Simon Marlow committed
791

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

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

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

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

          // 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
813 814
          gen_live   += gcThreadLiveWords(i,g);
          gen_blocks += gcThreadLiveBlocks(i,g);
815 816
      }

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

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

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

837
extern HsInt64 getAllocations( void ) 
838
{ return (HsInt64)GC_tot_alloc * sizeof(W_); }
839 840 841 842 843

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

mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
844
void
845 846 847 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
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);
    }
}