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

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

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

46 47
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 */
48

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

53 54
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
55
#endif
56

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

63 64 65
static lnat MaxResidency = 0;     // in words; for stats only
static lnat AvgResidency = 0;
static lnat ResidencySamples = 0; // for stats only
66 67 68

static lnat GC_start_faults = 0, GC_end_faults = 0;

69
static Ticks *GC_coll_times;
70

71 72 73
static void statsFlush( void );
static void statsClose( void );

74
Ticks stat_getElapsedGCTime(void)
75
{
76
    return GCe_tot_time;
77
}
sof's avatar
sof committed
78

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

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

double
103
mut_user_time( void )
104
{
105 106
    Ticks user;
    user = getProcessCPUTime();
107
    return TICK_TO_DBL(user - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time));
108 109
}

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

double
123
mut_user_time_during_heap_census( void )
124
{
125
  return TICK_TO_DBL(HC_start_time - GC_tot_time - RP_tot_time - HC_tot_time);
126
}
sof's avatar
sof committed
127
#endif /* PROFILING */
128

129 130 131 132 133 134
void
initStats(void)
{
    nat i;
  
    if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) {
135
	statsPrintf("    Alloc    Copied     Live    GC    GC     TOT     TOT  Page Flts\n");
136
	statsPrintf("    bytes     bytes     bytes  user  elap    user    elap\n");
137 138
    }
    GC_coll_times = 
139 140
	(Ticks *)stgMallocBytes(
	    sizeof(Ticks)*RtsFlags.GcFlags.generations,
141 142 143 144 145 146 147 148 149
	    "initStats");
    for (i = 0; i < RtsFlags.GcFlags.generations; i++) {
	GC_coll_times[i] = 0;
    }
}    

/* -----------------------------------------------------------------------------
   Initialisation time...
   -------------------------------------------------------------------------- */
150 151

void
152
stat_startInit(void)
153
{
154
    Ticks elapsed;
155

156
    elapsed = getProcessElapsedTime();
157
    ElapsedTimeStart = elapsed;
158 159 160
}

void 
161
stat_endInit(void)
162
{
163 164 165 166
    Ticks user, elapsed;

    getProcessTimes(&user, &elapsed);

167 168 169
    InitUserTime = user;
    InitElapsedStamp = elapsed; 
    if (ElapsedTimeStart > elapsed) {
170 171
	InitElapsedTime = 0;
    } else {
172
	InitElapsedTime = elapsed - ElapsedTimeStart;
173
    }
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
174 175 176 177 178 179 180 181 182 183 184 185
#if USE_PAPI
    papi_init_eventsets();

    /* 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
186 187
}

188 189 190 191 192 193
/* -----------------------------------------------------------------------------
   stat_startExit and stat_endExit
   
   These two measure the time taken in shutdownHaskell().
   -------------------------------------------------------------------------- */

194 195 196
void
stat_startExit(void)
{
197 198 199
    Ticks user, elapsed;

    getProcessTimes(&user, &elapsed);
200 201 202

    MutElapsedStamp = elapsed;
    MutElapsedTime = elapsed - GCe_tot_time -
203
	PROF_VAL(RPe_tot_time + HCe_tot_time) - InitElapsedStamp;
204
    if (MutElapsedTime < 0) { MutElapsedTime = 0; }	/* sometimes -0.00 */
205

206
    MutUserTime = user - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime;
207
    if (MutUserTime < 0) { MutUserTime = 0; }
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
208 209 210 211 212 213 214 215 216 217

#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
218 219 220 221 222
}

void
stat_endExit(void)
{
223 224 225
    Ticks user, elapsed;

    getProcessTimes(&user, &elapsed);
226 227 228

    ExitUserTime = user - MutUserTime - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime;
    ExitElapsedTime = elapsed - MutElapsedStamp;
229 230 231 232 233 234
    if (ExitUserTime < 0) {
	ExitUserTime = 0;
    }
    if (ExitElapsedTime < 0) {
	ExitElapsedTime = 0;
    }
235 236
}

237 238 239 240 241 242
/* -----------------------------------------------------------------------------
   Called at the beginning of each GC
   -------------------------------------------------------------------------- */

static nat rub_bell = 0;

chak's avatar
chak committed
243 244 245 246 247
/*  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
 */
248 249 250 251 252 253 254
void
stat_startGC(void)
{
    nat bell = RtsFlags.GcFlags.ringBell;

    if (bell) {
	if (bell > 1) {
255
	    debugBelch(" GC ");
256 257
	    rub_bell = 1;
	} else {
258
	    debugBelch("\007");
259 260 261
	}
    }

chak's avatar
chak committed
262
#if defined(PROFILING) || defined(DEBUG)
263
    GC_start_time = getProcessCPUTime();  // needed in mut_user_time_during_GC()
chak's avatar
chak committed
264 265
#endif

266
    if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
chak's avatar
chak committed
267
#if !defined(PROFILING) && !defined(DEBUG)
268
        GC_start_time = getProcessCPUTime();
chak's avatar
chak committed
269
#endif
270
	GCe_start_time = getProcessElapsedTime();
271
	if (RtsFlags.GcFlags.giveStats) {
272
	    GC_start_faults = getPageFaults();
273 274
	}
    }
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
275 276 277 278 279 280 281 282 283

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

284 285 286 287 288 289 290
}

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

void
291
stat_endGC (lnat alloc, lnat live, lnat copied, 
292
	    lnat scavd_copied, lnat gen)
293
{
294
    if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
295
	Ticks time, etime, gc_time, gc_etime;
296
	
297
	getProcessTimes(&time, &etime);
298 299 300
	gc_time  = time - GC_start_time;
	gc_etime = etime - GCe_start_time;
	
301
	if (RtsFlags.GcFlags.giveStats == VERBOSE_GC_STATS) {
302
	    nat faults = getPageFaults();
303
	    
304
	    statsPrintf("%9ld %9ld %9ld",
305 306
		    alloc*sizeof(W_), (copied+scavd_copied)*sizeof(W_), 
			live*sizeof(W_));
307
	    statsPrintf(" %5.2f %5.2f %7.2f %7.2f %4ld %4ld  (Gen: %2ld)\n", 
308 309 310 311
		    TICK_TO_DBL(gc_time),
		    TICK_TO_DBL(gc_etime),
		    TICK_TO_DBL(time),
		    TICK_TO_DBL(etime - ElapsedTimeStart),
312 313
		    faults - GC_start_faults,
		    GC_start_faults - GC_end_faults,
314
		    gen);
315 316

	    GC_end_faults = faults;
317
	    statsFlush();
318 319
	}

chak's avatar
chak committed
320
	GC_coll_times[gen] += gc_time;
321

322
	GC_tot_copied += (ullong) copied;
323
	GC_tot_scavd_copied += (ullong) scavd_copied;
324
	GC_tot_alloc  += (ullong) alloc;
325 326
	GC_tot_time   += gc_time;
	GCe_tot_time  += gc_etime;
327
	
328
#if defined(THREADED_RTS)
329
	{
330 331 332 333
	    Task *task;
	    if ((task = myTask()) != NULL) {
		task->gc_time += gc_time;
		task->gc_etime += gc_etime;
334 335 336 337
	    }
	}
#endif

338
	if (gen == RtsFlags.GcFlags.generations-1) { /* major GC? */
339 340 341 342 343
	    if (live > MaxResidency) {
		MaxResidency = live;
	    }
	    ResidencySamples++;
	    AvgResidency += live;
344
	}
345 346 347
    }

    if (rub_bell) {
348
	debugBelch("\b\b\b  \b\b\b");
349 350
	rub_bell = 0;
    }
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
351 352 353 354 355 356 357 358

#if USE_PAPI
    if(papi_is_reporting) {
      /* Switch to counting mutator events */
      papi_stop_gc_count();
      papi_start_mutator_count();
    }
#endif
359 360
}

361 362 363
/* -----------------------------------------------------------------------------
   Called at the beginning of each Retainer Profiliing
   -------------------------------------------------------------------------- */
364 365 366
#ifdef PROFILING
void
stat_startRP(void)
367
{
368 369
    Ticks user, elapsed;
    getProcessTimes( &user, &elapsed );
370 371 372

    RP_start_time = user;
    RPe_start_time = elapsed;
373
}
sof's avatar
sof committed
374
#endif /* PROFILING */
375 376 377 378

/* -----------------------------------------------------------------------------
   Called at the end of each Retainer Profiliing
   -------------------------------------------------------------------------- */
379 380 381 382

#ifdef PROFILING
void
stat_endRP(
383 384 385 386 387
  nat retainerGeneration,
#ifdef DEBUG_RETAINER
  nat maxCStackSize,
  int maxStackSize,
#endif
388
  double averageNumVisit)
389
{
390 391
    Ticks user, elapsed;
    getProcessTimes( &user, &elapsed );
392 393 394

    RP_tot_time += user - RP_start_time;
    RPe_tot_time += elapsed - RPe_start_time;
395 396 397 398 399 400 401 402 403

  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
404
#endif /* PROFILING */
405 406

/* -----------------------------------------------------------------------------
407
   Called at the beginning of each heap census
408
   -------------------------------------------------------------------------- */
409 410
#ifdef PROFILING
void
411
stat_startHeapCensus(void)
412
{
413 414
    Ticks user, elapsed;
    getProcessTimes( &user, &elapsed );
415 416 417

    HC_start_time = user;
    HCe_start_time = elapsed;
418
}
sof's avatar
sof committed
419
#endif /* PROFILING */
420 421

/* -----------------------------------------------------------------------------
422
   Called at the end of each heap census
423
   -------------------------------------------------------------------------- */
424 425
#ifdef PROFILING
void
426
stat_endHeapCensus(void) 
427
{
428 429
    Ticks user, elapsed;
    getProcessTimes( &user, &elapsed );
430 431 432

    HC_tot_time += user - HC_start_time;
    HCe_tot_time += elapsed - HCe_start_time;
433
}
sof's avatar
sof committed
434
#endif /* PROFILING */
435

436 437 438 439 440 441 442 443
/* -----------------------------------------------------------------------------
   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
444 445 446 447 448 449 450 451 452 453 454 455 456 457 458 459 460 461 462 463 464 465 466 467 468 469 470 471 472 473 474 475 476 477 478 479 480 481 482 483 484 485 486 487 488 489
#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)


490 491 492
void
stat_exit(int alloc)
{
493
    if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
494 495

	char temp[BIG_STRING_LEN];
496 497
	Ticks time;
	Ticks etime;
498
	nat g, total_collections = 0;
499

500 501
	getProcessTimes( &time, &etime );
	etime -= ElapsedTimeStart;
502 503

	GC_tot_alloc += alloc;
504

505 506 507
	/* Count total garbage collections */
	for (g = 0; g < RtsFlags.GcFlags.generations; g++)
	    total_collections += generations[g].collections;
508

509 510 511 512
	/* 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;
	
513 514 515
	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);
516 517
	}

518
	if (RtsFlags.GcFlags.giveStats >= SUMMARY_GC_STATS) {
519 520
	    ullong_format_string(GC_tot_alloc*sizeof(W_), 
				 temp, rtsTrue/*commas*/);
521
	    statsPrintf("%11s bytes allocated in the heap\n", temp);
522 523 524

	    ullong_format_string(GC_tot_copied*sizeof(W_), 
				 temp, rtsTrue/*commas*/);
525
	    statsPrintf("%11s bytes copied during GC (scavenged)\n", temp);
526

527 528 529 530
	    ullong_format_string(GC_tot_scavd_copied*sizeof(W_), 
				 temp, rtsTrue/*commas*/);
	    statsPrintf("%11s bytes copied during GC (not scavenged)\n", temp);
  
531 532
	    if ( ResidencySamples > 0 ) {
		ullong_format_string(MaxResidency*sizeof(W_), 
533
				     temp, rtsTrue/*commas*/);
534
		statsPrintf("%11s bytes maximum residency (%ld sample(s))\n",
535 536
			temp, ResidencySamples);
	    }
537
	    statsPrintf("\n");
538 539 540

	    /* Print garbage collections in each gen */
	    for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
541
		statsPrintf("%11d collections in generation %d (%6.2fs)\n", 
542 543 544 545
			generations[g].collections, g, 
			TICK_TO_DBL(GC_coll_times[g]));
	    }

546
	    statsPrintf("\n%11ld Mb total memory in use\n\n", 
547
		    mblocks_allocated * MBLOCK_SIZE / (1024 * 1024));
548

549
#if defined(THREADED_RTS)
550 551
	    {
		nat i;
552 553 554 555
		Task *task;
		for (i = 0, task = all_tasks; 
		     task != NULL; 
		     i++, task = task->all_link) {
556 557 558
		    statsPrintf("  Task %2d %-8s :  MUT time: %6.2fs  (%6.2fs elapsed)\n"
			    "                      GC  time: %6.2fs  (%6.2fs elapsed)\n\n", 
				i,
559 560 561 562 563
				(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));
564 565 566 567
		}
	    }
#endif

568
	    statsPrintf("  INIT  time  %6.2fs  (%6.2fs elapsed)\n",
569
		    TICK_TO_DBL(InitUserTime), TICK_TO_DBL(InitElapsedTime));
570
	    statsPrintf("  MUT   time  %6.2fs  (%6.2fs elapsed)\n",
571
		    TICK_TO_DBL(MutUserTime), TICK_TO_DBL(MutElapsedTime));
572
	    statsPrintf("  GC    time  %6.2fs  (%6.2fs elapsed)\n",
573
		    TICK_TO_DBL(GC_tot_time), TICK_TO_DBL(GCe_tot_time));
574
#ifdef PROFILING
575
	    statsPrintf("  RP    time  %6.2fs  (%6.2fs elapsed)\n",
576
		    TICK_TO_DBL(RP_tot_time), TICK_TO_DBL(RPe_tot_time));
577
	    statsPrintf("  PROF  time  %6.2fs  (%6.2fs elapsed)\n",
578
		    TICK_TO_DBL(HC_tot_time), TICK_TO_DBL(HCe_tot_time));
579
#endif 
580
	    statsPrintf("  EXIT  time  %6.2fs  (%6.2fs elapsed)\n",
581
		    TICK_TO_DBL(ExitUserTime), TICK_TO_DBL(ExitElapsedTime));
582
	    statsPrintf("  Total time  %6.2fs  (%6.2fs elapsed)\n\n",
583
		    TICK_TO_DBL(time), TICK_TO_DBL(etime));
584
	    statsPrintf("  %%GC time     %5.1f%%  (%.1f%% elapsed)\n\n",
585
		    TICK_TO_DBL(GC_tot_time)*100/TICK_TO_DBL(time),
sof's avatar
sof committed
586
		    TICK_TO_DBL(GCe_tot_time)*100/TICK_TO_DBL(etime));
587

588
	    if (time - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time) == 0)
589 590 591 592
		ullong_format_string(0, temp, rtsTrue/*commas*/);
	    else
		ullong_format_string(
		    (ullong)((GC_tot_alloc*sizeof(W_))/
sof's avatar
sof committed
593
			     TICK_TO_DBL(time - GC_tot_time - 
594
					 PROF_VAL(RP_tot_time + HC_tot_time))),
595 596
		    temp, rtsTrue/*commas*/);
	    
597
	    statsPrintf("  Alloc rate    %s bytes per MUT second\n\n", temp);
598
	
599
	    statsPrintf("  Productivity %5.1f%% of total user, %.1f%% of total elapsed\n\n",
sof's avatar
sof committed
600
		    TICK_TO_DBL(time - GC_tot_time - 
601
				PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime) * 100 
602
		    / TICK_TO_DBL(time), 
sof's avatar
sof committed
603
		    TICK_TO_DBL(time - GC_tot_time - 
604
				PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime) * 100 
605
		    / TICK_TO_DBL(etime));
Simon Marlow's avatar
Simon Marlow committed
606 607 608 609 610 611 612 613 614

            /*
            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
615 616 617 618 619
#if USE_PAPI
	    /* PAPI reporting, should put somewhere else?
	     * Note that the cycles are counted _after_ the initialization of the RTS -- AR */

	    statsPrintf("  -- CPU Mutator counters --\n");
620
	    papi_mut_cycles();
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
621 622 623
	    papi_report(MutatorCounters);

	    statsPrintf("\n  -- CPU GC counters --\n");
624
	    papi_gc_cycles();
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
625 626
	    papi_report(GCCounters);
#endif
627 628
	}

629
	if (RtsFlags.GcFlags.giveStats == ONELINE_GC_STATS) {
rrt's avatar
rrt committed
630
	  /* print the long long separately to avoid bugginess on mingwin (2001-07-02, mingw-0.5) */
631
	  statsPrintf("<<ghc: %llu bytes, ", GC_tot_alloc*(ullong)sizeof(W_));
632
	  statsPrintf("%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
633
		    total_collections,
634 635
		    ResidencySamples == 0 ? 0 : 
		        AvgResidency*sizeof(W_)/ResidencySamples, 
636
		    MaxResidency*sizeof(W_), 
rrt's avatar
rrt committed
637 638
		    ResidencySamples,
		    (unsigned long)(mblocks_allocated * MBLOCK_SIZE / (1024L * 1024L)),
639 640 641 642
		    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));
	}
643

644 645
	statsFlush();
	statsClose();
646
    }
647 648 649
    if (GC_coll_times)
      stgFree(GC_coll_times);
    GC_coll_times = NULL;
650
}
651 652 653 654 655 656

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

   Produce some detailed info on the state of the generational GC.
   -------------------------------------------------------------------------- */
657
#ifdef DEBUG
658
void
659
statDescribeGens(void)
660
{
661 662
  nat g, s, mut, lge;
  lnat live;
663 664 665
  bdescr *bd;
  step *step;

666
  debugBelch(
Simon Marlow's avatar
Simon Marlow committed
667 668
"     Gen    Steps      Max  Mut-list  Step   Blocks     Live    Large\n"
"                    Blocks     Bytes                          Objects\n");
669

670
  mut = 0;
671
  for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
672
      for (bd = generations[g].mut_list; bd != NULL; bd = bd->link) {
Simon Marlow's avatar
Simon Marlow committed
673
	  mut += (bd->free - bd->start) * sizeof(W_);
674 675 676 677
      }

    debugBelch("%8d %8d %8d %9d", g, generations[g].n_steps,
	    generations[g].max_blocks, mut);
678 679 680 681

    for (s = 0; s < generations[g].n_steps; s++) {
      step = &generations[g].steps[s];
      live = 0;
682 683 684 685
      for (bd = step->large_objects, lge = 0; bd; bd = bd->link) {
	lge++;
      }
      live = step->n_large_blocks * BLOCK_SIZE;
686
      bd = step->blocks;
687 688 689
      // This live figure will be slightly less that the "live" figure
      // given by +RTS -Sstderr, because we take don't count the
      // slop at the end of each block.
690
      for (; bd; bd = bd->link) {
691 692 693
	live += (bd->free - bd->start) * sizeof(W_);
      }
      if (s != 0) {
694
	debugBelch("%36s","");
695
      }
Simon Marlow's avatar
Simon Marlow committed
696
      debugBelch("%6d %8d %8ld %8d\n", s, step->n_blocks,
697 698 699
	      live, lge);
    }
  }
700
  debugBelch("\n");
701
}
702
#endif
703 704 705 706 707 708

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

709 710
extern HsInt64 getAllocations( void ) 
{ return (HsInt64)total_allocated * sizeof(W_); }
711 712 713 714 715

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

mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
716
void
717 718 719 720 721 722 723 724 725 726 727 728 729 730 731 732 733 734 735 736 737 738 739 740 741 742 743 744 745 746 747
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);
    }
}