remove empty dir
[ghc-hetmet.git] / ghc / rts / Stats.c
1 /* -----------------------------------------------------------------------------
2  *
3  * (c) The GHC Team, 1998-2005
4  *
5  * Statistics and timing-related functions.
6  *
7  * ---------------------------------------------------------------------------*/
8
9 #include "Rts.h"
10 #include "RtsFlags.h"
11 #include "RtsUtils.h"
12 #include "MBlock.h"
13 #include "Schedule.h"
14 #include "Stats.h"
15 #include "ParTicky.h"                       /* ToDo: move into Rts.h */
16 #include "Profiling.h"
17 #include "Storage.h"
18 #include "GetTime.h"
19
20 /* huh? */
21 #define BIG_STRING_LEN              512
22
23 #define TICK_TO_DBL(t) ((double)(t) / TICKS_PER_SECOND)
24
25 static Ticks ElapsedTimeStart = 0;
26
27 static Ticks InitUserTime     = 0;
28 static Ticks InitElapsedTime  = 0;
29 static Ticks InitElapsedStamp = 0;
30
31 static Ticks MutUserTime      = 0;
32 static Ticks MutElapsedTime   = 0;
33 static Ticks MutElapsedStamp  = 0;
34
35 static Ticks ExitUserTime     = 0;
36 static Ticks ExitElapsedTime  = 0;
37
38 static ullong GC_tot_alloc        = 0;
39 static ullong GC_tot_copied       = 0;
40 static ullong GC_tot_scavd_copied = 0;
41
42 static Ticks GC_start_time = 0,  GC_tot_time  = 0;  /* User GC Time */
43 static Ticks GCe_start_time = 0, GCe_tot_time = 0;  /* Elapsed GC time */
44
45 #ifdef PROFILING
46 static Ticks RP_start_time  = 0, RP_tot_time  = 0;  /* retainer prof user time */
47 static Ticks RPe_start_time = 0, RPe_tot_time = 0;  /* retainer prof elap time */
48
49 static Ticks HC_start_time, HC_tot_time = 0;     // heap census prof user time
50 static Ticks HCe_start_time, HCe_tot_time = 0;   // heap census prof elap time
51 #endif
52
53 #ifdef PROFILING
54 #define PROF_VAL(x)   (x)
55 #else
56 #define PROF_VAL(x)   0
57 #endif
58
59 static lnat MaxResidency = 0;     // in words; for stats only
60 static lnat AvgResidency = 0;
61 static lnat ResidencySamples = 0; // for stats only
62
63 static lnat GC_start_faults = 0, GC_end_faults = 0;
64
65 static Ticks *GC_coll_times;
66
67 static void statsPrintf( char *s, ... ) 
68     GNUC3_ATTRIBUTE(format (printf, 1, 2));
69
70 static void statsFlush( void );
71 static void statsClose( void );
72
73 Ticks stat_getElapsedGCTime(void)
74 {
75     return GCe_tot_time;
76 }
77
78 /* mut_user_time_during_GC() and mut_user_time()
79  *
80  * The former function can be used to get the current mutator time
81  * *during* a GC, i.e. between stat_startGC and stat_endGC.  This is
82  * used in the heap profiler for accurately time stamping the heap
83  * sample.  
84  *
85  * ATTENTION: mut_user_time_during_GC() relies on GC_start_time being 
86  *            defined in stat_startGC() - to minimise system calls, 
87  *            GC_start_time is, however, only defined when really needed (check
88  *            stat_startGC() for details)
89  */
90 double
91 mut_user_time_during_GC( void )
92 {
93   return TICK_TO_DBL(GC_start_time - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time));
94 }
95
96 double
97 mut_user_time( void )
98 {
99     Ticks user;
100     user = getProcessCPUTime();
101     return TICK_TO_DBL(user - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time));
102 }
103
104 #ifdef PROFILING
105 /*
106   mut_user_time_during_RP() is similar to mut_user_time_during_GC();
107   it returns the MUT time during retainer profiling.
108   The same is for mut_user_time_during_HC();
109  */
110 double
111 mut_user_time_during_RP( void )
112 {
113   return TICK_TO_DBL(RP_start_time - GC_tot_time - RP_tot_time - HC_tot_time);
114 }
115
116 double
117 mut_user_time_during_heap_census( void )
118 {
119   return TICK_TO_DBL(HC_start_time - GC_tot_time - RP_tot_time - HC_tot_time);
120 }
121 #endif /* PROFILING */
122
123 void
124 initStats(void)
125 {
126     nat i;
127   
128     if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) {
129         statsPrintf("    Alloc    Copied     Live    GC    GC     TOT     TOT  Page Flts\n");
130         statsPrintf("    bytes     bytes     bytes  user  elap    user    elap\n");
131     }
132     GC_coll_times = 
133         (Ticks *)stgMallocBytes(
134             sizeof(Ticks)*RtsFlags.GcFlags.generations,
135             "initStats");
136     for (i = 0; i < RtsFlags.GcFlags.generations; i++) {
137         GC_coll_times[i] = 0;
138     }
139 }    
140
141 /* -----------------------------------------------------------------------------
142    Initialisation time...
143    -------------------------------------------------------------------------- */
144
145 void
146 stat_startInit(void)
147 {
148     Ticks elapsed;
149
150     elapsed = getProcessElapsedTime();
151     ElapsedTimeStart = elapsed;
152 }
153
154 void 
155 stat_endInit(void)
156 {
157     Ticks user, elapsed;
158
159     getProcessTimes(&user, &elapsed);
160
161     InitUserTime = user;
162     InitElapsedStamp = elapsed; 
163     if (ElapsedTimeStart > elapsed) {
164         InitElapsedTime = 0;
165     } else {
166         InitElapsedTime = elapsed - ElapsedTimeStart;
167     }
168 }
169
170 /* -----------------------------------------------------------------------------
171    stat_startExit and stat_endExit
172    
173    These two measure the time taken in shutdownHaskell().
174    -------------------------------------------------------------------------- */
175
176 void
177 stat_startExit(void)
178 {
179     Ticks user, elapsed;
180
181     getProcessTimes(&user, &elapsed);
182
183     MutElapsedStamp = elapsed;
184     MutElapsedTime = elapsed - GCe_tot_time -
185         PROF_VAL(RPe_tot_time + HCe_tot_time) - InitElapsedStamp;
186     if (MutElapsedTime < 0) { MutElapsedTime = 0; }     /* sometimes -0.00 */
187
188     MutUserTime = user - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime;
189     if (MutUserTime < 0) { MutUserTime = 0; }
190 }
191
192 void
193 stat_endExit(void)
194 {
195     Ticks user, elapsed;
196
197     getProcessTimes(&user, &elapsed);
198
199     ExitUserTime = user - MutUserTime - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime;
200     ExitElapsedTime = elapsed - MutElapsedStamp;
201     if (ExitUserTime < 0) {
202         ExitUserTime = 0;
203     }
204     if (ExitElapsedTime < 0) {
205         ExitElapsedTime = 0;
206     }
207 }
208
209 /* -----------------------------------------------------------------------------
210    Called at the beginning of each GC
211    -------------------------------------------------------------------------- */
212
213 static nat rub_bell = 0;
214
215 /*  initialise global variables needed during GC
216  *
217  *  * GC_start_time is read in mut_user_time_during_GC(), which in turn is 
218  *    needed if either PROFILING or DEBUGing is enabled
219  */
220 void
221 stat_startGC(void)
222 {
223     nat bell = RtsFlags.GcFlags.ringBell;
224
225     if (bell) {
226         if (bell > 1) {
227             debugBelch(" GC ");
228             rub_bell = 1;
229         } else {
230             debugBelch("\007");
231         }
232     }
233
234 #if defined(PROFILING) || defined(DEBUG)
235     GC_start_time = getProcessCPUTime();  // needed in mut_user_time_during_GC()
236 #endif
237
238     if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
239 #if !defined(PROFILING) && !defined(DEBUG)
240         GC_start_time = getProcessCPUTime();
241 #endif
242         GCe_start_time = getProcessElapsedTime();
243         if (RtsFlags.GcFlags.giveStats) {
244             GC_start_faults = getPageFaults();
245         }
246     }
247 }
248
249 /* -----------------------------------------------------------------------------
250    Called at the end of each GC
251    -------------------------------------------------------------------------- */
252
253 void
254 stat_endGC (lnat alloc, lnat live, lnat copied, 
255             lnat scavd_copied, lnat gen)
256 {
257     if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
258         Ticks time, etime, gc_time, gc_etime;
259         
260         getProcessTimes(&time, &etime);
261         gc_time  = time - GC_start_time;
262         gc_etime = etime - GCe_start_time;
263         
264         if (RtsFlags.GcFlags.giveStats == VERBOSE_GC_STATS) {
265             nat faults = getPageFaults();
266             
267             statsPrintf("%9ld %9ld %9ld",
268                     alloc*sizeof(W_), (copied+scavd_copied)*sizeof(W_), 
269                         live*sizeof(W_));
270             statsPrintf(" %5.2f %5.2f %7.2f %7.2f %4ld %4ld  (Gen: %2ld)\n", 
271                     TICK_TO_DBL(gc_time),
272                     TICK_TO_DBL(gc_etime),
273                     TICK_TO_DBL(time),
274                     TICK_TO_DBL(etime - ElapsedTimeStart),
275                     faults - GC_start_faults,
276                     GC_start_faults - GC_end_faults,
277                     gen);
278
279             GC_end_faults = faults;
280             statsFlush();
281         }
282
283         GC_coll_times[gen] += gc_time;
284
285         GC_tot_copied += (ullong) copied;
286         GC_tot_scavd_copied += (ullong) scavd_copied;
287         GC_tot_alloc  += (ullong) alloc;
288         GC_tot_time   += gc_time;
289         GCe_tot_time  += gc_etime;
290         
291 #if defined(THREADED_RTS)
292         {
293             Task *task;
294             if ((task = myTask()) != NULL) {
295                 task->gc_time += gc_time;
296                 task->gc_etime += gc_etime;
297             }
298         }
299 #endif
300
301         if (gen == RtsFlags.GcFlags.generations-1) { /* major GC? */
302             if (live > MaxResidency) {
303                 MaxResidency = live;
304             }
305             ResidencySamples++;
306             AvgResidency += live;
307         }
308     }
309
310     if (rub_bell) {
311         debugBelch("\b\b\b  \b\b\b");
312         rub_bell = 0;
313     }
314 }
315
316 /* -----------------------------------------------------------------------------
317    Called at the beginning of each Retainer Profiliing
318    -------------------------------------------------------------------------- */
319 #ifdef PROFILING
320 void
321 stat_startRP(void)
322 {
323     Ticks user, elapsed;
324     getProcessTimes( &user, &elapsed );
325
326     RP_start_time = user;
327     RPe_start_time = elapsed;
328 }
329 #endif /* PROFILING */
330
331 /* -----------------------------------------------------------------------------
332    Called at the end of each Retainer Profiliing
333    -------------------------------------------------------------------------- */
334
335 #ifdef PROFILING
336 void
337 stat_endRP(
338   nat retainerGeneration,
339 #ifdef DEBUG_RETAINER
340   nat maxCStackSize,
341   int maxStackSize,
342 #endif
343   double averageNumVisit)
344 {
345     Ticks user, elapsed;
346     getProcessTimes( &user, &elapsed );
347
348     RP_tot_time += user - RP_start_time;
349     RPe_tot_time += elapsed - RPe_start_time;
350
351   fprintf(prof_file, "Retainer Profiling: %d, at %f seconds\n", 
352     retainerGeneration, mut_user_time_during_RP());
353 #ifdef DEBUG_RETAINER
354   fprintf(prof_file, "\tMax C stack size = %u\n", maxCStackSize);
355   fprintf(prof_file, "\tMax auxiliary stack size = %u\n", maxStackSize);
356 #endif
357   fprintf(prof_file, "\tAverage number of visits per object = %f\n", averageNumVisit);
358 }
359 #endif /* PROFILING */
360
361 /* -----------------------------------------------------------------------------
362    Called at the beginning of each heap census
363    -------------------------------------------------------------------------- */
364 #ifdef PROFILING
365 void
366 stat_startHeapCensus(void)
367 {
368     Ticks user, elapsed;
369     getProcessTimes( &user, &elapsed );
370
371     HC_start_time = user;
372     HCe_start_time = elapsed;
373 }
374 #endif /* PROFILING */
375
376 /* -----------------------------------------------------------------------------
377    Called at the end of each heap census
378    -------------------------------------------------------------------------- */
379 #ifdef PROFILING
380 void
381 stat_endHeapCensus(void) 
382 {
383     Ticks user, elapsed;
384     getProcessTimes( &user, &elapsed );
385
386     HC_tot_time += user - HC_start_time;
387     HCe_tot_time += elapsed - HCe_start_time;
388 }
389 #endif /* PROFILING */
390
391 /* -----------------------------------------------------------------------------
392    Called at the end of execution
393
394    NOTE: number of allocations is not entirely accurate: it doesn't
395    take into account the few bytes at the end of the heap that
396    were left unused when the heap-check failed.
397    -------------------------------------------------------------------------- */
398
399 void
400 stat_exit(int alloc)
401 {
402     if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
403
404         char temp[BIG_STRING_LEN];
405         Ticks time;
406         Ticks etime;
407         nat g, total_collections = 0;
408
409         getProcessTimes( &time, &etime );
410         etime -= ElapsedTimeStart;
411
412         GC_tot_alloc += alloc;
413
414         /* Count total garbage collections */
415         for (g = 0; g < RtsFlags.GcFlags.generations; g++)
416             total_collections += generations[g].collections;
417
418         /* avoid divide by zero if time is measured as 0.00 seconds -- SDM */
419         if (time  == 0.0)  time = 1;
420         if (etime == 0.0) etime = 1;
421         
422         if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) {
423             statsPrintf("%9ld %9.9s %9.9s", (lnat)alloc*sizeof(W_), "", "");
424             statsPrintf(" %5.2f %5.2f\n\n", 0.0, 0.0);
425         }
426
427         if (RtsFlags.GcFlags.giveStats >= SUMMARY_GC_STATS) {
428             ullong_format_string(GC_tot_alloc*sizeof(W_), 
429                                  temp, rtsTrue/*commas*/);
430             statsPrintf("%11s bytes allocated in the heap\n", temp);
431
432             ullong_format_string(GC_tot_copied*sizeof(W_), 
433                                  temp, rtsTrue/*commas*/);
434             statsPrintf("%11s bytes copied during GC (scavenged)\n", temp);
435
436             ullong_format_string(GC_tot_scavd_copied*sizeof(W_), 
437                                  temp, rtsTrue/*commas*/);
438             statsPrintf("%11s bytes copied during GC (not scavenged)\n", temp);
439   
440             if ( ResidencySamples > 0 ) {
441                 ullong_format_string(MaxResidency*sizeof(W_), 
442                                      temp, rtsTrue/*commas*/);
443                 statsPrintf("%11s bytes maximum residency (%ld sample(s))\n",
444                         temp, ResidencySamples);
445             }
446             statsPrintf("\n");
447
448             /* Print garbage collections in each gen */
449             for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
450                 statsPrintf("%11d collections in generation %d (%6.2fs)\n", 
451                         generations[g].collections, g, 
452                         TICK_TO_DBL(GC_coll_times[g]));
453             }
454
455             statsPrintf("\n%11ld Mb total memory in use\n\n", 
456                     mblocks_allocated * MBLOCK_SIZE / (1024 * 1024));
457
458 #if defined(THREADED_RTS)
459             {
460                 nat i;
461                 Task *task;
462                 for (i = 0, task = all_tasks; 
463                      task != NULL; 
464                      i++, task = task->all_link) {
465                     statsPrintf("  Task %2d %-8s :  MUT time: %6.2fs  (%6.2fs elapsed)\n"
466                             "                      GC  time: %6.2fs  (%6.2fs elapsed)\n\n", 
467                                 i,
468                                 (task->tso == NULL) ? "(worker)" : "(bound)",
469                                 TICK_TO_DBL(task->mut_time),
470                                 TICK_TO_DBL(task->mut_etime),
471                                 TICK_TO_DBL(task->gc_time),
472                                 TICK_TO_DBL(task->gc_etime));
473                 }
474             }
475 #endif
476
477             statsPrintf("  INIT  time  %6.2fs  (%6.2fs elapsed)\n",
478                     TICK_TO_DBL(InitUserTime), TICK_TO_DBL(InitElapsedTime));
479             statsPrintf("  MUT   time  %6.2fs  (%6.2fs elapsed)\n",
480                     TICK_TO_DBL(MutUserTime), TICK_TO_DBL(MutElapsedTime));
481             statsPrintf("  GC    time  %6.2fs  (%6.2fs elapsed)\n",
482                     TICK_TO_DBL(GC_tot_time), TICK_TO_DBL(GCe_tot_time));
483 #ifdef PROFILING
484             statsPrintf("  RP    time  %6.2fs  (%6.2fs elapsed)\n",
485                     TICK_TO_DBL(RP_tot_time), TICK_TO_DBL(RPe_tot_time));
486             statsPrintf("  PROF  time  %6.2fs  (%6.2fs elapsed)\n",
487                     TICK_TO_DBL(HC_tot_time), TICK_TO_DBL(HCe_tot_time));
488 #endif 
489             statsPrintf("  EXIT  time  %6.2fs  (%6.2fs elapsed)\n",
490                     TICK_TO_DBL(ExitUserTime), TICK_TO_DBL(ExitElapsedTime));
491             statsPrintf("  Total time  %6.2fs  (%6.2fs elapsed)\n\n",
492                     TICK_TO_DBL(time), TICK_TO_DBL(etime));
493             statsPrintf("  %%GC time     %5.1f%%  (%.1f%% elapsed)\n\n",
494                     TICK_TO_DBL(GC_tot_time)*100/TICK_TO_DBL(time),
495                     TICK_TO_DBL(GCe_tot_time)*100/TICK_TO_DBL(etime));
496
497             if (time - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time) == 0)
498                 ullong_format_string(0, temp, rtsTrue/*commas*/);
499             else
500                 ullong_format_string(
501                     (ullong)((GC_tot_alloc*sizeof(W_))/
502                              TICK_TO_DBL(time - GC_tot_time - 
503                                          PROF_VAL(RP_tot_time + HC_tot_time))),
504                     temp, rtsTrue/*commas*/);
505             
506             statsPrintf("  Alloc rate    %s bytes per MUT second\n\n", temp);
507         
508             statsPrintf("  Productivity %5.1f%% of total user, %.1f%% of total elapsed\n\n",
509                     TICK_TO_DBL(time - GC_tot_time - 
510                                 PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime) * 100 
511                     / TICK_TO_DBL(time), 
512                     TICK_TO_DBL(time - GC_tot_time - 
513                                 PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime) * 100 
514                     / TICK_TO_DBL(etime));
515         }
516
517         if (RtsFlags.GcFlags.giveStats == ONELINE_GC_STATS) {
518           /* print the long long separately to avoid bugginess on mingwin (2001-07-02, mingw-0.5) */
519           statsPrintf("<<ghc: %llu bytes, ", GC_tot_alloc*(ullong)sizeof(W_));
520           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",
521                     total_collections,
522                     ResidencySamples == 0 ? 0 : 
523                         AvgResidency*sizeof(W_)/ResidencySamples, 
524                     MaxResidency*sizeof(W_), 
525                     ResidencySamples,
526                     (unsigned long)(mblocks_allocated * MBLOCK_SIZE / (1024L * 1024L)),
527                     TICK_TO_DBL(InitUserTime), TICK_TO_DBL(InitElapsedTime),
528                     TICK_TO_DBL(MutUserTime), TICK_TO_DBL(MutElapsedTime),
529                     TICK_TO_DBL(GC_tot_time), TICK_TO_DBL(GCe_tot_time));
530         }
531
532         statsFlush();
533         statsClose();
534     }
535 }
536
537 /* -----------------------------------------------------------------------------
538    stat_describe_gens
539
540    Produce some detailed info on the state of the generational GC.
541    -------------------------------------------------------------------------- */
542 #ifdef DEBUG
543 void
544 statDescribeGens(void)
545 {
546   nat g, s, mut, lge;
547   lnat live;
548   bdescr *bd;
549   step *step;
550
551   debugBelch(
552 "     Gen    Steps      Max   Mutable  Step   Blocks     Live    Large\n"
553 "                     Blocks Closures                          Objects\n");
554
555   mut = 0;
556   for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
557       for (bd = generations[g].mut_list; bd != NULL; bd = bd->link) {
558           mut += bd->free - bd->start;
559       }
560
561     debugBelch("%8d %8d %8d %9d", g, generations[g].n_steps,
562             generations[g].max_blocks, mut);
563
564     for (s = 0; s < generations[g].n_steps; s++) {
565       step = &generations[g].steps[s];
566       live = 0;
567       for (bd = step->large_objects, lge = 0; bd; bd = bd->link) {
568         lge++;
569       }
570       live = step->n_large_blocks * BLOCK_SIZE;
571       bd = step->blocks;
572       // This live figure will be slightly less that the "live" figure
573       // given by +RTS -Sstderr, because we take don't count the
574       // slop at the end of each block.
575       for (; bd; bd = bd->link) {
576         live += (bd->free - bd->start) * sizeof(W_);
577       }
578       if (s != 0) {
579         debugBelch("%36s","");
580       }
581       debugBelch("%6d %8d %8d %8d\n", s, step->n_blocks,
582               live, lge);
583     }
584   }
585   debugBelch("\n");
586 }
587 #endif
588
589 /* -----------------------------------------------------------------------------
590    Stats available via a programmatic interface, so eg. GHCi can time
591    each compilation and expression evaluation.
592    -------------------------------------------------------------------------- */
593
594 extern HsInt64 getAllocations( void ) 
595 { return (HsInt64)total_allocated * sizeof(W_); }
596
597 /* -----------------------------------------------------------------------------
598    Dumping stuff in the stats file, or via the debug message interface
599    -------------------------------------------------------------------------- */
600
601 static void
602 statsPrintf( char *s, ... )
603 {
604     FILE *sf = RtsFlags.GcFlags.statsFile;
605     va_list ap;
606     
607     va_start(ap,s);
608     if (sf == NULL) {
609         vdebugBelch(s,ap);
610     } else {
611         vfprintf(sf, s, ap);
612     }
613     va_end(ap);
614 }
615
616 static void
617 statsFlush( void )
618 {
619     FILE *sf = RtsFlags.GcFlags.statsFile;
620     if (sf != NULL) {
621         fflush(sf);
622     }
623 }
624
625 static void
626 statsClose( void )
627 {
628     FILE *sf = RtsFlags.GcFlags.statsFile;
629     if (sf != NULL) {
630         fclose(sf);
631     }
632 }