[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