Use System.nanoTime for measuring query statistics

(a) on modern platforms, it's way faster to call this
(b) its more accurate
(c) on my SSD, queries are fast enough the System.currentTimeMillis does
not provide a decent measurement

h2/src/docsrc/html/changelog.html

@@ -21,6 +21,8 @@ Change Log
 
 <h2>Next Version (unreleased)</h2>
 <ul>
+<li>Use System.nanoTime for measuring query statistics
+</li>
 <li>Issue #324: Deadlock when sending BLOBs over TCP
 </li>
 <li>Fix for creating and accessing views in MULTITHREADED mode, test-case courtesy of Daniel Rosenbaum

h2/src/main/org/h2/command/Command.java

@@ -30,7 +30,7 @@ public abstract class Command implements CommandInterface {
     /**
      * The last start time.
      */
-    protected long startTime;
+    protected long startTime_nanos;
 
     /**
      * The trace module.
@@ -127,7 +127,7 @@ public abstract class Command implements CommandInterface {
      */
     void start() {
         if (trace.isInfoEnabled() || session.getDatabase().getQueryStatistics()) {
-            startTime = System.currentTimeMillis();
+            startTime_nanos = System.nanoTime();
         }
     }
 
@@ -162,10 +162,10 @@ public abstract class Command implements CommandInterface {
                 }
             }
         }
-        if (trace.isInfoEnabled() && startTime > 0) {
-            long time = System.currentTimeMillis() - startTime;
-            if (time > Constants.SLOW_QUERY_LIMIT_MS) {
-                trace.info("slow query: {0} ms", time);
+        if (trace.isInfoEnabled() && startTime_nanos > 0) {
+            long time_ms = (System.nanoTime() - startTime_nanos) / 1000 / 1000;
+            if (time_ms > Constants.SLOW_QUERY_LIMIT_MS) {
+                trace.info("slow query: {0} ms", time_ms);
             }
         }
     }
@@ -180,7 +180,7 @@ public abstract class Command implements CommandInterface {
      */
     @Override
     public ResultInterface executeQuery(int maxrows, boolean scrollable) {
-        startTime = 0;
+        startTime_nanos = 0;
         long start = 0;
         Database database = session.getDatabase();
         Object sync = database.isMultiThreaded() ? (Object) session : (Object) database;

h2/src/main/org/h2/command/CommandContainer.java

@@ -96,7 +96,7 @@ public class CommandContainer extends Command {
         session.setLastScopeIdentity(ValueNull.INSTANCE);
         prepared.checkParameters();
         int updateCount = prepared.update();
-        prepared.trace(startTime, updateCount);
+        prepared.trace(startTime_nanos, updateCount);
         setProgress(DatabaseEventListener.STATE_STATEMENT_END);
         return updateCount;
     }
@@ -108,7 +108,7 @@ public class CommandContainer extends Command {
         start();
         prepared.checkParameters();
         ResultInterface result = prepared.query(maxrows);
-        prepared.trace(startTime, result.getRowCount());
+        prepared.trace(startTime_nanos, result.getRowCount());
         setProgress(DatabaseEventListener.STATE_STATEMENT_END);
         return result;
     }

h2/src/main/org/h2/command/Prepared.java

@@ -302,19 +302,19 @@ public abstract class Prepared {
      * Print information about the statement executed if info trace level is
      * enabled.
      *
-     * @param startTime when the statement was started
+     * @param startTime_nanos when the statement was started
      * @param rowCount the query or update row count
      */
-    void trace(long startTime, int rowCount) {
-        if (session.getTrace().isInfoEnabled() && startTime > 0) {
-            long deltaTime = System.currentTimeMillis() - startTime;
+    void trace(long startTime_nanos, int rowCount) {
+        if (session.getTrace().isInfoEnabled() && startTime_nanos > 0) {
+            long deltaTime_nanos = System.nanoTime() - startTime_nanos;
             String params = Trace.formatParams(parameters);
-            session.getTrace().infoSQL(sqlStatement, params, rowCount, deltaTime);
+            session.getTrace().infoSQL(sqlStatement, params, rowCount, deltaTime_nanos / 1000 / 1000);
         }
         if (session.getDatabase().getQueryStatistics()) {
-            long deltaTime = System.currentTimeMillis() - startTime;
+            long deltaTime_nanos = System.nanoTime() - startTime_nanos;
             session.getDatabase().getQueryStatisticsData().
-                    update(toString(), deltaTime, rowCount);
+                    update(toString(), deltaTime_nanos, rowCount);
         }
     }
 

h2/src/main/org/h2/engine/QueryStatisticsData.java

@@ -54,11 +54,11 @@ public class QueryStatisticsData {
      * Update query statistics.
      *
      * @param sqlStatement the statement being executed
-     * @param executionTime the time in milliseconds the query/update took to
+     * @param executionTime_nanos the time in nanoseconds the query/update took to
      *            execute
      * @param rowCount the query or update row count
      */
-    public synchronized void update(String sqlStatement, long executionTime,
+    public synchronized void update(String sqlStatement, long executionTime_nanos,
             int rowCount) {
         QueryEntry entry = map.get(sqlStatement);
         if (entry == null) {
@@ -66,7 +66,7 @@ public class QueryStatisticsData {
             entry.sqlStatement = sqlStatement;
             map.put(sqlStatement, entry);
         }
-        entry.update(executionTime, rowCount);
+        entry.update(executionTime_nanos, rowCount);
 
         // Age-out the oldest entries if the map gets too big.
         // Test against 1.5 x max-size so we don't do this too often
@@ -112,19 +112,19 @@ public class QueryStatisticsData {
         public long lastUpdateTime;
 
         /**
-         * The minimum execution time, in milliseconds.
+         * The minimum execution time, in nanoseconds.
          */
-        public long executionTimeMin;
+        public long executionTimeMin_nanos;
 
         /**
-         * The maximum execution time, in milliseconds.
+         * The maximum execution time, in nanoseconds.
          */
-        public long executionTimeMax;
+        public long executionTimeMax_nanos;
 
         /**
          * The total execution time.
          */
-        public long executionTimeCumulative;
+        public long executionTimeCumulative_nanos;
 
         /**
          * The minimum number of rows.
@@ -144,7 +144,7 @@ public class QueryStatisticsData {
         /**
          * The mean execution time.
          */
-        public double executionTimeMean;
+        public double executionTimeMean_nanos;
 
         /**
          * The mean number of rows.
@@ -155,39 +155,38 @@ public class QueryStatisticsData {
         // http://en.wikipedia.org/wiki/Algorithms_for_calculating_variance
         // http://www.johndcook.com/standard_deviation.html
 
-        private double executionTimeM2;
+        private double executionTimeM2_nanos;
         private double rowCountM2;
 
         /**
          * Update the statistics entry.
          *
-         * @param time the execution time
+         * @param time_nanos the execution time in nanos
          * @param rows the number of rows
          */
-        void update(long time, int rows) {
+        void update(long time_nanos, int rows) {
             count++;
-            executionTimeMin = Math.min(time, executionTimeMin);
-            executionTimeMax = Math.max(time, executionTimeMax);
+            executionTimeMin_nanos = Math.min(time_nanos, executionTimeMin_nanos);
+            executionTimeMax_nanos = Math.max(time_nanos, executionTimeMax_nanos);
             rowCountMin = Math.min(rows, rowCountMin);
             rowCountMax = Math.max(rows, rowCountMax);
 
-            double delta = rows - rowCountMean;
-            rowCountMean += delta / count;
-            rowCountM2 += delta * (rows - rowCountMean);
+            double rowDelta = rows - rowCountMean;
+            rowCountMean += rowDelta / count;
+            rowCountM2 += rowDelta * (rows - rowCountMean);
 
-            delta = time - executionTimeMean;
-            executionTimeMean += delta / count;
-            executionTimeM2 += delta * (time - executionTimeMean);
+            double timeDelta = time_nanos - executionTimeMean_nanos;
+            executionTimeMean_nanos += timeDelta / count;
+            executionTimeM2_nanos += timeDelta * (time_nanos - executionTimeMean_nanos);
 
-            executionTimeCumulative += time;
+            executionTimeCumulative_nanos += time_nanos;
             rowCountCumulative += rows;
             lastUpdateTime = System.currentTimeMillis();
-
         }
 
         public double getExecutionTimeStandardDeviation() {
             // population standard deviation
-            return Math.sqrt(executionTimeM2 / count);
+            return Math.sqrt(executionTimeM2_nanos / count);
         }
 
         public double getRowCountStandardDeviation() {

h2/src/main/org/h2/table/MetaTable.java

@@ -524,9 +524,9 @@ public class MetaTable extends Table {
             cols = createColumns(
                     "SQL_STATEMENT",
                     "EXECUTION_COUNT INT",
-                    "MIN_EXECUTION_TIME LONG",
-                    "MAX_EXECUTION_TIME LONG",
-                    "CUMULATIVE_EXECUTION_TIME LONG",
+                    "MIN_EXECUTION_TIME DOUBLE",
+                    "MAX_EXECUTION_TIME DOUBLE",
+                    "CUMULATIVE_EXECUTION_TIME DOUBLE",
                     "AVERAGE_EXECUTION_TIME DOUBLE",
                     "STD_DEV_EXECUTION_TIME DOUBLE",
                     "MIN_ROW_COUNT INT",
@@ -1834,15 +1834,15 @@ public class MetaTable extends Table {
                             // EXECUTION_COUNT
                             "" + entry.count,
                             // MIN_EXECUTION_TIME
-                            "" + entry.executionTimeMin,
+                            "" + entry.executionTimeMin_nanos / 1000d / 1000,
                             // MAX_EXECUTION_TIME
-                            "" + entry.executionTimeMax,
+                            "" + entry.executionTimeMax_nanos / 1000d / 1000,
                             // CUMULATIVE_EXECUTION_TIME
-                            "" + entry.executionTimeCumulative,
+                            "" + entry.executionTimeCumulative_nanos / 1000d / 1000,
                             // AVERAGE_EXECUTION_TIME
-                            "" + entry.executionTimeMean,
+                            "" + entry.executionTimeMean_nanos / 1000d / 1000,
                             // STD_DEV_EXECUTION_TIME
-                            "" + entry.getExecutionTimeStandardDeviation(),
+                            "" + entry.getExecutionTimeStandardDeviation() / 1000d / 1000,
                             // MIN_ROW_COUNT
                             "" + entry.rowCountMin,
                             // MAX_ROW_COUNT