Stats.c 30.1 KB
Newer Older
1
/* -----------------------------------------------------------------------------
2
 *
3
 * (c) The GHC Team, 1998-2005
4 5 6 7 8
 *
 * Statistics and timing-related functions.
 *
 * ---------------------------------------------------------------------------*/

Simon Marlow's avatar
Simon Marlow committed
9
#include "PosixSource.h"
10
#include "Rts.h"
Simon Marlow's avatar
Simon Marlow committed
11

12
#include "RtsUtils.h"
13
#include "Schedule.h"
14
#include "Stats.h"
15
#include "Profiling.h"
16
#include "GetTime.h"
Simon Marlow's avatar
Simon Marlow committed
17
#include "sm/Storage.h"
18
#include "sm/GC.h" // gc_alloc_block_sync, whitehole_spin
Simon Marlow's avatar
Simon Marlow committed
19 20
#include "sm/GCThread.h"
#include "sm/BlockAlloc.h"
21

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

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

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
    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
290
stat_gcWorkerThreadStart (gc_thread *gct STG_UNUSED)
Simon Marlow's avatar
Simon Marlow committed
291
{
292 293 294 295 296
#if 0
    /*
     * We dont' collect per-thread GC stats any more, but this code
     * could be used to do that if we want to in the future:
     */
Simon Marlow's avatar
Simon Marlow committed
297 298 299 300 301
    if (RtsFlags.GcFlags.giveStats != NO_GC_STATS)
    {
        getProcessTimes(&gct->gc_start_cpu, &gct->gc_start_elapsed);
        gct->gc_start_thread_cpu  = getThreadCPUTime();
    }
302
#endif
Simon Marlow's avatar
Simon Marlow committed
303 304 305
}

void
306
stat_gcWorkerThreadDone (gc_thread *gct STG_UNUSED)
Simon Marlow's avatar
Simon Marlow committed
307
{
308 309 310 311 312
#if 0
    /*
     * We dont' collect per-thread GC stats any more, but this code
     * could be used to do that if we want to in the future:
     */
Simon Marlow's avatar
Simon Marlow committed
313
    Time thread_cpu, elapsed, gc_cpu, gc_elapsed;
Simon Marlow's avatar
Simon Marlow committed
314 315 316 317 318 319 320 321 322 323 324

    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);
    }
325
#endif
326 327 328 329 330 331 332
}

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

void
Simon Marlow's avatar
Simon Marlow committed
333 334
stat_endGC (gc_thread *gct,
            lnat alloc, lnat live, lnat copied, nat gen,
335
            lnat max_copied, lnat avg_copied, lnat slop)
336
{
337 338 339 340
    if (RtsFlags.GcFlags.giveStats != NO_GC_STATS ||
        RtsFlags.ProfFlags.doHeapProfile)
        // heap profiling needs GC_tot_time
    {
341
        Time cpu, elapsed, gc_cpu, gc_elapsed;
342
	
Simon Marlow's avatar
Simon Marlow committed
343 344 345 346 347 348
        getProcessTimes(&cpu, &elapsed);
        gc_elapsed    = elapsed - gct->gc_start_elapsed;

        gc_cpu = cpu - gct->gc_start_cpu;

        if (RtsFlags.GcFlags.giveStats == VERBOSE_GC_STATS) {
349
	    nat faults = getPageFaults();
350
	    
351
	    statsPrintf("%9ld %9ld %9ld",
352
		    alloc*sizeof(W_), copied*sizeof(W_), 
353
			live*sizeof(W_));
Simon Marlow's avatar
Simon Marlow committed
354
            statsPrintf(" %5.2f %5.2f %7.2f %7.2f %4ld %4ld  (Gen: %2d)\n",
Simon Marlow's avatar
Simon Marlow committed
355 356 357 358
                    TimeToSecondsDbl(gc_cpu),
		    TimeToSecondsDbl(gc_elapsed),
		    TimeToSecondsDbl(cpu),
		    TimeToSecondsDbl(elapsed - start_init_elapsed),
Simon Marlow's avatar
Simon Marlow committed
359 360 361 362 363
		    faults - gct->gc_start_faults,
                        gct->gc_start_faults - GC_end_faults,
                    gen);

            GC_end_faults = faults;
364
	    statsFlush();
365 366
	}

Simon Marlow's avatar
Simon Marlow committed
367 368 369 370 371
        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;
        }
372

Ian Lynagh's avatar
Ian Lynagh committed
373 374 375 376
	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
377
	GC_tot_cpu   += gc_cpu;
378 379 380 381 382 383 384 385 386 387 388 389 390 391 392 393
        
        /* For the moment we calculate both per-HEC and total allocation.
	 * There is thus redundancy here, but for the moment we will calculate
	 * it both the old and new way and assert they're the same.
	 * When we're sure it's working OK then we can simplify things.
	 * TODO: simplify calcAllocated and clearNurseries so they don't have
	 *       to calculate the total
	 */
        {
            lnat tot_alloc = 0;
            lnat n;
            for (n = 0; n < n_capabilities; n++) {
                tot_alloc += capabilities[n].total_allocated;
            }
            ASSERT(GC_tot_alloc == tot_alloc);
        }
394

395
	if (gen == RtsFlags.GcFlags.generations-1) { /* major GC? */
Simon Marlow's avatar
Simon Marlow committed
396 397
	    if (live > max_residency) {
		max_residency = live;
398
	    }
399
            current_residency = live;
Simon Marlow's avatar
Simon Marlow committed
400
	    residency_samples++;
401
	    cumulative_residency += live;
402
	}
403

Simon Marlow's avatar
Simon Marlow committed
404
        if (slop > max_slop) max_slop = slop;
405 406 407
    }

    if (rub_bell) {
408
	debugBelch("\b\b\b  \b\b\b");
409 410
	rub_bell = 0;
    }
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
411 412 413 414

#if USE_PAPI
    if(papi_is_reporting) {
      /* Switch to counting mutator events */
415 416 417 418 419
      if (gen == 0) {
          papi_stop_gc0_count();
      } else {
          papi_stop_gc1_count();
      }
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
420 421 422
      papi_start_mutator_count();
    }
#endif
423 424
}

425 426 427
/* -----------------------------------------------------------------------------
   Called at the beginning of each Retainer Profiliing
   -------------------------------------------------------------------------- */
428 429 430
#ifdef PROFILING
void
stat_startRP(void)
431
{
Simon Marlow's avatar
Simon Marlow committed
432
    Time user, elapsed;
433
    getProcessTimes( &user, &elapsed );
434 435 436

    RP_start_time = user;
    RPe_start_time = elapsed;
437
}
sof's avatar
sof committed
438
#endif /* PROFILING */
439 440 441 442

/* -----------------------------------------------------------------------------
   Called at the end of each Retainer Profiliing
   -------------------------------------------------------------------------- */
443 444 445 446

#ifdef PROFILING
void
stat_endRP(
447 448 449 450 451
  nat retainerGeneration,
#ifdef DEBUG_RETAINER
  nat maxCStackSize,
  int maxStackSize,
#endif
452
  double averageNumVisit)
453
{
Simon Marlow's avatar
Simon Marlow committed
454
    Time user, elapsed;
455
    getProcessTimes( &user, &elapsed );
456 457 458

    RP_tot_time += user - RP_start_time;
    RPe_tot_time += elapsed - RPe_start_time;
459 460 461 462 463 464 465 466 467

  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
468
#endif /* PROFILING */
469 470

/* -----------------------------------------------------------------------------
471
   Called at the beginning of each heap census
472
   -------------------------------------------------------------------------- */
473 474
#ifdef PROFILING
void
475
stat_startHeapCensus(void)
476
{
Simon Marlow's avatar
Simon Marlow committed
477
    Time user, elapsed;
478
    getProcessTimes( &user, &elapsed );
479 480 481

    HC_start_time = user;
    HCe_start_time = elapsed;
482
}
sof's avatar
sof committed
483
#endif /* PROFILING */
484 485

/* -----------------------------------------------------------------------------
486
   Called at the end of each heap census
487
   -------------------------------------------------------------------------- */
488 489
#ifdef PROFILING
void
490
stat_endHeapCensus(void) 
491
{
Simon Marlow's avatar
Simon Marlow committed
492
    Time user, elapsed;
493
    getProcessTimes( &user, &elapsed );
494 495 496

    HC_tot_time += user - HC_start_time;
    HCe_tot_time += elapsed - HCe_start_time;
497
}
sof's avatar
sof committed
498
#endif /* PROFILING */
499

500 501 502 503 504 505 506 507
/* -----------------------------------------------------------------------------
   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
508 509 510 511 512 513 514 515 516 517 518 519 520 521 522
#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
523
    showStgWord64(counter,temp,rtsTrue/*commas*/); \
Simon Marlow's avatar
Simon Marlow committed
524 525 526 527 528 529 530 531 532 533 534 535 536 537 538 539 540 541 542
    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
543 544
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; }
545

546 547 548
void
stat_exit(int alloc)
{
Simon Marlow's avatar
Simon Marlow committed
549
    generation *gen;
Simon Marlow's avatar
Simon Marlow committed
550 551 552 553 554 555 556 557
    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
558

559
    if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
560 561

	char temp[BIG_STRING_LEN];
Simon Marlow's avatar
Simon Marlow committed
562 563
	Time tot_cpu;
	Time tot_elapsed;
Simon Marlow's avatar
Simon Marlow committed
564
	nat i, g, total_collections = 0;
565

Simon Marlow's avatar
Simon Marlow committed
566 567
	getProcessTimes( &tot_cpu, &tot_elapsed );
	tot_elapsed -= start_init_elapsed;
568 569

	GC_tot_alloc += alloc;
570

571 572 573
	/* Count total garbage collections */
	for (g = 0; g < RtsFlags.GcFlags.generations; g++)
	    total_collections += generations[g].collections;
574

Simon Marlow's avatar
Simon Marlow committed
575 576 577
	/* 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;
578
	
579 580 581
	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);
582 583
	}

Simon Marlow's avatar
Simon Marlow committed
584 585 586 587 588
        for (i = 0; i < RtsFlags.GcFlags.generations; i++) {
            gc_cpu     += GC_coll_cpu[i];
            gc_elapsed += GC_coll_elapsed[i];
        }

589 590
        // heapCensus() is called by the GC, so RP and HC time are
        // included in the GC stats.  We therefore subtract them to
Ian Lynagh's avatar
Ian Lynagh committed
591
        // obtain the actual GC cpu time.
592 593
        gc_cpu     -= PROF_VAL(RP_tot_time + HC_tot_time);
        gc_elapsed -= PROF_VAL(RPe_tot_time + HCe_tot_time);
594

595 596
        init_cpu     = get_init_cpu();
        init_elapsed = get_init_elapsed();
dmp's avatar
dmp committed
597 598 599 600 601 602 603 604 605 606

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

607
	if (RtsFlags.GcFlags.giveStats >= SUMMARY_GC_STATS) {
Ian Lynagh's avatar
Ian Lynagh committed
608
	    showStgWord64(GC_tot_alloc*sizeof(W_), 
609
				 temp, rtsTrue/*commas*/);
610
	    statsPrintf("%16s bytes allocated in the heap\n", temp);
611

Ian Lynagh's avatar
Ian Lynagh committed
612
	    showStgWord64(GC_tot_copied*sizeof(W_), 
613
				 temp, rtsTrue/*commas*/);
614
	    statsPrintf("%16s bytes copied during GC\n", temp);
615

Simon Marlow's avatar
Simon Marlow committed
616 617
            if ( residency_samples > 0 ) {
		showStgWord64(max_residency*sizeof(W_), 
618
				     temp, rtsTrue/*commas*/);
619
		statsPrintf("%16s bytes maximum residency (%ld sample(s))\n",
Simon Marlow's avatar
Simon Marlow committed
620
			temp, residency_samples);
621
	    }
622

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

626
	    statsPrintf("%16ld MB total memory in use (%ld MB lost due to fragmentation)\n\n", 
627
                        peak_mblocks_allocated * MBLOCK_SIZE_W / (1024 * 1024 / sizeof(W_)),
628
                        (peak_mblocks_allocated * BLOCKS_PER_MBLOCK * BLOCK_SIZE_W - hw_alloc_blocks * BLOCK_SIZE_W) / (1024 * 1024 / sizeof(W_)));
629 630

	    /* Print garbage collections in each gen */
Simon Marlow's avatar
Simon Marlow committed
631 632 633 634 635 636 637
            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
638 639 640 641
                            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
642
            }
643

644
#if defined(THREADED_RTS)
645
            if (RtsFlags.ParFlags.parGcEnabled) {
646 647 648
                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,
649
                            n_capabilities
650 651 652
                    );
            }
#endif
Simon Marlow's avatar
Simon Marlow committed
653
            statsPrintf("\n");
654

655
#if defined(THREADED_RTS)
656 657 658 659
            statsPrintf("  TASKS: %d (%d bound, %d peak workers (%d total), using -N%d)\n",
                        taskCount, taskCount - workerCount,
                        peakWorkerCount, workerCount,
                        n_capabilities);
660

661 662
	    statsPrintf("\n");

663 664
            {
                nat i;
665
                SparkCounters sparks = { 0, 0, 0, 0, 0, 0};
666
                for (i = 0; i < n_capabilities; i++) {
667 668
                    sparks.created   += capabilities[i].spark_stats.created;
                    sparks.dud       += capabilities[i].spark_stats.dud;
669
                    sparks.overflowed+= capabilities[i].spark_stats.overflowed;
670 671 672
                    sparks.converted += capabilities[i].spark_stats.converted;
                    sparks.gcd       += capabilities[i].spark_stats.gcd;
                    sparks.fizzled   += capabilities[i].spark_stats.fizzled;
673 674
                }

675 676 677
                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,
678
                            sparks.gcd, sparks.fizzled);
679
            }
680 681
#endif

Simon Marlow's avatar
Simon Marlow committed
682
	    statsPrintf("  INIT    time  %6.2fs  (%6.2fs elapsed)\n",
Simon Marlow's avatar
Simon Marlow committed
683
                        TimeToSecondsDbl(init_cpu), TimeToSecondsDbl(init_elapsed));
Simon Marlow's avatar
Simon Marlow committed
684 685

            statsPrintf("  MUT     time  %6.2fs  (%6.2fs elapsed)\n",
Simon Marlow's avatar
Simon Marlow committed
686
                        TimeToSecondsDbl(mut_cpu), TimeToSecondsDbl(mut_elapsed));
Simon Marlow's avatar
Simon Marlow committed
687
            statsPrintf("  GC      time  %6.2fs  (%6.2fs elapsed)\n",
Simon Marlow's avatar
Simon Marlow committed
688
                        TimeToSecondsDbl(gc_cpu), TimeToSecondsDbl(gc_elapsed));
Simon Marlow's avatar
Simon Marlow committed
689

690
#ifdef PROFILING
Simon Marlow's avatar
Simon Marlow committed
691
	    statsPrintf("  RP      time  %6.2fs  (%6.2fs elapsed)\n",
Simon Marlow's avatar
Simon Marlow committed
692
		    TimeToSecondsDbl(RP_tot_time), TimeToSecondsDbl(RPe_tot_time));
Simon Marlow's avatar
Simon Marlow committed
693
	    statsPrintf("  PROF    time  %6.2fs  (%6.2fs elapsed)\n",
Simon Marlow's avatar
Simon Marlow committed
694
		    TimeToSecondsDbl(HC_tot_time), TimeToSecondsDbl(HCe_tot_time));
695
#endif 
Simon Marlow's avatar
Simon Marlow committed
696
	    statsPrintf("  EXIT    time  %6.2fs  (%6.2fs elapsed)\n",
Simon Marlow's avatar
Simon Marlow committed
697
		    TimeToSecondsDbl(exit_cpu), TimeToSecondsDbl(exit_elapsed));
Simon Marlow's avatar
Simon Marlow committed
698
	    statsPrintf("  Total   time  %6.2fs  (%6.2fs elapsed)\n\n",
Simon Marlow's avatar
Simon Marlow committed
699
		    TimeToSecondsDbl(tot_cpu), TimeToSecondsDbl(tot_elapsed));
Simon Marlow's avatar
Simon Marlow committed
700 701
#ifndef THREADED_RTS
	    statsPrintf("  %%GC     time     %5.1f%%  (%.1f%% elapsed)\n\n",
Simon Marlow's avatar
Simon Marlow committed
702 703
		    TimeToSecondsDbl(gc_cpu)*100/TimeToSecondsDbl(tot_cpu),
		    TimeToSecondsDbl(gc_elapsed)*100/TimeToSecondsDbl(tot_elapsed));
Simon Marlow's avatar
Simon Marlow committed
704 705
#endif

Simon Marlow's avatar
Simon Marlow committed
706
            if (mut_cpu == 0) {
Ian Lynagh's avatar
Ian Lynagh committed
707
		showStgWord64(0, temp, rtsTrue/*commas*/);
Simon Marlow's avatar
Simon Marlow committed
708
            } else {
Ian Lynagh's avatar
Ian Lynagh committed
709
		showStgWord64(
Simon Marlow's avatar
Simon Marlow committed
710 711 712 713
                    (StgWord64)((GC_tot_alloc*sizeof(W_)) / TimeToSecondsDbl(mut_cpu)),
                    temp, rtsTrue/*commas*/);
            }

714
	    statsPrintf("  Alloc rate    %s bytes per MUT second\n\n", temp);
715
	
716
	    statsPrintf("  Productivity %5.1f%% of total user, %.1f%% of total elapsed\n\n",
Simon Marlow's avatar
Simon Marlow committed
717
                    TimeToSecondsDbl(tot_cpu - gc_cpu -
Simon Marlow's avatar
Simon Marlow committed
718
				PROF_VAL(RP_tot_time + HC_tot_time) - init_cpu) * 100 
Simon Marlow's avatar
Simon Marlow committed
719
		    / TimeToSecondsDbl(tot_cpu), 
Simon Marlow's avatar
Simon Marlow committed
720 721 722
                    TimeToSecondsDbl(tot_cpu - gc_cpu -
                                PROF_VAL(RP_tot_time + HC_tot_time) - init_cpu) * 100
                    / TimeToSecondsDbl(tot_elapsed));
Simon Marlow's avatar
Simon Marlow committed
723 724 725 726 727 728 729 730 731

            /*
            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
732
#if USE_PAPI
733
            papi_stats_report();
734 735 736
#endif
#if defined(THREADED_RTS) && defined(PROF_SPIN)
            {
Simon Marlow's avatar
Simon Marlow committed
737
                nat g;
738 739
                
                statsPrintf("gc_alloc_block_sync: %"FMT_Word64"\n", gc_alloc_block_sync.spin);
740
                statsPrintf("whitehole_spin: %"FMT_Word64"\n", whitehole_spin);
741
                for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
Simon Marlow's avatar
Simon Marlow committed
742
                    statsPrintf("gen[%d].sync: %"FMT_Word64"\n", g, generations[g].sync.spin);
743 744
                }
            }
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
745
#endif
746 747
	}

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

783 784
	statsFlush();
	statsClose();
785
    }
simonmarhaskell@gmail.com's avatar
simonmarhaskell@gmail.com committed
786

Simon Marlow's avatar
Simon Marlow committed
787
    if (GC_coll_cpu) {
Simon Marlow's avatar
Simon Marlow committed
788
      stgFree(GC_coll_cpu);
Simon Marlow's avatar
Simon Marlow committed
789 790 791
      GC_coll_cpu = NULL;
    }
    if (GC_coll_elapsed) {
Simon Marlow's avatar
Simon Marlow committed
792
      stgFree(GC_coll_elapsed);
Simon Marlow's avatar
Simon Marlow committed
793 794 795 796 797 798
      GC_coll_elapsed = NULL;
    }
    if (GC_coll_max_pause) {
      stgFree(GC_coll_max_pause);
      GC_coll_max_pause = NULL;
    }
799
}
800 801 802 803 804 805 806

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

   Produce some detailed info on the state of the generational GC.
   -------------------------------------------------------------------------- */
void
807
statDescribeGens(void)
808
{
809
  nat g, mut, lge, i;
Simon Marlow's avatar
Simon Marlow committed
810
  lnat gen_slop;
811
  lnat tot_live, tot_slop;
Simon Marlow's avatar
Simon Marlow committed
812
  lnat gen_live, gen_blocks;
813
  bdescr *bd;
Simon Marlow's avatar
Simon Marlow committed
814 815
  generation *gen;
  
816
  debugBelch(
Simon Marlow's avatar
Simon Marlow committed
817 818 819 820
"----------------------------------------------------------\n"
"  Gen     Max  Mut-list  Blocks    Large     Live     Slop\n"
"       Blocks     Bytes          Objects                  \n"
"----------------------------------------------------------\n");
821

822 823
  tot_live = 0;
  tot_slop = 0;
Simon Marlow's avatar
Simon Marlow committed
824

825
  for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
Simon Marlow's avatar
Simon Marlow committed
826 827 828 829 830 831 832 833 834
      gen = &generations[g];

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

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

835
      mut = 0;
836 837
      for (i = 0; i < n_capabilities; i++) {
          mut += countOccupied(capabilities[i].mut_lists[g]);
838 839 840 841 842 843 844 845

          // 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
846 847
          gen_live   += gcThreadLiveWords(i,g);
          gen_blocks += gcThreadLiveBlocks(i,g);
848 849
      }

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

Simon Marlow's avatar
Simon Marlow committed
852 853 854 855 856 857
      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;
858
  }
Simon Marlow's avatar
Simon Marlow committed
859 860 861
  debugBelch("----------------------------------------------------------\n");
  debugBelch("%41s%8ld %8ld\n","",tot_live*sizeof(W_),tot_slop*sizeof(W_));
  debugBelch("----------------------------------------------------------\n");
862
  debugBelch("\n");
863
}
864 865 866 867 868 869

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

870
extern HsInt64 getAllocations( void ) 
871
{ return (HsInt64)GC_tot_alloc * sizeof(W_); }
872

873 874 875 876 877 878
/* 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
879 880 881 882
    Time gc_cpu = 0;
    Time gc_elapsed = 0;
    Time current_elapsed = 0;
    Time current_cpu = 0;
883 884 885 886 887 888 889 890 891 892 893 894 895 896 897 898 899 900 901 902 903 904 905

    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
906 907
    s->init_cpu_seconds = TimeToSecondsDbl(get_init_cpu());
    s->init_wall_seconds = TimeToSecondsDbl(get_init_elapsed());
908
    */
Simon Marlow's avatar
Simon Marlow committed
909 910 911 912
    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);
913
    /* EZY: Being consistent with incremental output, but maybe should also discount init */
Simon Marlow's avatar
Simon Marlow committed
914 915
    s->cpu_seconds = TimeToSecondsDbl(current_cpu);
    s->wall_seconds = TimeToSecondsDbl(current_elapsed - end_init_elapsed);
916 917 918 919 920 921 922 923 924 925 926 927 928 929 930 931 932 933 934 935 936 937 938 939
    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

940 941 942 943
/* -----------------------------------------------------------------------------
   Dumping stuff in the stats file, or via the debug message interface
   -------------------------------------------------------------------------- */

mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
944
void
945 946 947 948 949 950 951 952 953 954 955 956 957 958 959 960 961 962 963 964 965 966 967 968 969 970 971 972 973 974 975
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);
    }
}