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

Simon Marlow's avatar
Simon Marlow committed
29
#define TimeToSecondsDbl(t) ((double)(t) / TIME_RESOLUTION)
30

Simon Marlow's avatar
Simon Marlow committed
31
static Time
Simon Marlow's avatar
Simon Marlow committed
32 33 34 35
    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 Time 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 Time RP_start_time  = 0, RP_tot_time  = 0;  // retainer prof user time
static Time RPe_start_time = 0, RPe_tot_time = 0;  // retainer prof elap time
sof's avatar
sof committed
48

Simon Marlow's avatar
Simon Marlow committed
49 50
static Time HC_start_time, HC_tot_time = 0;     // heap census prof user time
static Time HCe_start_time, HCe_tot_time = 0;   // heap census prof elap time
sof's avatar
sof committed
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 Time *GC_coll_cpu = NULL;
static Time *GC_coll_elapsed = NULL;
static Time *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
Time stat_getElapsedTime(void)
Simon Marlow's avatar
Simon Marlow committed
81
{
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
double
Simon Marlow's avatar
Simon Marlow committed
90
mut_user_time_until( Time t )
Ian Lynagh's avatar
Ian Lynagh committed
91
{
Simon Marlow's avatar
Simon Marlow committed
92
    return TimeToSecondsDbl(t - GC_tot_cpu);
93 94
    // heapCensus() time is included in GC_tot_cpu, so we don't need
    // to subtract it here.
Ian Lynagh's avatar
Ian Lynagh committed
95 96
}

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

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

double
117
mut_user_time_during_heap_census( void )
118
{
Simon Marlow's avatar
Simon Marlow committed
119
    return TimeToSecondsDbl(HC_start_time - GC_tot_cpu - RP_tot_time);
120
}
sof's avatar
sof committed
121
#endif /* PROFILING */
122

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

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

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

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

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

    GC_end_faults = 0;
}    

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

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

/* -----------------------------------------------------------------------------
   Initialisation time...
   -------------------------------------------------------------------------- */
201 202

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

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

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

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

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

#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
244 245 246 247 248
}

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

252 253 254 255 256 257 258
/* -----------------------------------------------------------------------------
   Called at the beginning of each GC
   -------------------------------------------------------------------------- */

static nat rub_bell = 0;

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

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

mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
272 273 274 275 276 277 278 279
#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
280 281 282 283 284 285 286 287 288 289 290 291 292 293 294 295 296 297 298 299 300 301
    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)
{
Simon Marlow's avatar
Simon Marlow committed
302
    Time thread_cpu, elapsed, gc_cpu, gc_elapsed;
Simon Marlow's avatar
Simon Marlow committed
303 304 305 306 307 308 309 310 311 312 313

    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);
    }
314 315 316 317 318 319 320
}

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

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

            GC_end_faults = faults;
356
	    statsFlush();
357 358
	}

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

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

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

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

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

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

401 402 403
/* -----------------------------------------------------------------------------
   Called at the beginning of each Retainer Profiliing
   -------------------------------------------------------------------------- */
404 405 406
#ifdef PROFILING
void
stat_startRP(void)
407
{
Simon Marlow's avatar
Simon Marlow committed
408
    Time user, elapsed;
409
    getProcessTimes( &user, &elapsed );
410 411 412

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

/* -----------------------------------------------------------------------------
   Called at the end of each Retainer Profiliing
   -------------------------------------------------------------------------- */
419 420 421 422

#ifdef PROFILING
void
stat_endRP(
423 424 425 426 427
  nat retainerGeneration,
#ifdef DEBUG_RETAINER
  nat maxCStackSize,
  int maxStackSize,
#endif
428
  double averageNumVisit)
429
{
Simon Marlow's avatar
Simon Marlow committed
430
    Time user, elapsed;
431
    getProcessTimes( &user, &elapsed );
432 433 434

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

  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
444
#endif /* PROFILING */
445 446

/* -----------------------------------------------------------------------------
447
   Called at the beginning of each heap census
448
   -------------------------------------------------------------------------- */
449 450
#ifdef PROFILING
void
451
stat_startHeapCensus(void)
452
{
Simon Marlow's avatar
Simon Marlow committed
453
    Time user, elapsed;
454
    getProcessTimes( &user, &elapsed );
455 456 457

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

/* -----------------------------------------------------------------------------
462
   Called at the end of each heap census
463
   -------------------------------------------------------------------------- */
464 465
#ifdef PROFILING
void
466
stat_endHeapCensus(void) 
467
{
Simon Marlow's avatar
Simon Marlow committed
468
    Time user, elapsed;
469
    getProcessTimes( &user, &elapsed );
470 471 472

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

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

Simon Marlow's avatar
Simon Marlow committed
519 520
static inline Time get_init_cpu(void) { return end_init_cpu - start_init_cpu; }
static inline Time get_init_elapsed(void) { return end_init_elapsed - start_init_elapsed; }
521

522 523 524
void
stat_exit(int alloc)
{
Simon Marlow's avatar
Simon Marlow committed
525
    generation *gen;
Simon Marlow's avatar
Simon Marlow committed
526 527 528 529 530 531 532 533
    Time gc_cpu = 0;
    Time gc_elapsed = 0;
    Time init_cpu = 0;
    Time init_elapsed = 0;
    Time mut_cpu = 0;
    Time mut_elapsed = 0;
    Time exit_cpu = 0;
    Time exit_elapsed = 0;
Simon Marlow's avatar
Simon Marlow committed
534

535
    if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
536 537

	char temp[BIG_STRING_LEN];
Simon Marlow's avatar
Simon Marlow committed
538 539
	Time tot_cpu;
	Time tot_elapsed;
Simon Marlow's avatar
Simon Marlow committed
540
	nat i, g, total_collections = 0;
541

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

	GC_tot_alloc += alloc;
546

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

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

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

565 566 567 568 569 570
        // heapCensus() is called by the GC, so RP and HC time are
        // included in the GC stats.  We therefore subtract them to
        // obtain the actual GC cpu time.  XXX: we aren't doing this
        // for elapsed time.
        gc_cpu -= 0 + PROF_VAL(RP_tot_time + HC_tot_time);

571 572
        init_cpu     = get_init_cpu();
        init_elapsed = get_init_elapsed();
dmp's avatar
dmp committed
573 574 575 576 577 578 579 580 581 582

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

583
	if (RtsFlags.GcFlags.giveStats >= SUMMARY_GC_STATS) {
Ian Lynagh's avatar
Ian Lynagh committed
584
	    showStgWord64(GC_tot_alloc*sizeof(W_), 
585
				 temp, rtsTrue/*commas*/);
586
	    statsPrintf("%16s bytes allocated in the heap\n", temp);
587

Ian Lynagh's avatar
Ian Lynagh committed
588
	    showStgWord64(GC_tot_copied*sizeof(W_), 
589
				 temp, rtsTrue/*commas*/);
590
	    statsPrintf("%16s bytes copied during GC\n", temp);
591

Simon Marlow's avatar
Simon Marlow committed
592 593
            if ( residency_samples > 0 ) {
		showStgWord64(max_residency*sizeof(W_), 
594
				     temp, rtsTrue/*commas*/);
595
		statsPrintf("%16s bytes maximum residency (%ld sample(s))\n",
Simon Marlow's avatar
Simon Marlow committed
596
			temp, residency_samples);
597
	    }
598

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

602
	    statsPrintf("%16ld MB total memory in use (%ld MB lost due to fragmentation)\n\n", 
603
                        peak_mblocks_allocated * MBLOCK_SIZE_W / (1024 * 1024 / sizeof(W_)),
604
                        (peak_mblocks_allocated * BLOCKS_PER_MBLOCK * BLOCK_SIZE_W - hw_alloc_blocks * BLOCK_SIZE_W) / (1024 * 1024 / sizeof(W_)));
605 606

	    /* Print garbage collections in each gen */
Simon Marlow's avatar
Simon Marlow committed
607 608 609 610 611 612 613
            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,
Simon Marlow's avatar
Simon Marlow committed
614 615 616 617
                            TimeToSecondsDbl(GC_coll_cpu[g]),
                            TimeToSecondsDbl(GC_coll_elapsed[g]),
                            gen->collections == 0 ? 0 : TimeToSecondsDbl(GC_coll_elapsed[g] / gen->collections),
                            TimeToSecondsDbl(GC_coll_max_pause[g]));
Simon Marlow's avatar
Simon Marlow committed
618
            }
619

620
#if defined(THREADED_RTS)
621
            if (RtsFlags.ParFlags.parGcEnabled) {
622 623 624
                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,
625
                            n_capabilities
626 627 628
                    );
            }
#endif
Simon Marlow's avatar
Simon Marlow committed
629
            statsPrintf("\n");
630

631
#if defined(THREADED_RTS)
632 633
	    {
		nat i;
634
		Task *task;
635
                statsPrintf("                        MUT time (elapsed)       GC time  (elapsed)\n");
636 637 638
		for (i = 0, task = all_tasks; 
		     task != NULL; 
		     i++, task = task->all_link) {
639
		    statsPrintf("  Task %2d %-8s :  %6.2fs    (%6.2fs)     %6.2fs    (%6.2fs)\n",
640
				i,
641
				(task->worker) ? "(worker)" : "(bound)",
Simon Marlow's avatar
Simon Marlow committed
642 643 644 645
				TimeToSecondsDbl(task->mut_time),
				TimeToSecondsDbl(task->mut_etime),
				TimeToSecondsDbl(task->gc_time),
				TimeToSecondsDbl(task->gc_etime));
646 647
		}
	    }
648

649 650
	    statsPrintf("\n");

651 652
            {
                nat i;
653
                SparkCounters sparks = { 0, 0, 0, 0, 0, 0};
654
                for (i = 0; i < n_capabilities; i++) {
655 656
                    sparks.created   += capabilities[i].spark_stats.created;
                    sparks.dud       += capabilities[i].spark_stats.dud;
657
                    sparks.overflowed+= capabilities[i].spark_stats.overflowed;
658 659 660
                    sparks.converted += capabilities[i].spark_stats.converted;
                    sparks.gcd       += capabilities[i].spark_stats.gcd;
                    sparks.fizzled   += capabilities[i].spark_stats.fizzled;
661 662
                }

663 664 665
                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,
666
                            sparks.gcd, sparks.fizzled);
667
            }
668 669
#endif

Simon Marlow's avatar
Simon Marlow committed
670
	    statsPrintf("  INIT    time  %6.2fs  (%6.2fs elapsed)\n",
Simon Marlow's avatar
Simon Marlow committed
671
                        TimeToSecondsDbl(init_cpu), TimeToSecondsDbl(init_elapsed));
Simon Marlow's avatar
Simon Marlow committed
672 673

            statsPrintf("  MUT     time  %6.2fs  (%6.2fs elapsed)\n",
Simon Marlow's avatar
Simon Marlow committed
674
                        TimeToSecondsDbl(mut_cpu), TimeToSecondsDbl(mut_elapsed));
Simon Marlow's avatar
Simon Marlow committed
675
            statsPrintf("  GC      time  %6.2fs  (%6.2fs elapsed)\n",
Simon Marlow's avatar
Simon Marlow committed
676
                        TimeToSecondsDbl(gc_cpu), TimeToSecondsDbl(gc_elapsed));
Simon Marlow's avatar
Simon Marlow committed
677

678
#ifdef PROFILING
Simon Marlow's avatar
Simon Marlow committed
679
	    statsPrintf("  RP      time  %6.2fs  (%6.2fs elapsed)\n",
Simon Marlow's avatar
Simon Marlow committed
680
		    TimeToSecondsDbl(RP_tot_time), TimeToSecondsDbl(RPe_tot_time));
Simon Marlow's avatar
Simon Marlow committed
681
	    statsPrintf("  PROF    time  %6.2fs  (%6.2fs elapsed)\n",
Simon Marlow's avatar
Simon Marlow committed
682
		    TimeToSecondsDbl(HC_tot_time), TimeToSecondsDbl(HCe_tot_time));
683
#endif 
Simon Marlow's avatar
Simon Marlow committed
684
	    statsPrintf("  EXIT    time  %6.2fs  (%6.2fs elapsed)\n",
Simon Marlow's avatar
Simon Marlow committed
685
		    TimeToSecondsDbl(exit_cpu), TimeToSecondsDbl(exit_elapsed));
Simon Marlow's avatar
Simon Marlow committed
686
	    statsPrintf("  Total   time  %6.2fs  (%6.2fs elapsed)\n\n",
Simon Marlow's avatar
Simon Marlow committed
687
		    TimeToSecondsDbl(tot_cpu), TimeToSecondsDbl(tot_elapsed));
Simon Marlow's avatar
Simon Marlow committed
688 689
#ifndef THREADED_RTS
	    statsPrintf("  %%GC     time     %5.1f%%  (%.1f%% elapsed)\n\n",
Simon Marlow's avatar
Simon Marlow committed
690 691
		    TimeToSecondsDbl(gc_cpu)*100/TimeToSecondsDbl(tot_cpu),
		    TimeToSecondsDbl(gc_elapsed)*100/TimeToSecondsDbl(tot_elapsed));
Simon Marlow's avatar
Simon Marlow committed
692 693 694
#endif

	    if (tot_cpu - GC_tot_cpu - PROF_VAL(RP_tot_time + HC_tot_time) == 0)
Ian Lynagh's avatar
Ian Lynagh committed
695
		showStgWord64(0, temp, rtsTrue/*commas*/);
696
	    else
Ian Lynagh's avatar
Ian Lynagh committed
697 698
		showStgWord64(
		    (StgWord64)((GC_tot_alloc*sizeof(W_))/
Simon Marlow's avatar
Simon Marlow committed
699
			     TimeToSecondsDbl(tot_cpu - GC_tot_cpu - 
700
					 PROF_VAL(RP_tot_time + HC_tot_time))),
701 702
		    temp, rtsTrue/*commas*/);
	    
703
	    statsPrintf("  Alloc rate    %s bytes per MUT second\n\n", temp);
704
	
705
	    statsPrintf("  Productivity %5.1f%% of total user, %.1f%% of total elapsed\n\n",
Simon Marlow's avatar
Simon Marlow committed
706
		    TimeToSecondsDbl(tot_cpu - GC_tot_cpu - 
Simon Marlow's avatar
Simon Marlow committed
707
				PROF_VAL(RP_tot_time + HC_tot_time) - init_cpu) * 100 
Simon Marlow's avatar
Simon Marlow committed
708 709
		    / TimeToSecondsDbl(tot_cpu), 
		    TimeToSecondsDbl(tot_cpu - GC_tot_cpu - 
Simon Marlow's avatar
Simon Marlow committed
710
				PROF_VAL(RP_tot_time + HC_tot_time) - init_cpu) * 100 
Simon Marlow's avatar
Simon Marlow committed
711
		    / TimeToSecondsDbl(tot_elapsed));
Simon Marlow's avatar
Simon Marlow committed
712 713 714 715 716 717 718 719 720

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

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

772 773
	statsFlush();
	statsClose();
774
    }
simonmarhaskell@gmail.com's avatar
simonmarhaskell@gmail.com committed
775

Simon Marlow's avatar
Simon Marlow committed
776
    if (GC_coll_cpu) {
Simon Marlow's avatar
Simon Marlow committed
777
      stgFree(GC_coll_cpu);
Simon Marlow's avatar
Simon Marlow committed
778 779 780
      GC_coll_cpu = NULL;
    }
    if (GC_coll_elapsed) {
Simon Marlow's avatar
Simon Marlow committed
781
      stgFree(GC_coll_elapsed);
Simon Marlow's avatar
Simon Marlow committed
782 783 784 785 786 787
      GC_coll_elapsed = NULL;
    }
    if (GC_coll_max_pause) {
      stgFree(GC_coll_max_pause);
      GC_coll_max_pause = NULL;
    }
788
}
789 790 791 792 793 794 795

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

   Produce some detailed info on the state of the generational GC.
   -------------------------------------------------------------------------- */
void
796
statDescribeGens(void)
797
{
798
  nat g, mut, lge, i;
Simon Marlow's avatar
Simon Marlow committed
799
  lnat gen_slop;
800
  lnat tot_live, tot_slop;
Simon Marlow's avatar
Simon Marlow committed
801
  lnat gen_live, gen_blocks;
802
  bdescr *bd;
Simon Marlow's avatar
Simon Marlow committed
803 804
  generation *gen;
  
805
  debugBelch(
Simon Marlow's avatar
Simon Marlow committed
806 807 808 809
"----------------------------------------------------------\n"
"  Gen     Max  Mut-list  Blocks    Large     Live     Slop\n"
"       Blocks     Bytes          Objects                  \n"
"----------------------------------------------------------\n");
810

811 812
  tot_live = 0;
  tot_slop = 0;
Simon Marlow's avatar
Simon Marlow committed
813

814
  for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
Simon Marlow's avatar
Simon Marlow committed
815 816 817 818 819 820 821 822 823
      gen = &generations[g];

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

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

824
      mut = 0;
825 826
      for (i = 0; i < n_capabilities; i++) {
          mut += countOccupied(capabilities[i].mut_lists[g]);
827 828 829 830 831 832 833 834

          // 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
835 836
          gen_live   += gcThreadLiveWords(i,g);
          gen_blocks += gcThreadLiveBlocks(i,g);
837 838
      }

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

Simon Marlow's avatar
Simon Marlow committed
841 842 843 844 845 846
      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;
847
  }
Simon Marlow's avatar
Simon Marlow committed
848 849 850
  debugBelch("----------------------------------------------------------\n");
  debugBelch("%41s%8ld %8ld\n","",tot_live*sizeof(W_),tot_slop*sizeof(W_));
  debugBelch("----------------------------------------------------------\n");
851
  debugBelch("\n");
852
}
853 854 855 856 857 858

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

859
extern HsInt64 getAllocations( void ) 
860
{ return (HsInt64)GC_tot_alloc * sizeof(W_); }
861

862 863 864 865 866 867
/* EZY: I'm not convinced I got all the casting right. */

extern void getGCStats( GCStats *s )
{
    nat total_collections = 0;
    nat g;
Simon Marlow's avatar
Simon Marlow committed
868 869 870 871
    Time gc_cpu = 0;
    Time gc_elapsed = 0;
    Time current_elapsed = 0;
    Time current_cpu = 0;
872 873 874 875 876 877 878 879 880 881 882 883 884 885 886 887 888 889 890 891 892 893 894

    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_);
    /*
Simon Marlow's avatar
Simon Marlow committed
895 896
    s->init_cpu_seconds = TimeToSecondsDbl(get_init_cpu());
    s->init_wall_seconds = TimeToSecondsDbl(get_init_elapsed());
897
    */
Simon Marlow's avatar
Simon Marlow committed
898 899 900 901
    s->mutator_cpu_seconds = TimeToSecondsDbl(current_cpu - end_init_cpu - gc_cpu - PROF_VAL(RP_tot_time + HC_tot_time));
    s->mutator_wall_seconds = TimeToSecondsDbl(current_elapsed- end_init_elapsed - gc_elapsed);
    s->gc_cpu_seconds = TimeToSecondsDbl(gc_cpu);
    s->gc_wall_seconds = TimeToSecondsDbl(gc_elapsed);
902
    /* EZY: Being consistent with incremental output, but maybe should also discount init */
Simon Marlow's avatar
Simon Marlow committed
903 904
    s->cpu_seconds = TimeToSecondsDbl(current_cpu);
    s->wall_seconds = TimeToSecondsDbl(current_elapsed - end_init_elapsed);
905 906 907 908 909 910 911 912 913 914 915 916 917 918 919 920 921 922 923 924 925 926 927 928
    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

929 930 931 932
/* -----------------------------------------------------------------------------
   Dumping stuff in the stats file, or via the debug message interface
   -------------------------------------------------------------------------- */

mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
933
void
934 935 936 937 938 939 940 941 942 943 944 945 946 947 948 949 950 951 952 953 954 955 956 957 958 959 960 961 962 963 964
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);
    }
}