ghc/rts/Stats.c

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