Stats.c 24.6 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
19

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

24 25 26
/* huh? */
#define BIG_STRING_LEN              512

27
#define TICK_TO_DBL(t) ((double)(t) / TICKS_PER_SECOND)
28

29
static Ticks ElapsedTimeStart = 0;
30

31 32 33
static Ticks InitUserTime     = 0;
static Ticks InitElapsedTime  = 0;
static Ticks InitElapsedStamp = 0;
34

35 36 37
static Ticks MutUserTime      = 0;
static Ticks MutElapsedTime   = 0;
static Ticks MutElapsedStamp  = 0;
38

39 40
static Ticks ExitUserTime     = 0;
static Ticks ExitElapsedTime  = 0;
41

Ian Lynagh's avatar
Ian Lynagh committed
42 43
static StgWord64 GC_tot_alloc        = 0;
static StgWord64 GC_tot_copied       = 0;
44

Ian Lynagh's avatar
Ian Lynagh committed
45 46
static StgWord64 GC_par_max_copied = 0;
static StgWord64 GC_par_avg_copied = 0;
47

48 49
static Ticks GC_start_time = 0,  GC_tot_time  = 0;  /* User GC Time */
static Ticks GCe_start_time = 0, GCe_tot_time = 0;  /* Elapsed GC time */
50

sof's avatar
sof committed
51
#ifdef PROFILING
52 53
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
54

55 56
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
57
#endif
58

sof's avatar
sof committed
59
#ifdef PROFILING
60
#define PROF_VAL(x)   (x)
sof's avatar
sof committed
61 62 63
#else
#define PROF_VAL(x)   0
#endif
64

65 66 67
static lnat MaxResidency = 0;     // in words; for stats only
static lnat AvgResidency = 0;
static lnat ResidencySamples = 0; // for stats only
68
static lnat MaxSlop = 0;
69 70 71

static lnat GC_start_faults = 0, GC_end_faults = 0;

simonmarhaskell@gmail.com's avatar
simonmarhaskell@gmail.com committed
72 73
static Ticks *GC_coll_times = NULL;
static Ticks *GC_coll_etimes = NULL;
74

75 76 77
static void statsFlush( void );
static void statsClose( void );

78
Ticks stat_getElapsedGCTime(void)
79
{
80
    return GCe_tot_time;
81
}
sof's avatar
sof committed
82

Simon Marlow's avatar
Simon Marlow committed
83 84 85 86 87
Ticks stat_getElapsedTime(void)
{
    return getProcessElapsedTime() - ElapsedTimeStart;
}

88 89
/* mut_user_time_during_GC() and mut_user_time()
 *
chak's avatar
chak committed
90 91 92 93 94 95 96 97 98
 * The former function can be used to get the current mutator time
 * *during* a GC, i.e. between stat_startGC and stat_endGC.  This is
 * used in the heap profiler for accurately time stamping the heap
 * sample.  
 *
 * ATTENTION: mut_user_time_during_GC() relies on GC_start_time being 
 *	      defined in stat_startGC() - to minimise system calls, 
 *	      GC_start_time is, however, only defined when really needed (check
 *	      stat_startGC() for details)
99 100
 */
double
101
mut_user_time_during_GC( void )
102
{
103
  return TICK_TO_DBL(GC_start_time - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time));
104 105 106
}

double
107
mut_user_time( void )
108
{
109 110
    Ticks user;
    user = getProcessCPUTime();
111
    return TICK_TO_DBL(user - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time));
112 113
}

114
#ifdef PROFILING
115 116 117
/*
  mut_user_time_during_RP() is similar to mut_user_time_during_GC();
  it returns the MUT time during retainer profiling.
118
  The same is for mut_user_time_during_HC();
119 120 121 122
 */
double
mut_user_time_during_RP( void )
{
123
  return TICK_TO_DBL(RP_start_time - GC_tot_time - RP_tot_time - HC_tot_time);
124 125 126
}

double
127
mut_user_time_during_heap_census( void )
128
{
129
  return TICK_TO_DBL(HC_start_time - GC_tot_time - RP_tot_time - HC_tot_time);
130
}
sof's avatar
sof committed
131
#endif /* PROFILING */
132

133
// initStats0() has no dependencies, it can be called right at the beginning
134
void
135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174 175 176 177 178 179 180 181 182
initStats0(void)
{
    ElapsedTimeStart = 0;

    InitUserTime     = 0;
    InitElapsedTime  = 0;
    InitElapsedStamp = 0;

    MutUserTime      = 0;
    MutElapsedTime   = 0;
    MutElapsedStamp  = 0;

    ExitUserTime     = 0;
    ExitElapsedTime  = 0;

    GC_tot_alloc     = 0;
    GC_tot_copied    = 0;
    GC_par_max_copied = 0;
    GC_par_avg_copied = 0;
    GC_start_time = 0;
    GC_tot_time  = 0;
    GCe_start_time = 0;
    GCe_tot_time = 0;

#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

    MaxResidency = 0;
    AvgResidency = 0;
    ResidencySamples = 0;
    MaxSlop = 0;

    GC_start_faults = 0;
    GC_end_faults = 0;
}    

// initStats1() can be called after setupRtsFlags()
void
initStats1 (void)
183 184 185 186
{
    nat i;
  
    if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) {
187
	statsPrintf("    Alloc    Copied     Live    GC    GC     TOT     TOT  Page Flts\n");
188
	statsPrintf("    bytes     bytes     bytes  user  elap    user    elap\n");
189 190
    }
    GC_coll_times = 
191 192
	(Ticks *)stgMallocBytes(
	    sizeof(Ticks)*RtsFlags.GcFlags.generations,
193
	    "initStats");
194 195 196 197
    GC_coll_etimes = 
	(Ticks *)stgMallocBytes(
	    sizeof(Ticks)*RtsFlags.GcFlags.generations,
	    "initStats");
198 199
    for (i = 0; i < RtsFlags.GcFlags.generations; i++) {
	GC_coll_times[i] = 0;
200
	GC_coll_etimes[i] = 0;
201
    }
202
}
203 204 205 206

/* -----------------------------------------------------------------------------
   Initialisation time...
   -------------------------------------------------------------------------- */
207 208

void
209
stat_startInit(void)
210
{
211
    Ticks elapsed;
212

213
    elapsed = getProcessElapsedTime();
214
    ElapsedTimeStart = elapsed;
215 216 217
}

void 
218
stat_endInit(void)
219
{
220 221 222 223
    Ticks user, elapsed;

    getProcessTimes(&user, &elapsed);

224 225 226
    InitUserTime = user;
    InitElapsedStamp = elapsed; 
    if (ElapsedTimeStart > elapsed) {
227 228
	InitElapsedTime = 0;
    } else {
229
	InitElapsedTime = elapsed - ElapsedTimeStart;
230
    }
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
231 232 233 234 235 236 237 238 239 240
#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
241 242
}

243 244 245 246 247 248
/* -----------------------------------------------------------------------------
   stat_startExit and stat_endExit
   
   These two measure the time taken in shutdownHaskell().
   -------------------------------------------------------------------------- */

249 250 251
void
stat_startExit(void)
{
252 253 254
    Ticks user, elapsed;

    getProcessTimes(&user, &elapsed);
255 256 257

    MutElapsedStamp = elapsed;
    MutElapsedTime = elapsed - GCe_tot_time -
258
	PROF_VAL(RPe_tot_time + HCe_tot_time) - InitElapsedStamp;
259
    if (MutElapsedTime < 0) { MutElapsedTime = 0; }	/* sometimes -0.00 */
260

261 262
    MutUserTime = user - GC_tot_time - 
        PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime;
263
    if (MutUserTime < 0) { MutUserTime = 0; }
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
264 265 266 267 268 269 270 271 272 273

#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
274 275 276 277 278
}

void
stat_endExit(void)
{
279 280 281
    Ticks user, elapsed;

    getProcessTimes(&user, &elapsed);
282 283 284

    ExitUserTime = user - MutUserTime - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime;
    ExitElapsedTime = elapsed - MutElapsedStamp;
285 286 287 288 289 290
    if (ExitUserTime < 0) {
	ExitUserTime = 0;
    }
    if (ExitElapsedTime < 0) {
	ExitElapsedTime = 0;
    }
291 292
}

293 294 295 296 297 298
/* -----------------------------------------------------------------------------
   Called at the beginning of each GC
   -------------------------------------------------------------------------- */

static nat rub_bell = 0;

chak's avatar
chak committed
299 300 301 302 303
/*  initialise global variables needed during GC
 *
 *  * GC_start_time is read in mut_user_time_during_GC(), which in turn is 
 *    needed if either PROFILING or DEBUGing is enabled
 */
304 305 306 307 308 309 310
void
stat_startGC(void)
{
    nat bell = RtsFlags.GcFlags.ringBell;

    if (bell) {
	if (bell > 1) {
311
	    debugBelch(" GC ");
312 313
	    rub_bell = 1;
	} else {
314
	    debugBelch("\007");
315 316 317
	}
    }

318 319 320 321 322
    if (RtsFlags.GcFlags.giveStats != NO_GC_STATS
        || RtsFlags.ProfFlags.doHeapProfile)
        // heap profiling needs GC_tot_time
    {
        getProcessTimes(&GC_start_time, &GCe_start_time);
323
	if (RtsFlags.GcFlags.giveStats) {
324
	    GC_start_faults = getPageFaults();
325 326
	}
    }
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
327 328 329 330 331 332 333 334 335

#if USE_PAPI
    if(papi_is_reporting) {
      /* Switch to counting GC events */
      papi_stop_mutator_count();
      papi_start_gc_count();
    }
#endif

336 337 338 339 340 341 342
}

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

void
343
stat_endGC (lnat alloc, lnat live, lnat copied, lnat gen,
344
            lnat max_copied, lnat avg_copied, lnat slop)
345
{
346 347 348 349
    if (RtsFlags.GcFlags.giveStats != NO_GC_STATS ||
        RtsFlags.ProfFlags.doHeapProfile)
        // heap profiling needs GC_tot_time
    {
350
	Ticks time, etime, gc_time, gc_etime;
351
	
352
	getProcessTimes(&time, &etime);
353 354 355
	gc_time  = time - GC_start_time;
	gc_etime = etime - GCe_start_time;
	
356
	if (RtsFlags.GcFlags.giveStats == VERBOSE_GC_STATS) {
357
	    nat faults = getPageFaults();
358
	    
359
	    statsPrintf("%9ld %9ld %9ld",
360
		    alloc*sizeof(W_), copied*sizeof(W_), 
361
			live*sizeof(W_));
362
	    statsPrintf(" %5.2f %5.2f %7.2f %7.2f %4ld %4ld  (Gen: %2ld)\n", 
363 364 365 366
		    TICK_TO_DBL(gc_time),
		    TICK_TO_DBL(gc_etime),
		    TICK_TO_DBL(time),
		    TICK_TO_DBL(etime - ElapsedTimeStart),
367 368
		    faults - GC_start_faults,
		    GC_start_faults - GC_end_faults,
369
		    gen);
370 371

	    GC_end_faults = faults;
372
	    statsFlush();
373 374
	}

chak's avatar
chak committed
375
	GC_coll_times[gen] += gc_time;
376
	GC_coll_etimes[gen] += gc_etime;
377

Ian Lynagh's avatar
Ian Lynagh committed
378 379 380 381
	GC_tot_copied += (StgWord64) copied;
	GC_tot_alloc  += (StgWord64) alloc;
        GC_par_max_copied += (StgWord64) max_copied;
        GC_par_avg_copied += (StgWord64) avg_copied;
382 383
	GC_tot_time   += gc_time;
	GCe_tot_time  += gc_etime;
384
	
385
#if defined(THREADED_RTS)
386
	{
387 388 389 390
	    Task *task;
	    if ((task = myTask()) != NULL) {
		task->gc_time += gc_time;
		task->gc_etime += gc_etime;
391 392 393 394
	    }
	}
#endif

395
	if (gen == RtsFlags.GcFlags.generations-1) { /* major GC? */
396 397 398 399 400
	    if (live > MaxResidency) {
		MaxResidency = live;
	    }
	    ResidencySamples++;
	    AvgResidency += live;
401
	}
402 403

        if (slop > MaxSlop) MaxSlop = slop;
404 405 406
    }

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

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

424 425 426
/* -----------------------------------------------------------------------------
   Called at the beginning of each Retainer Profiliing
   -------------------------------------------------------------------------- */
427 428 429
#ifdef PROFILING
void
stat_startRP(void)
430
{
431 432
    Ticks user, elapsed;
    getProcessTimes( &user, &elapsed );
433 434 435

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

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

#ifdef PROFILING
void
stat_endRP(
446 447 448 449 450
  nat retainerGeneration,
#ifdef DEBUG_RETAINER
  nat maxCStackSize,
  int maxStackSize,
#endif
451
  double averageNumVisit)
452
{
453 454
    Ticks user, elapsed;
    getProcessTimes( &user, &elapsed );
455 456 457

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

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

/* -----------------------------------------------------------------------------
470
   Called at the beginning of each heap census
471
   -------------------------------------------------------------------------- */
472 473
#ifdef PROFILING
void
474
stat_startHeapCensus(void)
475
{
476 477
    Ticks user, elapsed;
    getProcessTimes( &user, &elapsed );
478 479 480

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

/* -----------------------------------------------------------------------------
485
   Called at the end of each heap census
486
   -------------------------------------------------------------------------- */
487 488
#ifdef PROFILING
void
489
stat_endHeapCensus(void) 
490
{
491 492
    Ticks user, elapsed;
    getProcessTimes( &user, &elapsed );
493 494 495

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

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

542
extern lnat hw_alloc_blocks;
Simon Marlow's avatar
Simon Marlow committed
543

544 545 546
void
stat_exit(int alloc)
{
547
    if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
548 549

	char temp[BIG_STRING_LEN];
550 551
	Ticks time;
	Ticks etime;
552
	nat g, total_collections = 0;
553

554 555
	getProcessTimes( &time, &etime );
	etime -= ElapsedTimeStart;
556 557

	GC_tot_alloc += alloc;
558

559 560 561
	/* Count total garbage collections */
	for (g = 0; g < RtsFlags.GcFlags.generations; g++)
	    total_collections += generations[g].collections;
562

563 564 565 566
	/* avoid divide by zero if time is measured as 0.00 seconds -- SDM */
	if (time  == 0.0)  time = 1;
	if (etime == 0.0) etime = 1;
	
567 568 569
	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);
570 571
	}

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

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

	    if ( ResidencySamples > 0 ) {
Ian Lynagh's avatar
Ian Lynagh committed
582
		showStgWord64(MaxResidency*sizeof(W_), 
583
				     temp, rtsTrue/*commas*/);
584
		statsPrintf("%16s bytes maximum residency (%ld sample(s))\n",
585 586
			temp, ResidencySamples);
	    }
587

Ian Lynagh's avatar
Ian Lynagh committed
588
	    showStgWord64(MaxSlop*sizeof(W_), temp, rtsTrue/*commas*/);
589 590
	    statsPrintf("%16s bytes maximum slop\n", temp);

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

	    /* Print garbage collections in each gen */
	    for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
597 598 599
		statsPrintf("  Generation %d: %5d collections, %5d parallel, %5.2fs, %5.2fs elapsed\n", 
                            g, generations[g].collections, 
                            generations[g].par_collections,
600 601
                        TICK_TO_DBL(GC_coll_times[g]),
                        TICK_TO_DBL(GC_coll_etimes[g]));
602 603
	    }

604
#if defined(THREADED_RTS)
605
            if (RtsFlags.ParFlags.parGcEnabled) {
606 607 608
                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,
609
                            RtsFlags.ParFlags.nNodes
610 611 612 613 614
                    );
            }
#endif

	    statsPrintf("\n");
615

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

634 635
	    statsPrintf("\n");

636 637 638
            {
                nat i;
                lnat sparks_created   = 0;
639
                lnat sparks_dud       = 0;
640
                lnat sparks_converted = 0;
641 642
                lnat sparks_gcd       = 0;
                lnat sparks_fizzled   = 0;
643 644
                for (i = 0; i < n_capabilities; i++) {
                    sparks_created   += capabilities[i].sparks_created;
645
                    sparks_dud       += capabilities[i].sparks_dud;
646
                    sparks_converted += capabilities[i].sparks_converted;
647 648
                    sparks_gcd       += capabilities[i].sparks_gcd;
                    sparks_fizzled   += capabilities[i].sparks_fizzled;
649 650
                }

651 652
                statsPrintf("  SPARKS: %ld (%ld converted, %ld dud, %ld GC'd, %ld fizzled)\n\n",
                            sparks_created + sparks_dud, sparks_converted, sparks_dud, sparks_gcd, sparks_fizzled);
653
            }
654 655
#endif

656
	    statsPrintf("  INIT  time  %6.2fs  (%6.2fs elapsed)\n",
657
		    TICK_TO_DBL(InitUserTime), TICK_TO_DBL(InitElapsedTime));
658
	    statsPrintf("  MUT   time  %6.2fs  (%6.2fs elapsed)\n",
659
		    TICK_TO_DBL(MutUserTime), TICK_TO_DBL(MutElapsedTime));
660
	    statsPrintf("  GC    time  %6.2fs  (%6.2fs elapsed)\n",
661
		    TICK_TO_DBL(GC_tot_time), TICK_TO_DBL(GCe_tot_time));
662
#ifdef PROFILING
663
	    statsPrintf("  RP    time  %6.2fs  (%6.2fs elapsed)\n",
664
		    TICK_TO_DBL(RP_tot_time), TICK_TO_DBL(RPe_tot_time));
665
	    statsPrintf("  PROF  time  %6.2fs  (%6.2fs elapsed)\n",
666
		    TICK_TO_DBL(HC_tot_time), TICK_TO_DBL(HCe_tot_time));
667
#endif 
668
	    statsPrintf("  EXIT  time  %6.2fs  (%6.2fs elapsed)\n",
669
		    TICK_TO_DBL(ExitUserTime), TICK_TO_DBL(ExitElapsedTime));
670
	    statsPrintf("  Total time  %6.2fs  (%6.2fs elapsed)\n\n",
671
		    TICK_TO_DBL(time), TICK_TO_DBL(etime));
672
	    statsPrintf("  %%GC time     %5.1f%%  (%.1f%% elapsed)\n\n",
673
		    TICK_TO_DBL(GC_tot_time)*100/TICK_TO_DBL(time),
sof's avatar
sof committed
674
		    TICK_TO_DBL(GCe_tot_time)*100/TICK_TO_DBL(etime));
675

676
	    if (time - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time) == 0)
Ian Lynagh's avatar
Ian Lynagh committed
677
		showStgWord64(0, temp, rtsTrue/*commas*/);
678
	    else
Ian Lynagh's avatar
Ian Lynagh committed
679 680
		showStgWord64(
		    (StgWord64)((GC_tot_alloc*sizeof(W_))/
sof's avatar
sof committed
681
			     TICK_TO_DBL(time - GC_tot_time - 
682
					 PROF_VAL(RP_tot_time + HC_tot_time))),
683 684
		    temp, rtsTrue/*commas*/);
	    
685
	    statsPrintf("  Alloc rate    %s bytes per MUT second\n\n", temp);
686
	
687
	    statsPrintf("  Productivity %5.1f%% of total user, %.1f%% of total elapsed\n\n",
sof's avatar
sof committed
688
		    TICK_TO_DBL(time - GC_tot_time - 
689
				PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime) * 100 
690
		    / TICK_TO_DBL(time), 
sof's avatar
sof committed
691
		    TICK_TO_DBL(time - GC_tot_time - 
692
				PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime) * 100 
693
		    / TICK_TO_DBL(etime));
Simon Marlow's avatar
Simon Marlow committed
694 695 696 697 698 699 700 701 702

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

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

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

758 759 760
    if (GC_coll_times)
      stgFree(GC_coll_times);
    GC_coll_times = NULL;
simonmarhaskell@gmail.com's avatar
simonmarhaskell@gmail.com committed
761 762 763
    if (GC_coll_etimes)
      stgFree(GC_coll_etimes);
    GC_coll_etimes = NULL;
764
}
765 766 767 768 769 770 771

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

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

786 787
  tot_live = 0;
  tot_slop = 0;
788
  for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
789
      mut = 0;
790 791
      for (i = 0; i < n_capabilities; i++) {
          mut += countOccupied(capabilities[i].mut_lists[g]);
792 793
      }

Simon Marlow's avatar
Simon Marlow committed
794
      gen = &generations[g];
795

Simon Marlow's avatar
Simon Marlow committed
796 797 798 799
      debugBelch("%5d %7d %9d", g, gen->max_blocks, mut);

      for (bd = gen->large_objects, lge = 0; bd; bd = bd->link) {
          lge++;
800
      }
Simon Marlow's avatar
Simon Marlow committed
801 802 803
      live = gen->n_words + countOccupied(gen->large_objects);
      slop = (gen->n_blocks + gen->n_large_blocks) * BLOCK_SIZE_W - live;
      debugBelch("%8d %8d %8ld %8ld\n", gen->n_blocks, lge,
804 805 806
                 live*sizeof(W_), slop*sizeof(W_));
      tot_live += live;
      tot_slop += slop;
807
  }
Simon Marlow's avatar
Simon Marlow committed
808 809 810
  debugBelch("----------------------------------------------------------\n");
  debugBelch("%41s%8ld %8ld\n","",tot_live*sizeof(W_),tot_slop*sizeof(W_));
  debugBelch("----------------------------------------------------------\n");
811
  debugBelch("\n");
812
}
813 814 815 816 817 818

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

819
extern HsInt64 getAllocations( void ) 
820
{ return (HsInt64)GC_tot_alloc * sizeof(W_); }
821 822 823 824 825

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

mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
826
void
827 828 829 830 831 832 833 834 835 836 837 838 839 840 841 842 843 844 845 846 847 848 849 850 851 852 853 854 855 856 857
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);
    }
}