Query Statistics: new feature which stores the newest 100 SQL queries executed…

Query Statistics: new feature which stores the newest 100 SQL queries executed and their performance data.
Useful for tracking down badly performing queries.

h2/src/docsrc/help/help.csv

@@ -1429,6 +1429,19 @@ This command commits an open transaction.
 SET PASSWORD 'abcstzri!.5'
 "
 
+"Commands (Other)","SET QUERY_STATISTICS","
+SET QUERY_STATISTICS { TRUE | FALSE }
+","
+Disabled or enables query statistics gathering for the whole database.
+The statistics are reflected in the INFORMATION_SCHEMA.QUERY_STATISTICS meta-table.
+
+This setting is not persistent.
+This command commits an open transaction.
+Admin rights are required to execute this command, as it affects all connections.
+","
+SET QUERY_STATISTICS FALSE
+"
+
 "Commands (Other)","SET QUERY_TIMEOUT","
 SET QUERY_TIMEOUT int
 ","

h2/src/docsrc/html/changelog.html

@@ -56,7 +56,9 @@ Change Log
 </li><li>Session-temporary LOB's could sometimes accumulate, increasing the size of the DB file until shutdown.
     Now they are cleared out at every commit.
 </li><li>There was a bug where a hash index with more than one column would be silently converted to a regular index.
-    It will now throw an exception.    
+    It will now throw an exception.
+</li><li>Query Statistics: new feature which stores the newest 100 SQL queries executed and their performance data.
+    Useful for tracking down badly performing queries.
 </li></ul>
 
 <h2>Version 1.3.173 (2013-07-28)</h2>

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

@@ -302,13 +302,17 @@ public abstract class Prepared {
      * enabled.
      *
      * @param startTime when the statement was started
-     * @param count the update count
+     * @param rowCount the query or update row count
      */
-    void trace(long startTime, int count) {
+    void trace(long startTime, int rowCount) {
         if (session.getTrace().isInfoEnabled() && startTime > 0) {
-            long time = System.currentTimeMillis() - startTime;
+            long deltaTime = System.currentTimeMillis() - startTime;
             String params = Trace.formatParams(parameters);
-            session.getTrace().infoSQL(sqlStatement, params, count, time);
+            session.getTrace().infoSQL(sqlStatement, params, rowCount, deltaTime);
+        }
+        if (session.getDatabase().getQueryStatistics()) {
+            long deltaTime = System.currentTimeMillis() - startTime;
+            session.getDatabase().getQueryStatisticsData().update(toString(), deltaTime, rowCount);
         }
     }
 

h2/src/main/org/h2/command/dml/Set.java

@@ -347,6 +347,15 @@ public class Set extends Prepared {
             database.setReferentialIntegrity(value == 1);
             break;
         }
+        case SetTypes.QUERY_STATISTICS: {
+            session.getUser().checkAdmin();
+            int value = getIntValue();
+            if (value < 0 || value > 1) {
+                throw DbException.getInvalidValueException("QUERY_STATISTICS", getIntValue());
+            }
+            database.setQueryStatistics(value == 1);
+            break;
+        }
         case SetTypes.SCHEMA: {
             Schema schema = database.getSchema(stringValue);
             session.setCurrentSchema(schema);

h2/src/main/org/h2/command/dml/SetTypes.java

@@ -214,6 +214,12 @@ public class SetTypes {
      */
     public static final int RETENTION_TIME = 40;
     
+    /**
+     * The type of a SET QUERY_STATISTICS_ACTIVE statement.
+     */
+    public static final int QUERY_STATISTICS = 41;
+    
+    
     private static final ArrayList<String> TYPES = New.arrayList();
 
     private SetTypes() {
@@ -263,6 +269,7 @@ public class SetTypes {
         list.add(BINARY_COLLATION, "BINARY_COLLATION");
         list.add(JAVA_OBJECT_SERIALIZER, "JAVA_OBJECT_SERIALIZER");
         list.add(RETENTION_TIME, "RETENTION_TIME");
+        list.add(QUERY_STATISTICS, "QUERY_STATISTICS");
     }
 
     /**

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

@@ -179,10 +179,11 @@ public class Database implements DataHandler {
     private MVTableEngine.Store mvStore;
     private int retentionTime;
     private DbException backgroundException;
-
     private JavaObjectSerializer javaObjectSerializer;
     private String javaObjectSerializerName;
     private volatile boolean javaObjectSerializerInitialized;
+    private boolean queryStatistics;
+    private QueryStatisticsData queryStatisticsData;
 
     public Database(ConnectionInfo ci, String cipher) {
         String name = ci.getName();
@@ -2080,6 +2081,32 @@ public class Database implements DataHandler {
         return referentialIntegrity;
     }
 
+    public void setQueryStatistics(boolean b) {
+        queryStatistics = b;
+        synchronized (this) {
+            queryStatisticsData = null;
+        }
+    }
+
+    public boolean getQueryStatistics() {
+        return queryStatistics;
+    }
+    
+    public QueryStatisticsData getQueryStatisticsData() {
+        if (queryStatistics) {
+            if (queryStatisticsData == null) {
+                synchronized (this) {
+                    if (queryStatisticsData == null) {
+                        queryStatisticsData = new QueryStatisticsData();
+                    }
+                }
+            }
+            return queryStatisticsData;
+        } else {
+            return null;
+        }
+    }
+    
     /**
      * Check if the database is currently opening. This is true until all stored
      * SQL statements have been executed.

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

+/*
+ * Copyright 2004-2013 H2 Group. Multiple-Licensed under the H2 License,
+ * Version 1.0, and under the Eclipse Public License, Version 1.0
+ * (http://h2database.com/html/license.html).
+ * Initial Developer: H2 Group
+ */
+package org.h2.engine;
+
+import java.util.ArrayList;
+import java.util.Collections;
+import java.util.Comparator;
+import java.util.HashMap;
+import java.util.HashSet;
+import java.util.Iterator;
+import java.util.Map;
+
+/**
+ * Maintains query statistics.
+ */
+public class QueryStatisticsData {
+
+    private static final int MAX_QUERY_ENTRIES = 100;
+
+    public static final class QueryEntry {
+        public long lastUpdateTime;
+        public int count;
+        public long executionTimeMin;
+        public long executionTimeMax;
+        public long executionTimeCumulative;
+        public int rowCountMin;
+        public int rowCountMax;
+        public long rowCountCumulative;
+        
+        // Using Welford's method, see also
+        // http://en.wikipedia.org/wiki/Algorithms_for_calculating_variance
+        // http://www.johndcook.com/standard_deviation.html
+        public double executionTimeMean;
+        public double executionTimeM2;
+        public double rowCountMean;
+        public double rowCountM2;
+        
+        public double getExecutionTimeStandardDeviation() {
+            // population standard deviation
+            return Math.sqrt(executionTimeM2 / count);
+        }
+        
+        public double getRowCountStandardDeviation() {
+            // population standard deviation
+            return Math.sqrt(rowCountM2 / count);
+        }
+
+    }
+
+    private final HashMap<String, QueryEntry> map = new HashMap<String, QueryEntry>();
+
+    /**
+     * Update query statistics.
+     * 
+     * @param sqlStatement the statement being executed
+     * @param executionTime the time in milliseconds the query/update took to execute
+     * @param rowCount the query or update row count
+     */
+    public synchronized void update(String sqlStatement, long executionTime, int rowCount) {
+        QueryEntry entry = map.get(sqlStatement);
+        if (entry == null) {
+            entry = new QueryEntry();
+            entry.count = 1;
+            entry.executionTimeMin = executionTime;
+            entry.executionTimeMax = executionTime;
+            entry.rowCountMin = rowCount;
+            entry.rowCountMax = rowCount;
+            entry.executionTimeMean = executionTime;
+            entry.executionTimeM2 = 0;
+            entry.rowCountMean = rowCount;
+            entry.rowCountM2 = 0;
+            map.put(sqlStatement, entry);
+        } else {
+            entry.count++;
+            entry.executionTimeMin = Math.min(executionTime, entry.executionTimeMin);
+            entry.executionTimeMax = Math.max(executionTime, entry.executionTimeMax);
+            entry.rowCountMin = Math.min(rowCount, entry.rowCountMin);
+            entry.rowCountMax = Math.max(rowCount, entry.rowCountMax);
+            
+            double delta = rowCount - entry.rowCountMean;
+            entry.rowCountMean += delta / entry.count;
+            entry.rowCountM2 += delta * (rowCount - entry.rowCountMean);
+            
+            delta = executionTime - entry.executionTimeMean;
+            entry.executionTimeMean += delta / entry.count;
+            entry.executionTimeM2 += delta * (executionTime - entry.executionTimeMean);
+        }
+        entry.executionTimeCumulative += executionTime;        
+        entry.rowCountCumulative += rowCount;
+        entry.lastUpdateTime = System.currentTimeMillis();
+
+        // 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
+        if (map.size() > MAX_QUERY_ENTRIES * 1.5f) {
+            // Sort the entries by age
+            ArrayList<QueryEntry> list = new ArrayList<QueryEntry>();
+            list.addAll(map.values());
+            Collections.sort(list, QUERY_ENTRY_COMPARATOR);
+            // Create a set of the oldest 1/3 of the entries
+            HashSet<QueryEntry> oldestSet = new HashSet<QueryEntry>(list.subList(0, list.size() / 3));
+            // Loop over the map using the set and remove the oldest 1/3 of the
+            // entries.
+            for (Iterator<Map.Entry<String, QueryEntry>> iter = map.entrySet().iterator(); iter.hasNext();) {
+                Map.Entry<String, QueryEntry> mapEntry = iter.next();
+                if (oldestSet.contains(mapEntry.getValue())) {
+                    iter.remove();
+                }
+            }
+        }
+    }
+    
+    public synchronized HashMap<String, QueryEntry> getQueryMap() {
+        // return a copy of the map so we don't have to worry about external synchronization
+        return new HashMap<String, QueryEntry>(map);
+    }
+
+    private static final Comparator<QueryEntry> QUERY_ENTRY_COMPARATOR = new Comparator<QueryEntry>() {
+        @Override
+        public int compare(QueryEntry o1, QueryEntry o2) {
+            return (int) Math.signum(o1.lastUpdateTime - o2.lastUpdateTime);
+        }
+    };
+}

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

@@ -17,7 +17,7 @@ import java.util.ArrayList;
 import java.util.Collections;
 import java.util.HashMap;
 import java.util.Locale;
-
+import java.util.Map;
 import org.h2.command.Command;
 import org.h2.constraint.Constraint;
 import org.h2.constraint.ConstraintCheck;
@@ -27,6 +27,7 @@ import org.h2.engine.Constants;
 import org.h2.engine.Database;
 import org.h2.engine.DbObject;
 import org.h2.engine.FunctionAlias;
+import org.h2.engine.QueryStatisticsData;
 import org.h2.engine.Right;
 import org.h2.engine.Role;
 import org.h2.engine.Session;
@@ -103,7 +104,8 @@ public class MetaTable extends Table {
     private static final int SESSIONS = 25;
     private static final int LOCKS = 26;
     private static final int SESSION_STATE = 27;
-    private static final int META_TABLE_TYPE_COUNT = SESSION_STATE + 1;
+    private static final int QUERY_STATISTICS = 28;
+    private static final int META_TABLE_TYPE_COUNT = QUERY_STATISTICS + 1;
 
     private final int type;
     private final int indexColumn;
@@ -511,6 +513,24 @@ public class MetaTable extends Table {
             );
             break;
         }
+        case QUERY_STATISTICS: {
+            setObjectName("QUERY_STATISTICS");
+            cols = createColumns(
+                    "SQL_STATEMENT",
+                    "EXECUTION_COUNT INT",
+                    "MIN_EXECUTION_TIME LONG",
+                    "MAX_EXECUTION_TIME LONG",
+                    "CUMULATIVE_EXECUTION_TIME LONG",
+                    "AVERAGE_EXECUTION_TIME DOUBLE",
+                    "STD_DEV_EXECUTION_TIME DOUBLE",
+                    "MIN_ROW_COUNT INT",
+                    "MAX_ROW_COUNT INT",
+                    "CUMULATIVE_ROW_COUNT LONG",
+                    "AVERAGE_ROW_COUNT DOUBLE",
+                    "STD_DEV_ROW_COUNT DOUBLE"
+            );
+            break;
+        }
         default:
             throw DbException.throwInternalError("type="+type);
         }
@@ -1619,6 +1639,42 @@ public class MetaTable extends Table {
             }
             break;
         }
+        case QUERY_STATISTICS: {
+            QueryStatisticsData control = database.getQueryStatisticsData();
+            if (control != null) {
+                HashMap<String, QueryStatisticsData.QueryEntry> map = control.getQueryMap();
+                for (Map.Entry<String, QueryStatisticsData.QueryEntry> mapEntry : map.entrySet()) {
+                    QueryStatisticsData.QueryEntry entry = mapEntry.getValue();
+                    add(rows,
+                            // SQL_STATEMENT
+                            mapEntry.getKey(),
+                            // EXECUTION_COUNT
+                            "" + entry.count,
+                            // MIN_EXECUTION_TIME
+                            "" + entry.executionTimeMin,
+                            // MAX_EXECUTION_TIME
+                            "" + entry.executionTimeMax,
+                            // CUMULATIVE_EXECUTION_TIME
+                            "" + entry.executionTimeCumulative,
+                            // AVERAGE_EXECUTION_TIME
+                            "" + entry.executionTimeMean,
+                            // STD_DEV_EXECUTION_TIME
+                            "" + entry.getExecutionTimeStandardDeviation(),
+                            // MIN_ROW_COUNT
+                            "" + entry.rowCountMin,
+                            // MAX_ROW_COUNT
+                            "" + entry.rowCountMax,
+                            // CUMULATIVE_ROW_COUNT
+                            "" + entry.rowCountCumulative,
+                            // AVERAGE_ROW_COUNT
+                            "" + entry.rowCountMean,
+                            // STD_DEV_ROW_COUNT
+                            "" + entry.getRowCountStandardDeviation()
+                    );
+                }
+            }
+            break;
+        }
         default:
             DbException.throwInternalError("type="+type);
         }

h2/src/test/org/h2/test/jdbc/TestMetaData.java

@@ -51,6 +51,7 @@ public class TestMetaData extends TestBase {
         testGeneral();
         testAllowLiteralsNone();
         testSessionsUncommitted();
+        testQueryStatistics();
     }
 
     private void testColumnResultSetMeta() throws SQLException {
@@ -848,6 +849,8 @@ public class TestMetaData extends TestBase {
         rs.next();
         assertEquals("LOCKS", rs.getString("TABLE_NAME"));
         rs.next();
+        assertEquals("QUERY_STATISTICS", rs.getString("TABLE_NAME"));
+        rs.next();
         assertEquals("RIGHTS", rs.getString("TABLE_NAME"));
         rs.next();
         assertEquals("ROLES", rs.getString("TABLE_NAME"));
@@ -995,4 +998,25 @@ public class TestMetaData extends TestBase {
         conn.close();
         deleteDb("metaData");
     }
+    
+    private void testQueryStatistics() throws SQLException {
+        Connection conn = getConnection("metaData");
+        Statement stat = conn.createStatement();
+        stat.execute("create table test(id int primary key, name varchar) as select x, space(1000) from system_range(1, 2000)");
+        
+        ResultSet rs = stat.executeQuery("select * from INFORMATION_SCHEMA.QUERY_STATISTICS");
+        assertFalse(rs.next());
+        rs.close();
+        stat.execute("SET QUERY_STATISTICS TRUE");
+        stat.execute("select * from test limit 10");
+        stat.execute("select * from test limit 10");
+        rs = stat.executeQuery("select * from INFORMATION_SCHEMA.QUERY_STATISTICS");
+        assertTrue(rs.next());
+        assertEquals("select * from test limit 10", rs.getString("SQL_STATEMENT"));
+        assertEquals(2, rs.getInt("EXECUTION_COUNT"));
+        assertEquals(20, rs.getInt("CUMULATIVE_ROW_COUNT"));
+        rs.close();
+        conn.close();
+        deleteDb("metaData");
+    }
 }