GC refactoring and cleanup
[ghc.git] / rts / Stats.c
1 /* -----------------------------------------------------------------------------
2 *
3 * (c) The GHC Team, 1998-2005
4 *
5 * Statistics and timing-related functions.
6 *
7 * ---------------------------------------------------------------------------*/
8
9 #include "PosixSource.h"
10 #include "Rts.h"
11
12 #include "RtsUtils.h"
13 #include "Schedule.h"
14 #include "Stats.h"
15 #include "Profiling.h"
16 #include "GetTime.h"
17 #include "sm/Storage.h"
18 #include "sm/GC.h" // gc_alloc_block_sync, whitehole_spin
19
20 #if USE_PAPI
21 #include "Papi.h"
22 #endif
23
24 /* huh? */
25 #define BIG_STRING_LEN 512
26
27 #define TICK_TO_DBL(t) ((double)(t) / TICKS_PER_SECOND)
28
29 static Ticks ElapsedTimeStart = 0;
30
31 static Ticks InitUserTime = 0;
32 static Ticks InitElapsedTime = 0;
33 static Ticks InitElapsedStamp = 0;
34
35 static Ticks MutUserTime = 0;
36 static Ticks MutElapsedTime = 0;
37 static Ticks MutElapsedStamp = 0;
38
39 static Ticks ExitUserTime = 0;
40 static Ticks ExitElapsedTime = 0;
41
42 static StgWord64 GC_tot_alloc = 0;
43 static StgWord64 GC_tot_copied = 0;
44
45 static StgWord64 GC_par_max_copied = 0;
46 static StgWord64 GC_par_avg_copied = 0;
47
48 static Ticks GC_start_time = 0, GC_tot_time = 0; /* User GC Time */
49 static Ticks GCe_start_time = 0, GCe_tot_time = 0; /* Elapsed GC time */
50
51 #ifdef PROFILING
52 static Ticks RP_start_time = 0, RP_tot_time = 0; /* retainer prof user time */
53 static Ticks RPe_start_time = 0, RPe_tot_time = 0; /* retainer prof elap time */
54
55 static Ticks HC_start_time, HC_tot_time = 0; // heap census prof user time
56 static Ticks HCe_start_time, HCe_tot_time = 0; // heap census prof elap time
57 #endif
58
59 #ifdef PROFILING
60 #define PROF_VAL(x) (x)
61 #else
62 #define PROF_VAL(x) 0
63 #endif
64
65 static lnat MaxResidency = 0; // in words; for stats only
66 static lnat AvgResidency = 0;
67 static lnat ResidencySamples = 0; // for stats only
68 static lnat MaxSlop = 0;
69
70 static lnat GC_start_faults = 0, GC_end_faults = 0;
71
72 static Ticks *GC_coll_times = NULL;
73 static Ticks *GC_coll_etimes = NULL;
74
75 static void statsFlush( void );
76 static void statsClose( void );
77
78 Ticks stat_getElapsedGCTime(void)
79 {
80 return GCe_tot_time;
81 }
82
83 Ticks stat_getElapsedTime(void)
84 {
85 return getProcessElapsedTime() - ElapsedTimeStart;
86 }
87
88 /* mut_user_time_during_GC() and mut_user_time()
89 *
90 * The former function can be used to get the current mutator time
91 * *during* a GC, i.e. between stat_startGC and stat_endGC. This is
92 * used in the heap profiler for accurately time stamping the heap
93 * sample.
94 *
95 * ATTENTION: mut_user_time_during_GC() relies on GC_start_time being
96 * defined in stat_startGC() - to minimise system calls,
97 * GC_start_time is, however, only defined when really needed (check
98 * stat_startGC() for details)
99 */
100 double
101 mut_user_time_during_GC( void )
102 {
103 return TICK_TO_DBL(GC_start_time - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time));
104 }
105
106 double
107 mut_user_time( void )
108 {
109 Ticks user;
110 user = getProcessCPUTime();
111 return TICK_TO_DBL(user - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time));
112 }
113
114 #ifdef PROFILING
115 /*
116 mut_user_time_during_RP() is similar to mut_user_time_during_GC();
117 it returns the MUT time during retainer profiling.
118 The same is for mut_user_time_during_HC();
119 */
120 double
121 mut_user_time_during_RP( void )
122 {
123 return TICK_TO_DBL(RP_start_time - GC_tot_time - RP_tot_time - HC_tot_time);
124 }
125
126 double
127 mut_user_time_during_heap_census( void )
128 {
129 return TICK_TO_DBL(HC_start_time - GC_tot_time - RP_tot_time - HC_tot_time);
130 }
131 #endif /* PROFILING */
132
133 // initStats0() has no dependencies, it can be called right at the beginning
134 void
135 initStats0(void)
136 {
137 ElapsedTimeStart = 0;
138
139 InitUserTime = 0;
140 InitElapsedTime = 0;
141 InitElapsedStamp = 0;
142
143 MutUserTime = 0;
144 MutElapsedTime = 0;
145 MutElapsedStamp = 0;
146
147 ExitUserTime = 0;
148 ExitElapsedTime = 0;
149
150 GC_tot_alloc = 0;
151 GC_tot_copied = 0;
152 GC_par_max_copied = 0;
153 GC_par_avg_copied = 0;
154 GC_start_time = 0;
155 GC_tot_time = 0;
156 GCe_start_time = 0;
157 GCe_tot_time = 0;
158
159 #ifdef PROFILING
160 RP_start_time = 0;
161 RP_tot_time = 0;
162 RPe_start_time = 0;
163 RPe_tot_time = 0;
164
165 HC_start_time = 0;
166 HC_tot_time = 0;
167 HCe_start_time = 0;
168 HCe_tot_time = 0;
169 #endif
170
171 MaxResidency = 0;
172 AvgResidency = 0;
173 ResidencySamples = 0;
174 MaxSlop = 0;
175
176 GC_start_faults = 0;
177 GC_end_faults = 0;
178 }
179
180 // initStats1() can be called after setupRtsFlags()
181 void
182 initStats1 (void)
183 {
184 nat i;
185
186 if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) {
187 statsPrintf(" Alloc Copied Live GC GC TOT TOT Page Flts\n");
188 statsPrintf(" bytes bytes bytes user elap user elap\n");
189 }
190 GC_coll_times =
191 (Ticks *)stgMallocBytes(
192 sizeof(Ticks)*RtsFlags.GcFlags.generations,
193 "initStats");
194 GC_coll_etimes =
195 (Ticks *)stgMallocBytes(
196 sizeof(Ticks)*RtsFlags.GcFlags.generations,
197 "initStats");
198 for (i = 0; i < RtsFlags.GcFlags.generations; i++) {
199 GC_coll_times[i] = 0;
200 GC_coll_etimes[i] = 0;
201 }
202 }
203
204 /* -----------------------------------------------------------------------------
205 Initialisation time...
206 -------------------------------------------------------------------------- */
207
208 void
209 stat_startInit(void)
210 {
211 Ticks elapsed;
212
213 elapsed = getProcessElapsedTime();
214 ElapsedTimeStart = elapsed;
215 }
216
217 void
218 stat_endInit(void)
219 {
220 Ticks user, elapsed;
221
222 getProcessTimes(&user, &elapsed);
223
224 InitUserTime = user;
225 InitElapsedStamp = elapsed;
226 if (ElapsedTimeStart > elapsed) {
227 InitElapsedTime = 0;
228 } else {
229 InitElapsedTime = elapsed - ElapsedTimeStart;
230 }
231 #if USE_PAPI
232 /* We start counting events for the mutator
233 * when garbage collection starts
234 * we switch to the GC event set. */
235 papi_start_mutator_count();
236
237 /* This flag is needed to avoid counting the last GC */
238 papi_is_reporting = 1;
239
240 #endif
241 }
242
243 /* -----------------------------------------------------------------------------
244 stat_startExit and stat_endExit
245
246 These two measure the time taken in shutdownHaskell().
247 -------------------------------------------------------------------------- */
248
249 void
250 stat_startExit(void)
251 {
252 Ticks user, elapsed;
253
254 getProcessTimes(&user, &elapsed);
255
256 MutElapsedStamp = elapsed;
257 MutElapsedTime = elapsed - GCe_tot_time -
258 PROF_VAL(RPe_tot_time + HCe_tot_time) - InitElapsedStamp;
259 if (MutElapsedTime < 0) { MutElapsedTime = 0; } /* sometimes -0.00 */
260
261 MutUserTime = user - GC_tot_time -
262 PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime;
263 if (MutUserTime < 0) { MutUserTime = 0; }
264
265 #if USE_PAPI
266 /* We stop counting mutator events
267 * GC events are not being counted at this point */
268 papi_stop_mutator_count();
269
270 /* This flag is needed, because GC is run once more after this function */
271 papi_is_reporting = 0;
272
273 #endif
274 }
275
276 void
277 stat_endExit(void)
278 {
279 Ticks user, elapsed;
280
281 getProcessTimes(&user, &elapsed);
282
283 ExitUserTime = user - MutUserTime - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime;
284 ExitElapsedTime = elapsed - MutElapsedStamp;
285 if (ExitUserTime < 0) {
286 ExitUserTime = 0;
287 }
288 if (ExitElapsedTime < 0) {
289 ExitElapsedTime = 0;
290 }
291 }
292
293 /* -----------------------------------------------------------------------------
294 Called at the beginning of each GC
295 -------------------------------------------------------------------------- */
296
297 static nat rub_bell = 0;
298
299 /* initialise global variables needed during GC
300 *
301 * * GC_start_time is read in mut_user_time_during_GC(), which in turn is
302 * needed if either PROFILING or DEBUGing is enabled
303 */
304 void
305 stat_startGC(void)
306 {
307 nat bell = RtsFlags.GcFlags.ringBell;
308
309 if (bell) {
310 if (bell > 1) {
311 debugBelch(" GC ");
312 rub_bell = 1;
313 } else {
314 debugBelch("\007");
315 }
316 }
317
318 if (RtsFlags.GcFlags.giveStats != NO_GC_STATS
319 || RtsFlags.ProfFlags.doHeapProfile)
320 // heap profiling needs GC_tot_time
321 {
322 getProcessTimes(&GC_start_time, &GCe_start_time);
323 if (RtsFlags.GcFlags.giveStats) {
324 GC_start_faults = getPageFaults();
325 }
326 }
327
328 #if USE_PAPI
329 if(papi_is_reporting) {
330 /* Switch to counting GC events */
331 papi_stop_mutator_count();
332 papi_start_gc_count();
333 }
334 #endif
335
336 }
337
338 /* -----------------------------------------------------------------------------
339 Called at the end of each GC
340 -------------------------------------------------------------------------- */
341
342 void
343 stat_endGC (lnat alloc, lnat live, lnat copied, lnat gen,
344 lnat max_copied, lnat avg_copied, lnat slop)
345 {
346 if (RtsFlags.GcFlags.giveStats != NO_GC_STATS ||
347 RtsFlags.ProfFlags.doHeapProfile)
348 // heap profiling needs GC_tot_time
349 {
350 Ticks time, etime, gc_time, gc_etime;
351
352 getProcessTimes(&time, &etime);
353 gc_time = time - GC_start_time;
354 gc_etime = etime - GCe_start_time;
355
356 if (RtsFlags.GcFlags.giveStats == VERBOSE_GC_STATS) {
357 nat faults = getPageFaults();
358
359 statsPrintf("%9ld %9ld %9ld",
360 alloc*sizeof(W_), copied*sizeof(W_),
361 live*sizeof(W_));
362 statsPrintf(" %5.2f %5.2f %7.2f %7.2f %4ld %4ld (Gen: %2ld)\n",
363 TICK_TO_DBL(gc_time),
364 TICK_TO_DBL(gc_etime),
365 TICK_TO_DBL(time),
366 TICK_TO_DBL(etime - ElapsedTimeStart),
367 faults - GC_start_faults,
368 GC_start_faults - GC_end_faults,
369 gen);
370
371 GC_end_faults = faults;
372 statsFlush();
373 }
374
375 GC_coll_times[gen] += gc_time;
376 GC_coll_etimes[gen] += gc_etime;
377
378 GC_tot_copied += (StgWord64) copied;
379 GC_tot_alloc += (StgWord64) alloc;
380 GC_par_max_copied += (StgWord64) max_copied;
381 GC_par_avg_copied += (StgWord64) avg_copied;
382 GC_tot_time += gc_time;
383 GCe_tot_time += gc_etime;
384
385 #if defined(THREADED_RTS)
386 {
387 Task *task;
388 if ((task = myTask()) != NULL) {
389 task->gc_time += gc_time;
390 task->gc_etime += gc_etime;
391 }
392 }
393 #endif
394
395 if (gen == RtsFlags.GcFlags.generations-1) { /* major GC? */
396 if (live > MaxResidency) {
397 MaxResidency = live;
398 }
399 ResidencySamples++;
400 AvgResidency += live;
401 }
402
403 if (slop > MaxSlop) MaxSlop = slop;
404 }
405
406 if (rub_bell) {
407 debugBelch("\b\b\b \b\b\b");
408 rub_bell = 0;
409 }
410
411 #if USE_PAPI
412 if(papi_is_reporting) {
413 /* Switch to counting mutator events */
414 if (gen == 0) {
415 papi_stop_gc0_count();
416 } else {
417 papi_stop_gc1_count();
418 }
419 papi_start_mutator_count();
420 }
421 #endif
422 }
423
424 /* -----------------------------------------------------------------------------
425 Called at the beginning of each Retainer Profiliing
426 -------------------------------------------------------------------------- */
427 #ifdef PROFILING
428 void
429 stat_startRP(void)
430 {
431 Ticks user, elapsed;
432 getProcessTimes( &user, &elapsed );
433
434 RP_start_time = user;
435 RPe_start_time = elapsed;
436 }
437 #endif /* PROFILING */
438
439 /* -----------------------------------------------------------------------------
440 Called at the end of each Retainer Profiliing
441 -------------------------------------------------------------------------- */
442
443 #ifdef PROFILING
444 void
445 stat_endRP(
446 nat retainerGeneration,
447 #ifdef DEBUG_RETAINER
448 nat maxCStackSize,
449 int maxStackSize,
450 #endif
451 double averageNumVisit)
452 {
453 Ticks user, elapsed;
454 getProcessTimes( &user, &elapsed );
455
456 RP_tot_time += user - RP_start_time;
457 RPe_tot_time += elapsed - RPe_start_time;
458
459 fprintf(prof_file, "Retainer Profiling: %d, at %f seconds\n",
460 retainerGeneration, mut_user_time_during_RP());
461 #ifdef DEBUG_RETAINER
462 fprintf(prof_file, "\tMax C stack size = %u\n", maxCStackSize);
463 fprintf(prof_file, "\tMax auxiliary stack size = %u\n", maxStackSize);
464 #endif
465 fprintf(prof_file, "\tAverage number of visits per object = %f\n", averageNumVisit);
466 }
467 #endif /* PROFILING */
468
469 /* -----------------------------------------------------------------------------
470 Called at the beginning of each heap census
471 -------------------------------------------------------------------------- */
472 #ifdef PROFILING
473 void
474 stat_startHeapCensus(void)
475 {
476 Ticks user, elapsed;
477 getProcessTimes( &user, &elapsed );
478
479 HC_start_time = user;
480 HCe_start_time = elapsed;
481 }
482 #endif /* PROFILING */
483
484 /* -----------------------------------------------------------------------------
485 Called at the end of each heap census
486 -------------------------------------------------------------------------- */
487 #ifdef PROFILING
488 void
489 stat_endHeapCensus(void)
490 {
491 Ticks user, elapsed;
492 getProcessTimes( &user, &elapsed );
493
494 HC_tot_time += user - HC_start_time;
495 HCe_tot_time += elapsed - HCe_start_time;
496 }
497 #endif /* PROFILING */
498
499 /* -----------------------------------------------------------------------------
500 Called at the end of execution
501
502 NOTE: number of allocations is not entirely accurate: it doesn't
503 take into account the few bytes at the end of the heap that
504 were left unused when the heap-check failed.
505 -------------------------------------------------------------------------- */
506
507 #ifdef DEBUG
508 #define TICK_VAR_INI(arity) \
509 StgInt SLOW_CALLS_##arity = 1; \
510 StgInt RIGHT_ARITY_##arity = 1; \
511 StgInt TAGGED_PTR_##arity = 0;
512
513 TICK_VAR_INI(1)
514 TICK_VAR_INI(2)
515
516 StgInt TOTAL_CALLS=1;
517 #endif
518
519 /* Report the value of a counter */
520 #define REPORT(counter) \
521 { \
522 showStgWord64(counter,temp,rtsTrue/*commas*/); \
523 statsPrintf(" (" #counter ") : %s\n",temp); \
524 }
525
526 /* Report the value of a counter as a percentage of another counter */
527 #define REPORT_PCT(counter,countertot) \
528 statsPrintf(" (" #counter ") %% of (" #countertot ") : %.1f%%\n", \
529 counter*100.0/countertot)
530
531 #define TICK_PRINT(arity) \
532 REPORT(SLOW_CALLS_##arity); \
533 REPORT_PCT(RIGHT_ARITY_##arity,SLOW_CALLS_##arity); \
534 REPORT_PCT(TAGGED_PTR_##arity,RIGHT_ARITY_##arity); \
535 REPORT(RIGHT_ARITY_##arity); \
536 REPORT(TAGGED_PTR_##arity)
537
538 #define TICK_PRINT_TOT(arity) \
539 statsPrintf(" (SLOW_CALLS_" #arity ") %% of (TOTAL_CALLS) : %.1f%%\n", \
540 SLOW_CALLS_##arity * 100.0/TOTAL_CALLS)
541
542 extern lnat hw_alloc_blocks;
543
544 void
545 stat_exit(int alloc)
546 {
547 if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
548
549 char temp[BIG_STRING_LEN];
550 Ticks time;
551 Ticks etime;
552 nat g, total_collections = 0;
553
554 getProcessTimes( &time, &etime );
555 etime -= ElapsedTimeStart;
556
557 GC_tot_alloc += alloc;
558
559 /* Count total garbage collections */
560 for (g = 0; g < RtsFlags.GcFlags.generations; g++)
561 total_collections += generations[g].collections;
562
563 /* avoid divide by zero if time is measured as 0.00 seconds -- SDM */
564 if (time == 0.0) time = 1;
565 if (etime == 0.0) etime = 1;
566
567 if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) {
568 statsPrintf("%9ld %9.9s %9.9s", (lnat)alloc*sizeof(W_), "", "");
569 statsPrintf(" %5.2f %5.2f\n\n", 0.0, 0.0);
570 }
571
572 if (RtsFlags.GcFlags.giveStats >= SUMMARY_GC_STATS) {
573 showStgWord64(GC_tot_alloc*sizeof(W_),
574 temp, rtsTrue/*commas*/);
575 statsPrintf("%16s bytes allocated in the heap\n", temp);
576
577 showStgWord64(GC_tot_copied*sizeof(W_),
578 temp, rtsTrue/*commas*/);
579 statsPrintf("%16s bytes copied during GC\n", temp);
580
581 if ( ResidencySamples > 0 ) {
582 showStgWord64(MaxResidency*sizeof(W_),
583 temp, rtsTrue/*commas*/);
584 statsPrintf("%16s bytes maximum residency (%ld sample(s))\n",
585 temp, ResidencySamples);
586 }
587
588 showStgWord64(MaxSlop*sizeof(W_), temp, rtsTrue/*commas*/);
589 statsPrintf("%16s bytes maximum slop\n", temp);
590
591 statsPrintf("%16ld MB total memory in use (%ld MB lost due to fragmentation)\n\n",
592 peak_mblocks_allocated * MBLOCK_SIZE_W / (1024 * 1024 / sizeof(W_)),
593 (peak_mblocks_allocated * BLOCKS_PER_MBLOCK * BLOCK_SIZE_W - hw_alloc_blocks * BLOCK_SIZE_W) / (1024 * 1024 / sizeof(W_)));
594
595 /* Print garbage collections in each gen */
596 for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
597 statsPrintf(" Generation %d: %5d collections, %5d parallel, %5.2fs, %5.2fs elapsed\n",
598 g, generations[g].collections,
599 generations[g].par_collections,
600 TICK_TO_DBL(GC_coll_times[g]),
601 TICK_TO_DBL(GC_coll_etimes[g]));
602 }
603
604 #if defined(THREADED_RTS)
605 if (RtsFlags.ParFlags.parGcEnabled) {
606 statsPrintf("\n Parallel GC work balance: %.2f (%ld / %ld, ideal %d)\n",
607 (double)GC_par_avg_copied / (double)GC_par_max_copied,
608 (lnat)GC_par_avg_copied, (lnat)GC_par_max_copied,
609 RtsFlags.ParFlags.nNodes
610 );
611 }
612 #endif
613
614 statsPrintf("\n");
615
616 #if defined(THREADED_RTS)
617 {
618 nat i;
619 Task *task;
620 statsPrintf(" MUT time (elapsed) GC time (elapsed)\n");
621 for (i = 0, task = all_tasks;
622 task != NULL;
623 i++, task = task->all_link) {
624 statsPrintf(" Task %2d %-8s : %6.2fs (%6.2fs) %6.2fs (%6.2fs)\n",
625 i,
626 (task->worker) ? "(worker)" : "(bound)",
627 TICK_TO_DBL(task->mut_time),
628 TICK_TO_DBL(task->mut_etime),
629 TICK_TO_DBL(task->gc_time),
630 TICK_TO_DBL(task->gc_etime));
631 }
632 }
633
634 statsPrintf("\n");
635
636 {
637 nat i;
638 lnat sparks_created = 0;
639 lnat sparks_dud = 0;
640 lnat sparks_converted = 0;
641 lnat sparks_gcd = 0;
642 lnat sparks_fizzled = 0;
643 for (i = 0; i < n_capabilities; i++) {
644 sparks_created += capabilities[i].sparks_created;
645 sparks_dud += capabilities[i].sparks_dud;
646 sparks_converted += capabilities[i].sparks_converted;
647 sparks_gcd += capabilities[i].sparks_gcd;
648 sparks_fizzled += capabilities[i].sparks_fizzled;
649 }
650
651 statsPrintf(" SPARKS: %ld (%ld converted, %ld dud, %ld GC'd, %ld fizzled)\n\n",
652 sparks_created + sparks_dud, sparks_converted, sparks_dud, sparks_gcd, sparks_fizzled);
653 }
654 #endif
655
656 statsPrintf(" INIT time %6.2fs (%6.2fs elapsed)\n",
657 TICK_TO_DBL(InitUserTime), TICK_TO_DBL(InitElapsedTime));
658 statsPrintf(" MUT time %6.2fs (%6.2fs elapsed)\n",
659 TICK_TO_DBL(MutUserTime), TICK_TO_DBL(MutElapsedTime));
660 statsPrintf(" GC time %6.2fs (%6.2fs elapsed)\n",
661 TICK_TO_DBL(GC_tot_time), TICK_TO_DBL(GCe_tot_time));
662 #ifdef PROFILING
663 statsPrintf(" RP time %6.2fs (%6.2fs elapsed)\n",
664 TICK_TO_DBL(RP_tot_time), TICK_TO_DBL(RPe_tot_time));
665 statsPrintf(" PROF time %6.2fs (%6.2fs elapsed)\n",
666 TICK_TO_DBL(HC_tot_time), TICK_TO_DBL(HCe_tot_time));
667 #endif
668 statsPrintf(" EXIT time %6.2fs (%6.2fs elapsed)\n",
669 TICK_TO_DBL(ExitUserTime), TICK_TO_DBL(ExitElapsedTime));
670 statsPrintf(" Total time %6.2fs (%6.2fs elapsed)\n\n",
671 TICK_TO_DBL(time), TICK_TO_DBL(etime));
672 statsPrintf(" %%GC time %5.1f%% (%.1f%% elapsed)\n\n",
673 TICK_TO_DBL(GC_tot_time)*100/TICK_TO_DBL(time),
674 TICK_TO_DBL(GCe_tot_time)*100/TICK_TO_DBL(etime));
675
676 if (time - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time) == 0)
677 showStgWord64(0, temp, rtsTrue/*commas*/);
678 else
679 showStgWord64(
680 (StgWord64)((GC_tot_alloc*sizeof(W_))/
681 TICK_TO_DBL(time - GC_tot_time -
682 PROF_VAL(RP_tot_time + HC_tot_time))),
683 temp, rtsTrue/*commas*/);
684
685 statsPrintf(" Alloc rate %s bytes per MUT second\n\n", temp);
686
687 statsPrintf(" Productivity %5.1f%% of total user, %.1f%% of total elapsed\n\n",
688 TICK_TO_DBL(time - GC_tot_time -
689 PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime) * 100
690 / TICK_TO_DBL(time),
691 TICK_TO_DBL(time - GC_tot_time -
692 PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime) * 100
693 / TICK_TO_DBL(etime));
694
695 /*
696 TICK_PRINT(1);
697 TICK_PRINT(2);
698 REPORT(TOTAL_CALLS);
699 TICK_PRINT_TOT(1);
700 TICK_PRINT_TOT(2);
701 */
702
703 #if USE_PAPI
704 papi_stats_report();
705 #endif
706 #if defined(THREADED_RTS) && defined(PROF_SPIN)
707 {
708 nat g;
709
710 statsPrintf("gc_alloc_block_sync: %"FMT_Word64"\n", gc_alloc_block_sync.spin);
711 statsPrintf("whitehole_spin: %"FMT_Word64"\n", whitehole_spin);
712 for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
713 statsPrintf("gen[%d].sync: %"FMT_Word64"\n", g, generations[g].sync.spin);
714 }
715 }
716 #endif
717 }
718
719 if (RtsFlags.GcFlags.giveStats == ONELINE_GC_STATS) {
720 char *fmt1, *fmt2;
721 if (RtsFlags.MiscFlags.machineReadable) {
722 fmt1 = " [(\"bytes allocated\", \"%llu\")\n";
723 fmt2 = " ,(\"num_GCs\", \"%d\")\n"
724 " ,(\"average_bytes_used\", \"%ld\")\n"
725 " ,(\"max_bytes_used\", \"%ld\")\n"
726 " ,(\"num_byte_usage_samples\", \"%ld\")\n"
727 " ,(\"peak_megabytes_allocated\", \"%lu\")\n"
728 " ,(\"init_cpu_seconds\", \"%.2f\")\n"
729 " ,(\"init_wall_seconds\", \"%.2f\")\n"
730 " ,(\"mutator_cpu_seconds\", \"%.2f\")\n"
731 " ,(\"mutator_wall_seconds\", \"%.2f\")\n"
732 " ,(\"GC_cpu_seconds\", \"%.2f\")\n"
733 " ,(\"GC_wall_seconds\", \"%.2f\")\n"
734 " ]\n";
735 }
736 else {
737 fmt1 = "<<ghc: %llu bytes, ";
738 fmt2 = "%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";
739 }
740 /* print the long long separately to avoid bugginess on mingwin (2001-07-02, mingw-0.5) */
741 statsPrintf(fmt1, GC_tot_alloc*(StgWord64)sizeof(W_));
742 statsPrintf(fmt2,
743 total_collections,
744 ResidencySamples == 0 ? 0 :
745 AvgResidency*sizeof(W_)/ResidencySamples,
746 MaxResidency*sizeof(W_),
747 ResidencySamples,
748 (unsigned long)(peak_mblocks_allocated * MBLOCK_SIZE / (1024L * 1024L)),
749 TICK_TO_DBL(InitUserTime), TICK_TO_DBL(InitElapsedTime),
750 TICK_TO_DBL(MutUserTime), TICK_TO_DBL(MutElapsedTime),
751 TICK_TO_DBL(GC_tot_time), TICK_TO_DBL(GCe_tot_time));
752 }
753
754 statsFlush();
755 statsClose();
756 }
757
758 if (GC_coll_times)
759 stgFree(GC_coll_times);
760 GC_coll_times = NULL;
761 if (GC_coll_etimes)
762 stgFree(GC_coll_etimes);
763 GC_coll_etimes = NULL;
764 }
765
766 /* -----------------------------------------------------------------------------
767 stat_describe_gens
768
769 Produce some detailed info on the state of the generational GC.
770 -------------------------------------------------------------------------- */
771 void
772 statDescribeGens(void)
773 {
774 nat g, mut, lge, i;
775 lnat gen_slop;
776 lnat tot_live, tot_slop;
777 lnat gen_live, gen_blocks;
778 bdescr *bd;
779 generation *gen;
780
781 debugBelch(
782 "----------------------------------------------------------\n"
783 " Gen Max Mut-list Blocks Large Live Slop\n"
784 " Blocks Bytes Objects \n"
785 "----------------------------------------------------------\n");
786
787 tot_live = 0;
788 tot_slop = 0;
789
790 for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
791 gen = &generations[g];
792
793 for (bd = gen->large_objects, lge = 0; bd; bd = bd->link) {
794 lge++;
795 }
796
797 gen_live = genLiveWords(gen);
798 gen_blocks = genLiveBlocks(gen);
799
800 mut = 0;
801 for (i = 0; i < n_capabilities; i++) {
802 mut += countOccupied(capabilities[i].mut_lists[g]);
803 gen_live += gcThreadLiveWords(i,g);
804 gen_blocks += gcThreadLiveBlocks(i,g);
805 }
806
807 debugBelch("%5d %7d %9d", g, gen->max_blocks, mut);
808
809 gen_slop = gen_blocks * BLOCK_SIZE_W - gen_live;
810
811 debugBelch("%8ld %8d %8ld %8ld\n", gen_blocks, lge,
812 gen_live*sizeof(W_), gen_slop*sizeof(W_));
813 tot_live += gen_live;
814 tot_slop += gen_slop;
815 }
816 debugBelch("----------------------------------------------------------\n");
817 debugBelch("%41s%8ld %8ld\n","",tot_live*sizeof(W_),tot_slop*sizeof(W_));
818 debugBelch("----------------------------------------------------------\n");
819 debugBelch("\n");
820 }
821
822 /* -----------------------------------------------------------------------------
823 Stats available via a programmatic interface, so eg. GHCi can time
824 each compilation and expression evaluation.
825 -------------------------------------------------------------------------- */
826
827 extern HsInt64 getAllocations( void )
828 { return (HsInt64)GC_tot_alloc * sizeof(W_); }
829
830 /* -----------------------------------------------------------------------------
831 Dumping stuff in the stats file, or via the debug message interface
832 -------------------------------------------------------------------------- */
833
834 void
835 statsPrintf( char *s, ... )
836 {
837 FILE *sf = RtsFlags.GcFlags.statsFile;
838 va_list ap;
839
840 va_start(ap,s);
841 if (sf == NULL) {
842 vdebugBelch(s,ap);
843 } else {
844 vfprintf(sf, s, ap);
845 }
846 va_end(ap);
847 }
848
849 static void
850 statsFlush( void )
851 {
852 FILE *sf = RtsFlags.GcFlags.statsFile;
853 if (sf != NULL) {
854 fflush(sf);
855 }
856 }
857
858 static void
859 statsClose( void )
860 {
861 FILE *sf = RtsFlags.GcFlags.statsFile;
862 if (sf != NULL) {
863 fclose(sf);
864 }
865 }