ghc/rts/Stats.c

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