809ad78c9ad12b30d7aabd9da1033b9a1ea08640
[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*sizeof(W_), live*sizeof(W_));
269             statsPrintf(" %5.2f %5.2f %7.2f %7.2f %4ld %4ld  (Gen: %2ld)\n", 
270                     TICK_TO_DBL(gc_time),
271                     TICK_TO_DBL(gc_etime),
272                     TICK_TO_DBL(time),
273                     TICK_TO_DBL(etime - ElapsedTimeStart),
274                     faults - GC_start_faults,
275                     GC_start_faults - GC_end_faults,
276                     gen);
277
278             GC_end_faults = faults;
279             statsFlush();
280         }
281
282         GC_coll_times[gen] += gc_time;
283
284         GC_tot_copied += (ullong) copied;
285         GC_tot_scavd_copied += (ullong) scavd_copied;
286         GC_tot_alloc  += (ullong) alloc;
287         GC_tot_time   += gc_time;
288         GCe_tot_time  += gc_etime;
289         
290 #if defined(THREADED_RTS)
291         {
292             Task *task;
293             if ((task = myTask()) != NULL) {
294                 task->gc_time += gc_time;
295                 task->gc_etime += gc_etime;
296             }
297         }
298 #endif
299
300         if (gen == RtsFlags.GcFlags.generations-1) { /* major GC? */
301             if (live > MaxResidency) {
302                 MaxResidency = live;
303             }
304             ResidencySamples++;
305             AvgResidency += live;
306         }
307     }
308
309     if (rub_bell) {
310         debugBelch("\b\b\b  \b\b\b");
311         rub_bell = 0;
312     }
313 }
314
315 /* -----------------------------------------------------------------------------
316    Called at the beginning of each Retainer Profiliing
317    -------------------------------------------------------------------------- */
318 #ifdef PROFILING
319 void
320 stat_startRP(void)
321 {
322     Ticks user, elapsed;
323     getProcessTimes( &user, &elapsed );
324
325     RP_start_time = user;
326     RPe_start_time = elapsed;
327 }
328 #endif /* PROFILING */
329
330 /* -----------------------------------------------------------------------------
331    Called at the end of each Retainer Profiliing
332    -------------------------------------------------------------------------- */
333
334 #ifdef PROFILING
335 void
336 stat_endRP(
337   nat retainerGeneration,
338 #ifdef DEBUG_RETAINER
339   nat maxCStackSize,
340   int maxStackSize,
341 #endif
342   double averageNumVisit)
343 {
344     Ticks user, elapsed;
345     getProcessTimes( &user, &elapsed );
346
347     RP_tot_time += user - RP_start_time;
348     RPe_tot_time += elapsed - RPe_start_time;
349
350   fprintf(prof_file, "Retainer Profiling: %d, at %f seconds\n", 
351     retainerGeneration, mut_user_time_during_RP());
352 #ifdef DEBUG_RETAINER
353   fprintf(prof_file, "\tMax C stack size = %u\n", maxCStackSize);
354   fprintf(prof_file, "\tMax auxiliary stack size = %u\n", maxStackSize);
355 #endif
356   fprintf(prof_file, "\tAverage number of visits per object = %f\n", averageNumVisit);
357 }
358 #endif /* PROFILING */
359
360 /* -----------------------------------------------------------------------------
361    Called at the beginning of each heap census
362    -------------------------------------------------------------------------- */
363 #ifdef PROFILING
364 void
365 stat_startHeapCensus(void)
366 {
367     Ticks user, elapsed;
368     getProcessTimes( &user, &elapsed );
369
370     HC_start_time = user;
371     HCe_start_time = elapsed;
372 }
373 #endif /* PROFILING */
374
375 /* -----------------------------------------------------------------------------
376    Called at the end of each heap census
377    -------------------------------------------------------------------------- */
378 #ifdef PROFILING
379 void
380 stat_endHeapCensus(void) 
381 {
382     Ticks user, elapsed;
383     getProcessTimes( &user, &elapsed );
384
385     HC_tot_time += user - HC_start_time;
386     HCe_tot_time += elapsed - HCe_start_time;
387 }
388 #endif /* PROFILING */
389
390 /* -----------------------------------------------------------------------------
391    Called at the end of execution
392
393    NOTE: number of allocations is not entirely accurate: it doesn't
394    take into account the few bytes at the end of the heap that
395    were left unused when the heap-check failed.
396    -------------------------------------------------------------------------- */
397
398 void
399 stat_exit(int alloc)
400 {
401     if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
402
403         char temp[BIG_STRING_LEN];
404         Ticks time;
405         Ticks etime;
406         nat g, total_collections = 0;
407
408         getProcessTimes( &time, &etime );
409         etime -= ElapsedTimeStart;
410
411         GC_tot_alloc += alloc;
412
413         /* Count total garbage collections */
414         for (g = 0; g < RtsFlags.GcFlags.generations; g++)
415             total_collections += generations[g].collections;
416
417         /* avoid divide by zero if time is measured as 0.00 seconds -- SDM */
418         if (time  == 0.0)  time = 1;
419         if (etime == 0.0) etime = 1;
420         
421         if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) {
422             statsPrintf("%9ld %9.9s %9.9s", (lnat)alloc*sizeof(W_), "", "");
423             statsPrintf(" %5.2f %5.2f\n\n", 0.0, 0.0);
424         }
425
426         if (RtsFlags.GcFlags.giveStats >= SUMMARY_GC_STATS) {
427             ullong_format_string(GC_tot_alloc*sizeof(W_), 
428                                  temp, rtsTrue/*commas*/);
429             statsPrintf("%11s bytes allocated in the heap\n", temp);
430
431             ullong_format_string(GC_tot_copied*sizeof(W_), 
432                                  temp, rtsTrue/*commas*/);
433             statsPrintf("%11s bytes copied during GC (scavenged)\n", temp);
434
435             ullong_format_string(GC_tot_scavd_copied*sizeof(W_), 
436                                  temp, rtsTrue/*commas*/);
437             statsPrintf("%11s bytes copied during GC (not scavenged)\n", temp);
438   
439             if ( ResidencySamples > 0 ) {
440                 ullong_format_string(MaxResidency*sizeof(W_), 
441                                      temp, rtsTrue/*commas*/);
442                 statsPrintf("%11s bytes maximum residency (%ld sample(s))\n",
443                         temp, ResidencySamples);
444             }
445             statsPrintf("\n");
446
447             /* Print garbage collections in each gen */
448             for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
449                 statsPrintf("%11d collections in generation %d (%6.2fs)\n", 
450                         generations[g].collections, g, 
451                         TICK_TO_DBL(GC_coll_times[g]));
452             }
453
454             statsPrintf("\n%11ld Mb total memory in use\n\n", 
455                     mblocks_allocated * MBLOCK_SIZE / (1024 * 1024));
456
457 #if defined(THREADED_RTS)
458             {
459                 nat i;
460                 Task *task;
461                 for (i = 0, task = all_tasks; 
462                      task != NULL; 
463                      i++, task = task->all_link) {
464                     statsPrintf("  Task %2d %-8s :  MUT time: %6.2fs  (%6.2fs elapsed)\n"
465                             "                      GC  time: %6.2fs  (%6.2fs elapsed)\n\n", 
466                                 i,
467                                 (task->tso == NULL) ? "(worker)" : "(bound)",
468                                 TICK_TO_DBL(task->mut_time),
469                                 TICK_TO_DBL(task->mut_etime),
470                                 TICK_TO_DBL(task->gc_time),
471                                 TICK_TO_DBL(task->gc_etime));
472                 }
473             }
474 #endif
475
476             statsPrintf("  INIT  time  %6.2fs  (%6.2fs elapsed)\n",
477                     TICK_TO_DBL(InitUserTime), TICK_TO_DBL(InitElapsedTime));
478             statsPrintf("  MUT   time  %6.2fs  (%6.2fs elapsed)\n",
479                     TICK_TO_DBL(MutUserTime), TICK_TO_DBL(MutElapsedTime));
480             statsPrintf("  GC    time  %6.2fs  (%6.2fs elapsed)\n",
481                     TICK_TO_DBL(GC_tot_time), TICK_TO_DBL(GCe_tot_time));
482 #ifdef PROFILING
483             statsPrintf("  RP    time  %6.2fs  (%6.2fs elapsed)\n",
484                     TICK_TO_DBL(RP_tot_time), TICK_TO_DBL(RPe_tot_time));
485             statsPrintf("  PROF  time  %6.2fs  (%6.2fs elapsed)\n",
486                     TICK_TO_DBL(HC_tot_time), TICK_TO_DBL(HCe_tot_time));
487 #endif 
488             statsPrintf("  EXIT  time  %6.2fs  (%6.2fs elapsed)\n",
489                     TICK_TO_DBL(ExitUserTime), TICK_TO_DBL(ExitElapsedTime));
490             statsPrintf("  Total time  %6.2fs  (%6.2fs elapsed)\n\n",
491                     TICK_TO_DBL(time), TICK_TO_DBL(etime));
492             statsPrintf("  %%GC time     %5.1f%%  (%.1f%% elapsed)\n\n",
493                     TICK_TO_DBL(GC_tot_time)*100/TICK_TO_DBL(time),
494                     TICK_TO_DBL(GCe_tot_time)*100/TICK_TO_DBL(etime));
495
496             if (time - GC_tot_time - PROF_VAL(RP_tot_time + HC_tot_time) == 0)
497                 ullong_format_string(0, temp, rtsTrue/*commas*/);
498             else
499                 ullong_format_string(
500                     (ullong)((GC_tot_alloc*sizeof(W_))/
501                              TICK_TO_DBL(time - GC_tot_time - 
502                                          PROF_VAL(RP_tot_time + HC_tot_time))),
503                     temp, rtsTrue/*commas*/);
504             
505             statsPrintf("  Alloc rate    %s bytes per MUT second\n\n", temp);
506         
507             statsPrintf("  Productivity %5.1f%% of total user, %.1f%% of total elapsed\n\n",
508                     TICK_TO_DBL(time - GC_tot_time - 
509                                 PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime) * 100 
510                     / TICK_TO_DBL(time), 
511                     TICK_TO_DBL(time - GC_tot_time - 
512                                 PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime) * 100 
513                     / TICK_TO_DBL(etime));
514         }
515
516         if (RtsFlags.GcFlags.giveStats == ONELINE_GC_STATS) {
517           /* print the long long separately to avoid bugginess on mingwin (2001-07-02, mingw-0.5) */
518           statsPrintf("<<ghc: %llu bytes, ", GC_tot_alloc*(ullong)sizeof(W_));
519           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",
520                     total_collections,
521                     ResidencySamples == 0 ? 0 : 
522                         AvgResidency*sizeof(W_)/ResidencySamples, 
523                     MaxResidency*sizeof(W_), 
524                     ResidencySamples,
525                     (unsigned long)(mblocks_allocated * MBLOCK_SIZE / (1024L * 1024L)),
526                     TICK_TO_DBL(InitUserTime), TICK_TO_DBL(InitElapsedTime),
527                     TICK_TO_DBL(MutUserTime), TICK_TO_DBL(MutElapsedTime),
528                     TICK_TO_DBL(GC_tot_time), TICK_TO_DBL(GCe_tot_time));
529         }
530
531         statsFlush();
532         statsClose();
533     }
534 }
535
536 /* -----------------------------------------------------------------------------
537    stat_describe_gens
538
539    Produce some detailed info on the state of the generational GC.
540    -------------------------------------------------------------------------- */
541 #ifdef DEBUG
542 void
543 statDescribeGens(void)
544 {
545   nat g, s, mut, lge, live;
546   bdescr *bd;
547   step *step;
548
549   debugBelch(
550 "     Gen    Steps      Max   Mutable  Step   Blocks     Live    Large\n"
551 "                     Blocks Closures                          Objects\n");
552
553   mut = 0;
554   for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
555       for (bd = generations[g].mut_list; bd != NULL; bd = bd->link) {
556           mut += bd->free - bd->start;
557       }
558
559     debugBelch("%8d %8d %8d %9d", g, generations[g].n_steps,
560             generations[g].max_blocks, mut);
561
562     for (s = 0; s < generations[g].n_steps; s++) {
563       step = &generations[g].steps[s];
564       for (bd = step->large_objects, lge = 0; bd; bd = bd->link)
565         lge++;
566       live = 0;
567       bd = step->blocks;
568       for (; bd; bd = bd->link) {
569         live += (bd->free - bd->start) * sizeof(W_);
570       }
571       if (s != 0) {
572         debugBelch("%36s","");
573       }
574       debugBelch("%6d %8d %8d %8d\n", s, step->n_blocks,
575               live, lge);
576     }
577   }
578   debugBelch("\n");
579 }
580 #endif
581
582 /* -----------------------------------------------------------------------------
583    Stats available via a programmatic interface, so eg. GHCi can time
584    each compilation and expression evaluation.
585    -------------------------------------------------------------------------- */
586
587 extern HsInt64 getAllocations( void ) 
588 { return (HsInt64)total_allocated * sizeof(W_); }
589
590 /* -----------------------------------------------------------------------------
591    Dumping stuff in the stats file, or via the debug message interface
592    -------------------------------------------------------------------------- */
593
594 static void
595 statsPrintf( char *s, ... )
596 {
597     FILE *sf = RtsFlags.GcFlags.statsFile;
598     va_list ap;
599     
600     va_start(ap,s);
601     if (sf == NULL) {
602         vdebugBelch(s,ap);
603     } else {
604         vfprintf(sf, s, ap);
605     }
606     va_end(ap);
607 }
608
609 static void
610 statsFlush( void )
611 {
612     FILE *sf = RtsFlags.GcFlags.statsFile;
613     if (sf != NULL) {
614         fflush(sf);
615     }
616 }
617
618 static void
619 statsClose( void )
620 {
621     FILE *sf = RtsFlags.GcFlags.statsFile;
622     if (sf != NULL) {
623         fclose(sf);
624     }
625 }