ghc/rts/Stats.c

   1 /* -----------------------------------------------------------------------------
   2  * $Id: Stats.c,v 1.2 1998/12/02 13:28:49 simonm Exp $
   3  *
   4  * Statistics and timing-related functions.
   5  *
   6  * ---------------------------------------------------------------------------*/
   7
   8 #define NON_POSIX_SOURCE
   9
  10 #include "Rts.h"
  11 #include "RtsFlags.h"
  12 #include "RtsUtils.h"
  13
  14 /**
  15  *  Ian: For the moment we just want to ignore
  16  * these on Nemesis
  17  **/
  18 #ifdef _NEMESIS_OS_
  19 #ifdef HAVE_SYS_TIMES_H
  20 #undef HAVE_SYS_TIMES_H /* <sys/times.h> */
  21 #endif
  22 #ifdef HAVE_SYS_RESOURCE_H /* <sys/resource.h> */
  23 #undef HAVE_SYS_RESOURCE_H
  24 #endif
  25 #ifdef HAVE_SYS_TIME_H  /* <sys/time.h> */
  26 #undef HAVE_SYS_TIME_H
  27 #endif
  28 #ifdef HAVE_SYS_TIMEB_H
  29 #undef HAVE_SYS_TIMEB_H /* <sys/timeb.h> */
  30 #endif
  31 #ifdef HAVE_UNISTD_H
  32 #undef HAVE_UNISTD_H    /* <unistd.h> */
  33 #endif
  34 #ifdef HAVE_TIMES
  35 #undef HAVE_TIMES
  36 #endif
  37 #ifdef HAVE_FTIME
  38 #undef HAVE_FTIME
  39 #endif
  40 #ifdef HAVE_GETRUSAGE
  41 #undef HAVE_GETRUSAGE
  42 #endif
  43 #ifdef HAVE_SYSCONF
  44 #undef HAVE_SYSCONF
  45 #endif
  46 #endif /* _NEMESIS_OS_ */
  47
  48 #include "Stats.h"
  49
  50 #ifdef HAVE_UNISTD_H
  51 #include <unistd.h>
  52 #endif
  53
  54 #ifdef HAVE_SYS_TIMES_H
  55 #include <sys/times.h>
  56 #endif
  57
  58 #ifdef HAVE_SYS_TIME_H
  59 #include <sys/time.h>
  60 #endif
  61
  62 #if defined(HAVE_SYS_RESOURCE_H) && ! irix_TARGET_OS
  63 #include <sys/resource.h>
  64 #endif
  65
  66 #ifdef HAVE_SYS_TIMEB_H
  67 #include <sys/timeb.h>
  68 #endif
  69
  70 #if HAVE_STDLIB_H
  71 #include <stdlib.h>
  72 #endif
  73
  74 /* huh? */
  75 #define BIG_STRING_LEN              512
  76
  77 static StgDouble ElapsedTimeStart = 0.0;
  78 static StgDouble TicksPerSecond   = 0.0;
  79
  80 static StgDouble InitUserTime = 0.0;
  81 static StgDouble InitElapsedTime = 0.0;
  82
  83 static ullong GC_tot_alloc = 0;
  84
  85 static StgDouble GC_start_time,  GC_tot_time = 0;  /* User GC Time */
  86 static StgDouble GCe_start_time, GCe_tot_time = 0; /* Elapsed GC time */
  87
  88 static StgDouble GC_min_time = 0;
  89 static StgDouble GCe_min_time = 0;
  90 static lnat GC_maj_no = 0;
  91 static lnat GC_min_no = 0;
  92 static lnat GC_min_since_maj = 0;
  93 static lnat GC_live_maj = 0;         /* Heap live at last major collection */
  94 static lnat GC_alloc_since_maj = 0;  /* Heap alloc since collection major */
  95
  96 lnat MaxResidency = 0;     /* in words; for stats only */
  97 lnat ResidencySamples = 0; /* for stats only */
  98
  99 static lnat GC_start_faults = 0, GC_end_faults = 0;
 100
 101 /* ToDo: convert this to use integers? --SDM */
 102
 103 /* elapsedtime() -- The current elapsed time in seconds */
 104
 105 StgDouble
 106 elapsedtime(void)
 107 {
 108 #if ! (defined(HAVE_TIMES) || defined(HAVE_FTIME))
 109     /* We will #ifdef around the fprintf for machines
 110        we *know* are unsupported. (WDP 94/05)
 111     */
 112     fprintf(stderr, "NOTE: `elapsedtime' does nothing!\n");
 113     return 0.0;
 114
 115 #else /* not stumped */
 116
 117 /* "ftime" may be nicer, but "times" is more standard;
 118    but, on a Sun, if you do not get the SysV one, you are *hosed*...
 119  */
 120
 121 # if defined(HAVE_TIMES) && ! sunos4_TARGET_OS
 122     struct tms t;
 123     clock_t r = times(&t);
 124
 125     return (((StgDouble)r)/TicksPerSecond - ElapsedTimeStart);
 126
 127 # else /* HAVE_FTIME */
 128     struct timeb t;
 129
 130     ftime(&t);
 131     return (fabs(t.time + 1e-3*t.millitm - ElapsedTimeStart));
 132
 133 # endif /* HAVE_FTIME */
 134 #endif /* not stumped */
 135 }
 136
 137 static nat
 138 pagefaults(void)
 139 {
 140 # if !defined(HAVE_GETRUSAGE) || irix_TARGET_OS
 141     return 0;
 142 # else
 143     struct rusage t;
 144
 145     getrusage(RUSAGE_SELF, &t);
 146     return(t.ru_majflt);
 147 # endif
 148 }
 149
 150 /* ToDo: use gettimeofday on systems that support it (u-sec accuracy) */
 151
 152 void
 153 start_time(void)
 154 {
 155     long ticks;
 156     /* Determine TicksPerSecond ... */
 157 #ifdef HAVE_SYSCONF
 158     ticks = sysconf(_SC_CLK_TCK);
 159     if ( ticks == -1 ) {
 160         fprintf(stderr, "stat_init: bad call to 'sysconf'!\n");
 161         stg_exit(EXIT_FAILURE);
 162     }
 163     TicksPerSecond = (StgDouble) ticks;
 164
 165 #else /* no "sysconf"; had better guess */
 166 # ifdef HZ
 167     TicksPerSecond = (StgDouble) (HZ);
 168
 169 # else /* had better guess wildly */
 170     /* We will #ifdef around the fprintf for machines
 171        we *know* are unsupported. (WDP 94/05)
 172     */
 173     fprintf(stderr, "NOTE: Guessing `TicksPerSecond = 60'!\n");
 174     TicksPerSecond = 60.0;
 175 # endif
 176 #endif
 177
 178     ElapsedTimeStart = elapsedtime();
 179 }
 180
 181
 182 void
 183 initStats(void)
 184 {
 185   FILE *sf = RtsFlags.GcFlags.statsFile;
 186
 187   if (RtsFlags.GcFlags.giveStats) {
 188     fprintf(sf, "  Alloc  Collect   Live   Resid   GC    GC     TOT     TOT  Page Flts\n");
 189     fprintf(sf, "  bytes   bytes    bytes   ency  user  elap    user    elap\n");
 190   }
 191 }
 192
 193
 194 StgDouble
 195 usertime(void)
 196 {
 197 #if ! (defined(HAVE_GETRUSAGE) || defined(HAVE_TIMES))
 198     /* We will #ifdef around the fprintf for machines
 199        we *know* are unsupported. (WDP 94/05)
 200     */
 201     fprintf(stderr, "NOTE: `usertime' does nothing!\n");
 202     return 0.0;
 203
 204 #else /* not stumped */
 205
 206 # if defined(HAVE_TIMES)
 207     struct tms t;
 208
 209     times(&t);
 210     return(((StgDouble)(t.tms_utime))/TicksPerSecond);
 211
 212 #else /* HAVE_GETRUSAGE */
 213     struct rusage t;
 214
 215     getrusage(RUSAGE_SELF, &t);
 216     return(t.ru_utime.tv_sec + 1e-6*t.ru_utime.tv_usec);
 217
 218 # endif /* HAVE_GETRUSAGE */
 219 #endif /* not stumped */
 220 }
 221
 222 void
 223 end_init(void)
 224 {
 225   InitUserTime = usertime();
 226   InitElapsedTime = elapsedtime();
 227   if (InitElapsedTime < 0.0) {
 228     InitElapsedTime = 0.0;
 229   }
 230 }
 231
 232 /* -----------------------------------------------------------------------------
 233    Called at the beginning of each GC
 234    -------------------------------------------------------------------------- */
 235
 236 static nat rub_bell = 0;
 237
 238 void
 239 stat_startGC(void)
 240 {
 241     FILE *sf = RtsFlags.GcFlags.statsFile;
 242
 243     nat bell = RtsFlags.GcFlags.ringBell;
 244
 245     if (bell) {
 246         if (bell > 1) {
 247             fprintf(stderr, " GC ");
 248             rub_bell = 1;
 249         } else {
 250             fprintf(stderr, "\007");
 251         }
 252     }
 253
 254     if (sf != NULL) {
 255         GC_start_time = usertime();
 256         GCe_start_time = elapsedtime();
 257         if (RtsFlags.GcFlags.giveStats) {
 258           GC_start_faults = pagefaults();
 259         }
 260     }
 261 }
 262
 263 /* -----------------------------------------------------------------------------
 264    Called at the end of each GC
 265    -------------------------------------------------------------------------- */
 266
 267 void
 268 stat_endGC(lnat alloc, lnat collect, lnat live, char *comment)
 269 {
 270     FILE *sf = RtsFlags.GcFlags.statsFile;
 271
 272     if (sf != NULL) {
 273         StgDouble time = usertime();
 274         StgDouble etime = elapsedtime();
 275
 276         if (RtsFlags.GcFlags.giveStats) {
 277             nat faults = pagefaults();
 278
 279             fprintf(sf, "%8ld %7ld %7ld %5.1f%%",
 280                     alloc*sizeof(W_), collect*sizeof(W_), live*sizeof(W_), collect == 0 ? 0.0 : (live / (StgDouble) collect * 100));
 281             fprintf(sf, " %5.2f %5.2f %7.2f %7.2f %4ld %4ld  %s\n",
 282                     (time-GC_start_time),
 283                     (etime-GCe_start_time),
 284                     time,
 285                     etime,
 286                     faults - GC_start_faults,
 287                     GC_start_faults - GC_end_faults,
 288                     comment);
 289
 290             GC_end_faults = faults;
 291             fflush(sf);
 292         }
 293
 294         GC_maj_no++;
 295         GC_tot_alloc += (ullong) alloc;
 296         GC_tot_time  += time-GC_start_time;
 297         GCe_tot_time += etime-GCe_start_time;
 298     }
 299
 300     if (rub_bell) {
 301         fprintf(stderr, "\b\b\b  \b\b\b");
 302         rub_bell = 0;
 303     }
 304 }
 305
 306 /* -----------------------------------------------------------------------------
 307    Called at the end of execution
 308
 309    NOTE: number of allocations is not entirely accurate: it doesn't
 310    take into account the few bytes at the end of the heap that
 311    were left unused when the heap-check failed.
 312    -------------------------------------------------------------------------- */
 313
 314 void
 315 stat_exit(int alloc)
 316 {
 317     FILE *sf = RtsFlags.GcFlags.statsFile;
 318
 319     if (sf != NULL){
 320         char temp[BIG_STRING_LEN];
 321         StgDouble time = usertime();
 322         StgDouble etime = elapsedtime();
 323         StgDouble MutTime, MutElapsedTime;
 324
 325         /* avoid divide by zero if time is measured as 0.00 seconds -- SDM */
 326         if (time  == 0.0)  time = 0.0001;
 327         if (etime == 0.0) etime = 0.0001;
 328
 329
 330         if (RtsFlags.GcFlags.giveStats) {
 331             fprintf(sf, "%8d\n\n", alloc*sizeof(W_));
 332         }
 333
 334         else {
 335             fprintf(sf, "%8ld %7.7s %6.6s %7.7s %6.6s",
 336                     (GC_alloc_since_maj + alloc)*sizeof(W_), "", "", "", "");
 337             fprintf(sf, "  %3ld  %5.2f %5.2f\n\n",
 338                     GC_min_since_maj, GC_min_time, GCe_min_time);
 339         }
 340         GC_min_no    += GC_min_since_maj;
 341         GC_tot_time  += GC_min_time;
 342         GCe_tot_time += GCe_min_time;
 343         GC_tot_alloc += GC_alloc_since_maj + alloc;
 344         ullong_format_string(GC_tot_alloc*sizeof(W_), temp, rtsTrue/*commas*/);
 345         fprintf(sf, "%11s bytes allocated in the heap\n", temp);
 346         if ( ResidencySamples > 0 ) {
 347             ullong_format_string(MaxResidency*sizeof(W_), temp, rtsTrue/*commas*/);
 348             fprintf(sf, "%11s bytes maximum residency (%.1f%%, %ld sample(s))\n",
 349                               temp,
 350                               MaxResidency / (StgDouble) RtsFlags.GcFlags.maxHeapSize * 100,
 351                               ResidencySamples);
 352         }
 353         fprintf(sf, "%11ld garbage collections performed (%ld major, %ld minor)\n\n",
 354                 GC_maj_no + GC_min_no, GC_maj_no, GC_min_no);
 355
 356         MutTime = time - GC_tot_time - InitUserTime;
 357         if (MutTime < 0) { MutTime = 0; }
 358         MutElapsedTime = etime - GCe_tot_time - InitElapsedTime;
 359         if (MutElapsedTime < 0) { MutElapsedTime = 0; } /* sometimes -0.00 */
 360
 361         fprintf(sf, "  INIT  time  %6.2fs  (%6.2fs elapsed)\n",
 362                 InitUserTime, InitElapsedTime);
 363         fprintf(sf, "  MUT   time  %6.2fs  (%6.2fs elapsed)\n",
 364                 MutTime, MutElapsedTime);
 365         fprintf(sf, "  GC    time  %6.2fs  (%6.2fs elapsed)\n",
 366                 GC_tot_time, GCe_tot_time);
 367         fprintf(sf, "  Total time  %6.2fs  (%6.2fs elapsed)\n\n",
 368                 time, etime);
 369
 370         fprintf(sf, "  %%GC time     %5.1f%%  (%.1f%% elapsed)\n\n",
 371                 GC_tot_time*100./time, GCe_tot_time*100./etime);
 372
 373         if (time - GC_tot_time == 0.0)
 374                 ullong_format_string(0, temp, rtsTrue/*commas*/);
 375         else
 376                 ullong_format_string((ullong)(GC_tot_alloc*sizeof(W_)/
 377                                               (time - GC_tot_time)),
 378                                      temp, rtsTrue/*commas*/);
 379
 380         fprintf(sf, "  Alloc rate    %s bytes per MUT second\n\n", temp);
 381
 382         fprintf(sf, "  Productivity %5.1f%% of total user, %.1f%% of total elapsed\n\n",
 383                 (time - GC_tot_time - InitUserTime) * 100. / time,
 384                 (time - GC_tot_time - InitUserTime) * 100. / etime);
 385         fflush(sf);
 386         fclose(sf);
 387     }
 388 }