[project @ 1999-11-02 17:19:15 by simonmar]

Time the shutdown code as well as the initialisation code.  This
figure is sometimes significant for SMP, because the tasks are all
killed by a signal (at the moment) and it might take a while for the
signal to be delivered.

diff --git a/ghc/rts/RtsStartup.c b/ghc/rts/RtsStartup.c
index 9d3c99c..8673986 100644 (file)
--- a/ghc/rts/RtsStartup.c
+++ b/ghc/rts/RtsStartup.c
@@ -1,5 +1,5 @@
 /* -----------------------------------------------------------------------------
- * $Id: RtsStartup.c,v 1.22 1999/11/02 15:06:01 simonmar Exp $
+ * $Id: RtsStartup.c,v 1.23 1999/11/02 17:19:15 simonmar Exp $
  *
  * (c) The GHC Team, 1998-1999
  *
@@ -174,6 +174,9 @@ shutdownHaskell(void)
   if (!rts_has_started_up)
      return;
 
+  /* start timing the shutdown */
+  stat_startExit();
+
   /* Finalize any remaining weak pointers */
   finalizeWeakPointersNow();
 
@@ -186,12 +189,17 @@ shutdownHaskell(void)
   /* stop all running tasks */
   exitScheduler();
 
-  /* clean up things from the storage manager's point of view */
-  exitStorage();
-
   /* stop the ticker */
   initialize_virtual_timer(0);
   
+  /* stop timing the shutdown, we're about to print stats */
+  stat_endExit();
+
+  /* clean up things from the storage manager's point of view.
+   * also outputs the stats (+RTS -s) info.
+   */
+  exitStorage();
+
 #if defined(PROFILING) || defined(DEBUG)
   endProfiling();
 #endif

diff --git a/ghc/rts/Schedule.c b/ghc/rts/Schedule.c
index 720386d..fb6749a 100644 (file)
--- a/ghc/rts/Schedule.c
+++ b/ghc/rts/Schedule.c
@@ -1,5 +1,5 @@
 /* -----------------------------------------------------------------------------
- * $Id: Schedule.c,v 1.28 1999/11/02 15:06:01 simonmar Exp $
+ * $Id: Schedule.c,v 1.29 1999/11/02 17:19:16 simonmar Exp $
  *
  * (c) The GHC Team, 1998-1999
  *
@@ -256,6 +256,12 @@ schedule( void )
     
     RELEASE_LOCK(&sched_mutex);
     
+#ifdef SMP
+    IF_DEBUG(scheduler,fprintf(stderr,"schedule (task %ld): running thread %d\n", pthread_self(),t->id));
+#else
+    IF_DEBUG(scheduler,fprintf(stderr,"schedule: running thread %d\n",t->id));
+#endif
+
     /* Run the current thread 
      */
     switch (cap->rCurrentTSO->whatNext) {

diff --git a/ghc/rts/Stats.c b/ghc/rts/Stats.c
index c82827d..097b5b9 100644 (file)
--- a/ghc/rts/Stats.c
+++ b/ghc/rts/Stats.c
@@ -1,5 +1,5 @@
 /* -----------------------------------------------------------------------------
- * $Id: Stats.c,v 1.15 1999/11/02 15:06:03 simonmar Exp $
+ * $Id: Stats.c,v 1.16 1999/11/02 17:19:16 simonmar Exp $
  *
  * (c) The GHC Team, 1998-1999
  *
@@ -64,6 +64,12 @@ static double TicksPerSecond   = 0.0;
 static double InitUserTime = 0.0;
 static double InitElapsedTime = 0.0;
 
+static double MutUserTime = 0.0;
+static double MutElapsedTime = 0.0;
+
+static double ExitUserTime = 0.0;
+static double ExitElapsedTime = 0.0;
+
 static ullong GC_tot_alloc = 0;
 static ullong GC_tot_copied = 0;
 
@@ -294,6 +300,42 @@ end_init(void)
   }
 }
 
+void
+stat_startExit(void)
+{
+  MutElapsedTime = elapsedtime() - GCe_tot_time - InitElapsedTime;
+  if (MutElapsedTime < 0) { MutElapsedTime = 0; }      /* sometimes -0.00 */
+
+  /* for SMP, we don't know the mutator time yet, we have to inspect
+   * all the running threads to find out, and they haven't stopped
+   * yet.  So we just timestamp MutUserTime at this point so we can
+   * calculate the EXIT time.  The real MutUserTime is calculated
+   * in stat_exit below.
+   */
+#ifdef SMP
+  MutUserTime = usertime();
+#else
+  MutUserTime = usertime() - GC_tot_time - InitUserTime;
+#endif
+}
+
+void
+stat_endExit(void)
+{
+#ifdef SMP
+  ExitUserTime = usertime() - MutUserTime;
+#else
+  ExitUserTime = usertime() - MutUserTime - GC_tot_time - InitUserTime;
+#endif
+  ExitElapsedTime = elapsedtime() - MutElapsedTime;
+  if (ExitUserTime < 0.0) {
+    ExitUserTime = 0.0;
+  }
+  if (ExitElapsedTime < 0.0) {
+    ExitElapsedTime = 0.0;
+  }
+}
+
 /* -----------------------------------------------------------------------------
    Called at the beginning of each GC
    -------------------------------------------------------------------------- */
@@ -411,7 +453,6 @@ stat_exit(int alloc)
        char temp[BIG_STRING_LEN];
        double time = usertime();
        double etime = elapsedtime();
-       double MutTime, MutElapsedTime;
 
        /* avoid divide by zero if time is measured as 0.00 seconds -- SDM */
        if (time  == 0.0)  time = 0.0001;
@@ -448,36 +489,32 @@ stat_exit(int alloc)
        fprintf(sf,"\n%11ld Mb total memory in use\n\n", 
                mblocks_allocated * MBLOCK_SIZE / (1024 * 1024));
 
-       MutElapsedTime = etime - GCe_tot_time - InitElapsedTime;
-       if (MutElapsedTime < 0) { MutElapsedTime = 0; } /* sometimes -0.00 */
-
-#ifndef SMP
-       MutTime = time - GC_tot_time - InitUserTime;
-       if (MutTime < 0) { MutTime = 0; }
-
-#else /* SMP */
        /* For SMP, we have to get the user time from each thread
         * and try to work out the total time.
         */
+#ifdef SMP
        {
          nat i;
-         MutTime = 0.0;
+         MutUserTime = 0.0;
          for (i = 0; i < RtsFlags.ConcFlags.nNodes; i++) {
+           MutUserTime += task_ids[i].mut_time;
            fprintf(sf, "  Task %2d:  MUT time: %6.2fs,  GC time: %6.2fs\n", 
                    i, task_ids[i].mut_time, task_ids[i].gc_time);
-           MutTime += task_ids[i].mut_time;
          }
        }
-       time = MutTime + GC_tot_time + InitUserTime;
+       time = MutUserTime + GC_tot_time + InitUserTime + ExitUserTime;
+       if (MutUserTime < 0) { MutUserTime = 0; }
        fprintf(sf,"\n");
 #endif
 
        fprintf(sf, "  INIT  time  %6.2fs  (%6.2fs elapsed)\n",
                InitUserTime, InitElapsedTime);
        fprintf(sf, "  MUT   time  %6.2fs  (%6.2fs elapsed)\n",
-               MutTime, MutElapsedTime);
+               MutUserTime, MutElapsedTime);
        fprintf(sf, "  GC    time  %6.2fs  (%6.2fs elapsed)\n",
                GC_tot_time, GCe_tot_time);
+       fprintf(sf, "  EXIT  time  %6.2fs  (%6.2fs elapsed)\n",
+               ExitUserTime, ExitElapsedTime);
        fprintf(sf, "  Total time  %6.2fs  (%6.2fs elapsed)\n\n",
                time, etime);
 

diff --git a/ghc/rts/Stats.h b/ghc/rts/Stats.h
index ec2f2b8..0bf0886 100644 (file)
--- a/ghc/rts/Stats.h
+++ b/ghc/rts/Stats.h
@@ -1,5 +1,5 @@
 /* -----------------------------------------------------------------------------
- * $Id: Stats.h,v 1.6 1999/09/15 13:45:20 simonmar Exp $
+ * $Id: Stats.h,v 1.7 1999/11/02 17:19:17 simonmar Exp $
  *
  * (c) The GHC Team, 1998-1999
  *
@@ -12,9 +12,14 @@ extern void      start_time(void);
 extern StgDouble usertime(void);
 extern void      end_init(void);
 extern void      stat_exit(int alloc);
+
 extern void      stat_startGC(void);
 extern void      stat_endGC(lnat alloc, lnat collect, lnat live, 
                            lnat copied, lnat gen);
+
+extern void      stat_startExit(void);
+extern void      stat_endExit(void);
+
 extern void      initStats(void);
 extern void      stat_describe_gens(void);
 extern double    mut_user_time_during_GC(void);