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

#include "Rts.h"
#include "RtsFlags.h"
#include "RtsUtils.h"
12
#include "MBlock.h"
13
#include "Storage.h"
14
#include "Schedule.h"
15
#include "Stats.h"
sof's avatar
sof committed
16
#include "ParTicky.h"                       /* ToDo: move into Rts.h */
17
#include "Profiling.h"
18
#include "GetTime.h"
19
#include "GC.h"
20

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

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

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

30
static Ticks ElapsedTimeStart = 0;
31

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

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

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

43 44 45
static ullong GC_tot_alloc        = 0;
static ullong GC_tot_copied       = 0;

46 47 48
static ullong GC_par_max_copied = 0;
static ullong GC_par_avg_copied = 0;

49 50
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 */
51

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

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

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

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

static lnat GC_start_faults = 0, GC_end_faults = 0;

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

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

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

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

89 90
/* mut_user_time_during_GC() and mut_user_time()
 *
chak's avatar
chak committed
91 92 93 94 95 96 97 98 99
 * 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)
100 101
 */
double
102
mut_user_time_during_GC( void )
103
{
104
  return TICK_TO_DBL(GC_start_time - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time));
105 106 107
}

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

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

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

134
// initStats0() has no dependencies, it can be called right at the beginning
135
void
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 183
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)
184 185 186 187
{
    nat i;
  
    if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) {
188
	statsPrintf("    Alloc    Copied     Live    GC    GC     TOT     TOT  Page Flts\n");
189
	statsPrintf("    bytes     bytes     bytes  user  elap    user    elap\n");
190 191
    }
    GC_coll_times = 
192 193
	(Ticks *)stgMallocBytes(
	    sizeof(Ticks)*RtsFlags.GcFlags.generations,
194
	    "initStats");
195 196 197 198
    GC_coll_etimes = 
	(Ticks *)stgMallocBytes(
	    sizeof(Ticks)*RtsFlags.GcFlags.generations,
	    "initStats");
199 200
    for (i = 0; i < RtsFlags.GcFlags.generations; i++) {
	GC_coll_times[i] = 0;
201
	GC_coll_etimes[i] = 0;
202
    }
203
}
204 205 206 207

/* -----------------------------------------------------------------------------
   Initialisation time...
   -------------------------------------------------------------------------- */
208 209

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

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

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

    getProcessTimes(&user, &elapsed);

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

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

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

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

    MutElapsedStamp = elapsed;
    MutElapsedTime = elapsed - GCe_tot_time -
259
	PROF_VAL(RPe_tot_time + HCe_tot_time) - InitElapsedStamp;
260
    if (MutElapsedTime < 0) { MutElapsedTime = 0; }	/* sometimes -0.00 */
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
	}
    }

chak's avatar
chak committed
318
#if defined(PROFILING) || defined(DEBUG)
319
    GC_start_time = getProcessCPUTime();  // needed in mut_user_time_during_GC()
chak's avatar
chak committed
320 321
#endif

322
    if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
chak's avatar
chak committed
323
#if !defined(PROFILING) && !defined(DEBUG)
324
        GC_start_time = getProcessCPUTime();
chak's avatar
chak committed
325
#endif
326
	GCe_start_time = getProcessElapsedTime();
327
	if (RtsFlags.GcFlags.giveStats) {
328
	    GC_start_faults = getPageFaults();
329 330
	}
    }
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
331 332 333 334 335 336 337 338 339

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

340 341 342 343 344 345 346
}

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

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

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

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

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

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

        if (slop > MaxSlop) MaxSlop = 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
{
432 433
    Ticks user, elapsed;
    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
{
454 455
    Ticks user, elapsed;
    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
{
477 478
    Ticks user, elapsed;
    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
{
492 493
    Ticks user, elapsed;
    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 523 524 525 526 527 528 529 530 531 532 533 534 535 536 537 538 539 540 541 542 543 544 545 546 547 548 549 550 551 552
#ifdef DEBUG
#define TICK_VAR(arity) \
  extern StgInt SLOW_CALLS_##arity; \
  extern StgInt RIGHT_ARITY_##arity; \
  extern StgInt TAGGED_PTR_##arity;

#define TICK_VAR_INI(arity) \
  StgInt SLOW_CALLS_##arity = 1; \
  StgInt RIGHT_ARITY_##arity = 1; \
  StgInt TAGGED_PTR_##arity = 0;

extern StgInt TOTAL_CALLS;

TICK_VAR(1)
TICK_VAR(2)

TICK_VAR_INI(1)
TICK_VAR_INI(2)

StgInt TOTAL_CALLS=1;
#endif

/* Report the value of a counter */
#define REPORT(counter) \
  { \
    ullong_format_string(counter,temp,rtsTrue/*commas*/); \
    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)

553
extern lnat hw_alloc_blocks;
Simon Marlow's avatar
Simon Marlow committed
554

555 556 557
void
stat_exit(int alloc)
{
558
    if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
559 560

	char temp[BIG_STRING_LEN];
561 562
	Ticks time;
	Ticks etime;
563
	nat g, total_collections = 0;
564

565 566
	getProcessTimes( &time, &etime );
	etime -= ElapsedTimeStart;
567 568

	GC_tot_alloc += alloc;
569

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

574 575 576 577
	/* 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;
	
578 579 580
	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);
581 582
	}

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

	    ullong_format_string(GC_tot_copied*sizeof(W_), 
				 temp, rtsTrue/*commas*/);
590
	    statsPrintf("%16s bytes copied during GC\n", temp);
591 592 593

	    if ( ResidencySamples > 0 ) {
		ullong_format_string(MaxResidency*sizeof(W_), 
594
				     temp, rtsTrue/*commas*/);
595
		statsPrintf("%16s bytes maximum residency (%ld sample(s))\n",
596 597
			temp, ResidencySamples);
	    }
598 599 600 601

	    ullong_format_string(MaxSlop*sizeof(W_), temp, rtsTrue/*commas*/);
	    statsPrintf("%16s bytes maximum slop\n", temp);

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

	    /* Print garbage collections in each gen */
	    for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
608 609 610
		statsPrintf("  Generation %d: %5d collections, %5d parallel, %5.2fs, %5.2fs elapsed\n", 
                            g, generations[g].collections, 
                            generations[g].par_collections,
611 612
                        TICK_TO_DBL(GC_coll_times[g]),
                        TICK_TO_DBL(GC_coll_etimes[g]));
613 614
	    }

615
#if defined(THREADED_RTS)
616
            if (RtsFlags.ParFlags.parGcEnabled) {
617 618 619
                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,
620
                            RtsFlags.ParFlags.nNodes
621 622 623 624 625
                    );
            }
#endif

	    statsPrintf("\n");
626

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

645 646
	    statsPrintf("\n");

647 648 649 650 651 652 653 654 655 656 657 658 659 660
            {
                nat i;
                lnat sparks_created   = 0;
                lnat sparks_converted = 0;
                lnat sparks_pruned    = 0;
                for (i = 0; i < n_capabilities; i++) {
                    sparks_created   += capabilities[i].sparks_created;
                    sparks_converted += capabilities[i].sparks_converted;
                    sparks_pruned    += capabilities[i].sparks_pruned;
                }

                statsPrintf("  SPARKS: %ld (%ld converted, %ld pruned)\n\n",
                            sparks_created, sparks_converted, sparks_pruned);
            }
661 662
#endif

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

683
	    if (time - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time) == 0)
684 685 686 687
		ullong_format_string(0, temp, rtsTrue/*commas*/);
	    else
		ullong_format_string(
		    (ullong)((GC_tot_alloc*sizeof(W_))/
sof's avatar
sof committed
688
			     TICK_TO_DBL(time - GC_tot_time - 
689
					 PROF_VAL(RP_tot_time + HC_tot_time))),
690 691
		    temp, rtsTrue/*commas*/);
	    
692
	    statsPrintf("  Alloc rate    %s bytes per MUT second\n\n", temp);
693
	
694
	    statsPrintf("  Productivity %5.1f%% of total user, %.1f%% of total elapsed\n\n",
sof's avatar
sof committed
695
		    TICK_TO_DBL(time - GC_tot_time - 
696
				PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime) * 100 
697
		    / TICK_TO_DBL(time), 
sof's avatar
sof committed
698
		    TICK_TO_DBL(time - GC_tot_time - 
699
				PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime) * 100 
700
		    / TICK_TO_DBL(etime));
Simon Marlow's avatar
Simon Marlow committed
701 702 703 704 705 706 707 708 709

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

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

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

767 768 769
    if (GC_coll_times)
      stgFree(GC_coll_times);
    GC_coll_times = NULL;
simonmarhaskell@gmail.com's avatar
simonmarhaskell@gmail.com committed
770 771 772
    if (GC_coll_etimes)
      stgFree(GC_coll_etimes);
    GC_coll_etimes = NULL;
773
}
774 775 776 777 778 779 780

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

   Produce some detailed info on the state of the generational GC.
   -------------------------------------------------------------------------- */
void
781
statDescribeGens(void)
782
{
783
  nat g, s, mut, lge;
784 785
  lnat live, slop;
  lnat tot_live, tot_slop;
786 787 788
  bdescr *bd;
  step *step;

789
  debugBelch(
790 791 792 793
"-----------------------------------------------------------------\n"
"  Gen     Max  Mut-list  Step   Blocks    Large     Live     Slop\n"
"       Blocks     Bytes                 Objects                  \n"
"-----------------------------------------------------------------\n");
794

795 796
  tot_live = 0;
  tot_slop = 0;
797
  for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
798
      mut = 0;
799
      for (bd = generations[g].mut_list; bd != NULL; bd = bd->link) {
Simon Marlow's avatar
Simon Marlow committed
800
	  mut += (bd->free - bd->start) * sizeof(W_);
801 802
      }

803
    debugBelch("%5d %7d %9d", g, generations[g].max_blocks, mut);
804 805 806

    for (s = 0; s < generations[g].n_steps; s++) {
      step = &generations[g].steps[s];
807 808 809
      for (bd = step->large_objects, lge = 0; bd; bd = bd->link) {
	lge++;
      }
810
      live = step->n_words + countOccupied(step->large_objects);
811
      if (s != 0) {
812
	debugBelch("%23s","");
813
      }
814 815 816 817 818
      slop = (step->n_blocks + step->n_large_blocks) * BLOCK_SIZE_W - live;
      debugBelch("%6d %8d %8d %8ld %8ld\n", s, step->n_blocks, lge,
                 live*sizeof(W_), slop*sizeof(W_));
      tot_live += live;
      tot_slop += slop;
819 820
    }
  }
821 822 823
  debugBelch("-----------------------------------------------------------------\n");
  debugBelch("%48s%8ld %8ld\n","",tot_live*sizeof(W_),tot_slop*sizeof(W_));
  debugBelch("-----------------------------------------------------------------\n");
824
  debugBelch("\n");
825
}
826 827 828 829 830 831

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

832 833
extern HsInt64 getAllocations( void ) 
{ return (HsInt64)total_allocated * sizeof(W_); }
834 835 836 837 838

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

mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
839
void
840 841 842 843 844 845 846 847 848 849 850 851 852 853 854 855 856 857 858 859 860 861 862 863 864 865 866 867 868 869 870
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);
    }
}