ghc/rts/Stats.c

   1 /* -----------------------------------------------------------------------------
   2  * $Id: Stats.c,v 1.19 1999/12/03 15:55:29 chak 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 #include "Schedule.h"
  18 #include "Stats.h"
  19
  20 #ifdef HAVE_UNISTD_H
  21 #include <unistd.h>
  22 #endif
  23
  24 #ifndef __MINGW32__
  25 # ifdef HAVE_SYS_TIMES_H
  26 #  include <sys/times.h>
  27 # endif
  28 #endif
  29
  30 #ifdef HAVE_SYS_TIME_H
  31 #include <sys/time.h>
  32 #endif
  33
  34 #ifdef __CYGWIN32__
  35 # ifdef HAVE_TIME_H
  36 #  include <time.h>
  37 # endif
  38 #endif
  39
  40 #if ! irix_TARGET_OS && ! defined(__MINGW32__)
  41 # if defined(HAVE_SYS_RESOURCE_H)
  42 #  include <sys/resource.h>
  43 # endif
  44 #endif
  45
  46 #ifdef HAVE_SYS_TIMEB_H
  47 #include <sys/timeb.h>
  48 #endif
  49
  50 #if HAVE_STDLIB_H
  51 #include <stdlib.h>
  52 #endif
  53
  54 #if HAVE_WINDOWS_H
  55 #include <windows.h>
  56 #endif
  57
  58 /* huh? */
  59 #define BIG_STRING_LEN              512
  60
  61 static double ElapsedTimeStart = 0.0;
  62 static double TicksPerSecond   = 0.0;
  63
  64 static double InitUserTime = 0.0;
  65 static double InitElapsedTime = 0.0;
  66 static double InitElapsedStamp = 0.0;
  67
  68 static double MutUserTime = 0.0;
  69 static double MutElapsedTime = 0.0;
  70 static double MutElapsedStamp = 0.0;
  71
  72 static double ExitUserTime = 0.0;
  73 static double ExitElapsedTime = 0.0;
  74
  75 static ullong GC_tot_alloc = 0;
  76 static ullong GC_tot_copied = 0;
  77
  78 static double GC_start_time,  GC_tot_time = 0;  /* User GC Time */
  79 static double GCe_start_time, GCe_tot_time = 0; /* Elapsed GC time */
  80
  81 lnat MaxResidency = 0;     /* in words; for stats only */
  82 lnat ResidencySamples = 0; /* for stats only */
  83
  84 static lnat GC_start_faults = 0, GC_end_faults = 0;
  85
  86 static double *GC_coll_times;
  87
  88 /* ToDo: convert this to use integers? --SDM */
  89
  90 /* elapsedtime() -- The current elapsed time in seconds */
  91
  92 #ifdef _WIN32
  93 #define NS_PER_SEC 10000000LL
  94 /* Convert FILETIMEs into secs since the Epoch (Jan1-1970) */
  95 #define FT2longlong(ll,ft)    \
  96     (ll)=(ft).dwHighDateTime; \
  97     (ll) <<= 32;              \
  98     (ll) |= (ft).dwLowDateTime; \
  99     (ll) /= (unsigned long long) (NS_PER_SEC / CLOCKS_PER_SEC)
 100 #endif
 101
 102 #ifdef _WIN32
 103 /* cygwin32 or mingw32 version */
 104 double
 105 elapsedtime(void)
 106 {
 107     FILETIME creationTime, exitTime, kernelTime, userTime;
 108     long long int kT, uT;
 109
 110
 111     /* ToDo: pin down elapsed times to just the OS thread(s) that
 112        are evaluating/managing Haskell code.
 113     */
 114     if (!GetProcessTimes (GetCurrentProcess(), &creationTime,
 115                           &exitTime, &kernelTime, &userTime)) {
 116         /* Probably on a Win95 box..*/
 117         return 0;
 118     }
 119
 120     FT2longlong(kT,kernelTime);
 121     FT2longlong(uT,userTime);
 122     return (((StgDouble)(uT + kT))/TicksPerSecond);
 123 }
 124
 125 #else
 126
 127 double
 128 elapsedtime(void)
 129 {
 130
 131 # if ! (defined(HAVE_TIMES) || defined(HAVE_FTIME))
 132     /* We will #ifdef around the fprintf for machines
 133        we *know* are unsupported. (WDP 94/05)
 134     */
 135     fprintf(stderr, "NOTE: `elapsedtime' does nothing!\n");
 136     return 0.0;
 137
 138 # else /* not stumped */
 139
 140 /* "ftime" may be nicer, but "times" is more standard;
 141    but, on a Sun, if you do not get the SysV one, you are *hosed*...
 142  */
 143
 144 #  if defined(HAVE_TIMES) && ! sunos4_TARGET_OS
 145     struct tms t;
 146     clock_t r = times(&t);
 147
 148     return (((double)r)/TicksPerSecond);
 149
 150 #  else /* HAVE_FTIME */
 151     struct timeb t;
 152
 153     ftime(&t);
 154     return (fabs(t.time + 1e-3*t.millitm));
 155
 156 #  endif /* HAVE_FTIME */
 157 # endif /* not stumped */
 158 }
 159 #endif /* !_WIN32 */
 160
 161 /* mut_user_time_during_GC() and mut_user_time()
 162  *
 163  * The former function can be used to get the current mutator time
 164  * *during* a GC, i.e. between stat_startGC and stat_endGC.  This is
 165  * used in the heap profiler for accurately time stamping the heap
 166  * sample.
 167  *
 168  * ATTENTION: mut_user_time_during_GC() relies on GC_start_time being
 169  *            defined in stat_startGC() - to minimise system calls,
 170  *            GC_start_time is, however, only defined when really needed (check
 171  *            stat_startGC() for details)
 172  */
 173 double
 174 mut_user_time_during_GC(void)
 175 {
 176   return (GC_start_time - GC_tot_time);
 177 }
 178
 179 double
 180 mut_user_time(void)
 181 {
 182   return (usertime() - GC_tot_time);
 183 }
 184
 185
 186 static nat
 187 pagefaults(void)
 188 {
 189   /* ToDo (on NT): better, get this via the performance data
 190      that's stored in the registry. */
 191 # if !defined(HAVE_GETRUSAGE) || irix_TARGET_OS || defined(_WIN32)
 192     return 0;
 193 # else
 194     struct rusage t;
 195
 196     getrusage(RUSAGE_SELF, &t);
 197     return(t.ru_majflt);
 198 # endif
 199 }
 200
 201 /* ToDo: use gettimeofday on systems that support it (u-sec accuracy) */
 202
 203 void
 204 start_time(void)
 205 {
 206 #ifdef HAVE_SYSCONF
 207     long ticks;
 208     /* Determine TicksPerSecond ... */
 209
 210     ticks = sysconf(_SC_CLK_TCK);
 211     if ( ticks == -1 ) {
 212         fprintf(stderr, "stat_init: bad call to 'sysconf'!\n");
 213         stg_exit(EXIT_FAILURE);
 214     }
 215     TicksPerSecond = (double) ticks;
 216
 217 /* no "sysconf"; had better guess */
 218 #elif defined(HZ)
 219     TicksPerSecond = (StgDouble) (HZ);
 220
 221 #elif defined(CLOCKS_PER_SEC)
 222     TicksPerSecond = (StgDouble) (CLOCKS_PER_SEC);
 223 #else /* had better guess wildly */
 224     /* We will #ifdef around the fprintf for machines
 225        we *know* are unsupported. (WDP 94/05)
 226     */
 227     fprintf(stderr, "NOTE: Guessing `TicksPerSecond = 60'!\n");
 228     TicksPerSecond = 60.0;
 229 #endif
 230
 231     ElapsedTimeStart = elapsedtime();
 232 }
 233
 234
 235 void
 236 initStats(void)
 237 {
 238   nat i;
 239   FILE *sf = RtsFlags.GcFlags.statsFile;
 240
 241   if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) {
 242     fprintf(sf, "    Alloc    Collect    Live    GC    GC     TOT     TOT  Page Flts\n");
 243     fprintf(sf, "    bytes     bytes     bytes  user  elap    user    elap\n");
 244   }
 245   GC_coll_times =
 246     (double *)stgMallocBytes(sizeof(double) * RtsFlags.GcFlags.generations,
 247                            "initStats");
 248   for (i = 0; i < RtsFlags.GcFlags.generations; i++) {
 249     GC_coll_times[i] = 0.0;
 250   }
 251 }
 252
 253 #ifdef _WIN32
 254 double
 255 usertime(void)
 256 {
 257     FILETIME creationTime, exitTime, kernelTime, userTime;
 258     long long int uT;
 259
 260     /* Convert FILETIMEs into long longs */
 261
 262     if (!GetProcessTimes (GetCurrentProcess(), &creationTime,
 263                           &exitTime, &kernelTime, &userTime)) {
 264         /* Probably exec'ing this on a Win95 box..*/
 265         return 0;
 266     }
 267
 268     FT2longlong(uT,userTime);
 269     return (((StgDouble)uT)/TicksPerSecond);
 270 }
 271 #else
 272
 273 double
 274 usertime(void)
 275 {
 276 # if ! (defined(HAVE_GETRUSAGE) || defined(HAVE_TIMES))
 277     /* We will #ifdef around the fprintf for machines
 278        we *know* are unsupported. (WDP 94/05)
 279     */
 280     fprintf(stderr, "NOTE: `usertime' does nothing!\n");
 281     return 0.0;
 282
 283 # else /* not stumped */
 284
 285 #  if defined(HAVE_TIMES)
 286     struct tms t;
 287
 288     times(&t);
 289     return(((double)(t.tms_utime))/TicksPerSecond);
 290
 291 #  else /* HAVE_GETRUSAGE */
 292     struct rusage t;
 293
 294     getrusage(RUSAGE_SELF, &t);
 295     return(t.ru_utime.tv_sec + 1e-6*t.ru_utime.tv_usec);
 296
 297 #  endif /* HAVE_GETRUSAGE */
 298 # endif /* not stumped */
 299 }
 300 #endif /* ! _WIN32 */
 301
 302 void
 303 end_init(void)
 304 {
 305   InitUserTime = usertime();
 306   InitElapsedStamp = elapsedtime();
 307   InitElapsedTime = InitElapsedStamp - ElapsedTimeStart;
 308   if (InitElapsedTime < 0.0) {
 309     InitElapsedTime = 0.0;
 310   }
 311 }
 312
 313 /* -----------------------------------------------------------------------------
 314    stat_startExit and stat_endExit
 315
 316    These two measure the time taken in shutdownHaskell().
 317    -------------------------------------------------------------------------- */
 318
 319 void
 320 stat_startExit(void)
 321 {
 322   MutElapsedStamp = elapsedtime();
 323   MutElapsedTime = MutElapsedStamp - GCe_tot_time - InitElapsedStamp;
 324   if (MutElapsedTime < 0) { MutElapsedTime = 0; }       /* sometimes -0.00 */
 325
 326   /* for SMP, we don't know the mutator time yet, we have to inspect
 327    * all the running threads to find out, and they haven't stopped
 328    * yet.  So we just timestamp MutUserTime at this point so we can
 329    * calculate the EXIT time.  The real MutUserTime is calculated
 330    * in stat_exit below.
 331    */
 332 #ifdef SMP
 333   MutUserTime = usertime();
 334 #else
 335   MutUserTime = usertime() - GC_tot_time - InitUserTime;
 336   if (MutUserTime < 0) { MutUserTime = 0; }
 337 #endif
 338 }
 339
 340 void
 341 stat_endExit(void)
 342 {
 343 #ifdef SMP
 344   ExitUserTime = usertime() - MutUserTime;
 345 #else
 346   ExitUserTime = usertime() - MutUserTime - GC_tot_time - InitUserTime;
 347 #endif
 348   ExitElapsedTime = elapsedtime() - MutElapsedStamp;
 349   if (ExitUserTime < 0.0) {
 350     ExitUserTime = 0.0;
 351   }
 352   if (ExitElapsedTime < 0.0) {
 353     ExitElapsedTime = 0.0;
 354   }
 355 }
 356
 357 /* -----------------------------------------------------------------------------
 358    Called at the beginning of each GC
 359    -------------------------------------------------------------------------- */
 360
 361 static nat rub_bell = 0;
 362
 363 /*  initialise global variables needed during GC
 364  *
 365  *  * GC_start_time is read in mut_user_time_during_GC(), which in turn is
 366  *    needed if either PROFILING or DEBUGing is enabled
 367  */
 368 void
 369 stat_startGC(void)
 370 {
 371     FILE *sf = RtsFlags.GcFlags.statsFile;
 372
 373     nat bell = RtsFlags.GcFlags.ringBell;
 374
 375     if (bell) {
 376         if (bell > 1) {
 377             fprintf(stderr, " GC ");
 378             rub_bell = 1;
 379         } else {
 380             fprintf(stderr, "\007");
 381         }
 382     }
 383
 384 #if defined(PROFILING) || defined(DEBUG)
 385     GC_start_time = usertime();  /* needed in mut_user_time_during_GC() */
 386 #endif
 387
 388     if (sf != NULL) {
 389 #if !defined(PROFILING) && !defined(DEBUG)
 390         GC_start_time = usertime();
 391 #endif
 392         GCe_start_time = elapsedtime();
 393         if (RtsFlags.GcFlags.giveStats) {
 394           GC_start_faults = pagefaults();
 395         }
 396     }
 397 }
 398
 399 /* -----------------------------------------------------------------------------
 400    Called at the end of each GC
 401    -------------------------------------------------------------------------- */
 402
 403 void
 404 stat_endGC(lnat alloc, lnat collect, lnat live, lnat copied, lnat gen)
 405 {
 406     FILE *sf = RtsFlags.GcFlags.statsFile;
 407
 408     if (sf != NULL) {
 409         double time     = usertime();
 410         double etime    = elapsedtime();
 411         double gc_time  = time - GC_start_time;
 412         double gc_etime = etime - GCe_start_time;
 413
 414         if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) {
 415             nat faults = pagefaults();
 416
 417             fprintf(sf, "%9ld %9ld %9ld",
 418                     alloc*sizeof(W_), collect*sizeof(W_), live*sizeof(W_));
 419             fprintf(sf, " %5.2f %5.2f %7.2f %7.2f %4ld %4ld  (Gen: %2ld)\n",
 420                     gc_time,
 421                     gc_etime,
 422                     time,
 423                     etime,
 424                     faults - GC_start_faults,
 425                     GC_start_faults - GC_end_faults,
 426                     gen);
 427
 428             GC_end_faults = faults;
 429             fflush(sf);
 430         }
 431
 432         GC_coll_times[gen] += gc_time;
 433
 434         GC_tot_copied += (ullong) copied;
 435         GC_tot_alloc  += (ullong) alloc;
 436         GC_tot_time   += gc_time;
 437         GCe_tot_time  += gc_etime;
 438
 439 #ifdef SMP
 440         {
 441           nat i;
 442           pthread_t me = pthread_self();
 443
 444           for (i = 0; i < RtsFlags.ConcFlags.nNodes; i++) {
 445             if (me == task_ids[i].id) {
 446               task_ids[i].gc_time += gc_time;
 447               task_ids[i].gc_etime += gc_etime;
 448               break;
 449             }
 450           }
 451         }
 452 #endif
 453
 454         if (gen == RtsFlags.GcFlags.generations-1) { /* major GC? */
 455           if (live > MaxResidency) {
 456             MaxResidency = live;
 457           }
 458           ResidencySamples++;
 459         }
 460     }
 461
 462     if (rub_bell) {
 463         fprintf(stderr, "\b\b\b  \b\b\b");
 464         rub_bell = 0;
 465     }
 466 }
 467
 468 /* -----------------------------------------------------------------------------
 469    stat_workerStop
 470
 471    Called under SMP when a worker thread finishes.  We drop the timing
 472    stats for this thread into the task_ids struct for that thread.
 473    -------------------------------------------------------------------------- */
 474
 475 #ifdef SMP
 476 void
 477 stat_workerStop(void)
 478 {
 479   nat i;
 480   pthread_t me = pthread_self();
 481
 482   for (i = 0; i < RtsFlags.ConcFlags.nNodes; i++) {
 483     if (task_ids[i].id == me) {
 484       task_ids[i].mut_time = usertime() - task_ids[i].gc_time;
 485       task_ids[i].mut_etime = elapsedtime()
 486                                  - GCe_tot_time
 487                                  - task_ids[i].elapsedtimestart;
 488       if (task_ids[i].mut_time < 0.0)  { task_ids[i].mut_time = 0.0;  }
 489       if (task_ids[i].mut_etime < 0.0) { task_ids[i].mut_etime = 0.0; }
 490     }
 491   }
 492 }
 493 #endif
 494
 495 /* -----------------------------------------------------------------------------
 496    Called at the end of execution
 497
 498    NOTE: number of allocations is not entirely accurate: it doesn't
 499    take into account the few bytes at the end of the heap that
 500    were left unused when the heap-check failed.
 501    -------------------------------------------------------------------------- */
 502
 503 void
 504 stat_exit(int alloc)
 505 {
 506     FILE *sf = RtsFlags.GcFlags.statsFile;
 507
 508     if (sf != NULL){
 509         char temp[BIG_STRING_LEN];
 510         double time = usertime();
 511         double etime = elapsedtime() - ElapsedTimeStart;
 512
 513         /* avoid divide by zero if time is measured as 0.00 seconds -- SDM */
 514         if (time  == 0.0)  time = 0.0001;
 515         if (etime == 0.0) etime = 0.0001;
 516
 517         if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) {
 518           fprintf(sf, "%9ld %9.9s %9.9s",       (lnat)alloc*sizeof(W_), "", "");
 519           fprintf(sf, " %5.2f %5.2f\n\n", 0.0, 0.0);
 520         }
 521
 522         GC_tot_alloc += alloc;
 523
 524         ullong_format_string(GC_tot_alloc*sizeof(W_), temp, rtsTrue/*commas*/);
 525         fprintf(sf, "%11s bytes allocated in the heap\n", temp);
 526
 527         ullong_format_string(GC_tot_copied*sizeof(W_), temp, rtsTrue/*commas*/);
 528         fprintf(sf, "%11s bytes copied during GC\n", temp);
 529
 530         if ( ResidencySamples > 0 ) {
 531             ullong_format_string(MaxResidency*sizeof(W_), temp, rtsTrue/*commas*/);
 532             fprintf(sf, "%11s bytes maximum residency (%ld sample(s))\n",
 533                               temp,
 534                               ResidencySamples);
 535         }
 536         fprintf(sf,"\n");
 537
 538         { /* Count garbage collections */
 539           nat g;
 540           for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
 541             fprintf(sf, "%11d collections in generation %d (%6.2fs)\n",
 542                     generations[g].collections, g, GC_coll_times[g]);
 543           }
 544         }
 545         fprintf(sf,"\n%11ld Mb total memory in use\n\n",
 546                 mblocks_allocated * MBLOCK_SIZE / (1024 * 1024));
 547
 548         /* For SMP, we have to get the user time from each thread
 549          * and try to work out the total time.
 550          */
 551 #ifdef SMP
 552         {
 553           nat i;
 554           MutUserTime = 0.0;
 555           for (i = 0; i < RtsFlags.ConcFlags.nNodes; i++) {
 556             MutUserTime += task_ids[i].mut_time;
 557             fprintf(sf, "  Task %2d:  MUT time: %6.2fs  (%6.2fs elapsed)\n"
 558                         "            GC  time: %6.2fs  (%6.2fs elapsed)\n\n",
 559                     i,
 560                     task_ids[i].mut_time, task_ids[i].mut_etime,
 561                     task_ids[i].gc_time, task_ids[i].gc_etime);
 562           }
 563         }
 564         time = MutUserTime + GC_tot_time + InitUserTime + ExitUserTime;
 565         if (MutUserTime < 0) { MutUserTime = 0; }
 566 #endif
 567
 568         fprintf(sf, "  INIT  time  %6.2fs  (%6.2fs elapsed)\n",
 569                 InitUserTime, InitElapsedTime);
 570         fprintf(sf, "  MUT   time  %6.2fs  (%6.2fs elapsed)\n",
 571                 MutUserTime, MutElapsedTime);
 572         fprintf(sf, "  GC    time  %6.2fs  (%6.2fs elapsed)\n",
 573                 GC_tot_time, GCe_tot_time);
 574         fprintf(sf, "  EXIT  time  %6.2fs  (%6.2fs elapsed)\n",
 575                 ExitUserTime, ExitElapsedTime);
 576         fprintf(sf, "  Total time  %6.2fs  (%6.2fs elapsed)\n\n",
 577                 time, etime);
 578
 579         fprintf(sf, "  %%GC time     %5.1f%%  (%.1f%% elapsed)\n\n",
 580                 GC_tot_time*100./time, GCe_tot_time*100./etime);
 581
 582         if (time - GC_tot_time == 0.0)
 583                 ullong_format_string(0, temp, rtsTrue/*commas*/);
 584         else
 585                 ullong_format_string((ullong)(GC_tot_alloc*sizeof(W_)/
 586                                               (time - GC_tot_time)),
 587                                      temp, rtsTrue/*commas*/);
 588
 589         fprintf(sf, "  Alloc rate    %s bytes per MUT second\n\n", temp);
 590
 591         fprintf(sf, "  Productivity %5.1f%% of total user, %.1f%% of total elapsed\n\n",
 592                 (time - GC_tot_time - InitUserTime) * 100. / time,
 593                 (time - GC_tot_time - InitUserTime) * 100. / etime);
 594         fflush(sf);
 595         fclose(sf);
 596     }
 597 }
 598
 599 /* -----------------------------------------------------------------------------
 600    stat_describe_gens
 601
 602    Produce some detailed info on the state of the generational GC.
 603    -------------------------------------------------------------------------- */
 604 void
 605 stat_describe_gens(void)
 606 {
 607   nat g, s, mut, mut_once, lge, live;
 608   StgMutClosure *m;
 609   bdescr *bd;
 610   step *step;
 611
 612   fprintf(stderr, "     Gen    Steps      Max   Mutable  Mut-Once  Step   Blocks     Live    Large\n                    Blocks  Closures  Closures                         Objects\n");
 613
 614   for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
 615     for (m = generations[g].mut_list, mut = 0; m != END_MUT_LIST;
 616          m = m->mut_link)
 617       mut++;
 618     for (m = generations[g].mut_once_list, mut_once = 0; m != END_MUT_LIST;
 619          m = m->mut_link)
 620       mut_once++;
 621     fprintf(stderr, "%8d %8d %8d %9d %9d", g, generations[g].n_steps,
 622             generations[g].max_blocks, mut, mut_once);
 623
 624     for (s = 0; s < generations[g].n_steps; s++) {
 625       step = &generations[g].steps[s];
 626       for (bd = step->large_objects, lge = 0; bd; bd = bd->link)
 627         lge++;
 628       live = 0;
 629       if (RtsFlags.GcFlags.generations == 1) {
 630         bd = step->to_space;
 631       } else {
 632         bd = step->blocks;
 633       }
 634       for (; bd; bd = bd->link) {
 635         live += (bd->free - bd->start) * sizeof(W_);
 636       }
 637       if (s != 0) {
 638         fprintf(stderr,"%46s","");
 639       }
 640       fprintf(stderr,"%6d %8d %8d %8d\n", s, step->n_blocks,
 641               live, lge);
 642     }
 643   }
 644   fprintf(stderr,"\n");
 645 }