ghc/rts/Stats.c

   1 /* -----------------------------------------------------------------------------
   2  * $Id: Stats.c,v 1.5 1999/02/03 16:42:18 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 #include "StoragePriv.h"
  14 #include "MBlock.h"
  15
  16 /**
  17  *  Ian: For the moment we just want to ignore
  18  * these on Nemesis
  19  **/
  20 #ifdef _NEMESIS_OS_
  21 #ifdef HAVE_SYS_TIMES_H
  22 #undef HAVE_SYS_TIMES_H /* <sys/times.h> */
  23 #endif
  24 #ifdef HAVE_SYS_RESOURCE_H /* <sys/resource.h> */
  25 #undef HAVE_SYS_RESOURCE_H
  26 #endif
  27 #ifdef HAVE_SYS_TIME_H  /* <sys/time.h> */
  28 #undef HAVE_SYS_TIME_H
  29 #endif
  30 #ifdef HAVE_SYS_TIMEB_H
  31 #undef HAVE_SYS_TIMEB_H /* <sys/timeb.h> */
  32 #endif
  33 #ifdef HAVE_UNISTD_H
  34 #undef HAVE_UNISTD_H    /* <unistd.h> */
  35 #endif
  36 #ifdef HAVE_TIMES
  37 #undef HAVE_TIMES
  38 #endif
  39 #ifdef HAVE_FTIME
  40 #undef HAVE_FTIME
  41 #endif
  42 #ifdef HAVE_GETRUSAGE
  43 #undef HAVE_GETRUSAGE
  44 #endif
  45 #ifdef HAVE_SYSCONF
  46 #undef HAVE_SYSCONF
  47 #endif
  48 #endif /* _NEMESIS_OS_ */
  49
  50 #include "Stats.h"
  51
  52 #ifdef HAVE_UNISTD_H
  53 #include <unistd.h>
  54 #endif
  55
  56 #ifdef HAVE_SYS_TIMES_H
  57 #include <sys/times.h>
  58 #endif
  59
  60 #ifdef HAVE_SYS_TIME_H
  61 #include <sys/time.h>
  62 #endif
  63
  64 #if defined(HAVE_SYS_RESOURCE_H) && ! irix_TARGET_OS
  65 #include <sys/resource.h>
  66 #endif
  67
  68 #ifdef HAVE_SYS_TIMEB_H
  69 #include <sys/timeb.h>
  70 #endif
  71
  72 #if HAVE_STDLIB_H
  73 #include <stdlib.h>
  74 #endif
  75
  76 /* huh? */
  77 #define BIG_STRING_LEN              512
  78
  79 static StgDouble ElapsedTimeStart = 0.0;
  80 static StgDouble TicksPerSecond   = 0.0;
  81
  82 static StgDouble InitUserTime = 0.0;
  83 static StgDouble InitElapsedTime = 0.0;
  84
  85 static ullong GC_tot_alloc = 0;
  86
  87 static StgDouble GC_start_time,  GC_tot_time = 0;  /* User GC Time */
  88 static StgDouble GCe_start_time, GCe_tot_time = 0; /* Elapsed GC time */
  89
  90 lnat MaxResidency = 0;     /* in words; for stats only */
  91 lnat ResidencySamples = 0; /* for stats only */
  92
  93 static lnat GC_start_faults = 0, GC_end_faults = 0;
  94
  95 /* ToDo: convert this to use integers? --SDM */
  96
  97 /* elapsedtime() -- The current elapsed time in seconds */
  98
  99 StgDouble
 100 elapsedtime(void)
 101 {
 102 #if ! (defined(HAVE_TIMES) || defined(HAVE_FTIME))
 103     /* We will #ifdef around the fprintf for machines
 104        we *know* are unsupported. (WDP 94/05)
 105     */
 106     fprintf(stderr, "NOTE: `elapsedtime' does nothing!\n");
 107     return 0.0;
 108
 109 #else /* not stumped */
 110
 111 /* "ftime" may be nicer, but "times" is more standard;
 112    but, on a Sun, if you do not get the SysV one, you are *hosed*...
 113  */
 114
 115 # if defined(HAVE_TIMES) && ! sunos4_TARGET_OS
 116     struct tms t;
 117     clock_t r = times(&t);
 118
 119     return (((StgDouble)r)/TicksPerSecond - ElapsedTimeStart);
 120
 121 # else /* HAVE_FTIME */
 122     struct timeb t;
 123
 124     ftime(&t);
 125     return (fabs(t.time + 1e-3*t.millitm - ElapsedTimeStart));
 126
 127 # endif /* HAVE_FTIME */
 128 #endif /* not stumped */
 129 }
 130
 131 static nat
 132 pagefaults(void)
 133 {
 134 # if !defined(HAVE_GETRUSAGE) || irix_TARGET_OS
 135     return 0;
 136 # else
 137     struct rusage t;
 138
 139     getrusage(RUSAGE_SELF, &t);
 140     return(t.ru_majflt);
 141 # endif
 142 }
 143
 144 /* ToDo: use gettimeofday on systems that support it (u-sec accuracy) */
 145
 146 void
 147 start_time(void)
 148 {
 149     long ticks;
 150     /* Determine TicksPerSecond ... */
 151 #ifdef HAVE_SYSCONF
 152     ticks = sysconf(_SC_CLK_TCK);
 153     if ( ticks == -1 ) {
 154         fprintf(stderr, "stat_init: bad call to 'sysconf'!\n");
 155         stg_exit(EXIT_FAILURE);
 156     }
 157     TicksPerSecond = (StgDouble) ticks;
 158
 159 #else /* no "sysconf"; had better guess */
 160 # ifdef HZ
 161     TicksPerSecond = (StgDouble) (HZ);
 162
 163 # else /* had better guess wildly */
 164     /* We will #ifdef around the fprintf for machines
 165        we *know* are unsupported. (WDP 94/05)
 166     */
 167     fprintf(stderr, "NOTE: Guessing `TicksPerSecond = 60'!\n");
 168     TicksPerSecond = 60.0;
 169 # endif
 170 #endif
 171
 172     ElapsedTimeStart = elapsedtime();
 173 }
 174
 175
 176 void
 177 initStats(void)
 178 {
 179   FILE *sf = RtsFlags.GcFlags.statsFile;
 180
 181   if (RtsFlags.GcFlags.giveStats) {
 182     fprintf(sf, "    Alloc    Collect    Live    GC    GC     TOT     TOT  Page Flts\n");
 183     fprintf(sf, "    bytes     bytes     bytes  user  elap    user    elap\n");
 184   }
 185 }
 186
 187
 188 StgDouble
 189 usertime(void)
 190 {
 191 #if ! (defined(HAVE_GETRUSAGE) || defined(HAVE_TIMES))
 192     /* We will #ifdef around the fprintf for machines
 193        we *know* are unsupported. (WDP 94/05)
 194     */
 195     fprintf(stderr, "NOTE: `usertime' does nothing!\n");
 196     return 0.0;
 197
 198 #else /* not stumped */
 199
 200 # if defined(HAVE_TIMES)
 201     struct tms t;
 202
 203     times(&t);
 204     return(((StgDouble)(t.tms_utime))/TicksPerSecond);
 205
 206 #else /* HAVE_GETRUSAGE */
 207     struct rusage t;
 208
 209     getrusage(RUSAGE_SELF, &t);
 210     return(t.ru_utime.tv_sec + 1e-6*t.ru_utime.tv_usec);
 211
 212 # endif /* HAVE_GETRUSAGE */
 213 #endif /* not stumped */
 214 }
 215
 216 void
 217 end_init(void)
 218 {
 219   InitUserTime = usertime();
 220   InitElapsedTime = elapsedtime();
 221   if (InitElapsedTime < 0.0) {
 222     InitElapsedTime = 0.0;
 223   }
 224 }
 225
 226 /* -----------------------------------------------------------------------------
 227    Called at the beginning of each GC
 228    -------------------------------------------------------------------------- */
 229
 230 static nat rub_bell = 0;
 231
 232 void
 233 stat_startGC(void)
 234 {
 235     FILE *sf = RtsFlags.GcFlags.statsFile;
 236
 237     nat bell = RtsFlags.GcFlags.ringBell;
 238
 239     if (bell) {
 240         if (bell > 1) {
 241             fprintf(stderr, " GC ");
 242             rub_bell = 1;
 243         } else {
 244             fprintf(stderr, "\007");
 245         }
 246     }
 247
 248     if (sf != NULL) {
 249         GC_start_time = usertime();
 250         GCe_start_time = elapsedtime();
 251         if (RtsFlags.GcFlags.giveStats) {
 252           GC_start_faults = pagefaults();
 253         }
 254     }
 255 }
 256
 257 /* -----------------------------------------------------------------------------
 258    Called at the end of each GC
 259    -------------------------------------------------------------------------- */
 260
 261 void
 262 stat_endGC(lnat alloc, lnat collect, lnat live, lnat gen)
 263 {
 264     FILE *sf = RtsFlags.GcFlags.statsFile;
 265
 266     if (sf != NULL) {
 267         StgDouble time = usertime();
 268         StgDouble etime = elapsedtime();
 269
 270         if (RtsFlags.GcFlags.giveStats) {
 271             nat faults = pagefaults();
 272
 273             fprintf(sf, "%9ld %9ld %9ld",
 274                     alloc*sizeof(W_), collect*sizeof(W_), live*sizeof(W_));
 275             fprintf(sf, " %5.2f %5.2f %7.2f %7.2f %4ld %4ld  (Gen: %2ld)\n",
 276                     (time-GC_start_time),
 277                     (etime-GCe_start_time),
 278                     time,
 279                     etime,
 280                     faults - GC_start_faults,
 281                     GC_start_faults - GC_end_faults,
 282                     gen);
 283
 284             GC_end_faults = faults;
 285             fflush(sf);
 286         }
 287
 288         GC_tot_alloc += (ullong) alloc;
 289         GC_tot_time  += time-GC_start_time;
 290         GCe_tot_time += etime-GCe_start_time;
 291
 292         if (gen == RtsFlags.GcFlags.generations-1) { /* major GC? */
 293           if (live > MaxResidency) {
 294             MaxResidency = live;
 295           }
 296           ResidencySamples++;
 297         }
 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         fprintf(sf, "%9ld %9.9s %9.9s",
 331                 (lnat)alloc*sizeof(W_), "", "");
 332         fprintf(sf, " %5.2f %5.2f\n\n", 0.0, 0.0);
 333
 334         GC_tot_alloc += alloc;
 335
 336         ullong_format_string(GC_tot_alloc*sizeof(W_), temp, rtsTrue/*commas*/);
 337         fprintf(sf, "%11s bytes allocated in the heap\n", temp);
 338
 339         if ( ResidencySamples > 0 ) {
 340             ullong_format_string(MaxResidency*sizeof(W_), temp, rtsTrue/*commas*/);
 341             fprintf(sf, "%11s bytes maximum residency (%ld sample(s))\n",
 342                               temp,
 343                               ResidencySamples);
 344         }
 345         fprintf(sf,"\n");
 346
 347         { /* Count garbage collections */
 348           nat g;
 349           for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
 350             fprintf(sf, "%11d collections in generation %d\n",
 351                     generations[g].collections, g);
 352           }
 353         }
 354         fprintf(sf,"\n%11ld Mb total memory in use\n\n",
 355                 mblocks_allocated * MBLOCK_SIZE / (1024 * 1024));
 356
 357         MutTime = time - GC_tot_time - InitUserTime;
 358         if (MutTime < 0) { MutTime = 0; }
 359         MutElapsedTime = etime - GCe_tot_time - InitElapsedTime;
 360         if (MutElapsedTime < 0) { MutElapsedTime = 0; } /* sometimes -0.00 */
 361
 362         fprintf(sf, "  INIT  time  %6.2fs  (%6.2fs elapsed)\n",
 363                 InitUserTime, InitElapsedTime);
 364         fprintf(sf, "  MUT   time  %6.2fs  (%6.2fs elapsed)\n",
 365                 MutTime, MutElapsedTime);
 366         fprintf(sf, "  GC    time  %6.2fs  (%6.2fs elapsed)\n",
 367                 GC_tot_time, GCe_tot_time);
 368         fprintf(sf, "  Total time  %6.2fs  (%6.2fs elapsed)\n\n",
 369                 time, etime);
 370
 371         fprintf(sf, "  %%GC time     %5.1f%%  (%.1f%% elapsed)\n\n",
 372                 GC_tot_time*100./time, GCe_tot_time*100./etime);
 373
 374         if (time - GC_tot_time == 0.0)
 375                 ullong_format_string(0, temp, rtsTrue/*commas*/);
 376         else
 377                 ullong_format_string((ullong)(GC_tot_alloc*sizeof(W_)/
 378                                               (time - GC_tot_time)),
 379                                      temp, rtsTrue/*commas*/);
 380
 381         fprintf(sf, "  Alloc rate    %s bytes per MUT second\n\n", temp);
 382
 383         fprintf(sf, "  Productivity %5.1f%% of total user, %.1f%% of total elapsed\n\n",
 384                 (time - GC_tot_time - InitUserTime) * 100. / time,
 385                 (time - GC_tot_time - InitUserTime) * 100. / etime);
 386         fflush(sf);
 387         fclose(sf);
 388     }
 389 }
 390
 391 /* -----------------------------------------------------------------------------
 392    stat_describe_gens
 393
 394    Produce some detailed info on the state of the generational GC.
 395    -------------------------------------------------------------------------- */
 396 void
 397 stat_describe_gens(void)
 398 {
 399   nat g, s, mut, mut_once, lge, live;
 400   StgMutClosure *m;
 401   bdescr *bd;
 402   step *step;
 403
 404   fprintf(stderr, "     Gen    Steps      Max   Mutable  Mut-Once  Step  Blocks     Live    Large\n                    Blocks  Closures  Closures                         Objects\n");
 405
 406   for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
 407     for (m = generations[g].mut_list, mut = 0; m != END_MUT_LIST;
 408          m = m->mut_link)
 409       mut++;
 410     for (m = generations[g].mut_once_list, mut_once = 0; m != END_MUT_LIST;
 411          m = m->mut_link)
 412       mut_once++;
 413     fprintf(stderr, "%8d %8d %8d %9d %9d", g, generations[g].n_steps,
 414             generations[g].max_blocks, mut, mut_once);
 415
 416     for (s = 0; s < generations[g].n_steps; s++) {
 417       step = &generations[g].steps[s];
 418       for (bd = step->large_objects, lge = 0; bd; bd = bd->link)
 419         lge++;
 420       live = 0;
 421       for (bd = step->blocks; bd; bd = bd->link) {
 422         live += (bd->free - bd->start) * sizeof(W_);
 423       }
 424       if (s != 0) {
 425         fprintf(stderr,"%46s","");
 426       }
 427       fprintf(stderr,"%6d %8d %8d %8d\n", s, step->n_blocks,
 428               live, lge);
 429     }
 430   }
 431   fprintf(stderr,"\n");
 432 }