ghc/rts/Stats.c

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