1c5d243e64b64e0cc8b42783f77800f982035c49
[ghc-hetmet.git] / ghc / rts / Stats.c
1 /* -----------------------------------------------------------------------------
2  * $Id: Stats.c,v 1.18 1999/11/11 13:17:36 simonmar Exp $
3  *
4  * (c) The GHC Team, 1998-1999
5  *
6  * Statistics and timing-related functions.
7  *
8  * ---------------------------------------------------------------------------*/
9
10 #define NON_POSIX_SOURCE
11
12 #include "Rts.h"
13 #include "RtsFlags.h"
14 #include "RtsUtils.h"
15 #include "StoragePriv.h"
16 #include "MBlock.h"
17 #include "Schedule.h"
18 #include "Stats.h"
19
20 #ifdef HAVE_UNISTD_H
21 #include <unistd.h>
22 #endif
23
24 #ifndef __MINGW32__
25 # ifdef HAVE_SYS_TIMES_H
26 #  include <sys/times.h>
27 # endif
28 #endif
29
30 #ifdef HAVE_SYS_TIME_H
31 #include <sys/time.h>
32 #endif
33
34 #ifdef __CYGWIN32__
35 # ifdef HAVE_TIME_H
36 #  include <time.h>
37 # endif
38 #endif
39
40 #if ! irix_TARGET_OS && ! defined(__MINGW32__)
41 # if defined(HAVE_SYS_RESOURCE_H)
42 #  include <sys/resource.h>
43 # endif
44 #endif
45
46 #ifdef HAVE_SYS_TIMEB_H
47 #include <sys/timeb.h>
48 #endif
49
50 #if HAVE_STDLIB_H
51 #include <stdlib.h>
52 #endif
53
54 #if HAVE_WINDOWS_H
55 #include <windows.h>
56 #endif
57
58 /* huh? */
59 #define BIG_STRING_LEN              512
60
61 static double ElapsedTimeStart = 0.0;
62 static double TicksPerSecond   = 0.0;
63
64 static double InitUserTime = 0.0;
65 static double InitElapsedTime = 0.0;
66 static double InitElapsedStamp = 0.0;
67
68 static double MutUserTime = 0.0;
69 static double MutElapsedTime = 0.0;
70 static double MutElapsedStamp = 0.0;
71
72 static double ExitUserTime = 0.0;
73 static double ExitElapsedTime = 0.0;
74
75 static ullong GC_tot_alloc = 0;
76 static ullong GC_tot_copied = 0;
77
78 static double GC_start_time,  GC_tot_time = 0;  /* User GC Time */
79 static double GCe_start_time, GCe_tot_time = 0; /* Elapsed GC time */
80
81 lnat MaxResidency = 0;     /* in words; for stats only */
82 lnat ResidencySamples = 0; /* for stats only */
83
84 static lnat GC_start_faults = 0, GC_end_faults = 0;
85
86 static double *GC_coll_times;
87
88 /* ToDo: convert this to use integers? --SDM */
89
90 /* elapsedtime() -- The current elapsed time in seconds */
91
92 #ifdef _WIN32
93 #define NS_PER_SEC 10000000LL
94 /* Convert FILETIMEs into secs since the Epoch (Jan1-1970) */
95 #define FT2longlong(ll,ft)    \
96     (ll)=(ft).dwHighDateTime; \
97     (ll) <<= 32;              \
98     (ll) |= (ft).dwLowDateTime; \
99     (ll) /= (unsigned long long) (NS_PER_SEC / CLOCKS_PER_SEC)
100 #endif
101
102 #ifdef _WIN32
103 /* cygwin32 or mingw32 version */
104 double
105 elapsedtime(void)
106 {
107     FILETIME creationTime, exitTime, kernelTime, userTime;
108     long long int kT, uT;
109  
110  
111     /* ToDo: pin down elapsed times to just the OS thread(s) that
112        are evaluating/managing Haskell code.
113     */
114     if (!GetProcessTimes (GetCurrentProcess(), &creationTime,
115                           &exitTime, &kernelTime, &userTime)) {
116         /* Probably on a Win95 box..*/
117         return 0;
118     }
119
120     FT2longlong(kT,kernelTime);
121     FT2longlong(uT,userTime);
122     return (((StgDouble)(uT + kT))/TicksPerSecond);
123 }
124
125 #else 
126
127 double
128 elapsedtime(void)
129 {
130
131 # if ! (defined(HAVE_TIMES) || defined(HAVE_FTIME))
132     /* We will #ifdef around the fprintf for machines
133        we *know* are unsupported. (WDP 94/05)
134     */
135     fprintf(stderr, "NOTE: `elapsedtime' does nothing!\n");
136     return 0.0;
137
138 # else /* not stumped */
139
140 /* "ftime" may be nicer, but "times" is more standard;
141    but, on a Sun, if you do not get the SysV one, you are *hosed*...
142  */
143
144 #  if defined(HAVE_TIMES) && ! sunos4_TARGET_OS
145     struct tms t;
146     clock_t r = times(&t);
147
148     return (((double)r)/TicksPerSecond);
149
150 #  else /* HAVE_FTIME */
151     struct timeb t;
152
153     ftime(&t);
154     return (fabs(t.time + 1e-3*t.millitm));
155
156 #  endif /* HAVE_FTIME */
157 # endif /* not stumped */
158 }
159 #endif /* !_WIN32 */
160
161 /* mut_user_time_during_GC() and mut_user_time()
162  *
163  * This function can be used to get the current mutator time *during*
164  * a GC, i.e. between stat_startGC and stat_endGC.  This is used in
165  * the heap profiler for accurately time stamping the heap sample.
166  */
167 double
168 mut_user_time_during_GC(void)
169 {
170   return (GC_start_time - GC_tot_time);
171 }
172
173 double
174 mut_user_time(void)
175 {
176   return (usertime() - GC_tot_time);
177 }
178
179
180 static nat
181 pagefaults(void)
182 {
183   /* ToDo (on NT): better, get this via the performance data
184      that's stored in the registry. */
185 # if !defined(HAVE_GETRUSAGE) || irix_TARGET_OS || defined(_WIN32)
186     return 0;
187 # else
188     struct rusage t;
189
190     getrusage(RUSAGE_SELF, &t);
191     return(t.ru_majflt);
192 # endif
193 }
194
195 /* ToDo: use gettimeofday on systems that support it (u-sec accuracy) */
196
197 void
198 start_time(void)
199 {
200 #ifdef HAVE_SYSCONF
201     long ticks;
202     /* Determine TicksPerSecond ... */
203
204     ticks = sysconf(_SC_CLK_TCK);
205     if ( ticks == -1 ) {
206         fprintf(stderr, "stat_init: bad call to 'sysconf'!\n");
207         stg_exit(EXIT_FAILURE);
208     }
209     TicksPerSecond = (double) ticks;
210
211 /* no "sysconf"; had better guess */
212 #elif defined(HZ)
213     TicksPerSecond = (StgDouble) (HZ);
214
215 #elif defined(CLOCKS_PER_SEC)
216     TicksPerSecond = (StgDouble) (CLOCKS_PER_SEC);
217 #else /* had better guess wildly */
218     /* We will #ifdef around the fprintf for machines
219        we *know* are unsupported. (WDP 94/05)
220     */
221     fprintf(stderr, "NOTE: Guessing `TicksPerSecond = 60'!\n");
222     TicksPerSecond = 60.0;
223 #endif
224
225     ElapsedTimeStart = elapsedtime();
226 }
227
228
229 void
230 initStats(void)
231 {
232   nat i;
233   FILE *sf = RtsFlags.GcFlags.statsFile;
234   
235   if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) {
236     fprintf(sf, "    Alloc    Collect    Live    GC    GC     TOT     TOT  Page Flts\n");
237     fprintf(sf, "    bytes     bytes     bytes  user  elap    user    elap\n");
238   }
239   GC_coll_times = 
240     (double *)stgMallocBytes(sizeof(double) * RtsFlags.GcFlags.generations,
241                            "initStats");
242   for (i = 0; i < RtsFlags.GcFlags.generations; i++) {
243     GC_coll_times[i] = 0.0;
244   }
245 }    
246
247 #ifdef _WIN32
248 double
249 usertime(void)
250 {
251     FILETIME creationTime, exitTime, kernelTime, userTime;
252     long long int uT;
253
254     /* Convert FILETIMEs into long longs */
255
256     if (!GetProcessTimes (GetCurrentProcess(), &creationTime,
257                           &exitTime, &kernelTime, &userTime)) {
258         /* Probably exec'ing this on a Win95 box..*/
259         return 0;
260     }
261
262     FT2longlong(uT,userTime);
263     return (((StgDouble)uT)/TicksPerSecond);
264 }
265 #else
266
267 double
268 usertime(void)
269 {
270 # if ! (defined(HAVE_GETRUSAGE) || defined(HAVE_TIMES))
271     /* We will #ifdef around the fprintf for machines
272        we *know* are unsupported. (WDP 94/05)
273     */
274     fprintf(stderr, "NOTE: `usertime' does nothing!\n");
275     return 0.0;
276
277 # else /* not stumped */
278
279 #  if defined(HAVE_TIMES) 
280     struct tms t;
281
282     times(&t);
283     return(((double)(t.tms_utime))/TicksPerSecond);
284
285 #  else /* HAVE_GETRUSAGE */
286     struct rusage t;
287
288     getrusage(RUSAGE_SELF, &t);
289     return(t.ru_utime.tv_sec + 1e-6*t.ru_utime.tv_usec);
290
291 #  endif /* HAVE_GETRUSAGE */
292 # endif /* not stumped */
293 }
294 #endif /* ! _WIN32 */
295
296 void 
297 end_init(void)
298 {
299   InitUserTime = usertime();
300   InitElapsedStamp = elapsedtime(); 
301   InitElapsedTime = InitElapsedStamp - ElapsedTimeStart;
302   if (InitElapsedTime < 0.0) {
303     InitElapsedTime = 0.0;
304   }
305 }
306
307 /* -----------------------------------------------------------------------------
308    stat_startExit and stat_endExit
309    
310    These two measure the time taken in shutdownHaskell().
311    -------------------------------------------------------------------------- */
312
313 void
314 stat_startExit(void)
315 {
316   MutElapsedStamp = elapsedtime(); 
317   MutElapsedTime = MutElapsedStamp - GCe_tot_time - InitElapsedStamp;
318   if (MutElapsedTime < 0) { MutElapsedTime = 0; }       /* sometimes -0.00 */
319
320   /* for SMP, we don't know the mutator time yet, we have to inspect
321    * all the running threads to find out, and they haven't stopped
322    * yet.  So we just timestamp MutUserTime at this point so we can
323    * calculate the EXIT time.  The real MutUserTime is calculated
324    * in stat_exit below.
325    */
326 #ifdef SMP
327   MutUserTime = usertime();
328 #else
329   MutUserTime = usertime() - GC_tot_time - InitUserTime;
330   if (MutUserTime < 0) { MutUserTime = 0; }
331 #endif
332 }
333
334 void
335 stat_endExit(void)
336 {
337 #ifdef SMP
338   ExitUserTime = usertime() - MutUserTime;
339 #else
340   ExitUserTime = usertime() - MutUserTime - GC_tot_time - InitUserTime;
341 #endif
342   ExitElapsedTime = elapsedtime() - MutElapsedStamp;
343   if (ExitUserTime < 0.0) {
344     ExitUserTime = 0.0;
345   }
346   if (ExitElapsedTime < 0.0) {
347     ExitElapsedTime = 0.0;
348   }
349 }
350
351 /* -----------------------------------------------------------------------------
352    Called at the beginning of each GC
353    -------------------------------------------------------------------------- */
354
355 static nat rub_bell = 0;
356
357 void
358 stat_startGC(void)
359 {
360     FILE *sf = RtsFlags.GcFlags.statsFile;
361
362     nat bell = RtsFlags.GcFlags.ringBell;
363
364     if (bell) {
365         if (bell > 1) {
366             fprintf(stderr, " GC ");
367             rub_bell = 1;
368         } else {
369             fprintf(stderr, "\007");
370         }
371     }
372
373     if (sf != NULL) {
374         GC_start_time = usertime();
375         GCe_start_time = elapsedtime();
376         if (RtsFlags.GcFlags.giveStats) {
377           GC_start_faults = pagefaults();
378         }
379     }
380 }
381
382 /* -----------------------------------------------------------------------------
383    Called at the end of each GC
384    -------------------------------------------------------------------------- */
385
386 void
387 stat_endGC(lnat alloc, lnat collect, lnat live, lnat copied, lnat gen)
388 {
389     FILE *sf = RtsFlags.GcFlags.statsFile;
390
391     if (sf != NULL) {
392         double time     = usertime();
393         double etime    = elapsedtime();
394         double gc_time  = time-GC_start_time;
395         double gc_etime = etime-GCe_start_time;
396
397         if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) {
398             nat faults = pagefaults();
399
400             fprintf(sf, "%9ld %9ld %9ld",
401                     alloc*sizeof(W_), collect*sizeof(W_), live*sizeof(W_));
402             fprintf(sf, " %5.2f %5.2f %7.2f %7.2f %4ld %4ld  (Gen: %2ld)\n", 
403                     gc_time, 
404                     gc_etime,
405                     time,
406                     etime,
407                     faults - GC_start_faults,
408                     GC_start_faults - GC_end_faults,
409                     gen);
410
411             GC_end_faults = faults;
412             fflush(sf);
413         }
414
415         GC_coll_times[gen] += time-GC_start_time;
416
417         GC_tot_copied += (ullong) copied;
418         GC_tot_alloc  += (ullong) alloc;
419         GC_tot_time   += gc_time;
420         GCe_tot_time  += gc_etime;
421
422 #ifdef SMP
423         {
424           nat i;
425           pthread_t me = pthread_self();
426
427           for (i = 0; i < RtsFlags.ConcFlags.nNodes; i++) {
428             if (me == task_ids[i].id) {
429               task_ids[i].gc_time += gc_time;
430               task_ids[i].gc_etime += gc_etime;
431               break;
432             }
433           }
434         }
435 #endif
436
437         if (gen == RtsFlags.GcFlags.generations-1) { /* major GC? */
438           if (live > MaxResidency) {
439             MaxResidency = live;
440           }
441           ResidencySamples++;
442         }
443     }
444
445     if (rub_bell) {
446         fprintf(stderr, "\b\b\b  \b\b\b");
447         rub_bell = 0;
448     }
449 }
450
451 /* -----------------------------------------------------------------------------
452    stat_workerStop
453
454    Called under SMP when a worker thread finishes.  We drop the timing
455    stats for this thread into the task_ids struct for that thread.
456    -------------------------------------------------------------------------- */
457
458 #ifdef SMP
459 void
460 stat_workerStop(void)
461 {
462   nat i;
463   pthread_t me = pthread_self();
464
465   for (i = 0; i < RtsFlags.ConcFlags.nNodes; i++) {
466     if (task_ids[i].id == me) {
467       task_ids[i].mut_time = usertime() - task_ids[i].gc_time;
468       task_ids[i].mut_etime = elapsedtime()
469                                  - GCe_tot_time
470                                  - task_ids[i].elapsedtimestart;
471       if (task_ids[i].mut_time < 0.0)  { task_ids[i].mut_time = 0.0;  }
472       if (task_ids[i].mut_etime < 0.0) { task_ids[i].mut_etime = 0.0; }
473     }
474   }
475 }
476 #endif
477
478 /* -----------------------------------------------------------------------------
479    Called at the end of execution
480
481    NOTE: number of allocations is not entirely accurate: it doesn't
482    take into account the few bytes at the end of the heap that
483    were left unused when the heap-check failed.
484    -------------------------------------------------------------------------- */
485
486 void
487 stat_exit(int alloc)
488 {
489     FILE *sf = RtsFlags.GcFlags.statsFile;
490
491     if (sf != NULL){
492         char temp[BIG_STRING_LEN];
493         double time = usertime();
494         double etime = elapsedtime() - ElapsedTimeStart;
495
496         /* avoid divide by zero if time is measured as 0.00 seconds -- SDM */
497         if (time  == 0.0)  time = 0.0001;
498         if (etime == 0.0) etime = 0.0001;
499         
500         if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) {
501           fprintf(sf, "%9ld %9.9s %9.9s",       (lnat)alloc*sizeof(W_), "", "");
502           fprintf(sf, " %5.2f %5.2f\n\n", 0.0, 0.0);
503         }
504
505         GC_tot_alloc += alloc;
506
507         ullong_format_string(GC_tot_alloc*sizeof(W_), temp, rtsTrue/*commas*/);
508         fprintf(sf, "%11s bytes allocated in the heap\n", temp);
509
510         ullong_format_string(GC_tot_copied*sizeof(W_), temp, rtsTrue/*commas*/);
511         fprintf(sf, "%11s bytes copied during GC\n", temp);
512
513         if ( ResidencySamples > 0 ) {
514             ullong_format_string(MaxResidency*sizeof(W_), temp, rtsTrue/*commas*/);
515             fprintf(sf, "%11s bytes maximum residency (%ld sample(s))\n",
516                               temp,
517                               ResidencySamples);
518         }
519         fprintf(sf,"\n");
520
521         { /* Count garbage collections */
522           nat g;
523           for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
524             fprintf(sf, "%11d collections in generation %d (%6.2fs)\n", 
525                     generations[g].collections, g, GC_coll_times[g]);
526           }
527         }
528         fprintf(sf,"\n%11ld Mb total memory in use\n\n", 
529                 mblocks_allocated * MBLOCK_SIZE / (1024 * 1024));
530
531         /* For SMP, we have to get the user time from each thread
532          * and try to work out the total time.
533          */
534 #ifdef SMP
535         {
536           nat i;
537           MutUserTime = 0.0;
538           for (i = 0; i < RtsFlags.ConcFlags.nNodes; i++) {
539             MutUserTime += task_ids[i].mut_time;
540             fprintf(sf, "  Task %2d:  MUT time: %6.2fs  (%6.2fs elapsed)\n"
541                         "            GC  time: %6.2fs  (%6.2fs elapsed)\n\n", 
542                     i, 
543                     task_ids[i].mut_time, task_ids[i].mut_etime,
544                     task_ids[i].gc_time, task_ids[i].gc_etime);
545           }
546         }
547         time = MutUserTime + GC_tot_time + InitUserTime + ExitUserTime;
548         if (MutUserTime < 0) { MutUserTime = 0; }
549 #endif
550
551         fprintf(sf, "  INIT  time  %6.2fs  (%6.2fs elapsed)\n",
552                 InitUserTime, InitElapsedTime);
553         fprintf(sf, "  MUT   time  %6.2fs  (%6.2fs elapsed)\n",
554                 MutUserTime, MutElapsedTime);
555         fprintf(sf, "  GC    time  %6.2fs  (%6.2fs elapsed)\n",
556                 GC_tot_time, GCe_tot_time);
557         fprintf(sf, "  EXIT  time  %6.2fs  (%6.2fs elapsed)\n",
558                 ExitUserTime, ExitElapsedTime);
559         fprintf(sf, "  Total time  %6.2fs  (%6.2fs elapsed)\n\n",
560                 time, etime);
561
562         fprintf(sf, "  %%GC time     %5.1f%%  (%.1f%% elapsed)\n\n",
563                 GC_tot_time*100./time, GCe_tot_time*100./etime);
564
565         if (time - GC_tot_time == 0.0)
566                 ullong_format_string(0, temp, rtsTrue/*commas*/);
567         else
568                 ullong_format_string((ullong)(GC_tot_alloc*sizeof(W_)/
569                                               (time - GC_tot_time)),
570                                      temp, rtsTrue/*commas*/);
571
572         fprintf(sf, "  Alloc rate    %s bytes per MUT second\n\n", temp);
573
574         fprintf(sf, "  Productivity %5.1f%% of total user, %.1f%% of total elapsed\n\n",
575                 (time - GC_tot_time - InitUserTime) * 100. / time, 
576                 (time - GC_tot_time - InitUserTime) * 100. / etime);
577         fflush(sf);
578         fclose(sf);
579     }
580 }
581
582 /* -----------------------------------------------------------------------------
583    stat_describe_gens
584
585    Produce some detailed info on the state of the generational GC.
586    -------------------------------------------------------------------------- */
587 void
588 stat_describe_gens(void)
589 {
590   nat g, s, mut, mut_once, lge, live;
591   StgMutClosure *m;
592   bdescr *bd;
593   step *step;
594
595   fprintf(stderr, "     Gen    Steps      Max   Mutable  Mut-Once  Step   Blocks     Live    Large\n                    Blocks  Closures  Closures                         Objects\n");
596
597   for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
598     for (m = generations[g].mut_list, mut = 0; m != END_MUT_LIST; 
599          m = m->mut_link) 
600       mut++;
601     for (m = generations[g].mut_once_list, mut_once = 0; m != END_MUT_LIST; 
602          m = m->mut_link) 
603       mut_once++;
604     fprintf(stderr, "%8d %8d %8d %9d %9d", g, generations[g].n_steps,
605             generations[g].max_blocks, mut, mut_once);
606
607     for (s = 0; s < generations[g].n_steps; s++) {
608       step = &generations[g].steps[s];
609       for (bd = step->large_objects, lge = 0; bd; bd = bd->link)
610         lge++;
611       live = 0;
612       if (RtsFlags.GcFlags.generations == 1) {
613         bd = step->to_space;
614       } else {
615         bd = step->blocks;
616       }
617       for (; bd; bd = bd->link) {
618         live += (bd->free - bd->start) * sizeof(W_);
619       }
620       if (s != 0) {
621         fprintf(stderr,"%46s","");
622       }
623       fprintf(stderr,"%6d %8d %8d %8d\n", s, step->n_blocks,
624               live, lge);
625     }
626   }
627   fprintf(stderr,"\n");
628 }