[project @ 2005-01-28 12:55:17 by simonmar]
[ghc-hetmet.git] / ghc / rts / Stats.c
index 1991090..7c1dbaf 100644 (file)
@@ -1,7 +1,6 @@
 /* -----------------------------------------------------------------------------
- * $Id: Stats.c,v 1.40 2001/11/27 16:35:57 simonmar Exp $
  *
- * (c) The GHC Team, 1998-1999
+ * (c) The GHC Team, 1998-2004
  *
  * Statistics and timing-related functions.
  *
 #include "Rts.h"
 #include "RtsFlags.h"
 #include "RtsUtils.h"
-#include "StoragePriv.h"
 #include "MBlock.h"
 #include "Schedule.h"
 #include "Stats.h"
 #include "ParTicky.h"                       /* ToDo: move into Rts.h */
 #include "Profiling.h"
+#include "Storage.h"
 
 #ifdef HAVE_UNISTD_H
 #include <unistd.h>
 #endif
 
-#ifndef mingw32_TARGET_OS
+#ifndef mingw32_HOST_OS
 # ifdef HAVE_SYS_TIMES_H
 #  include <sys/times.h>
 # endif
@@ -41,7 +40,7 @@
 # endif
 #endif
 
-#if ! irix_TARGET_OS && ! defined(mingw32_TARGET_OS)
+#if ! irix_HOST_OS && ! defined(mingw32_HOST_OS)
 # if defined(HAVE_SYS_RESOURCE_H)
 #  include <sys/resource.h>
 # endif
@@ -59,7 +58,7 @@
 #include <windows.h>
 #endif
 
-#if defined(PAR) || !(!defined(HAVE_GETRUSAGE) || irix_TARGET_OS || defined(mingw32_TARGET_OS) || defined(cygwin32_TARGET_OS))
+#if defined(PAR) || !(!defined(HAVE_GETRUSAGE) || irix_HOST_OS || defined(mingw32_HOST_OS) || defined(cygwin32_HOST_OS))
 #include <sys/resource.h>
 #endif
 
@@ -111,9 +110,9 @@ static TICK_TYPE HCe_start_time, HCe_tot_time = 0;   // heap census prof elap ti
 #define PROF_VAL(x)   0
 #endif
 
-lnat MaxResidency = 0;     /* in words; for stats only */
-lnat AvgResidency = 0;
-lnat ResidencySamples = 0; /* for stats only */
+static lnat MaxResidency = 0;     // in words; for stats only
+static lnat AvgResidency = 0;
+static lnat ResidencySamples = 0; // for stats only
 
 static lnat GC_start_faults = 0, GC_end_faults = 0;
 
@@ -122,9 +121,13 @@ static TICK_TYPE *GC_coll_times;
 static void  getTimes(void);
 static nat   pageFaults(void);
 
+static void statsPrintf( char *s, ... );
+static void statsFlush( void );
+static void statsClose( void );
+
 /* elapsedtime() -- The current elapsed time in seconds */
 
-#if defined(mingw32_TARGET_OS) || defined(cygwin32_TARGET_OS)
+#if defined(mingw32_HOST_OS) || defined(cygwin32_HOST_OS)
 #define HNS_PER_SEC 10000000LL /* FILETIMES are in units of 100ns */
 /* Convert FILETIMEs into secs */
 #define FT2longlong(ll,ft)    \
@@ -134,7 +137,7 @@ static nat   pageFaults(void);
     (ll) /= (unsigned long long) (HNS_PER_SEC / CLOCKS_PER_SEC)
 #endif
 
-#if defined(mingw32_TARGET_OS) || defined(cygwin32_TARGET_OS)
+#if defined(mingw32_HOST_OS) || defined(cygwin32_HOST_OS)
 /* cygwin32 or mingw32 version */
 static void
 getTimes(void)
@@ -198,7 +201,7 @@ getTimes(void)
     /* We will #ifdef around the fprintf for machines
        we *know* are unsupported. (WDP 94/05)
     */
-    fprintf(stderr, "NOTE: `getTimes' does nothing!\n");
+    debugBelch("NOTE: `getTimes' does nothing!\n");
     return 0.0;
 
 #else /* not stumped */
@@ -261,7 +264,7 @@ pageFaults(void)
 {
   /* ToDo (on NT): better, get this via the performance data
      that's stored in the registry. */
-# if !defined(HAVE_GETRUSAGE) || irix_TARGET_OS || defined(mingw32_TARGET_OS) || defined(cygwin32_TARGET_OS)
+# if !defined(HAVE_GETRUSAGE) || irix_HOST_OS || defined(mingw32_HOST_OS) || defined(cygwin32_HOST_OS)
     return 0;
 # else
     struct rusage t;
@@ -275,11 +278,10 @@ void
 initStats(void)
 {
     nat i;
-    FILE *sf = RtsFlags.GcFlags.statsFile;
   
     if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) {
-       fprintf(sf, "    Alloc    Collect    Live    GC    GC     TOT     TOT  Page Flts\n");
-       fprintf(sf, "    bytes     bytes     bytes  user  elap    user    elap\n");
+       statsPrintf("    Alloc    Collect    Live    GC    GC     TOT     TOT  Page Flts\n");
+       statsPrintf("    bytes     bytes     bytes  user  elap    user    elap\n");
     }
     GC_coll_times = 
        (TICK_TYPE *)stgMallocBytes(
@@ -306,7 +308,7 @@ stat_startInit(void)
 
     ticks = sysconf(_SC_CLK_TCK);
     if ( ticks == -1 ) {
-       fprintf(stderr, "stat_init: bad call to 'sysconf'!\n");
+       debugBelch("stat_init: bad call to 'sysconf'!\n");
        stg_exit(EXIT_FAILURE);
     }
     TicksPerSecond = ticks;
@@ -322,7 +324,7 @@ stat_startInit(void)
     /* We will #ifdef around the fprintf for machines
        we *know* are unsupported. (WDP 94/05)
     */
-    fprintf(stderr, "NOTE: Guessing `TicksPerSecond = 60'!\n");
+    debugBelch("NOTE: Guessing `TicksPerSecond = 60'!\n");
     TicksPerSecond = 60;
 #endif
 
@@ -408,10 +410,10 @@ stat_startGC(void)
 
     if (bell) {
        if (bell > 1) {
-           fprintf(stderr, " GC ");
+           debugBelch(" GC ");
            rub_bell = 1;
        } else {
-           fprintf(stderr, "\007");
+           debugBelch("\007");
        }
     }
 
@@ -439,8 +441,6 @@ stat_startGC(void)
 void
 stat_endGC(lnat alloc, lnat collect, lnat live, lnat copied, lnat gen)
 {
-    FILE *sf = RtsFlags.GcFlags.statsFile;
-
     if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
        TICK_TYPE time, etime, gc_time, gc_etime;
        
@@ -450,12 +450,12 @@ stat_endGC(lnat alloc, lnat collect, lnat live, lnat copied, lnat gen)
        gc_time  = time - GC_start_time;
        gc_etime = etime - GCe_start_time;
        
-       if (RtsFlags.GcFlags.giveStats == VERBOSE_GC_STATS && sf != NULL) {
+       if (RtsFlags.GcFlags.giveStats == VERBOSE_GC_STATS) {
            nat faults = pageFaults();
            
-           fprintf(sf, "%9ld %9ld %9ld",
+           statsPrintf("%9ld %9ld %9ld",
                    alloc*sizeof(W_), collect*sizeof(W_), live*sizeof(W_));
-           fprintf(sf, " %5.2f %5.2f %7.2f %7.2f %4ld %4ld  (Gen: %2ld)\n", 
+           statsPrintf(" %5.2f %5.2f %7.2f %7.2f %4ld %4ld  (Gen: %2ld)\n", 
                    TICK_TO_DBL(gc_time),
                    TICK_TO_DBL(gc_etime),
                    TICK_TO_DBL(time),
@@ -465,7 +465,7 @@ stat_endGC(lnat alloc, lnat collect, lnat live, lnat copied, lnat gen)
                    gen);
 
            GC_end_faults = faults;
-           fflush(sf);
+           statsFlush();
        }
 
        GC_coll_times[gen] += gc_time;
@@ -500,7 +500,7 @@ stat_endGC(lnat alloc, lnat collect, lnat live, lnat copied, lnat gen)
     }
 
     if (rub_bell) {
-       fprintf(stderr, "\b\b\b  \b\b\b");
+       debugBelch("\b\b\b  \b\b\b");
        rub_bell = 0;
     }
 }
@@ -579,17 +579,19 @@ stat_endHeapCensus(void)
    stats for this thread into the task_ids struct for that thread.
    -------------------------------------------------------------------------- */
 
-#ifdef SMP
+#if defined(SMP)
 void
 stat_workerStop(void)
 {
     nat i;
     pthread_t me = pthread_self();
 
+    getTimes();
+
     for (i = 0; i < RtsFlags.ParFlags.nNodes; i++) {
        if (task_ids[i].id == me) {
-           task_ids[i].mut_time = usertime() - task_ids[i].gc_time;
-           task_ids[i].mut_etime = elapsedtime()
+           task_ids[i].mut_time = CurrentUserTime - task_ids[i].gc_time;
+           task_ids[i].mut_etime = CurrentElapsedTime
                - GCe_tot_time
                - task_ids[i].elapsedtimestart;
            if (task_ids[i].mut_time < 0.0)  { task_ids[i].mut_time = 0.0;  }
@@ -599,6 +601,14 @@ stat_workerStop(void)
 }
 #endif
 
+#if defined(SMP)
+long int stat_getElapsedTime ()
+{
+  getTimes();
+  return CurrentElapsedTime;
+}
+#endif
+
 /* -----------------------------------------------------------------------------
    Called at the end of execution
 
@@ -610,8 +620,6 @@ stat_workerStop(void)
 void
 stat_exit(int alloc)
 {
-    FILE *sf = RtsFlags.GcFlags.statsFile;
-    
     if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) {
 
        char temp[BIG_STRING_LEN];
@@ -647,43 +655,43 @@ stat_exit(int alloc)
        if (MutUserTime < 0) { MutUserTime = 0; }
 #endif
 
-       if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS && sf != NULL) {
-           fprintf(sf, "%9ld %9.9s %9.9s", (lnat)alloc*sizeof(W_), "", "");
-           fprintf(sf, " %5.2f %5.2f\n\n", 0.0, 0.0);
+       if (RtsFlags.GcFlags.giveStats >= VERBOSE_GC_STATS) {
+           statsPrintf("%9ld %9.9s %9.9s", (lnat)alloc*sizeof(W_), "", "");
+           statsPrintf(" %5.2f %5.2f\n\n", 0.0, 0.0);
        }
 
-       if (RtsFlags.GcFlags.giveStats >= SUMMARY_GC_STATS && sf != NULL) {
+       if (RtsFlags.GcFlags.giveStats >= SUMMARY_GC_STATS) {
            ullong_format_string(GC_tot_alloc*sizeof(W_), 
                                 temp, rtsTrue/*commas*/);
-           fprintf(sf, "%11s bytes allocated in the heap\n", temp);
+           statsPrintf("%11s bytes allocated in the heap\n", temp);
 
            ullong_format_string(GC_tot_copied*sizeof(W_), 
                                 temp, rtsTrue/*commas*/);
-           fprintf(sf, "%11s bytes copied during GC\n", temp);
+           statsPrintf("%11s bytes copied during GC\n", temp);
 
            if ( ResidencySamples > 0 ) {
                ullong_format_string(MaxResidency*sizeof(W_), 
                                     temp, rtsTrue/*commas*/);
-               fprintf(sf, "%11s bytes maximum residency (%ld sample(s))\n",
+               statsPrintf("%11s bytes maximum residency (%ld sample(s))\n",
                        temp, ResidencySamples);
            }
-           fprintf(sf,"\n");
+           statsPrintf("\n");
 
            /* Print garbage collections in each gen */
            for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
-               fprintf(sf, "%11d collections in generation %d (%6.2fs)\n", 
+               statsPrintf("%11d collections in generation %d (%6.2fs)\n", 
                        generations[g].collections, g, 
                        TICK_TO_DBL(GC_coll_times[g]));
            }
 
-           fprintf(sf,"\n%11ld Mb total memory in use\n\n", 
+           statsPrintf("\n%11ld Mb total memory in use\n\n", 
                    mblocks_allocated * MBLOCK_SIZE / (1024 * 1024));
 
 #ifdef SMP
            {
                nat i;
                for (i = 0; i < RtsFlags.ParFlags.nNodes; i++) {
-                   fprintf(sf, "  Task %2d:  MUT time: %6.2fs  (%6.2fs elapsed)\n"
+                   statsPrintf("  Task %2d:  MUT time: %6.2fs  (%6.2fs elapsed)\n"
                            "            GC  time: %6.2fs  (%6.2fs elapsed)\n\n", 
                            i, 
                            TICK_TO_DBL(task_ids[i].mut_time),
@@ -694,23 +702,23 @@ stat_exit(int alloc)
            }
 #endif
 
-           fprintf(sf, "  INIT  time  %6.2fs  (%6.2fs elapsed)\n",
+           statsPrintf("  INIT  time  %6.2fs  (%6.2fs elapsed)\n",
                    TICK_TO_DBL(InitUserTime), TICK_TO_DBL(InitElapsedTime));
-           fprintf(sf, "  MUT   time  %6.2fs  (%6.2fs elapsed)\n",
+           statsPrintf("  MUT   time  %6.2fs  (%6.2fs elapsed)\n",
                    TICK_TO_DBL(MutUserTime), TICK_TO_DBL(MutElapsedTime));
-           fprintf(sf, "  GC    time  %6.2fs  (%6.2fs elapsed)\n",
+           statsPrintf("  GC    time  %6.2fs  (%6.2fs elapsed)\n",
                    TICK_TO_DBL(GC_tot_time), TICK_TO_DBL(GCe_tot_time));
 #ifdef PROFILING
-           fprintf(sf, "  RP    time  %6.2fs  (%6.2fs elapsed)\n",
+           statsPrintf("  RP    time  %6.2fs  (%6.2fs elapsed)\n",
                    TICK_TO_DBL(RP_tot_time), TICK_TO_DBL(RPe_tot_time));
-           fprintf(sf, "  PROF  time  %6.2fs  (%6.2fs elapsed)\n",
+           statsPrintf("  PROF  time  %6.2fs  (%6.2fs elapsed)\n",
                    TICK_TO_DBL(HC_tot_time), TICK_TO_DBL(HCe_tot_time));
 #endif 
-           fprintf(sf, "  EXIT  time  %6.2fs  (%6.2fs elapsed)\n",
+           statsPrintf("  EXIT  time  %6.2fs  (%6.2fs elapsed)\n",
                    TICK_TO_DBL(ExitUserTime), TICK_TO_DBL(ExitElapsedTime));
-           fprintf(sf, "  Total time  %6.2fs  (%6.2fs elapsed)\n\n",
+           statsPrintf("  Total time  %6.2fs  (%6.2fs elapsed)\n\n",
                    TICK_TO_DBL(time), TICK_TO_DBL(etime));
-           fprintf(sf, "  %%GC time     %5.1f%%  (%.1f%% elapsed)\n\n",
+           statsPrintf("  %%GC time     %5.1f%%  (%.1f%% elapsed)\n\n",
                    TICK_TO_DBL(GC_tot_time)*100/TICK_TO_DBL(time),
                    TICK_TO_DBL(GCe_tot_time)*100/TICK_TO_DBL(etime));
 
@@ -723,9 +731,9 @@ stat_exit(int alloc)
                                         PROF_VAL(RP_tot_time + HC_tot_time))),
                    temp, rtsTrue/*commas*/);
            
-           fprintf(sf, "  Alloc rate    %s bytes per MUT second\n\n", temp);
+           statsPrintf("  Alloc rate    %s bytes per MUT second\n\n", temp);
        
-           fprintf(sf, "  Productivity %5.1f%% of total user, %.1f%% of total elapsed\n\n",
+           statsPrintf("  Productivity %5.1f%% of total user, %.1f%% of total elapsed\n\n",
                    TICK_TO_DBL(time - GC_tot_time - 
                                PROF_VAL(RP_tot_time + HC_tot_time) - InitUserTime) * 100 
                    / TICK_TO_DBL(time), 
@@ -734,12 +742,13 @@ stat_exit(int alloc)
                    / TICK_TO_DBL(etime));
        }
 
-       if (RtsFlags.GcFlags.giveStats == ONELINE_GC_STATS && sf != NULL) {
+       if (RtsFlags.GcFlags.giveStats == ONELINE_GC_STATS) {
          /* print the long long separately to avoid bugginess on mingwin (2001-07-02, mingw-0.5) */
-         fprintf(sf, "<<ghc: %llu bytes, ", GC_tot_alloc*sizeof(W_));
-         fprintf(sf, "%d GCs, %ld/%ld avg/max bytes residency (%ld samples), %luM in use, %.2f INIT (%.2f elapsed), %.2f MUT (%.2f elapsed), %.2f GC (%.2f elapsed) :ghc>>\n",
+         statsPrintf("<<ghc: %llu bytes, ", GC_tot_alloc*sizeof(W_));
+         statsPrintf("%d GCs, %ld/%ld avg/max bytes residency (%ld samples), %luM in use, %.2f INIT (%.2f elapsed), %.2f MUT (%.2f elapsed), %.2f GC (%.2f elapsed) :ghc>>\n",
                    total_collections,
-                   AvgResidency*sizeof(W_)/ResidencySamples, 
+                   ResidencySamples == 0 ? 0 : 
+                       AvgResidency*sizeof(W_)/ResidencySamples, 
                    MaxResidency*sizeof(W_), 
                    ResidencySamples,
                    (unsigned long)(mblocks_allocated * MBLOCK_SIZE / (1024L * 1024L)),
@@ -748,8 +757,8 @@ stat_exit(int alloc)
                    TICK_TO_DBL(GC_tot_time), TICK_TO_DBL(GCe_tot_time));
        }
 
-       fflush(sf);
-       fclose(sf);
+       statsFlush();
+       statsClose();
     }
 }
 
@@ -767,7 +776,7 @@ statDescribeGens(void)
   bdescr *bd;
   step *step;
 
-  fprintf(stderr, "     Gen    Steps      Max   Mutable  Mut-Once  Step   Blocks     Live    Large\n                    Blocks  Closures  Closures                          Objects\n");
+  debugBelch("     Gen    Steps      Max   Mutable  Mut-Once  Step   Blocks     Live    Large\n                    Blocks  Closures  Closures                          Objects\n");
 
   for (g = 0; g < RtsFlags.GcFlags.generations; g++) {
     for (m = generations[g].mut_list, mut = 0; m != END_MUT_LIST; 
@@ -776,7 +785,7 @@ statDescribeGens(void)
     for (m = generations[g].mut_once_list, mut_once = 0; m != END_MUT_LIST; 
         m = m->mut_link) 
       mut_once++;
-    fprintf(stderr, "%8d %8d %8d %9d %9d", g, generations[g].n_steps,
+    debugBelch("%8d %8d %8d %9d %9d", g, generations[g].n_steps,
            generations[g].max_blocks, mut, mut_once);
 
     for (s = 0; s < generations[g].n_steps; s++) {
@@ -793,13 +802,13 @@ statDescribeGens(void)
        live += (bd->free - bd->start) * sizeof(W_);
       }
       if (s != 0) {
-       fprintf(stderr,"%46s","");
+       debugBelch("%46s","");
       }
-      fprintf(stderr,"%6d %8d %8d %8d\n", s, step->n_blocks,
+      debugBelch("%6d %8d %8d %8d\n", s, step->n_blocks,
              live, lge);
     }
   }
-  fprintf(stderr,"\n");
+  debugBelch("\n");
 }
 #endif
 
@@ -808,5 +817,42 @@ statDescribeGens(void)
    each compilation and expression evaluation.
    -------------------------------------------------------------------------- */
 
-extern HsInt getAllocations( void ) 
-{ return (HsInt)(total_allocated * sizeof(W_)); }
+extern HsInt64 getAllocations( void ) 
+{ return (HsInt64)total_allocated * sizeof(W_); }
+
+/* -----------------------------------------------------------------------------
+   Dumping stuff in the stats file, or via the debug message interface
+   -------------------------------------------------------------------------- */
+
+static void
+statsPrintf( char *s, ... )
+{
+    FILE *sf = RtsFlags.GcFlags.statsFile;
+    va_list ap;
+    
+    va_start(ap,s);
+    if (sf == NULL) {
+       vdebugBelch(s,ap);
+    } else {
+       vfprintf(sf, s, ap);
+    }
+    va_end(ap);
+}
+
+static void
+statsFlush( void )
+{
+    FILE *sf = RtsFlags.GcFlags.statsFile;
+    if (sf != NULL) {
+       fflush(sf);
+    }
+}
+
+static void
+statsClose( void )
+{
+    FILE *sf = RtsFlags.GcFlags.statsFile;
+    if (sf != NULL) {
+       fclose(sf);
+    }
+}