ghc/rts/Stats.c

   1 /* -----------------------------------------------------------------------------
   2  * $Id: Stats.c,v 1.13 1999/05/20 10:23:43 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
 187 static nat
 188 pagefaults(void)
 189 {
 190   /* ToDo (on NT): better, get this via the performance data
 191      that's stored in the registry. */
 192 # if !defined(HAVE_GETRUSAGE) || irix_TARGET_OS || defined(_WIN32)
 193     return 0;
 194 # else
 195     struct rusage t;
 196
 197     getrusage(RUSAGE_SELF, &t);
 198     return(t.ru_majflt);
 199 # endif
 200 }
 201
 202 /* ToDo: use gettimeofday on systems that support it (u-sec accuracy) */
 203
 204 void
 205 start_time(void)
 206 {
 207 #ifdef HAVE_SYSCONF
 208     long ticks;
 209     /* Determine TicksPerSecond ... */
 210
 211     ticks = sysconf(_SC_CLK_TCK);
 212     if ( ticks == -1 ) {
 213         fprintf(stderr, "stat_init: bad call to 'sysconf'!\n");
 214         stg_exit(EXIT_FAILURE);
 215     }
 216     TicksPerSecond = (double) ticks;
 217
 218 /* no "sysconf"; had better guess */
 219 #elif defined(HZ)
 220     TicksPerSecond = (StgDouble) (HZ);
 221
 222 #elif defined(CLOCKS_PER_SEC)
 223     TicksPerSecond = (StgDouble) (CLOCKS_PER_SEC);
 224 #else /* had better guess wildly */
 225     /* We will #ifdef around the fprintf for machines
 226        we *know* are unsupported. (WDP 94/05)
 227     */
 228     fprintf(stderr, "NOTE: Guessing `TicksPerSecond = 60'!\n");
 229     TicksPerSecond = 60.0;
 230 #endif
 231
 232     ElapsedTimeStart = elapsedtime();
 233 }
 234
 235
 236 void
 237 initStats(void)
 238 {
 239   nat i;
 240   FILE *sf = RtsFlags.GcFlags.statsFile;
 241
 242   if (RtsFlags.GcFlags.giveStats) {
 243     fprintf(sf, "    Alloc    Collect    Live    GC    GC     TOT     TOT  Page Flts\n");
 244     fprintf(sf, "    bytes     bytes     bytes  user  elap    user    elap\n");
 245   }
 246   GC_coll_times =
 247     (double *)stgMallocBytes(sizeof(double) * RtsFlags.GcFlags.generations,
 248                            "initStats");
 249   for (i = 0; i < RtsFlags.GcFlags.generations; i++) {
 250     GC_coll_times[i] = 0.0;
 251   }
 252 }
 253
 254 #ifdef _WIN32
 255 double
 256 usertime(void)
 257 {
 258     FILETIME creationTime, exitTime, kernelTime, userTime;
 259     long long int uT;
 260
 261     /* Convert FILETIMEs into long longs */
 262
 263     if (!GetProcessTimes (GetCurrentProcess(), &creationTime,
 264                           &exitTime, &kernelTime, &userTime)) {
 265         /* Probably exec'ing this on a Win95 box..*/
 266         return 0;
 267     }
 268
 269     FT2longlong(uT,userTime);
 270     return (((StgDouble)uT)/TicksPerSecond);
 271 }
 272 #else
 273
 274 double
 275 usertime(void)
 276 {
 277 # if ! (defined(HAVE_GETRUSAGE) || defined(HAVE_TIMES))
 278     /* We will #ifdef around the fprintf for machines
 279        we *know* are unsupported. (WDP 94/05)
 280     */
 281     fprintf(stderr, "NOTE: `usertime' does nothing!\n");
 282     return 0.0;
 283
 284 # else /* not stumped */
 285
 286 #  if defined(HAVE_TIMES)
 287     struct tms t;
 288
 289     times(&t);
 290     return(((double)(t.tms_utime))/TicksPerSecond);
 291
 292 #  else /* HAVE_GETRUSAGE */
 293     struct rusage t;
 294
 295     getrusage(RUSAGE_SELF, &t);
 296     return(t.ru_utime.tv_sec + 1e-6*t.ru_utime.tv_usec);
 297
 298 #  endif /* HAVE_GETRUSAGE */
 299 # endif /* not stumped */
 300 }
 301 #endif /* ! _WIN32 */
 302
 303 void
 304 end_init(void)
 305 {
 306   InitUserTime = usertime();
 307   InitElapsedTime = elapsedtime();
 308   if (InitElapsedTime < 0.0) {
 309     InitElapsedTime = 0.0;
 310   }
 311 }
 312
 313 /* -----------------------------------------------------------------------------
 314    Called at the beginning of each GC
 315    -------------------------------------------------------------------------- */
 316
 317 static nat rub_bell = 0;
 318
 319 void
 320 stat_startGC(void)
 321 {
 322     FILE *sf = RtsFlags.GcFlags.statsFile;
 323
 324     nat bell = RtsFlags.GcFlags.ringBell;
 325
 326     if (bell) {
 327         if (bell > 1) {
 328             fprintf(stderr, " GC ");
 329             rub_bell = 1;
 330         } else {
 331             fprintf(stderr, "\007");
 332         }
 333     }
 334
 335     if (sf != NULL) {
 336         GC_start_time = usertime();
 337         GCe_start_time = elapsedtime();
 338         if (RtsFlags.GcFlags.giveStats) {
 339           GC_start_faults = pagefaults();
 340         }
 341     }
 342 }
 343
 344 /* -----------------------------------------------------------------------------
 345    Called at the end of each GC
 346    -------------------------------------------------------------------------- */
 347
 348 void
 349 stat_endGC(lnat alloc, lnat collect, lnat live, lnat copied, lnat gen)
 350 {
 351     FILE *sf = RtsFlags.GcFlags.statsFile;
 352
 353     if (sf != NULL) {
 354         double time = usertime();
 355         double etime = elapsedtime();
 356
 357         if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) {
 358             nat faults = pagefaults();
 359
 360             fprintf(sf, "%9ld %9ld %9ld",
 361                     alloc*sizeof(W_), collect*sizeof(W_), live*sizeof(W_));
 362             fprintf(sf, " %5.2f %5.2f %7.2f %7.2f %4ld %4ld  (Gen: %2ld)\n",
 363                     (time-GC_start_time),
 364                     (etime-GCe_start_time),
 365                     time,
 366                     etime,
 367                     faults - GC_start_faults,
 368                     GC_start_faults - GC_end_faults,
 369                     gen);
 370
 371             GC_end_faults = faults;
 372             fflush(sf);
 373         }
 374
 375         GC_coll_times[gen] += time-GC_start_time;
 376
 377         GC_tot_copied += (ullong) copied;
 378         GC_tot_alloc  += (ullong) alloc;
 379         GC_tot_time   += time-GC_start_time;
 380         GCe_tot_time  += etime-GCe_start_time;
 381
 382         if (gen == RtsFlags.GcFlags.generations-1) { /* major GC? */
 383           if (live > MaxResidency) {
 384             MaxResidency = live;
 385           }
 386           ResidencySamples++;
 387         }
 388     }
 389
 390     if (rub_bell) {
 391         fprintf(stderr, "\b\b\b  \b\b\b");
 392         rub_bell = 0;
 393     }
 394 }
 395
 396 /* -----------------------------------------------------------------------------
 397    Called at the end of execution
 398
 399    NOTE: number of allocations is not entirely accurate: it doesn't
 400    take into account the few bytes at the end of the heap that
 401    were left unused when the heap-check failed.
 402    -------------------------------------------------------------------------- */
 403
 404 void
 405 stat_exit(int alloc)
 406 {
 407     FILE *sf = RtsFlags.GcFlags.statsFile;
 408
 409     if (sf != NULL){
 410         char temp[BIG_STRING_LEN];
 411         double time = usertime();
 412         double etime = elapsedtime();
 413         double MutTime, MutElapsedTime;
 414
 415         /* avoid divide by zero if time is measured as 0.00 seconds -- SDM */
 416         if (time  == 0.0)  time = 0.0001;
 417         if (etime == 0.0) etime = 0.0001;
 418
 419
 420         fprintf(sf, "%9ld %9.9s %9.9s",
 421                 (lnat)alloc*sizeof(W_), "", "");
 422         fprintf(sf, " %5.2f %5.2f\n\n", 0.0, 0.0);
 423
 424         GC_tot_alloc += alloc;
 425
 426         ullong_format_string(GC_tot_alloc*sizeof(W_), temp, rtsTrue/*commas*/);
 427         fprintf(sf, "%11s bytes allocated in the heap\n", temp);
 428
 429         ullong_format_string(GC_tot_copied*sizeof(W_), temp, rtsTrue/*commas*/);
 430         fprintf(sf, "%11s bytes copied during GC\n", temp);
 431
 432         if ( ResidencySamples > 0 ) {
 433             ullong_format_string(MaxResidency*sizeof(W_), temp, rtsTrue/*commas*/);
 434             fprintf(sf, "%11s bytes maximum residency (%ld sample(s))\n",
 435                               temp,
 436                               ResidencySamples);
 437         }
 438         fprintf(sf,"\n");
 439
 440         { /* Count garbage collections */
 441           nat g;
 442           for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
 443             fprintf(sf, "%11d collections in generation %d (%6.2fs)\n",
 444                     generations[g].collections, g, GC_coll_times[g]);
 445           }
 446         }
 447         fprintf(sf,"\n%11ld Mb total memory in use\n\n",
 448                 mblocks_allocated * MBLOCK_SIZE / (1024 * 1024));
 449
 450         MutTime = time - GC_tot_time - InitUserTime;
 451         if (MutTime < 0) { MutTime = 0; }
 452         MutElapsedTime = etime - GCe_tot_time - InitElapsedTime;
 453         if (MutElapsedTime < 0) { MutElapsedTime = 0; } /* sometimes -0.00 */
 454
 455         fprintf(sf, "  INIT  time  %6.2fs  (%6.2fs elapsed)\n",
 456                 InitUserTime, InitElapsedTime);
 457         fprintf(sf, "  MUT   time  %6.2fs  (%6.2fs elapsed)\n",
 458                 MutTime, MutElapsedTime);
 459         fprintf(sf, "  GC    time  %6.2fs  (%6.2fs elapsed)\n",
 460                 GC_tot_time, GCe_tot_time);
 461         fprintf(sf, "  Total time  %6.2fs  (%6.2fs elapsed)\n\n",
 462                 time, etime);
 463
 464         fprintf(sf, "  %%GC time     %5.1f%%  (%.1f%% elapsed)\n\n",
 465                 GC_tot_time*100./time, GCe_tot_time*100./etime);
 466
 467         if (time - GC_tot_time == 0.0)
 468                 ullong_format_string(0, temp, rtsTrue/*commas*/);
 469         else
 470                 ullong_format_string((ullong)(GC_tot_alloc*sizeof(W_)/
 471                                               (time - GC_tot_time)),
 472                                      temp, rtsTrue/*commas*/);
 473
 474         fprintf(sf, "  Alloc rate    %s bytes per MUT second\n\n", temp);
 475
 476         fprintf(sf, "  Productivity %5.1f%% of total user, %.1f%% of total elapsed\n\n",
 477                 (time - GC_tot_time - InitUserTime) * 100. / time,
 478                 (time - GC_tot_time - InitUserTime) * 100. / etime);
 479         fflush(sf);
 480         fclose(sf);
 481     }
 482 }
 483
 484 /* -----------------------------------------------------------------------------
 485    stat_describe_gens
 486
 487    Produce some detailed info on the state of the generational GC.
 488    -------------------------------------------------------------------------- */
 489 void
 490 stat_describe_gens(void)
 491 {
 492   nat g, s, mut, mut_once, lge, live;
 493   StgMutClosure *m;
 494   bdescr *bd;
 495   step *step;
 496
 497   fprintf(stderr, "     Gen    Steps      Max   Mutable  Mut-Once  Step   Blocks     Live    Large\n                    Blocks  Closures  Closures                         Objects\n");
 498
 499   for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
 500     for (m = generations[g].mut_list, mut = 0; m != END_MUT_LIST;
 501          m = m->mut_link)
 502       mut++;
 503     for (m = generations[g].mut_once_list, mut_once = 0; m != END_MUT_LIST;
 504          m = m->mut_link)
 505       mut_once++;
 506     fprintf(stderr, "%8d %8d %8d %9d %9d", g, generations[g].n_steps,
 507             generations[g].max_blocks, mut, mut_once);
 508
 509     for (s = 0; s < generations[g].n_steps; s++) {
 510       step = &generations[g].steps[s];
 511       for (bd = step->large_objects, lge = 0; bd; bd = bd->link)
 512         lge++;
 513       live = 0;
 514       if (RtsFlags.GcFlags.generations == 1) {
 515         bd = step->to_space;
 516       } else {
 517         bd = step->blocks;
 518       }
 519       for (; bd; bd = bd->link) {
 520         live += (bd->free - bd->start) * sizeof(W_);
 521       }
 522       if (s != 0) {
 523         fprintf(stderr,"%46s","");
 524       }
 525       fprintf(stderr,"%6d %8d %8d %8d\n", s, step->n_blocks,
 526               live, lge);
 527     }
 528   }
 529   fprintf(stderr,"\n");
 530 }