Merge pull request #1085 from rainers/gc_summary

add some useful metrics to GC summary
dlang · Jan 6, 2015 · f1758f4 · f1758f4
2 parents e011440 + 086f838
commit f1758f4
Show file tree

Hide file tree

Showing 2 changed files with 14 additions and 7 deletions.
diff --git a/benchmark/runbench.d b/benchmark/runbench.d
@@ -85,13 +85,13 @@ void runTests(Config cfg)
                 rename("gcx.log", tgt);
                 auto lines = File(tgt, "r").byLine()
                     .find!(ln => ln.canFind("maxPoolMemory"));
-                if (!lines.empty) gcprof = lines.front.find("maxPoolMemory").idup;
+                if (!lines.empty) gcprof = lines.front.find("GC summary:")[11..$].idup;
             }
             else
             {
                 auto lines = output.splitter(ctRegex!`\r\n|\r|\n`)
-                    .find!(ln => ln.startsWith("maxPoolMemory"));
-                if (!lines.empty) gcprof = lines.front;
+                    .find!(ln => ln.startsWith("GC summary:"));
+                if (!lines.empty) gcprof = lines.front[11..$];
             }
         }
         auto res = minDur.split!("seconds", "msecs");

diff --git a/src/gc/gc.d b/src/gc/gc.d
@@ -107,6 +107,7 @@ __gshared Duration prepTime;
 __gshared Duration markTime;
 __gshared Duration sweepTime;
 __gshared Duration recoverTime;
+__gshared Duration maxPauseTime;
 __gshared size_t numCollections;
 __gshared size_t maxPoolMemory;
 
@@ -1464,11 +1465,14 @@ struct Gcx
                    sweepTime.total!("msecs"));
             printf("\tTotal page recovery time:  %lld milliseconds\n",
                    recoverTime.total!("msecs"));
+            long maxPause = maxPauseTime.total!("msecs");
+            printf("\tMax Pause Time:  %lld milliseconds\n", maxPause);
             long gcTime = (recoverTime + sweepTime + markTime + prepTime).total!("msecs");
             printf("\tGrand total GC time:  %lld milliseconds\n", gcTime);
             long pauseTime = (markTime + prepTime).total!("msecs");
-            printf("maxPoolMemory = %lld MB, pause time = %lld ms\n",
-                   cast(long) maxPoolMemory >> 20, pauseTime);
+            printf("GC summary:%5lld MB,%5lld GC%5lld ms, Pauses%5lld ms <%5lld ms\n",
+                   cast(long) maxPoolMemory >> 20, cast(ulong)numCollections, gcTime,
+                   pauseTime, maxPause);
         }
 
         debug(CACHE_HITRATE)
@@ -2477,11 +2481,11 @@ struct Gcx
     {
         size_t n;
         Pool*  pool;
-        MonoTime start, stop;
+        MonoTime start, stop, begin;
 
         if (GC.config.profile)
         {
-            start = currTime;
+            begin = start = currTime;
         }
 
         debug(COLLECT_PRINTF) printf("Gcx.fullcollect()\n");
@@ -2626,6 +2630,9 @@ struct Gcx
         {
             stop = currTime;
             markTime += (stop - start);
+            Duration pause = stop - begin;
+            if (pause > maxPauseTime)
+                maxPauseTime = pause;
             start = stop;
         }