GC overhead calculation and reporting on performance/scalability tests

h2/src/main/org/h2/mvstore/DataUtils.java

@@ -22,7 +22,7 @@ import org.h2.util.New;
 /**
  * Utility methods
  */
-public class DataUtils {
+public final class DataUtils {
 
     /**
      * An error occurred while reading from the file.
@@ -758,8 +758,8 @@ public class DataUtils {
         int size = arguments.length;
         if (size > 0) {
             Object o = arguments[size - 1];
-            if (o instanceof Exception) {
-                e.initCause((Exception) o);
+            if (o instanceof Throwable) {
+                e.initCause((Throwable) o);
             }
         }
         return e;
@@ -776,6 +776,7 @@ public class DataUtils {
     public static String formatMessage(int errorCode, String message,
             Object... arguments) {
         // convert arguments to strings, to avoid locale specific formatting
+        arguments = arguments.clone();
         for (int i = 0; i < arguments.length; i++) {
             Object a = arguments[i];
             if (!(a instanceof Exception)) {
@@ -936,10 +937,10 @@ public class DataUtils {
      * @param <K> the key type
      * @param <V> the value type
      */
-    public static class MapEntry<K, V> implements Map.Entry<K, V> {
+    public static final class MapEntry<K, V> implements Map.Entry<K, V> {
 
         private final K key;
-        private V value;
+        private final V value;
 
         public MapEntry(K key, V value) {
             this.key = key;

h2/src/main/org/h2/util/Utils.java

@@ -8,6 +8,7 @@ package org.h2.util;
 import java.io.ByteArrayOutputStream;
 import java.io.IOException;
 import java.io.InputStream;
+import java.lang.management.GarbageCollectorMXBean;
 import java.lang.management.ManagementFactory;
 import java.lang.management.OperatingSystemMXBean;
 import java.lang.reflect.Constructor;
@@ -314,6 +315,17 @@ public class Utils {
         return max / 1024;
     }
 
+    public static long getGarbageCollectionTime() {
+        long totalGCTime = 0;
+        for (GarbageCollectorMXBean gcMXBean : ManagementFactory.getGarbageCollectorMXBeans()) {
+            long collectionTime = gcMXBean.getCollectionTime();
+            if(collectionTime > 0) {
+                totalGCTime += collectionTime;
+            }
+        }
+        return totalGCTime;
+    }
+
     private static synchronized void collectGarbage() {
         Runtime runtime = Runtime.getRuntime();
         long total = runtime.totalMemory();

h2/src/test/org/h2/test/bench/Database.java

@@ -23,6 +23,7 @@ import java.util.concurrent.atomic.AtomicInteger;
 import org.h2.test.TestBase;
 import org.h2.tools.Server;
 import org.h2.util.StringUtils;
+import org.h2.util.Utils;
 
 /**
  * Represents a database in the benchmark test application.
@@ -37,12 +38,14 @@ class Database {
     private final ArrayList<String[]> replace = new ArrayList<>();
     private String currentAction;
     private long startTimeNs;
+    private long initialGCTime;
     private Connection conn;
     private Statement stat;
     private long lastTrace;
     private final Random random = new Random(1);
     private final ArrayList<Object[]> results = new ArrayList<>();
     private int totalTime;
+    private int totalGCTime;
     private final AtomicInteger executedStatements = new AtomicInteger(0);
     private int threadCount;
 
@@ -68,6 +71,15 @@ class Database {
         return totalTime;
     }
 
+    /**
+     * Get the total measured GC time.
+     *
+     * @return the time in milliseconds
+     */
+    int getTotalGCTime() {
+        return totalGCTime;
+    }
+
     /**
      * Get the result array.
      *
@@ -272,6 +284,7 @@ class Database {
     void start(Bench bench, String action) {
         this.currentAction = bench.getName() + ": " + action;
         this.startTimeNs = System.nanoTime();
+        this.initialGCTime = Utils.getGarbageCollectionTime();
     }
 
     /**
@@ -280,9 +293,11 @@ class Database {
      */
     void end() {
         long time = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - startTimeNs);
+        long gcCollectionTime = Utils.getGarbageCollectionTime() - initialGCTime;
         log(currentAction, "ms", (int) time);
         if (test.isCollect()) {
             totalTime += time;
+            totalGCTime += gcCollectionTime;
         }
     }
 

h2/src/test/org/h2/test/bench/TestPerformance.java

@@ -149,17 +149,17 @@ public class TestPerformance implements Database.DatabaseTest {
             writer = new PrintWriter(new FileWriter(out));
             ResultSet rs = stat.executeQuery(
                     "CALL '<table><tr><th>Test Case</th><th>Unit</th>' " +
-                    "|| SELECT GROUP_CONCAT('<th>' || DB || '</th>' " +
+                    "|| (SELECT GROUP_CONCAT('<th>' || DB || '</th>' " +
                     "ORDER BY DBID SEPARATOR '') FROM " +
-                    "(SELECT DISTINCT DBID, DB FROM RESULTS)" +
+                    "(SELECT DISTINCT DBID, DB FROM RESULTS))" +
                     "|| '</tr>' || CHAR(10) " +
-                    "|| SELECT GROUP_CONCAT('<tr><td>' || TEST || " +
+                    "|| (SELECT GROUP_CONCAT('<tr><td>' || TEST || " +
                     "'</td><td>' || UNIT || '</td>' || ( " +
                     "SELECT GROUP_CONCAT('<td>' || RESULT || '</td>' " +
                     "ORDER BY DBID SEPARATOR '') FROM RESULTS R2 WHERE " +
                     "R2.TESTID = R1.TESTID) || '</tr>' " +
                     "ORDER BY TESTID SEPARATOR CHAR(10)) FROM " +
-                    "(SELECT DISTINCT TESTID, TEST, UNIT FROM RESULTS) R1" +
+                    "(SELECT DISTINCT TESTID, TEST, UNIT FROM RESULTS) R1)" +
                     "|| '</table>'"
             );
             rs.next();
@@ -243,6 +243,7 @@ public class TestPerformance implements Database.DatabaseTest {
             int statPerSec = (int) (db.getExecutedStatements() * 1000L / db.getTotalTime());
             db.log("Statements per second", "#", statPerSec);
             System.out.println("Statements per second: " + statPerSec);
+            System.out.println("GC overhead: " + (100 * db.getTotalGCTime() / db.getTotalTime()) + "%");
             collect = false;
             db.stopServer();
         }

h2/src/test/org/h2/test/bench/TestScalability.java

@@ -193,6 +193,7 @@ public class TestScalability implements Database.DatabaseTest {
                     1000L / db.getTotalTime());
             db.log("Statements per second", "#", statPerSec);
             System.out.println("Statements per second: " + statPerSec);
+            System.out.println("GC overhead: " + (100 * db.getTotalGCTime() / db.getTotalTime()) + "%");
             collect = false;
             db.stopServer();
         }