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

59 60 61
// current = current as of last GC
static lnat current_residency = 0; // in words; for stats only
static lnat max_residency     = 0;
62
static lnat cumulative_residency = 0;
Simon Marlow's avatar
Simon Marlow committed
63
static lnat residency_samples = 0; // for stats only
64
static lnat current_slop      = 0;
Simon Marlow's avatar
Simon Marlow committed
65
static lnat max_slop          = 0;
66

Simon Marlow's avatar
Simon Marlow committed
67
static lnat GC_end_faults = 0;
68

Simon Marlow's avatar
Simon Marlow committed
69 70 71
static Ticks *GC_coll_cpu = NULL;
static Ticks *GC_coll_elapsed = NULL;
static Ticks *GC_coll_max_pause = NULL;
72

73 74 75
static void statsFlush( void );
static void statsClose( void );

Simon Marlow's avatar
Simon Marlow committed
76 77 78
/* -----------------------------------------------------------------------------
   Current elapsed time
   ------------------------------------------------------------------------- */
sof's avatar
sof committed
79

Simon Marlow's avatar
Simon Marlow committed
80 81
Ticks stat_getElapsedTime(void)
{
Simon Marlow's avatar
Simon Marlow committed
82
    return getProcessElapsedTime() - start_init_elapsed;
Simon Marlow's avatar
Simon Marlow committed
83 84
}

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

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

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

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

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

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

125
void
126 127
initStats0(void)
{
Simon Marlow's avatar
Simon Marlow committed
128 129 130 131
    start_init_cpu    = 0;
    start_init_elapsed = 0;
    end_init_cpu     = 0;
    end_init_elapsed  = 0;
132

Simon Marlow's avatar
Simon Marlow committed
133 134 135 136
    start_exit_cpu    = 0;
    start_exit_elapsed = 0;
    end_exit_cpu     = 0;
    end_exit_elapsed  = 0;
137 138 139 140 141

    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
142
    GC_tot_cpu  = 0;
143 144 145 146 147 148 149 150 151 152 153 154 155

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

    GC_end_faults = 0;
}    

Simon Marlow's avatar
Simon Marlow committed
164 165 166 167
/* ---------------------------------------------------------------------------
   initStats1() can be called after setupRtsFlags()
   ------------------------------------------------------------------------ */

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

/* -----------------------------------------------------------------------------
   Initialisation time...
   -------------------------------------------------------------------------- */
199 200

void
201
stat_startInit(void)
202
{
Simon Marlow's avatar
Simon Marlow committed
203
    getProcessTimes(&start_init_cpu, &start_init_elapsed);
204 205 206
}

void 
207
stat_endInit(void)
208
{
Simon Marlow's avatar
Simon Marlow committed
209
    getProcessTimes(&end_init_cpu, &end_init_elapsed);
210

mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
211 212 213 214 215 216 217 218 219 220
#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
221 222
}

223 224 225 226 227 228
/* -----------------------------------------------------------------------------
   stat_startExit and stat_endExit
   
   These two measure the time taken in shutdownHaskell().
   -------------------------------------------------------------------------- */

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

#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
242 243 244 245 246
}

void
stat_endExit(void)
{
Simon Marlow's avatar
Simon Marlow committed
247
    getProcessTimes(&end_exit_cpu, &end_exit_elapsed);
248 249
}

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

static nat rub_bell = 0;

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

    if (bell) {
	if (bell > 1) {
263
	    debugBelch(" GC ");
264 265
	    rub_bell = 1;
	} else {
266
	    debugBelch("\007");
267 268 269
	}
    }

mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
270 271 272 273 274 275 276 277
#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
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 309 310 311
    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);
    }
312 313 314 315 316 317 318
}

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

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

Simon Marlow's avatar
Simon Marlow committed
357 358 359 360 361
        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;
        }
362

Ian Lynagh's avatar
Ian Lynagh committed
363 364 365 366
	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
367
	GC_tot_cpu   += gc_cpu;
368

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

Simon Marlow's avatar
Simon Marlow committed
378
        if (slop > max_slop) max_slop = slop;
379 380 381
    }

    if (rub_bell) {
382
	debugBelch("\b\b\b  \b\b\b");
383 384
	rub_bell = 0;
    }
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
385 386 387 388

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

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

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

/* -----------------------------------------------------------------------------
   Called at the end of each Retainer Profiliing
   -------------------------------------------------------------------------- */
417 418 419 420

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

    RP_tot_time += user - RP_start_time;
    RPe_tot_time += elapsed - RPe_start_time;
433 434 435 436 437 438 439 440 441

  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
442
#endif /* PROFILING */
443 444

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

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

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

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

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

517 518 519
static inline Ticks get_init_cpu(void) { return end_init_cpu - start_init_cpu; }
static inline Ticks get_init_elapsed(void) { return end_init_elapsed - start_init_elapsed; }

520 521 522
void
stat_exit(int alloc)
{
Simon Marlow's avatar
Simon Marlow committed
523 524 525 526 527 528 529 530 531 532
    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;

533
    if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
534 535

	char temp[BIG_STRING_LEN];
Simon Marlow's avatar
Simon Marlow committed
536 537 538
	Ticks tot_cpu;
	Ticks tot_elapsed;
	nat i, g, total_collections = 0;
539

Simon Marlow's avatar
Simon Marlow committed
540 541
	getProcessTimes( &tot_cpu, &tot_elapsed );
	tot_elapsed -= start_init_elapsed;
542 543

	GC_tot_alloc += alloc;
544

545 546 547
	/* Count total garbage collections */
	for (g = 0; g < RtsFlags.GcFlags.generations; g++)
	    total_collections += generations[g].collections;
548

Simon Marlow's avatar
Simon Marlow committed
549 550 551
	/* 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;
552
	
553 554 555
	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);
556 557
	}

Simon Marlow's avatar
Simon Marlow committed
558 559 560 561 562
        for (i = 0; i < RtsFlags.GcFlags.generations; i++) {
            gc_cpu     += GC_coll_cpu[i];
            gc_elapsed += GC_coll_elapsed[i];
        }

563 564
        init_cpu     = get_init_cpu();
        init_elapsed = get_init_elapsed();
dmp's avatar
dmp committed
565 566 567 568 569 570 571 572 573 574

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

575
	if (RtsFlags.GcFlags.giveStats >= SUMMARY_GC_STATS) {
Ian Lynagh's avatar
Ian Lynagh committed
576
	    showStgWord64(GC_tot_alloc*sizeof(W_), 
577
				 temp, rtsTrue/*commas*/);
578
	    statsPrintf("%16s bytes allocated in the heap\n", temp);
579

Ian Lynagh's avatar
Ian Lynagh committed
580
	    showStgWord64(GC_tot_copied*sizeof(W_), 
581
				 temp, rtsTrue/*commas*/);
582
	    statsPrintf("%16s bytes copied during GC\n", temp);
583

Simon Marlow's avatar
Simon Marlow committed
584 585
            if ( residency_samples > 0 ) {
		showStgWord64(max_residency*sizeof(W_), 
586
				     temp, rtsTrue/*commas*/);
587
		statsPrintf("%16s bytes maximum residency (%ld sample(s))\n",
Simon Marlow's avatar
Simon Marlow committed
588
			temp, residency_samples);
589
	    }
590

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

594
	    statsPrintf("%16ld MB total memory in use (%ld MB lost due to fragmentation)\n\n", 
595
                        peak_mblocks_allocated * MBLOCK_SIZE_W / (1024 * 1024 / sizeof(W_)),
596
                        (peak_mblocks_allocated * BLOCKS_PER_MBLOCK * BLOCK_SIZE_W - hw_alloc_blocks * BLOCK_SIZE_W) / (1024 * 1024 / sizeof(W_)));
597 598

	    /* Print garbage collections in each gen */
Simon Marlow's avatar
Simon Marlow committed
599 600 601 602 603 604 605 606 607 608 609 610
            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]));
            }
611

612
#if defined(THREADED_RTS)
613
            if (RtsFlags.ParFlags.parGcEnabled) {
614 615 616
                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,
617
                            RtsFlags.ParFlags.nNodes
618 619 620
                    );
            }
#endif
Simon Marlow's avatar
Simon Marlow committed
621
            statsPrintf("\n");
622

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

641 642
	    statsPrintf("\n");

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

655 656 657
                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,
658
                            sparks.gcd, sparks.fizzled);
659
            }
660 661
#endif

Simon Marlow's avatar
Simon Marlow committed
662 663 664 665 666 667 668 669
	    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));

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

            /*
            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
713
#if USE_PAPI
714
            papi_stats_report();
715 716 717
#endif
#if defined(THREADED_RTS) && defined(PROF_SPIN)
            {
Simon Marlow's avatar
Simon Marlow committed
718
                nat g;
719 720
                
                statsPrintf("gc_alloc_block_sync: %"FMT_Word64"\n", gc_alloc_block_sync.spin);
721
                statsPrintf("whitehole_spin: %"FMT_Word64"\n", whitehole_spin);
722
                for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
Simon Marlow's avatar
Simon Marlow committed
723
                    statsPrintf("gen[%d].sync: %"FMT_Word64"\n", g, generations[g].sync.spin);
724 725
                }
            }
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
726
#endif
727 728
	}

729
	if (RtsFlags.GcFlags.giveStats == ONELINE_GC_STATS) {
Ian Lynagh's avatar
Ian Lynagh committed
730 731 732 733 734 735 736 737 738 739 740 741 742 743 744 745 746 747 748 749
      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
750
	  /* print the long long separately to avoid bugginess on mingwin (2001-07-02, mingw-0.5) */
Ian Lynagh's avatar
Ian Lynagh committed
751
	  statsPrintf(fmt1, GC_tot_alloc*(StgWord64)sizeof(W_));
Ian Lynagh's avatar
Ian Lynagh committed
752
	  statsPrintf(fmt2,
rrt's avatar
rrt committed
753
		    total_collections,
Simon Marlow's avatar
Simon Marlow committed
754
		    residency_samples == 0 ? 0 : 
755
		        cumulative_residency*sizeof(W_)/residency_samples, 
Simon Marlow's avatar
Simon Marlow committed
756 757
		    max_residency*sizeof(W_), 
		    residency_samples,
758
		    (unsigned long)(peak_mblocks_allocated * MBLOCK_SIZE / (1024L * 1024L)),
Simon Marlow's avatar
Simon Marlow committed
759 760 761
		    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));
762
	}
763

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

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

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

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

803 804
  tot_live = 0;
  tot_slop = 0;
Simon Marlow's avatar
Simon Marlow committed
805

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

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

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

816
      mut = 0;
817 818
      for (i = 0; i < n_capabilities; i++) {
          mut += countOccupied(capabilities[i].mut_lists[g]);
819 820 821 822 823 824 825 826

          // 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
827 828
          gen_live   += gcThreadLiveWords(i,g);
          gen_blocks += gcThreadLiveBlocks(i,g);
829 830
      }

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

Simon Marlow's avatar
Simon Marlow committed
833 834 835 836 837 838
      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;
839
  }
Simon Marlow's avatar
Simon Marlow committed
840 841 842
  debugBelch("----------------------------------------------------------\n");
  debugBelch("%41s%8ld %8ld\n","",tot_live*sizeof(W_),tot_slop*sizeof(W_));
  debugBelch("----------------------------------------------------------\n");
843
  debugBelch("\n");
844
}
845 846 847 848 849 850

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

851
extern HsInt64 getAllocations( void ) 
852
{ return (HsInt64)GC_tot_alloc * sizeof(W_); }
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 883 884 885 886 887 888 889 890 891 892 893
/* EZY: I'm not convinced I got all the casting right. */

extern void getGCStats( GCStats *s )
{
    nat total_collections = 0;
    nat g;
    Ticks gc_cpu = 0;
    Ticks gc_elapsed = 0;
    Ticks current_elapsed = 0;
    Ticks current_cpu = 0;

    getProcessTimes(&current_cpu, &current_elapsed);

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

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

    s->bytes_allocated = GC_tot_alloc*(StgWord64)sizeof(W_);
    s->num_gcs = total_collections;
    s->num_byte_usage_samples = residency_samples;
    s->max_bytes_used = max_residency*sizeof(W_);
    s->cumulative_bytes_used = cumulative_residency*(StgWord64)sizeof(W_);
    s->peak_megabytes_allocated = (StgWord64)(peak_mblocks_allocated * MBLOCK_SIZE / (1024L * 1024L));
    s->bytes_copied = GC_tot_copied*(StgWord64)sizeof(W_);
    s->max_bytes_slop = max_slop*(StgWord64)sizeof(W_);
    s->current_bytes_used = current_residency*(StgWord64)sizeof(W_);
    s->current_bytes_slop = current_slop*(StgWord64)sizeof(W_);
    /*
    s->init_cpu_seconds = TICK_TO_DBL(get_init_cpu());
    s->init_wall_seconds = TICK_TO_DBL(get_init_elapsed());
    */
    s->mutator_cpu_seconds = TICK_TO_DBL(current_cpu - end_init_cpu - gc_cpu - PROF_VAL(RP_tot_time + HC_tot_time));
    s->mutator_wall_seconds = TICK_TO_DBL(current_elapsed- end_init_elapsed - gc_elapsed);
    s->gc_cpu_seconds = TICK_TO_DBL(gc_cpu);
    s->gc_wall_seconds = TICK_TO_DBL(gc_elapsed);
894 895 896
    /* EZY: Being consistent with incremental output, but maybe should also discount init */
    s->cpu_seconds = TICK_TO_DBL(current_cpu);
    s->wall_seconds = TICK_TO_DBL(current_elapsed - end_init_elapsed);
897 898 899 900 901 902 903 904 905 906 907 908 909 910 911 912 913 914 915 916 917 918 919 920
    s->par_avg_bytes_copied = GC_par_avg_copied*(StgWord64)sizeof(W_);
    s->par_max_bytes_copied = GC_par_max_copied*(StgWord64)sizeof(W_);
}
// extern void getTaskStats( TaskStats **s ) {}
#if 0
extern void getSparkStats( SparkCounters *s ) {
    nat i;
    s->created = 0;
    s->dud = 0;
    s->overflowed = 0;
    s->converted = 0;
    s->gcd = 0;
    s->fizzled = 0;
    for (i = 0; i < n_capabilities; i++) {
        s->created   += capabilities[i].spark_stats.created;
        s->dud       += capabilities[i].spark_stats.dud;
        s->overflowed+= capabilities[i].spark_stats.overflowed;
        s->converted += capabilities[i].spark_stats.converted;
        s->gcd       += capabilities[i].spark_stats.gcd;
        s->fizzled   += capabilities[i].spark_stats.fizzled;
    }
}
#endif

921 922 923 924
/* -----------------------------------------------------------------------------
   Dumping stuff in the stats file, or via the debug message interface
   -------------------------------------------------------------------------- */

mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
925
void
926 927 928 929 930 931 932 933 934 935 936 937 938 939 940 941 942 943 944 945 946 947 948 949 950 951 952 953 954 955 956
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);
    }
}