Stats.c 23.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
#include "GC.h"
20

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

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

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

30
static Ticks ElapsedTimeStart = 0;
31

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

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

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

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

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

49
50
static Ticks GC_start_time = 0,  GC_tot_time  = 0;  /* User GC Time */
static Ticks GCe_start_time = 0, GCe_tot_time = 0;  /* Elapsed GC time */
51

sof's avatar
sof committed
52
#ifdef PROFILING
53
54
static Ticks RP_start_time  = 0, RP_tot_time  = 0;  /* retainer prof user time */
static Ticks RPe_start_time = 0, RPe_tot_time = 0;  /* retainer prof elap time */
sof's avatar
sof committed
55

56
57
static Ticks HC_start_time, HC_tot_time = 0;     // heap census prof user time
static Ticks HCe_start_time, HCe_tot_time = 0;   // heap census prof elap time
sof's avatar
sof committed
58
#endif
59

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

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

static lnat GC_start_faults = 0, GC_end_faults = 0;

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

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

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

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

89
90
/* mut_user_time_during_GC() and mut_user_time()
 *
chak's avatar
chak committed
91
92
93
94
95
96
97
98
99
 * The former function can be used to get the current mutator time
 * *during* a GC, i.e. between stat_startGC and stat_endGC.  This is
 * used in the heap profiler for accurately time stamping the heap
 * sample.  
 *
 * ATTENTION: mut_user_time_during_GC() relies on GC_start_time being 
 *	      defined in stat_startGC() - to minimise system calls, 
 *	      GC_start_time is, however, only defined when really needed (check
 *	      stat_startGC() for details)
100
101
 */
double
102
mut_user_time_during_GC( void )
103
{
104
  return TICK_TO_DBL(GC_start_time - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time));
105
106
107
}

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

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

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

134
// initStats0() has no dependencies, it can be called right at the beginning
135
void
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
initStats0(void)
{
    ElapsedTimeStart = 0;

    InitUserTime     = 0;
    InitElapsedTime  = 0;
    InitElapsedStamp = 0;

    MutUserTime      = 0;
    MutElapsedTime   = 0;
    MutElapsedStamp  = 0;

    ExitUserTime     = 0;
    ExitElapsedTime  = 0;

    GC_tot_alloc     = 0;
    GC_tot_copied    = 0;
    GC_par_max_copied = 0;
    GC_par_avg_copied = 0;
    GC_start_time = 0;
    GC_tot_time  = 0;
    GCe_start_time = 0;
    GCe_tot_time = 0;

#ifdef PROFILING
    RP_start_time  = 0;
    RP_tot_time  = 0;
    RPe_start_time = 0;
    RPe_tot_time = 0;

    HC_start_time = 0;
    HC_tot_time = 0;
    HCe_start_time = 0;
    HCe_tot_time = 0;
#endif

    MaxResidency = 0;
    AvgResidency = 0;
    ResidencySamples = 0;
    MaxSlop = 0;

    GC_start_faults = 0;
    GC_end_faults = 0;
}    

// initStats1() can be called after setupRtsFlags()
void
initStats1 (void)
184
185
186
187
{
    nat i;
  
    if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) {
188
	statsPrintf("    Alloc    Copied     Live    GC    GC     TOT     TOT  Page Flts\n");
189
	statsPrintf("    bytes     bytes     bytes  user  elap    user    elap\n");
190
191
    }
    GC_coll_times = 
192
193
	(Ticks *)stgMallocBytes(
	    sizeof(Ticks)*RtsFlags.GcFlags.generations,
194
	    "initStats");
195
196
197
198
    GC_coll_etimes = 
	(Ticks *)stgMallocBytes(
	    sizeof(Ticks)*RtsFlags.GcFlags.generations,
	    "initStats");
199
200
    for (i = 0; i < RtsFlags.GcFlags.generations; i++) {
	GC_coll_times[i] = 0;
201
	GC_coll_etimes[i] = 0;
202
    }
203
}
204
205
206
207

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

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

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

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

    getProcessTimes(&user, &elapsed);

225
226
227
    InitUserTime = user;
    InitElapsedStamp = elapsed; 
    if (ElapsedTimeStart > elapsed) {
228
229
	InitElapsedTime = 0;
    } else {
230
	InitElapsedTime = elapsed - ElapsedTimeStart;
231
    }
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
232
233
234
235
236
237
238
239
240
241
#if USE_PAPI
    /* We start counting events for the mutator
     * when garbage collection starts
     * we switch to the GC event set. */
    papi_start_mutator_count();

    /* This flag is needed to avoid counting the last GC */
    papi_is_reporting = 1;

#endif
242
243
}

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

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

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

    MutElapsedStamp = elapsed;
    MutElapsedTime = elapsed - GCe_tot_time -
259
	PROF_VAL(RPe_tot_time + HCe_tot_time) - InitElapsedStamp;
260
    if (MutElapsedTime < 0) { MutElapsedTime = 0; }	/* sometimes -0.00 */
261

262
    MutUserTime = user - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime;
263
    if (MutUserTime < 0) { MutUserTime = 0; }
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
264
265
266
267
268
269
270
271
272
273

#if USE_PAPI
    /* We stop counting mutator events
     * GC events are not being counted at this point */
    papi_stop_mutator_count();

    /* This flag is needed, because GC is run once more after this function */
    papi_is_reporting = 0;

#endif
274
275
276
277
278
}

void
stat_endExit(void)
{
279
280
281
    Ticks user, elapsed;

    getProcessTimes(&user, &elapsed);
282
283
284

    ExitUserTime = user - MutUserTime - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime;
    ExitElapsedTime = elapsed - MutElapsedStamp;
285
286
287
288
289
290
    if (ExitUserTime < 0) {
	ExitUserTime = 0;
    }
    if (ExitElapsedTime < 0) {
	ExitElapsedTime = 0;
    }
291
292
}

293
294
295
296
297
298
/* -----------------------------------------------------------------------------
   Called at the beginning of each GC
   -------------------------------------------------------------------------- */

static nat rub_bell = 0;

chak's avatar
chak committed
299
300
301
302
303
/*  initialise global variables needed during GC
 *
 *  * GC_start_time is read in mut_user_time_during_GC(), which in turn is 
 *    needed if either PROFILING or DEBUGing is enabled
 */
304
305
306
307
308
309
310
void
stat_startGC(void)
{
    nat bell = RtsFlags.GcFlags.ringBell;

    if (bell) {
	if (bell > 1) {
311
	    debugBelch(" GC ");
312
313
	    rub_bell = 1;
	} else {
314
	    debugBelch("\007");
315
316
317
	}
    }

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

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

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

340
341
342
343
344
345
346
}

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

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

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

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

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

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

        if (slop > MaxSlop) MaxSlop = slop;
405
406
407
    }

    if (rub_bell) {
408
	debugBelch("\b\b\b  \b\b\b");
409
410
	rub_bell = 0;
    }
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
411
412
413
414

#if USE_PAPI
    if(papi_is_reporting) {
      /* Switch to counting mutator events */
415
416
417
418
419
      if (gen == 0) {
          papi_stop_gc0_count();
      } else {
          papi_stop_gc1_count();
      }
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
420
421
422
      papi_start_mutator_count();
    }
#endif
423
424
}

425
426
427
/* -----------------------------------------------------------------------------
   Called at the beginning of each Retainer Profiliing
   -------------------------------------------------------------------------- */
428
429
430
#ifdef PROFILING
void
stat_startRP(void)
431
{
432
433
    Ticks user, elapsed;
    getProcessTimes( &user, &elapsed );
434
435
436

    RP_start_time = user;
    RPe_start_time = elapsed;
437
}
sof's avatar
sof committed
438
#endif /* PROFILING */
439
440
441
442

/* -----------------------------------------------------------------------------
   Called at the end of each Retainer Profiliing
   -------------------------------------------------------------------------- */
443
444
445
446

#ifdef PROFILING
void
stat_endRP(
447
448
449
450
451
  nat retainerGeneration,
#ifdef DEBUG_RETAINER
  nat maxCStackSize,
  int maxStackSize,
#endif
452
  double averageNumVisit)
453
{
454
455
    Ticks user, elapsed;
    getProcessTimes( &user, &elapsed );
456
457
458

    RP_tot_time += user - RP_start_time;
    RPe_tot_time += elapsed - RPe_start_time;
459
460
461
462
463
464
465
466
467

  fprintf(prof_file, "Retainer Profiling: %d, at %f seconds\n", 
    retainerGeneration, mut_user_time_during_RP());
#ifdef DEBUG_RETAINER
  fprintf(prof_file, "\tMax C stack size = %u\n", maxCStackSize);
  fprintf(prof_file, "\tMax auxiliary stack size = %u\n", maxStackSize);
#endif
  fprintf(prof_file, "\tAverage number of visits per object = %f\n", averageNumVisit);
}
sof's avatar
sof committed
468
#endif /* PROFILING */
469
470

/* -----------------------------------------------------------------------------
471
   Called at the beginning of each heap census
472
   -------------------------------------------------------------------------- */
473
474
#ifdef PROFILING
void
475
stat_startHeapCensus(void)
476
{
477
478
    Ticks user, elapsed;
    getProcessTimes( &user, &elapsed );
479
480
481

    HC_start_time = user;
    HCe_start_time = elapsed;
482
}
sof's avatar
sof committed
483
#endif /* PROFILING */
484
485

/* -----------------------------------------------------------------------------
486
   Called at the end of each heap census
487
   -------------------------------------------------------------------------- */
488
489
#ifdef PROFILING
void
490
stat_endHeapCensus(void) 
491
{
492
493
    Ticks user, elapsed;
    getProcessTimes( &user, &elapsed );
494
495
496

    HC_tot_time += user - HC_start_time;
    HCe_tot_time += elapsed - HCe_start_time;
497
}
sof's avatar
sof committed
498
#endif /* PROFILING */
499

500
501
502
503
504
505
506
507
/* -----------------------------------------------------------------------------
   Called at the end of execution

   NOTE: number of allocations is not entirely accurate: it doesn't
   take into account the few bytes at the end of the heap that
   were left unused when the heap-check failed.
   -------------------------------------------------------------------------- */

Simon Marlow's avatar
Simon Marlow committed
508
509
510
511
512
513
514
515
516
517
518
519
520
521
522
523
524
525
526
527
528
529
530
531
532
533
534
535
536
537
538
539
540
541
542
543
544
545
546
547
548
549
550
551
552
#ifdef DEBUG
#define TICK_VAR(arity) \
  extern StgInt SLOW_CALLS_##arity; \
  extern StgInt RIGHT_ARITY_##arity; \
  extern StgInt TAGGED_PTR_##arity;

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

extern StgInt TOTAL_CALLS;

TICK_VAR(1)
TICK_VAR(2)

TICK_VAR_INI(1)
TICK_VAR_INI(2)

StgInt TOTAL_CALLS=1;
#endif

/* Report the value of a counter */
#define REPORT(counter) \
  { \
    ullong_format_string(counter,temp,rtsTrue/*commas*/); \
    statsPrintf("  (" #counter ")  : %s\n",temp);				\
  }

/* Report the value of a counter as a percentage of another counter */
#define REPORT_PCT(counter,countertot) \
  statsPrintf("  (" #counter ") %% of (" #countertot ") : %.1f%%\n", \
	      counter*100.0/countertot)

#define TICK_PRINT(arity) \
  REPORT(SLOW_CALLS_##arity); \
  REPORT_PCT(RIGHT_ARITY_##arity,SLOW_CALLS_##arity); \
  REPORT_PCT(TAGGED_PTR_##arity,RIGHT_ARITY_##arity); \
  REPORT(RIGHT_ARITY_##arity); \
  REPORT(TAGGED_PTR_##arity)

#define TICK_PRINT_TOT(arity) \
  statsPrintf("  (SLOW_CALLS_" #arity ") %% of (TOTAL_CALLS) : %.1f%%\n", \
	      SLOW_CALLS_##arity * 100.0/TOTAL_CALLS)

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

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

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

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

	GC_tot_alloc += alloc;
569

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

574
575
576
577
	/* avoid divide by zero if time is measured as 0.00 seconds -- SDM */
	if (time  == 0.0)  time = 1;
	if (etime == 0.0) etime = 1;
	
578
579
580
	if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) {
	    statsPrintf("%9ld %9.9s %9.9s", (lnat)alloc*sizeof(W_), "", "");
	    statsPrintf(" %5.2f %5.2f\n\n", 0.0, 0.0);
581
582
	}

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

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

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

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

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

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

615
616
617
618
619
620
621
622
623
624
625
#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");
626

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

646
	    statsPrintf("  INIT  time  %6.2fs  (%6.2fs elapsed)\n",
647
		    TICK_TO_DBL(InitUserTime), TICK_TO_DBL(InitElapsedTime));
648
	    statsPrintf("  MUT   time  %6.2fs  (%6.2fs elapsed)\n",
649
		    TICK_TO_DBL(MutUserTime), TICK_TO_DBL(MutElapsedTime));
650
	    statsPrintf("  GC    time  %6.2fs  (%6.2fs elapsed)\n",
651
		    TICK_TO_DBL(GC_tot_time), TICK_TO_DBL(GCe_tot_time));
652
#ifdef PROFILING
653
	    statsPrintf("  RP    time  %6.2fs  (%6.2fs elapsed)\n",
654
		    TICK_TO_DBL(RP_tot_time), TICK_TO_DBL(RPe_tot_time));
655
	    statsPrintf("  PROF  time  %6.2fs  (%6.2fs elapsed)\n",
656
		    TICK_TO_DBL(HC_tot_time), TICK_TO_DBL(HCe_tot_time));
657
#endif 
658
	    statsPrintf("  EXIT  time  %6.2fs  (%6.2fs elapsed)\n",
659
		    TICK_TO_DBL(ExitUserTime), TICK_TO_DBL(ExitElapsedTime));
660
	    statsPrintf("  Total time  %6.2fs  (%6.2fs elapsed)\n\n",
661
		    TICK_TO_DBL(time), TICK_TO_DBL(etime));
662
	    statsPrintf("  %%GC time     %5.1f%%  (%.1f%% elapsed)\n\n",
663
		    TICK_TO_DBL(GC_tot_time)*100/TICK_TO_DBL(time),
sof's avatar
sof committed
664
		    TICK_TO_DBL(GCe_tot_time)*100/TICK_TO_DBL(etime));
665

666
	    if (time - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time) == 0)
667
668
669
670
		ullong_format_string(0, temp, rtsTrue/*commas*/);
	    else
		ullong_format_string(
		    (ullong)((GC_tot_alloc*sizeof(W_))/
sof's avatar
sof committed
671
			     TICK_TO_DBL(time - GC_tot_time - 
672
					 PROF_VAL(RP_tot_time + HC_tot_time))),
673
674
		    temp, rtsTrue/*commas*/);
	    
675
	    statsPrintf("  Alloc rate    %s bytes per MUT second\n\n", temp);
676
	
677
	    statsPrintf("  Productivity %5.1f%% of total user, %.1f%% of total elapsed\n\n",
sof's avatar
sof committed
678
		    TICK_TO_DBL(time - GC_tot_time - 
679
				PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime) * 100 
680
		    / TICK_TO_DBL(time), 
sof's avatar
sof committed
681
		    TICK_TO_DBL(time - GC_tot_time - 
682
				PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime) * 100 
683
		    / TICK_TO_DBL(etime));
Simon Marlow's avatar
Simon Marlow committed
684
685
686
687
688
689
690
691
692

            /*
            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
693
#if USE_PAPI
694
            papi_stats_report();
695
696
697
698
699
700
701
702
703
704
705
706
707
708
709
#endif
#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);
                    }
                }
            }
mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
710
#endif
711
712
	}

713
	if (RtsFlags.GcFlags.giveStats == ONELINE_GC_STATS) {
rrt's avatar
rrt committed
714
	  /* print the long long separately to avoid bugginess on mingwin (2001-07-02, mingw-0.5) */
715
	  statsPrintf("<<ghc: %llu bytes, ", GC_tot_alloc*(ullong)sizeof(W_));
716
	  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
717
		    total_collections,
718
719
		    ResidencySamples == 0 ? 0 : 
		        AvgResidency*sizeof(W_)/ResidencySamples, 
720
		    MaxResidency*sizeof(W_), 
rrt's avatar
rrt committed
721
722
		    ResidencySamples,
		    (unsigned long)(mblocks_allocated * MBLOCK_SIZE / (1024L * 1024L)),
723
724
725
726
		    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));
	}
727

728
729
	statsFlush();
	statsClose();
730
    }
simonmarhaskell@gmail.com's avatar
simonmarhaskell@gmail.com committed
731

732
733
734
    if (GC_coll_times)
      stgFree(GC_coll_times);
    GC_coll_times = NULL;
simonmarhaskell@gmail.com's avatar
simonmarhaskell@gmail.com committed
735
736
737
    if (GC_coll_etimes)
      stgFree(GC_coll_etimes);
    GC_coll_etimes = NULL;
738
}
739
740
741
742
743
744
745

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

   Produce some detailed info on the state of the generational GC.
   -------------------------------------------------------------------------- */
void
746
statDescribeGens(void)
747
{
748
  nat g, s, mut, lge;
749
750
  lnat live, slop;
  lnat tot_live, tot_slop;
751
752
753
  bdescr *bd;
  step *step;

754
  debugBelch(
755
756
757
758
"-----------------------------------------------------------------\n"
"  Gen     Max  Mut-list  Step   Blocks    Large     Live     Slop\n"
"       Blocks     Bytes                 Objects                  \n"
"-----------------------------------------------------------------\n");
759

760
761
  tot_live = 0;
  tot_slop = 0;
762
  for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
763
      mut = 0;
764
      for (bd = generations[g].mut_list; bd != NULL; bd = bd->link) {
Simon Marlow's avatar
Simon Marlow committed
765
	  mut += (bd->free - bd->start) * sizeof(W_);
766
767
      }

768
    debugBelch("%5d %7d %9d", g, generations[g].max_blocks, mut);
769
770
771

    for (s = 0; s < generations[g].n_steps; s++) {
      step = &generations[g].steps[s];
772
773
774
      for (bd = step->large_objects, lge = 0; bd; bd = bd->link) {
	lge++;
      }
775
      live = step->n_words + countOccupied(step->large_objects);
776
      if (s != 0) {
777
	debugBelch("%23s","");
778
      }
779
780
781
782
783
      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;
784
785
    }
  }
786
787
788
  debugBelch("-----------------------------------------------------------------\n");
  debugBelch("%48s%8ld %8ld\n","",tot_live*sizeof(W_),tot_slop*sizeof(W_));
  debugBelch("-----------------------------------------------------------------\n");
789
  debugBelch("\n");
790
}
791
792
793
794
795
796

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

797
798
extern HsInt64 getAllocations( void ) 
{ return (HsInt64)total_allocated * sizeof(W_); }
799
800
801
802
803

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

mrchebas@gmail.com's avatar
mrchebas@gmail.com committed
804
void
805
806
807
808
809
810
811
812
813
814
815
816
817
818
819
820
821
822
823
824
825
826
827
828
829
830
831
832
833
834
835
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);
    }
}