Stats.c 20.9 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 20 21
#include "GC.h"
#include "GCUtils.h"
#include "Evac.h"
22

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

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

30
#define TICK_TO_DBL(t) ((double)(t) / TICKS_PER_SECOND)
31

32
static Ticks ElapsedTimeStart = 0;
33

34 35 36
static Ticks InitUserTime     = 0;
static Ticks InitElapsedTime  = 0;
static Ticks InitElapsedStamp = 0;
37

38 39 40
static Ticks MutUserTime      = 0;
static Ticks MutElapsedTime   = 0;
static Ticks MutElapsedStamp  = 0;
41

42 43
static Ticks ExitUserTime     = 0;
static Ticks ExitElapsedTime  = 0;
44

45 46 47
static ullong GC_tot_alloc        = 0;
static ullong GC_tot_copied       = 0;

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 69 70

static lnat GC_start_faults = 0, GC_end_faults = 0;

71
static Ticks *GC_coll_times;
72
static Ticks *GC_coll_etimes;
73

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

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

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

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

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

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

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

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

/* -----------------------------------------------------------------------------
   Initialisation time...
   -------------------------------------------------------------------------- */
158 159

void
160
stat_startInit(void)
161
{
162
    Ticks elapsed;
163

164
    elapsed = getProcessElapsedTime();
165
    ElapsedTimeStart = elapsed;
166 167 168
}

void 
169
stat_endInit(void)
170
{
171 172 173 174
    Ticks user, elapsed;

    getProcessTimes(&user, &elapsed);

175 176 177
    InitUserTime = user;
    InitElapsedStamp = elapsed; 
    if (ElapsedTimeStart > elapsed) {
178 179
	InitElapsedTime = 0;
    } else {
180
	InitElapsedTime = elapsed - ElapsedTimeStart;
181
    }
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
182 183 184 185 186 187 188 189 190 191
#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
192 193
}

194 195 196 197 198 199
/* -----------------------------------------------------------------------------
   stat_startExit and stat_endExit
   
   These two measure the time taken in shutdownHaskell().
   -------------------------------------------------------------------------- */

200 201 202
void
stat_startExit(void)
{
203 204 205
    Ticks user, elapsed;

    getProcessTimes(&user, &elapsed);
206 207 208

    MutElapsedStamp = elapsed;
    MutElapsedTime = elapsed - GCe_tot_time -
209
	PROF_VAL(RPe_tot_time + HCe_tot_time) - InitElapsedStamp;
210
    if (MutElapsedTime < 0) { MutElapsedTime = 0; }	/* sometimes -0.00 */
211

212
    MutUserTime = user - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime;
213
    if (MutUserTime < 0) { MutUserTime = 0; }
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
214 215 216 217 218 219 220 221 222 223

#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
224 225 226 227 228
}

void
stat_endExit(void)
{
229 230 231
    Ticks user, elapsed;

    getProcessTimes(&user, &elapsed);
232 233 234

    ExitUserTime = user - MutUserTime - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime;
    ExitElapsedTime = elapsed - MutElapsedStamp;
235 236 237 238 239 240
    if (ExitUserTime < 0) {
	ExitUserTime = 0;
    }
    if (ExitElapsedTime < 0) {
	ExitElapsedTime = 0;
    }
241 242
}

243 244 245 246 247 248
/* -----------------------------------------------------------------------------
   Called at the beginning of each GC
   -------------------------------------------------------------------------- */

static nat rub_bell = 0;

chak's avatar
chak committed
249 250 251 252 253
/*  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
 */
254 255 256 257 258 259 260
void
stat_startGC(void)
{
    nat bell = RtsFlags.GcFlags.ringBell;

    if (bell) {
	if (bell > 1) {
261
	    debugBelch(" GC ");
262 263
	    rub_bell = 1;
	} else {
264
	    debugBelch("\007");
265 266 267
	}
    }

chak's avatar
chak committed
268
#if defined(PROFILING) || defined(DEBUG)
269
    GC_start_time = getProcessCPUTime();  // needed in mut_user_time_during_GC()
chak's avatar
chak committed
270 271
#endif

272
    if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
chak's avatar
chak committed
273
#if !defined(PROFILING) && !defined(DEBUG)
274
        GC_start_time = getProcessCPUTime();
chak's avatar
chak committed
275
#endif
276
	GCe_start_time = getProcessElapsedTime();
277
	if (RtsFlags.GcFlags.giveStats) {
278
	    GC_start_faults = getPageFaults();
279 280
	}
    }
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
281 282 283 284 285 286 287 288 289

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

290 291 292 293 294 295 296
}

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

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

	    GC_end_faults = faults;
322
	    statsFlush();
323 324
	}

chak's avatar
chak committed
325
	GC_coll_times[gen] += gc_time;
326
	GC_coll_etimes[gen] += gc_etime;
327

328 329
	GC_tot_copied += (ullong) copied;
	GC_tot_alloc  += (ullong) alloc;
330 331
	GC_tot_time   += gc_time;
	GCe_tot_time  += gc_etime;
332
	
333
#if defined(THREADED_RTS)
334
	{
335 336 337 338
	    Task *task;
	    if ((task = myTask()) != NULL) {
		task->gc_time += gc_time;
		task->gc_etime += gc_etime;
339 340 341 342
	    }
	}
#endif

343
	if (gen == RtsFlags.GcFlags.generations-1) { /* major GC? */
344 345 346 347 348
	    if (live > MaxResidency) {
		MaxResidency = live;
	    }
	    ResidencySamples++;
	    AvgResidency += live;
349
	}
350 351 352
    }

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

#if USE_PAPI
    if(papi_is_reporting) {
      /* Switch to counting mutator events */
360 361 362 363 364
      if (gen == 0) {
          papi_stop_gc0_count();
      } else {
          papi_stop_gc1_count();
      }
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
365 366 367
      papi_start_mutator_count();
    }
#endif
368 369
}

370 371 372
/* -----------------------------------------------------------------------------
   Called at the beginning of each Retainer Profiliing
   -------------------------------------------------------------------------- */
373 374 375
#ifdef PROFILING
void
stat_startRP(void)
376
{
377 378
    Ticks user, elapsed;
    getProcessTimes( &user, &elapsed );
379 380 381

    RP_start_time = user;
    RPe_start_time = elapsed;
382
}
sof's avatar
sof committed
383
#endif /* PROFILING */
384 385 386 387

/* -----------------------------------------------------------------------------
   Called at the end of each Retainer Profiliing
   -------------------------------------------------------------------------- */
388 389 390 391

#ifdef PROFILING
void
stat_endRP(
392 393 394 395 396
  nat retainerGeneration,
#ifdef DEBUG_RETAINER
  nat maxCStackSize,
  int maxStackSize,
#endif
397
  double averageNumVisit)
398
{
399 400
    Ticks user, elapsed;
    getProcessTimes( &user, &elapsed );
401 402 403

    RP_tot_time += user - RP_start_time;
    RPe_tot_time += elapsed - RPe_start_time;
404 405 406 407 408 409 410 411 412

  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
413
#endif /* PROFILING */
414 415

/* -----------------------------------------------------------------------------
416
   Called at the beginning of each heap census
417
   -------------------------------------------------------------------------- */
418 419
#ifdef PROFILING
void
420
stat_startHeapCensus(void)
421
{
422 423
    Ticks user, elapsed;
    getProcessTimes( &user, &elapsed );
424 425 426

    HC_start_time = user;
    HCe_start_time = elapsed;
427
}
sof's avatar
sof committed
428
#endif /* PROFILING */
429 430

/* -----------------------------------------------------------------------------
431
   Called at the end of each heap census
432
   -------------------------------------------------------------------------- */
433 434
#ifdef PROFILING
void
435
stat_endHeapCensus(void) 
436
{
437 438
    Ticks user, elapsed;
    getProcessTimes( &user, &elapsed );
439 440 441

    HC_tot_time += user - HC_start_time;
    HCe_tot_time += elapsed - HCe_start_time;
442
}
sof's avatar
sof committed
443
#endif /* PROFILING */
444

445 446 447 448 449 450 451 452
/* -----------------------------------------------------------------------------
   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
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 490 491 492 493 494 495 496 497 498
#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)


499 500 501
void
stat_exit(int alloc)
{
502
    if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
503 504

	char temp[BIG_STRING_LEN];
505 506
	Ticks time;
	Ticks etime;
507
	nat g, total_collections = 0;
508

509 510
	getProcessTimes( &time, &etime );
	etime -= ElapsedTimeStart;
511 512

	GC_tot_alloc += alloc;
513

514 515 516
	/* Count total garbage collections */
	for (g = 0; g < RtsFlags.GcFlags.generations; g++)
	    total_collections += generations[g].collections;
517

518 519 520 521
	/* 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;
	
522 523 524
	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);
525 526
	}

527
	if (RtsFlags.GcFlags.giveStats >= SUMMARY_GC_STATS) {
528 529
	    ullong_format_string(GC_tot_alloc*sizeof(W_), 
				 temp, rtsTrue/*commas*/);
530
	    statsPrintf("%11s bytes allocated in the heap\n", temp);
531 532 533

	    ullong_format_string(GC_tot_copied*sizeof(W_), 
				 temp, rtsTrue/*commas*/);
534
	    statsPrintf("%11s bytes copied during GC\n", temp);
535 536 537

	    if ( ResidencySamples > 0 ) {
		ullong_format_string(MaxResidency*sizeof(W_), 
538
				     temp, rtsTrue/*commas*/);
539
		statsPrintf("%11s bytes maximum residency (%ld sample(s))\n",
540 541
			temp, ResidencySamples);
	    }
542
	    statsPrintf("\n");
543 544 545

	    /* Print garbage collections in each gen */
	    for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
546
		statsPrintf("%11d collections in generation %d, %6.2fs, %6.2fs elapsed\n", 
547
			generations[g].collections, g, 
548 549
                        TICK_TO_DBL(GC_coll_times[g]),
                        TICK_TO_DBL(GC_coll_etimes[g]));
550 551
	    }

552
	    statsPrintf("\n%11ld MB total memory in use\n\n", 
553
		    mblocks_allocated * MBLOCK_SIZE / (1024 * 1024));
554

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

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

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

            /*
            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
621
#if USE_PAPI
622
            papi_stats_report();
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
623
#endif
624 625
	}

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

641 642
	statsFlush();
	statsClose();
643
    }
644 645 646
    if (GC_coll_times)
      stgFree(GC_coll_times);
    GC_coll_times = NULL;
647 648 649 650 651 652 653 654 655 656 657 658 659 660 661 662 663

#if defined(THREADED_RTS) && defined(PROF_SPIN)
    {
	nat g, s;

	statsPrintf("recordMutableGen_sync: %"FMT_Word64"\n", recordMutableGen_sync.spin);
	statsPrintf("gc_alloc_block_sync: %"FMT_Word64"\n", gc_alloc_block_sync.spin);
	statsPrintf("static_objects_sync: %"FMT_Word64"\n", static_objects_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_todo: %"FMT_Word64"\n", g, s, generations[g].steps[s].sync_todo.spin);
		statsPrintf("gen[%d].steps[%d].sync_large_objects: %"FMT_Word64"\n", g, s, generations[g].steps[s].sync_large_objects.spin);
	    }
	}
    }
#endif
664
}
665 666 667 668 669 670 671

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

   Produce some detailed info on the state of the generational GC.
   -------------------------------------------------------------------------- */
void
672
statDescribeGens(void)
673
{
674 675
  nat g, s, mut, lge;
  lnat live;
676 677 678
  bdescr *bd;
  step *step;

679
  debugBelch(
Simon Marlow's avatar
Simon Marlow committed
680 681
"     Gen    Steps      Max  Mut-list  Step   Blocks     Live    Large\n"
"                    Blocks     Bytes                          Objects\n");
682

683
  mut = 0;
684
  for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
685
      for (bd = generations[g].mut_list; bd != NULL; bd = bd->link) {
Simon Marlow's avatar
Simon Marlow committed
686
	  mut += (bd->free - bd->start) * sizeof(W_);
687 688 689 690
      }

    debugBelch("%8d %8d %8d %9d", g, generations[g].n_steps,
	    generations[g].max_blocks, mut);
691 692 693 694

    for (s = 0; s < generations[g].n_steps; s++) {
      step = &generations[g].steps[s];
      live = 0;
695 696 697 698 699 700
      for (bd = step->large_objects, lge = 0; bd; bd = bd->link) {
	lge++;
      }
      // 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.
701
      live += countOccupied(step->blocks) + countOccupied(step->large_objects);
702
      if (s != 0) {
703
	debugBelch("%36s","");
704
      }
Simon Marlow's avatar
Simon Marlow committed
705
      debugBelch("%6d %8d %8ld %8d\n", s, step->n_blocks,
706 707 708
	      live, lge);
    }
  }
709
  debugBelch("\n");
710
}
711 712 713 714 715 716

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

717 718
extern HsInt64 getAllocations( void ) 
{ return (HsInt64)total_allocated * sizeof(W_); }
719 720 721 722 723

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

mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
724
void
725 726 727 728 729 730 731 732 733 734 735 736 737 738 739 740 741 742 743 744 745 746 747 748 749 750 751 752 753 754 755
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);
    }
}