ghc/rts/Stats.c

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