Stats.c 22.2 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 50
static ullong GC_par_max_copied = 0;
static ullong GC_par_avg_copied = 0;

51 52
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 */
53

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

58 59
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
60
#endif
61

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

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

static lnat GC_start_faults = 0, GC_end_faults = 0;

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

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

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

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

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

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

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

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

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

/* -----------------------------------------------------------------------------
   Initialisation time...
   -------------------------------------------------------------------------- */
161 162

void
163
stat_startInit(void)
164
{
165
    Ticks elapsed;
166

167
    elapsed = getProcessElapsedTime();
168
    ElapsedTimeStart = elapsed;
169 170 171
}

void 
172
stat_endInit(void)
173
{
174 175 176 177
    Ticks user, elapsed;

    getProcessTimes(&user, &elapsed);

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

197 198 199 200 201 202
/* -----------------------------------------------------------------------------
   stat_startExit and stat_endExit
   
   These two measure the time taken in shutdownHaskell().
   -------------------------------------------------------------------------- */

203 204 205
void
stat_startExit(void)
{
206 207 208
    Ticks user, elapsed;

    getProcessTimes(&user, &elapsed);
209 210 211

    MutElapsedStamp = elapsed;
    MutElapsedTime = elapsed - GCe_tot_time -
212
	PROF_VAL(RPe_tot_time + HCe_tot_time) - InitElapsedStamp;
213
    if (MutElapsedTime < 0) { MutElapsedTime = 0; }	/* sometimes -0.00 */
214

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

#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
227 228 229 230 231
}

void
stat_endExit(void)
{
232 233 234
    Ticks user, elapsed;

    getProcessTimes(&user, &elapsed);
235 236 237

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

246 247 248 249 250 251
/* -----------------------------------------------------------------------------
   Called at the beginning of each GC
   -------------------------------------------------------------------------- */

static nat rub_bell = 0;

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

    if (bell) {
	if (bell > 1) {
264
	    debugBelch(" GC ");
265 266
	    rub_bell = 1;
	} else {
267
	    debugBelch("\007");
268 269 270
	}
    }

chak's avatar
chak committed
271
#if defined(PROFILING) || defined(DEBUG)
272
    GC_start_time = getProcessCPUTime();  // needed in mut_user_time_during_GC()
chak's avatar
chak committed
273 274
#endif

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

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

293 294 295 296 297 298 299
}

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

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

	    GC_end_faults = faults;
326
	    statsFlush();
327 328
	}

chak's avatar
chak committed
329
	GC_coll_times[gen] += gc_time;
330
	GC_coll_etimes[gen] += gc_etime;
331

332 333
	GC_tot_copied += (ullong) copied;
	GC_tot_alloc  += (ullong) alloc;
334 335
        GC_par_max_copied += (ullong) max_copied;
        GC_par_avg_copied += (ullong) avg_copied;
336 337
	GC_tot_time   += gc_time;
	GCe_tot_time  += gc_etime;
338
	
339
#if defined(THREADED_RTS)
340
	{
341 342 343 344
	    Task *task;
	    if ((task = myTask()) != NULL) {
		task->gc_time += gc_time;
		task->gc_etime += gc_etime;
345 346 347 348
	    }
	}
#endif

349
	if (gen == RtsFlags.GcFlags.generations-1) { /* major GC? */
350 351 352 353 354
	    if (live > MaxResidency) {
		MaxResidency = live;
	    }
	    ResidencySamples++;
	    AvgResidency += live;
355
	}
356 357 358
    }

    if (rub_bell) {
359
	debugBelch("\b\b\b  \b\b\b");
360 361
	rub_bell = 0;
    }
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
362 363 364 365

#if USE_PAPI
    if(papi_is_reporting) {
      /* Switch to counting mutator events */
366 367 368 369 370
      if (gen == 0) {
          papi_stop_gc0_count();
      } else {
          papi_stop_gc1_count();
      }
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
371 372 373
      papi_start_mutator_count();
    }
#endif
374 375
}

376 377 378
/* -----------------------------------------------------------------------------
   Called at the beginning of each Retainer Profiliing
   -------------------------------------------------------------------------- */
379 380 381
#ifdef PROFILING
void
stat_startRP(void)
382
{
383 384
    Ticks user, elapsed;
    getProcessTimes( &user, &elapsed );
385 386 387

    RP_start_time = user;
    RPe_start_time = elapsed;
388
}
sof's avatar
sof committed
389
#endif /* PROFILING */
390 391 392 393

/* -----------------------------------------------------------------------------
   Called at the end of each Retainer Profiliing
   -------------------------------------------------------------------------- */
394 395 396 397

#ifdef PROFILING
void
stat_endRP(
398 399 400 401 402
  nat retainerGeneration,
#ifdef DEBUG_RETAINER
  nat maxCStackSize,
  int maxStackSize,
#endif
403
  double averageNumVisit)
404
{
405 406
    Ticks user, elapsed;
    getProcessTimes( &user, &elapsed );
407 408 409

    RP_tot_time += user - RP_start_time;
    RPe_tot_time += elapsed - RPe_start_time;
410 411 412 413 414 415 416 417 418

  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
419
#endif /* PROFILING */
420 421

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

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

/* -----------------------------------------------------------------------------
437
   Called at the end of each heap census
438
   -------------------------------------------------------------------------- */
439 440
#ifdef PROFILING
void
441
stat_endHeapCensus(void) 
442
{
443 444
    Ticks user, elapsed;
    getProcessTimes( &user, &elapsed );
445 446 447

    HC_tot_time += user - HC_start_time;
    HCe_tot_time += elapsed - HCe_start_time;
448
}
sof's avatar
sof committed
449
#endif /* PROFILING */
450

451 452 453 454 455 456 457 458
/* -----------------------------------------------------------------------------
   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
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 499 500 501 502 503 504
#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)


505 506 507
void
stat_exit(int alloc)
{
508
    if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
509 510

	char temp[BIG_STRING_LEN];
511 512
	Ticks time;
	Ticks etime;
513
	nat g, total_collections = 0;
514

515 516
	getProcessTimes( &time, &etime );
	etime -= ElapsedTimeStart;
517 518

	GC_tot_alloc += alloc;
519

520 521 522
	/* Count total garbage collections */
	for (g = 0; g < RtsFlags.GcFlags.generations; g++)
	    total_collections += generations[g].collections;
523

524 525 526 527
	/* 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;
	
528 529 530
	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);
531 532
	}

533
	if (RtsFlags.GcFlags.giveStats >= SUMMARY_GC_STATS) {
534 535
	    ullong_format_string(GC_tot_alloc*sizeof(W_), 
				 temp, rtsTrue/*commas*/);
536
	    statsPrintf("%16s bytes allocated in the heap\n", temp);
537 538 539

	    ullong_format_string(GC_tot_copied*sizeof(W_), 
				 temp, rtsTrue/*commas*/);
540
	    statsPrintf("%16s bytes copied during GC\n", temp);
541 542 543

	    if ( ResidencySamples > 0 ) {
		ullong_format_string(MaxResidency*sizeof(W_), 
544
				     temp, rtsTrue/*commas*/);
545
		statsPrintf("%16s bytes maximum residency (%ld sample(s))\n",
546 547
			temp, ResidencySamples);
	    }
548 549
	    statsPrintf("%16ld MB total memory in use\n\n", 
		    mblocks_allocated * MBLOCK_SIZE / (1024 * 1024));
550 551 552

	    /* Print garbage collections in each gen */
	    for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
553 554 555
		statsPrintf("  Generation %d: %5d collections, %5d parallel, %5.2fs, %5.2fs elapsed\n", 
                            g, generations[g].collections, 
                            generations[g].par_collections,
556 557
                        TICK_TO_DBL(GC_coll_times[g]),
                        TICK_TO_DBL(GC_coll_etimes[g]));
558 559
	    }

560 561 562 563 564 565 566 567 568 569 570
#if defined(THREADED_RTS)
            if (RtsFlags.ParFlags.gcThreads > 1) {
                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,
                            RtsFlags.ParFlags.gcThreads
                    );
            }
#endif

	    statsPrintf("\n");
571

572
#if defined(THREADED_RTS)
573 574
	    {
		nat i;
575 576 577 578
		Task *task;
		for (i = 0, task = all_tasks; 
		     task != NULL; 
		     i++, task = task->all_link) {
579 580 581
		    statsPrintf("  Task %2d %-8s :  MUT time: %6.2fs  (%6.2fs elapsed)\n"
			    "                      GC  time: %6.2fs  (%6.2fs elapsed)\n\n", 
				i,
582 583 584 585 586
				(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));
587 588 589 590
		}
	    }
#endif

591
	    statsPrintf("  INIT  time  %6.2fs  (%6.2fs elapsed)\n",
592
		    TICK_TO_DBL(InitUserTime), TICK_TO_DBL(InitElapsedTime));
593
	    statsPrintf("  MUT   time  %6.2fs  (%6.2fs elapsed)\n",
594
		    TICK_TO_DBL(MutUserTime), TICK_TO_DBL(MutElapsedTime));
595
	    statsPrintf("  GC    time  %6.2fs  (%6.2fs elapsed)\n",
596
		    TICK_TO_DBL(GC_tot_time), TICK_TO_DBL(GCe_tot_time));
597
#ifdef PROFILING
598
	    statsPrintf("  RP    time  %6.2fs  (%6.2fs elapsed)\n",
599
		    TICK_TO_DBL(RP_tot_time), TICK_TO_DBL(RPe_tot_time));
600
	    statsPrintf("  PROF  time  %6.2fs  (%6.2fs elapsed)\n",
601
		    TICK_TO_DBL(HC_tot_time), TICK_TO_DBL(HCe_tot_time));
602
#endif 
603
	    statsPrintf("  EXIT  time  %6.2fs  (%6.2fs elapsed)\n",
604
		    TICK_TO_DBL(ExitUserTime), TICK_TO_DBL(ExitElapsedTime));
605
	    statsPrintf("  Total time  %6.2fs  (%6.2fs elapsed)\n\n",
606
		    TICK_TO_DBL(time), TICK_TO_DBL(etime));
607
	    statsPrintf("  %%GC time     %5.1f%%  (%.1f%% elapsed)\n\n",
608
		    TICK_TO_DBL(GC_tot_time)*100/TICK_TO_DBL(time),
sof's avatar
sof committed
609
		    TICK_TO_DBL(GCe_tot_time)*100/TICK_TO_DBL(etime));
610

611
	    if (time - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time) == 0)
612 613 614 615
		ullong_format_string(0, temp, rtsTrue/*commas*/);
	    else
		ullong_format_string(
		    (ullong)((GC_tot_alloc*sizeof(W_))/
sof's avatar
sof committed
616
			     TICK_TO_DBL(time - GC_tot_time - 
617
					 PROF_VAL(RP_tot_time + HC_tot_time))),
618 619
		    temp, rtsTrue/*commas*/);
	    
620
	    statsPrintf("  Alloc rate    %s bytes per MUT second\n\n", temp);
621
	
622
	    statsPrintf("  Productivity %5.1f%% of total user, %.1f%% of total elapsed\n\n",
sof's avatar
sof committed
623
		    TICK_TO_DBL(time - GC_tot_time - 
624
				PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime) * 100 
625
		    / TICK_TO_DBL(time), 
sof's avatar
sof committed
626
		    TICK_TO_DBL(time - GC_tot_time - 
627
				PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime) * 100 
628
		    / TICK_TO_DBL(etime));
Simon Marlow's avatar
Simon Marlow committed
629 630 631 632 633 634 635 636 637

            /*
            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
638
#if USE_PAPI
639
            papi_stats_report();
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
640
#endif
641 642
	}

643
	if (RtsFlags.GcFlags.giveStats == ONELINE_GC_STATS) {
rrt's avatar
rrt committed
644
	  /* print the long long separately to avoid bugginess on mingwin (2001-07-02, mingw-0.5) */
645
	  statsPrintf("<<ghc: %llu bytes, ", GC_tot_alloc*(ullong)sizeof(W_));
646
	  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
647
		    total_collections,
648 649
		    ResidencySamples == 0 ? 0 : 
		        AvgResidency*sizeof(W_)/ResidencySamples, 
650
		    MaxResidency*sizeof(W_), 
rrt's avatar
rrt committed
651 652
		    ResidencySamples,
		    (unsigned long)(mblocks_allocated * MBLOCK_SIZE / (1024L * 1024L)),
653 654 655 656
		    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));
	}
657

simonmarhaskell@gmail.com's avatar
simonmarhaskell@gmail.com committed
658 659 660 661 662 663 664 665 666 667 668 669 670 671 672 673
#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("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

674 675
	statsFlush();
	statsClose();
676
    }
simonmarhaskell@gmail.com's avatar
simonmarhaskell@gmail.com committed
677

678 679 680
    if (GC_coll_times)
      stgFree(GC_coll_times);
    GC_coll_times = NULL;
simonmarhaskell@gmail.com's avatar
simonmarhaskell@gmail.com committed
681 682 683
    if (GC_coll_etimes)
      stgFree(GC_coll_etimes);
    GC_coll_etimes = NULL;
684
}
685 686 687 688 689 690 691

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

   Produce some detailed info on the state of the generational GC.
   -------------------------------------------------------------------------- */
void
692
statDescribeGens(void)
693
{
694
  nat g, s, mut, lge;
695 696
  lnat live, slop;
  lnat tot_live, tot_slop;
697 698 699
  bdescr *bd;
  step *step;

700
  debugBelch(
701 702 703 704
"-----------------------------------------------------------------\n"
"  Gen     Max  Mut-list  Step   Blocks    Large     Live     Slop\n"
"       Blocks     Bytes                 Objects                  \n"
"-----------------------------------------------------------------\n");
705

706 707
  tot_live = 0;
  tot_slop = 0;
708
  for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
709
      mut = 0;
710
      for (bd = generations[g].mut_list; bd != NULL; bd = bd->link) {
Simon Marlow's avatar
Simon Marlow committed
711
	  mut += (bd->free - bd->start) * sizeof(W_);
712 713
      }

714
    debugBelch("%5d %7d %9d", g, generations[g].max_blocks, mut);
715 716 717

    for (s = 0; s < generations[g].n_steps; s++) {
      step = &generations[g].steps[s];
718 719 720
      for (bd = step->large_objects, lge = 0; bd; bd = bd->link) {
	lge++;
      }
721
      live = step->n_words + countOccupied(step->large_objects);
722
      if (s != 0) {
723
	debugBelch("%23s","");
724
      }
725 726 727 728 729
      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;
730 731
    }
  }
732 733 734
  debugBelch("-----------------------------------------------------------------\n");
  debugBelch("%48s%8ld %8ld\n","",tot_live*sizeof(W_),tot_slop*sizeof(W_));
  debugBelch("-----------------------------------------------------------------\n");
735
  debugBelch("\n");
736
}
737 738 739 740 741 742

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

743 744
extern HsInt64 getAllocations( void ) 
{ return (HsInt64)total_allocated * sizeof(W_); }
745 746 747 748 749

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

mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
750
void
751 752 753 754 755 756 757 758 759 760 761 762 763 764 765 766 767 768 769 770 771 772 773 774 775 776 777 778 779 780 781
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);
    }
}