Merge pull request #727 from manolama/jvmstats

[core] Add the Utils.getGCTotalTime() method for showing how long

core/src/main/java/com/yahoo/ycsb/Client.java

@@ -30,6 +30,7 @@ import java.util.Enumeration;
 import java.util.HashMap;
 import java.util.List;
 import java.util.Map;
+import java.util.Map.Entry;
 import java.util.Properties;
 import java.util.concurrent.CountDownLatch;
 import java.util.concurrent.TimeUnit;
@@ -76,6 +77,7 @@ class StatusThread extends Thread
   private double _maxLoadAvg;
   private double _minLoadAvg = Double.MAX_VALUE;
   private long lastGCCount = 0;
+  private long lastGCTime = 0;
 
   /**
    * Creates a new StatusThread without JVM stat tracking.
@@ -274,7 +276,10 @@ class StatusThread extends Thread
      
     final long gcs = Utils.getGCTotalCollectionCount();
     _measurements.measure("GCS", (int)(gcs - lastGCCount));
+    final long gcTime = Utils.getGCTotalTime();
+    _measurements.measure("GCS_TIME", (int)(gcTime - lastGCTime));
     lastGCCount = gcs;
+    lastGCTime = gcTime;
   }
   
   /** @return The maximum threads running during the test. */
@@ -692,7 +697,20 @@ public class Client
       double throughput = 1000.0 * (opcount) / (runtime);
       exporter.write("OVERALL", "Throughput(ops/sec)", throughput);
       
-      exporter.write("TOTAL_GCs", "Count", Utils.getGCTotalCollectionCount());
+      final Map<String, Long[]> gcs = Utils.getGCStatst();
+      long totalGCCount = 0;
+      long totalGCTime = 0;
+      for (final Entry<String, Long[]> entry : gcs.entrySet()) {
+        exporter.write("TOTAL_GCS_" + entry.getKey(), "Count", entry.getValue()[0]);
+        exporter.write("TOTAL_GC_TIME_" + entry.getKey(), "Time(ms)", entry.getValue()[1]);
+        exporter.write("TOTAL_GC_TIME_%_" + entry.getKey(), "Time(%)",((double)entry.getValue()[1] / runtime) * (double)100);
+        totalGCCount += entry.getValue()[0];
+        totalGCTime += entry.getValue()[1];
+      }
+      exporter.write("TOTAL_GCs", "Count", totalGCCount);
+      
+      exporter.write("TOTAL_GC_TIME", "Time(ms)", totalGCTime);
+      exporter.write("TOTAL_GC_TIME_%", "Time(%)", ((double)totalGCTime / runtime) * (double)100);
       if (statusthread != null && statusthread.trackJVMStats()) {
         exporter.write("MAX_MEM_USED", "MBs", statusthread.getMaxUsedMem());
         exporter.write("MIN_MEM_USED", "MBs", statusthread.getMinUsedMem());

core/src/main/java/com/yahoo/ycsb/Utils.java

@@ -20,7 +20,9 @@ package com.yahoo.ycsb;
 import java.lang.management.GarbageCollectorMXBean;
 import java.lang.management.ManagementFactory;
 import java.lang.management.OperatingSystemMXBean;
+import java.util.HashMap;
 import java.util.List;
+import java.util.Map;
 import java.util.Random;
 
 /**
@@ -219,8 +221,53 @@ public class Utils
             ManagementFactory.getGarbageCollectorMXBeans();
         long count = 0;
         for (final GarbageCollectorMXBean bean : gcBeans) {
+          if (bean.getCollectionCount() < 0) {
+            continue;
+          }
           count += bean.getCollectionCount();
         }
         return count;
       }
+      
+      /** @return The total time, in milliseconds, spent in GC. */ 
+      public static long getGCTotalTime() {
+        final List<GarbageCollectorMXBean> gcBeans = 
+            ManagementFactory.getGarbageCollectorMXBeans();
+        long time = 0;
+        for (final GarbageCollectorMXBean bean : gcBeans) {
+          if (bean.getCollectionTime() < 0) {
+            continue;
+          }
+          time += bean.getCollectionTime();
+        }
+        return time;
+      }
+
+      /**
+       * Returns a map of garbage collectors and their stats.
+       * The first object in the array is the total count since JVM start and the
+       * second is the total time (ms) since JVM start. 
+       * If a garbage collectors does not support the collector MXBean, then it
+       * will not be represented in the map.
+       * @return A non-null map of garbage collectors and their metrics. The map
+       * may be empty.
+       */ 
+      public static Map<String, Long[]> getGCStatst() {
+        final List<GarbageCollectorMXBean> gcBeans = 
+            ManagementFactory.getGarbageCollectorMXBeans();
+        final Map<String, Long[]> map = new HashMap<String, Long[]>(gcBeans.size());
+        for (final GarbageCollectorMXBean bean : gcBeans) {
+          if (!bean.isValid() || bean.getCollectionCount() < 0 || 
+              bean.getCollectionTime() < 0) {
+            continue;
+          }
+          
+          final Long[] measurements = new Long[] {
+              bean.getCollectionCount(),
+              bean.getCollectionTime()
+          };
+          map.put(bean.getName().replace(" ", "_"), measurements);
+        }
+        return map;
+      }
 }

core/src/test/java/com/yahoo/ycsb/TestUtils.java

@@ -110,8 +110,12 @@ public class TestUtils {
     Utils.getSystemLoadAverage();
     // This will probably be zero but should never be negative.
     assertTrue(Utils.getGCTotalCollectionCount() >= 0);
+    // Could be zero similar to GC total collection count
+    assertTrue(Utils.getGCTotalTime() >= 0);
+    // Could be empty
+    assertTrue(Utils.getGCStatst().size() >= 0);
   }
-  
+   
   /**
    * Since this version of TestNG doesn't appear to have an assertArrayEquals,
    * this will compare the two to make sure they're the same.