ghc/rts/Stats.c

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