ghc/rts/Stats.c

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