[MLton-commit] r6444

spoons at mlton.org spoons at mlton.org
Mon Mar 3 07:29:31 PST 2008


Additional statistics and profiling-tools.

Statistics and tools that I have found useful in debugging the
parallel runtime and in collecting data from my research.

----------------------------------------------------------------------

U   mlton/branches/shared-heap-multicore/runtime/gc/done.c
U   mlton/branches/shared-heap-multicore/runtime/gc/garbage-collection.c
U   mlton/branches/shared-heap-multicore/runtime/gc/profiling.c
U   mlton/branches/shared-heap-multicore/runtime/gc/rusage.c
U   mlton/branches/shared-heap-multicore/runtime/gc/statistics.h
U   mlton/branches/shared-heap-multicore/runtime/gc/world.c

----------------------------------------------------------------------

Modified: mlton/branches/shared-heap-multicore/runtime/gc/done.c
===================================================================
--- mlton/branches/shared-heap-multicore/runtime/gc/done.c	2008-03-03 15:29:00 UTC (rev 6443)
+++ mlton/branches/shared-heap-multicore/runtime/gc/done.c	2008-03-03 15:29:30 UTC (rev 6444)
@@ -38,15 +38,24 @@
 
 void GC_done (GC_state s) {
   FILE *out;
-
-  enter (s);
+  
+  s->syncReason = SYNC_FORCE;
+  ENTER0 (s);
   minorGC (s);
   out = stderr;
-  if (s->controls.summary) {
+  if (s->controls->summary) {
     uintmax_t totalTime;
     uintmax_t gcTime;
+    uintmax_t syncTime;
+    //uintmax_t threadTime;
+    uintmax_t rtTime;
+    //uintmax_t lockTime;
 
-    gcTime = rusageTime (&s->cumulativeStatistics.ru_gc);
+    gcTime = timevalTime (&s->cumulativeStatistics->tv_gc);
+    syncTime = timevalTime (&s->cumulativeStatistics->tv_sync);
+    //threadTime = rusageTime (&s->cumulativeStatistics->ru_thread);
+    rtTime = timevalTime (&s->cumulativeStatistics->tv_rt);
+    /* lockTime = rusageTime (&s->cumulativeStatistics->ru_lock); */
     fprintf (out, "GC type\t\ttime ms\t number\t\t  bytes\t      bytes/sec\n");
     fprintf (out, "-------------\t-------\t-------\t---------------\t---------------\n");
     displayCollectionStats
@@ -72,21 +81,58 @@
              (0 == totalTime) 
              ? 0.0 
              : 100.0 * ((double) gcTime) / (double)totalTime);
+    fprintf (out, "total sync time: %s ms (%.1f%%)\n",
+             uintmaxToCommaString (syncTime), 
+             (0 == totalTime) 
+             ? 0.0 
+             : 100.0 * ((double) syncTime) / (double)totalTime);
+    /*
+    fprintf (out, "total thread time: %s ms (%.1f%%)\n",
+             uintmaxToCommaString (threadTime), 
+             (0 == totalTime) 
+             ? 0.0 
+             : 100.0 * ((double) threadTime) / (double)totalTime);
+    */
+    fprintf (out, "total rt time: %s ms (%.1f%%)\n",
+             uintmaxToCommaString (rtTime), 
+             (0 == totalTime) 
+             ? 0.0 
+             : 100.0 * ((double) rtTime) / (double)totalTime);
+    /* 
+    fprintf (out, "total lock time: %s ms (%.1f%%)\n",
+             uintmaxToCommaString (lockTime), 
+             (0 == totalTime) 
+             ? 0.0 
+             : 100.0 * ((double) lockTime) / (double)totalTime);
+    */
     fprintf (out, "max pause: %s ms\n",
-             uintmaxToCommaString (s->cumulativeStatistics.maxPause));
+             uintmaxToCommaString (s->cumulativeStatistics->maxPause));
     fprintf (out, "total allocated: %s bytes\n",
-             uintmaxToCommaString (s->cumulativeStatistics.bytesAllocated));
+             uintmaxToCommaString (s->cumulativeStatistics->bytesAllocated));
+    fprintf (out, "total filled: %s bytes\n",
+             uintmaxToCommaString (s->cumulativeStatistics->bytesFilled));
     fprintf (out, "max live: %s bytes\n",
-             uintmaxToCommaString (s->cumulativeStatistics.maxBytesLive));
+             uintmaxToCommaString (s->cumulativeStatistics->maxBytesLive));
     fprintf (out, "max semispace: %s bytes\n", 
-             uintmaxToCommaString (s->cumulativeStatistics.maxHeapSizeSeen));
+             uintmaxToCommaString (s->cumulativeStatistics->maxHeapSizeSeen));
     fprintf (out, "max stack size: %s bytes\n", 
-             uintmaxToCommaString (s->cumulativeStatistics.maxStackSizeSeen));
+             uintmaxToCommaString (s->cumulativeStatistics->maxStackSizeSeen));
     fprintf (out, "marked cards: %s\n", 
-             uintmaxToCommaString (s->cumulativeStatistics.markedCards));
+             uintmaxToCommaString (s->cumulativeStatistics->markedCards));
     fprintf (out, "minor scanned: %s bytes\n",
-             uintmaxToCommaString (s->cumulativeStatistics.minorBytesScanned));
+             uintmaxToCommaString (s->cumulativeStatistics->minorBytesScanned));
+
+    fprintf (out, "sync for old gen array: %s\n",
+             uintmaxToCommaString (s->cumulativeStatistics->syncForOldGenArray));
+    fprintf (out, "sync for new gen array: %s\n",
+             uintmaxToCommaString (s->cumulativeStatistics->syncForNewGenArray));
+    fprintf (out, "sync for stack: %s\n",
+             uintmaxToCommaString (s->cumulativeStatistics->syncForStack));
+    fprintf (out, "sync for heap: %s\n",
+             uintmaxToCommaString (s->cumulativeStatistics->syncForHeap));
+    fprintf (out, "sync misc: %s\n",
+             uintmaxToCommaString (s->cumulativeStatistics->syncMisc));
   }
-  releaseHeap (s, &s->heap);
-  releaseHeap (s, &s->secondaryHeap);
+  releaseHeap (s, s->heap);
+  releaseHeap (s, s->secondaryHeap);
 }

Modified: mlton/branches/shared-heap-multicore/runtime/gc/garbage-collection.c
===================================================================
--- mlton/branches/shared-heap-multicore/runtime/gc/garbage-collection.c	2008-03-03 15:29:00 UTC (rev 6443)
+++ mlton/branches/shared-heap-multicore/runtime/gc/garbage-collection.c	2008-03-03 15:29:30 UTC (rev 6444)
@@ -33,9 +33,11 @@
   else
     majorMarkCompactGC (s);
   s->hashConsDuringGC = FALSE;
-  s->lastMajorStatistics.bytesLive = s->heap.oldGenSize;
-  if (s->lastMajorStatistics.bytesLive > s->cumulativeStatistics.maxBytesLive)
-    s->cumulativeStatistics.maxBytesLive = s->lastMajorStatistics.bytesLive;
+  s->lastMajorStatistics->bytesLive = s->heap->oldGenSize;
+  if (s->lastMajorStatistics->bytesLive > s->cumulativeStatistics->maxBytesLive)
+    s->cumulativeStatistics->maxBytesLive = s->lastMajorStatistics->bytesLive;
+  if (s->lastMajorStatistics->bytesLive > s->cumulativeStatistics->maxBytesLiveSinceReset)
+    s->cumulativeStatistics->maxBytesLiveSinceReset = s->lastMajorStatistics->bytesLive;
   /* Notice that the s->bytesLive below is different than the
    * s->bytesLive used as an argument to createHeapSecondary above.
    * Above, it was an estimate.  Here, it is exactly how much was live
@@ -94,7 +96,7 @@
   uintmax_t gcTime;
   bool stackTopOk;
   size_t stackBytesRequested;
-  struct rusage ru_start;
+  struct timeval tv_start;
   size_t totalBytesRequested;
 
   enterGC (s);
@@ -104,7 +106,7 @@
              uintmaxToCommaString(oldGenBytesRequested));
   assert (invariantForGC (s));
   if (needGCTime (s))
-    startTiming (&ru_start);
+    startWallTiming (&tv_start);
   minorGC (s);
   stackTopOk = invariantForMutatorStack (s);
   stackBytesRequested = 
@@ -135,20 +137,24 @@
   assert (hasHeapBytesFree (s, oldGenBytesRequested + stackBytesRequested,
                             nurseryBytesRequested));
   unless (stackTopOk)
-    growStackCurrent (s);
-  setGCStateCurrentThreadAndStack (s);
+    growStackCurrent (s, TRUE);
+  for (int proc = 0; proc < s->numberOfProcs; proc++) {
+    /* DOC XXX must come first to setup maps properly */
+    s->procStates[proc].generationalMaps = s->generationalMaps;
+    setGCStateCurrentThreadAndStack (&s->procStates[proc]);
+  }
   if (needGCTime (s)) {
-    gcTime = stopTiming (&ru_start, &s->cumulativeStatistics.ru_gc);
-    s->cumulativeStatistics.maxPause = 
-      max (s->cumulativeStatistics.maxPause, gcTime);
+    gcTime = stopWallTiming (&tv_start, &s->cumulativeStatistics->tv_gc);
+    s->cumulativeStatistics->maxPause = 
+      max (s->cumulativeStatistics->maxPause, gcTime);
   } else
     gcTime = 0;  /* Assign gcTime to quell gcc warning. */
-  if (DEBUG or s->controls.messages) {
+  if (DEBUG or s->controls->messages) {
     fprintf (stderr, "[GC: Finished gc; time: %s ms, old-gen: %s bytes (%.1f%%).]\n",
              uintmaxToCommaString(gcTime),
-             uintmaxToCommaString(s->heap.oldGenSize),
-             100.0 * ((double)(s->heap.oldGenSize) 
-                      / (double)(s->heap.size)));
+             uintmaxToCommaString(s->heap->oldGenSize),
+             100.0 * ((double)(s->heap->oldGenSize) 
+                      / (double)(s->heap->availableSize)));
   }
   /* Send a GC signal. */
   if (s->signalsInfo.gcSignalHandled

Modified: mlton/branches/shared-heap-multicore/runtime/gc/profiling.c
===================================================================
--- mlton/branches/shared-heap-multicore/runtime/gc/profiling.c	2008-03-03 15:29:00 UTC (rev 6443)
+++ mlton/branches/shared-heap-multicore/runtime/gc/profiling.c	2008-03-03 15:29:30 UTC (rev 6444)
@@ -359,25 +359,39 @@
     sourceSeqsIndex = SOURCE_SEQ_GC;
   else {
     frameIndex = getCachedStackTopFrameIndex (s);
-    if (C_FRAME == s->frameLayouts[frameIndex].kind)
-      sourceSeqsIndex = s->sourceMaps.frameSources[frameIndex];
-    else {
-      if (PROFILE_TIME_LABEL == s->profiling.kind) {
-      if (s->sourceMaps.textStart <= pc and pc < s->sourceMaps.textEnd)
-        sourceSeqsIndex = s->sourceMaps.textSources [pc - s->sourceMaps.textStart];
+    if (frameIndex < s->frameLayoutsLength) {
+      if (C_FRAME == s->frameLayouts[frameIndex].kind)
+        sourceSeqsIndex = s->sourceMaps.frameSources[frameIndex];
       else {
-        if (DEBUG_PROFILE)
-          fprintf (stderr, "pc out of bounds\n");
-        sourceSeqsIndex = SOURCE_SEQ_UNKNOWN;
+        if (PROFILE_TIME_LABEL == s->profiling.kind) {
+          if (s->sourceMaps.textStart <= pc and pc < s->sourceMaps.textEnd)
+            sourceSeqsIndex = s->sourceMaps.textSources [pc - s->sourceMaps.textStart];
+          else {
+            if (DEBUG_PROFILE)
+              fprintf (stderr, "pc out of bounds\n");
+            sourceSeqsIndex = SOURCE_SEQ_UNKNOWN;
+          }
+        } else {
+          sourceSeqsIndex = s->sourceMaps.curSourceSeqsIndex;
+        }
       }
-      } else {
-        sourceSeqsIndex = s->sourceMaps.curSourceSeqsIndex;
-      }
     }
+    else {
+      if (DEBUG_PROFILE)
+        fprintf (stderr, "unknown frame index\n");
+      sourceSeqsIndex = SOURCE_SEQ_UNKNOWN;
+    }
   }
   incForProfiling (s, 1, sourceSeqsIndex);
 }
 
+void GC_profileDisable (void) {
+  setProfTimer (0);
+}
+void GC_profileEnable (void) {
+  setProfTimer (10000);
+}
+
 static void initProfilingTime (GC_state s) {
   struct sigaction sa;
 

Modified: mlton/branches/shared-heap-multicore/runtime/gc/rusage.c
===================================================================
--- mlton/branches/shared-heap-multicore/runtime/gc/rusage.c	2008-03-03 15:29:00 UTC (rev 6443)
+++ mlton/branches/shared-heap-multicore/runtime/gc/rusage.c	2008-03-03 15:29:30 UTC (rev 6444)
@@ -16,7 +16,7 @@
   const int       million = 1000000;
   time_t          sec,
                   usec;
-
+  /* FIXME could be refactored to use timevalPlusMax */
   sec = ru1->ru_utime.tv_sec + ru2->ru_utime.tv_sec;
   usec = ru1->ru_utime.tv_usec + ru2->ru_utime.tv_usec;
   sec += (usec / million);
@@ -38,7 +38,7 @@
   const int       million = 1000000;
   time_t          sec,
                   usec;
-
+  /* FIXME could be refactored to use timevalMinusMax */
   sec = (ru1->ru_utime.tv_sec - ru2->ru_utime.tv_sec) - 1;
   usec = ru1->ru_utime.tv_usec + million - ru2->ru_utime.tv_usec;
   sec += (usec / million);
@@ -67,10 +67,10 @@
 
 /* Return time as number of milliseconds. */
 uintmax_t getCurrentTime (void) {
-  struct rusage ru;
+  struct timeval tv;
 
-  getrusage (RUSAGE_SELF, &ru);
-  return rusageTime (&ru);
+  gettimeofday (&tv, (struct timezone *) NULL);
+  return timevalTime (&tv);
 }
 
 void startTiming (struct rusage *ru_start) {
@@ -85,3 +85,60 @@
   rusagePlusMax (ru_acc, &ru_total, ru_acc);
   return rusageTime (&ru_total);
 }
+
+
+void timevalZero (struct timeval *tv) {
+  memset (tv, 0, sizeof (*tv));
+}
+
+void timevalPlusMax (struct timeval *tv1,
+                     struct timeval *tv2,
+                     struct timeval *tv) {
+  const int       million = 1000000;
+  time_t          sec,
+                  usec;
+
+  sec = tv1->tv_sec + tv2->tv_sec;
+  usec = tv1->tv_usec + tv2->tv_usec;
+  sec += (usec / million);
+  usec %= million;
+  tv->tv_sec = sec;
+  tv->tv_usec = usec;
+}
+
+void timevalMinusMax (struct timeval *tv1,
+                      struct timeval *tv2,
+                      struct timeval *tv) {
+  const int       million = 1000000;
+  time_t          sec,
+                  usec;
+
+  sec = (tv1->tv_sec - tv2->tv_sec) - 1;
+  usec = tv1->tv_usec + million - tv2->tv_usec;
+  sec += (usec / million);
+  usec %= million;
+  tv->tv_sec = sec;
+  tv->tv_usec = usec;
+}
+
+uintmax_t timevalTime (struct timeval *tv) {
+  uintmax_t result;
+
+  result = 0;
+  result += 1000 * tv->tv_sec;
+  result += tv->tv_usec / 1000;
+  return result;
+}
+
+void startWallTiming (struct timeval *tv_start) {
+  gettimeofday (tv_start, (struct timezone *) NULL);
+}
+
+uintmax_t stopWallTiming (struct timeval *tv_start, struct timeval *tv_acc) {
+  struct timeval tv_finish, tv_total;
+
+  gettimeofday (&tv_finish, (struct timezone *) NULL);
+  timevalMinusMax (&tv_finish, tv_start, &tv_total);
+  timevalPlusMax (tv_acc, &tv_total, tv_acc);
+  return timevalTime (&tv_total);
+}

Modified: mlton/branches/shared-heap-multicore/runtime/gc/statistics.h
===================================================================
--- mlton/branches/shared-heap-multicore/runtime/gc/statistics.h	2008-03-03 15:29:00 UTC (rev 6443)
+++ mlton/branches/shared-heap-multicore/runtime/gc/statistics.h	2008-03-03 15:29:30 UTC (rev 6444)
@@ -8,8 +8,20 @@
 
 #if (defined (MLTON_GC_INTERNAL_TYPES))
 
+enum {
+  SYNC_NONE = 0,
+  SYNC_OLD_GEN_ARRAY,
+  SYNC_NEW_GEN_ARRAY,
+  SYNC_STACK,
+  SYNC_HEAP,
+  SYNC_FORCE,
+  SYNC_PACK,
+  SYNC_SAVE_WORLD,
+};
+
 struct GC_cumulativeStatistics {
   uintmax_t bytesAllocated;
+  uintmax_t bytesFilled; /* i.e. unused gaps */
   uintmax_t bytesCopied;
   uintmax_t bytesCopiedMinor;
   uintmax_t bytesMarkCompacted;
@@ -17,6 +29,7 @@
   uintmax_t markedCards; /* Number of marked cards seen during minor GCs. */
 
   size_t maxBytesLive;
+  size_t maxBytesLiveSinceReset;
   size_t maxHeapSizeSeen;
   size_t maxStackSizeSeen;
 
@@ -24,16 +37,27 @@
 
   uintmax_t numLimitChecks;
 
+  uintmax_t syncForOldGenArray;
+  uintmax_t syncForNewGenArray;
+  uintmax_t syncForStack;
+  uintmax_t syncForHeap;
+  uintmax_t syncMisc;
+
   uintmax_t numCopyingGCs;
   uintmax_t numHashConsGCs;
   uintmax_t numMarkCompactGCs;
   uintmax_t numMinorGCs;
 
   uintmax_t maxPause;
-  struct rusage ru_gc; /* total resource usage spent in gc */
+  struct timeval tv_gc; /* time spent in gc */
   struct rusage ru_gcCopy; /* resource usage in major copying gcs. */
   struct rusage ru_gcMarkCompact; /* resource usage in mark-compact gcs. */
   struct rusage ru_gcMinor; /* resource usage in minor gcs. */
+  struct rusage ru_thread; /* total resource for thread operations */
+
+  /* use wall clock instead of rusage */
+  struct timeval tv_rt; /* total time "inside" runtime (not incl. synch.) */
+  struct timeval tv_sync; /* time waiting to synchronize in runtime */
 };
 
 struct GC_lastMajorStatistics {

Modified: mlton/branches/shared-heap-multicore/runtime/gc/world.c
===================================================================
--- mlton/branches/shared-heap-multicore/runtime/gc/world.c	2008-03-03 15:29:00 UTC (rev 6443)
+++ mlton/branches/shared-heap-multicore/runtime/gc/world.c	2008-03-03 15:29:30 UTC (rev 6444)
@@ -88,8 +88,9 @@
 
 void GC_saveWorld (GC_state s, NullString8_t fileName) {
   FILE *f;
-
-  enter (s);
+  s->syncReason = SYNC_SAVE_WORLD;
+  /* XXX is fileName heap allocated? */
+  ENTER0 (s);
   f = fopen ((const char*)fileName, "wb");
   if (f == 0) {
     s->saveWorldStatus = false;
@@ -106,7 +107,7 @@
 
   s->saveWorldStatus = true;
 done:
-  leave (s);
+  LEAVE0 (s);
   return;
 }
 




More information about the MLton-commit mailing list