Stats.c 20 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 44
static ullong GC_tot_alloc        = 0;
static ullong GC_tot_copied       = 0;

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

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

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

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

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

static lnat GC_start_faults = 0, GC_end_faults = 0;

68
static Ticks *GC_coll_times;
69

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

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

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

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

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

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

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

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

/* -----------------------------------------------------------------------------
   Initialisation time...
   -------------------------------------------------------------------------- */
149 150

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

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

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

    getProcessTimes(&user, &elapsed);

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

185 186 187 188 189 190
/* -----------------------------------------------------------------------------
   stat_startExit and stat_endExit
   
   These two measure the time taken in shutdownHaskell().
   -------------------------------------------------------------------------- */

191 192 193
void
stat_startExit(void)
{
194 195 196
    Ticks user, elapsed;

    getProcessTimes(&user, &elapsed);
197 198 199

    MutElapsedStamp = elapsed;
    MutElapsedTime = elapsed - GCe_tot_time -
200
	PROF_VAL(RPe_tot_time + HCe_tot_time) - InitElapsedStamp;
201
    if (MutElapsedTime < 0) { MutElapsedTime = 0; }	/* sometimes -0.00 */
202

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

#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
215 216 217 218 219
}

void
stat_endExit(void)
{
220 221 222
    Ticks user, elapsed;

    getProcessTimes(&user, &elapsed);
223 224 225

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

234 235 236 237 238 239
/* -----------------------------------------------------------------------------
   Called at the beginning of each GC
   -------------------------------------------------------------------------- */

static nat rub_bell = 0;

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

    if (bell) {
	if (bell > 1) {
252
	    debugBelch(" GC ");
253 254
	    rub_bell = 1;
	} else {
255
	    debugBelch("\007");
256 257 258
	}
    }

chak's avatar
chak committed
259
#if defined(PROFILING) || defined(DEBUG)
260
    GC_start_time = getProcessCPUTime();  // needed in mut_user_time_during_GC()
chak's avatar
chak committed
261 262
#endif

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

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

281 282 283 284 285 286 287
}

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

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

	    GC_end_faults = faults;
313
	    statsFlush();
314 315
	}

chak's avatar
chak committed
316
	GC_coll_times[gen] += gc_time;
317

318 319
	GC_tot_copied += (ullong) copied;
	GC_tot_alloc  += (ullong) alloc;
320 321
	GC_tot_time   += gc_time;
	GCe_tot_time  += gc_etime;
322
	
323
#if defined(THREADED_RTS)
324
	{
325 326 327 328
	    Task *task;
	    if ((task = myTask()) != NULL) {
		task->gc_time += gc_time;
		task->gc_etime += gc_etime;
329 330 331 332
	    }
	}
#endif

333
	if (gen == RtsFlags.GcFlags.generations-1) { /* major GC? */
334 335 336 337 338
	    if (live > MaxResidency) {
		MaxResidency = live;
	    }
	    ResidencySamples++;
	    AvgResidency += live;
339
	}
340 341 342
    }

    if (rub_bell) {
343
	debugBelch("\b\b\b  \b\b\b");
344 345
	rub_bell = 0;
    }
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
346 347 348 349

#if USE_PAPI
    if(papi_is_reporting) {
      /* Switch to counting mutator events */
350 351 352 353 354
      if (gen == 0) {
          papi_stop_gc0_count();
      } else {
          papi_stop_gc1_count();
      }
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
355 356 357
      papi_start_mutator_count();
    }
#endif
358 359
}

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

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

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

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

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

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

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

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

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

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

435 436 437 438 439 440 441 442
/* -----------------------------------------------------------------------------
   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
443 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
#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)


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

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

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

	GC_tot_alloc += alloc;
503

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

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

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

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

	    if ( ResidencySamples > 0 ) {
		ullong_format_string(MaxResidency*sizeof(W_), 
528
				     temp, rtsTrue/*commas*/);
529
		statsPrintf("%11s bytes maximum residency (%ld sample(s))\n",
530 531
			temp, ResidencySamples);
	    }
532
	    statsPrintf("\n");
533 534 535

	    /* Print garbage collections in each gen */
	    for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
536
		statsPrintf("%11d collections in generation %d (%6.2fs)\n", 
537 538 539 540
			generations[g].collections, g, 
			TICK_TO_DBL(GC_coll_times[g]));
	    }

541
	    statsPrintf("\n%11ld Mb total memory in use\n\n", 
542
		    mblocks_allocated * MBLOCK_SIZE / (1024 * 1024));
543

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

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

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

            /*
            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
610
#if USE_PAPI
611
            papi_stats_report();
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
612
#endif
613 614
	}

615
	if (RtsFlags.GcFlags.giveStats == ONELINE_GC_STATS) {
rrt's avatar
rrt committed
616
	  /* print the long long separately to avoid bugginess on mingwin (2001-07-02, mingw-0.5) */
617
	  statsPrintf("<<ghc: %llu bytes, ", GC_tot_alloc*(ullong)sizeof(W_));
618
	  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
619
		    total_collections,
620 621
		    ResidencySamples == 0 ? 0 : 
		        AvgResidency*sizeof(W_)/ResidencySamples, 
622
		    MaxResidency*sizeof(W_), 
rrt's avatar
rrt committed
623 624
		    ResidencySamples,
		    (unsigned long)(mblocks_allocated * MBLOCK_SIZE / (1024L * 1024L)),
625 626 627 628
		    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));
	}
629

630 631
	statsFlush();
	statsClose();
632
    }
633 634 635
    if (GC_coll_times)
      stgFree(GC_coll_times);
    GC_coll_times = NULL;
636
}
637 638 639 640 641 642

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

   Produce some detailed info on the state of the generational GC.
   -------------------------------------------------------------------------- */
643
#ifdef DEBUG
644
void
645
statDescribeGens(void)
646
{
647 648
  nat g, s, mut, lge;
  lnat live;
649 650 651
  bdescr *bd;
  step *step;

652
  debugBelch(
Simon Marlow's avatar
Simon Marlow committed
653 654
"     Gen    Steps      Max  Mut-list  Step   Blocks     Live    Large\n"
"                    Blocks     Bytes                          Objects\n");
655

656
  mut = 0;
657
  for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
658
      for (bd = generations[g].mut_list; bd != NULL; bd = bd->link) {
Simon Marlow's avatar
Simon Marlow committed
659
	  mut += (bd->free - bd->start) * sizeof(W_);
660 661 662 663
      }

    debugBelch("%8d %8d %8d %9d", g, generations[g].n_steps,
	    generations[g].max_blocks, mut);
664 665 666 667

    for (s = 0; s < generations[g].n_steps; s++) {
      step = &generations[g].steps[s];
      live = 0;
668 669 670 671
      for (bd = step->large_objects, lge = 0; bd; bd = bd->link) {
	lge++;
      }
      live = step->n_large_blocks * BLOCK_SIZE;
672
      bd = step->blocks;
673 674 675
      // 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.
676
      for (; bd; bd = bd->link) {
677 678 679
	live += (bd->free - bd->start) * sizeof(W_);
      }
      if (s != 0) {
680
	debugBelch("%36s","");
681
      }
Simon Marlow's avatar
Simon Marlow committed
682
      debugBelch("%6d %8d %8ld %8d\n", s, step->n_blocks,
683 684 685
	      live, lge);
    }
  }
686
  debugBelch("\n");
687
}
688
#endif
689 690 691 692 693 694

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

695 696
extern HsInt64 getAllocations( void ) 
{ return (HsInt64)total_allocated * sizeof(W_); }
697 698 699 700 701

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

mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
702
void
703 704 705 706 707 708 709 710 711 712 713 714 715 716 717 718 719 720 721 722 723 724 725 726 727 728 729 730 731 732 733
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);
    }
}