ghc/rts/Stats.c

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