KEYCLOAK-2710 Possibility to log some hibernate statistics

docbook/auth-server-docs/reference/en/en-US/modules/server-installation.xml

@@ -206,6 +206,15 @@ bin/add-user-keycloak.[sh|bat] -r master -u <username> -p <password>
                             </para>
                         </listitem>
                     </varlistentry>
+                    <varlistentry>
+                        <term>globalStatsInterval</term>
+                        <listitem>
+                            <para>
+                                Will log global statistics from Hibernate about executed DB queries and other things. Statistics are always reported
+                                to server log at specified interval (in seconds) and are cleared after each report.
+                            </para>
+                        </listitem>
+                    </varlistentry>
                     <varlistentry>
                         <term>schema</term>
                         <listitem>

model/jpa/src/main/java/org/keycloak/connections/jpa/DefaultJpaConnectionProviderFactory.java

@@ -40,6 +40,8 @@ import org.keycloak.connections.jpa.util.JpaUtils;
 import org.keycloak.models.KeycloakSession;
 import org.keycloak.models.KeycloakSessionFactory;
 import org.keycloak.provider.ServerInfoAwareProviderFactory;
+import org.keycloak.services.scheduled.ScheduledTaskRunner;
+import org.keycloak.timer.TimerProvider;
 
 /**
  * @author <a href="mailto:sthorger@redhat.com">Stian Thorgersen</a>
@@ -180,10 +182,19 @@ public class DefaultJpaConnectionProviderFactory implements JpaConnectionProvide
 	                        logger.trace("Database update completed");
 	                    }
 
+                        int globalStatsInterval = config.getInt("globalStatsInterval", -1);
+                        if (globalStatsInterval != -1) {
+                            properties.put("hibernate.generate_statistics", true);
+                        }
+
 	                    logger.trace("Creating EntityManagerFactory");
 	                    emf = Persistence.createEntityManagerFactory(unitName, properties);
 	                    logger.trace("EntityManagerFactory created");
 
+                        if (globalStatsInterval != -1) {
+                            startGlobalStats(session, globalStatsInterval);
+                        }
+
                     } catch (Exception e) {
                         // Safe rollback
                         if (connection != null) {
@@ -260,6 +271,12 @@ public class DefaultJpaConnectionProviderFactory implements JpaConnectionProvide
         }
     }
 
+    protected void startGlobalStats(KeycloakSession session, int globalStatsIntervalSecs) {
+        logger.debugf("Started Hibernate statistics with the interval %s seconds", globalStatsIntervalSecs);
+        TimerProvider timer = session.getProvider(TimerProvider.class);
+        timer.schedule(new ScheduledTaskRunner(session.getKeycloakSessionFactory(), new HibernateStatsReporter(emf)), globalStatsIntervalSecs * 1000, "ReportHibernateGlobalStats");
+    }
+
 
     @Override
     public Connection getConnection() {

model/jpa/src/main/java/org/keycloak/connections/jpa/HibernateStatsReporter.java

@@ -0,0 +1,73 @@
+/*
+ * Copyright 2016 Red Hat, Inc. and/or its affiliates
+ * and other contributors as indicated by the @author tags.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package org.keycloak.connections.jpa;
+
+import javax.persistence.EntityManagerFactory;
+
+import org.hibernate.SessionFactory;
+import org.hibernate.jpa.internal.EntityManagerFactoryImpl;
+import org.hibernate.stat.QueryStatistics;
+import org.hibernate.stat.Statistics;
+import org.jboss.logging.Logger;
+import org.keycloak.models.KeycloakSession;
+import org.keycloak.services.scheduled.ScheduledTask;
+
+/**
+ * @author <a href="mailto:mposolda@redhat.com">Marek Posolda</a>
+ */
+public class HibernateStatsReporter implements ScheduledTask {
+
+    private final EntityManagerFactory emf;
+    private static final Logger logger = Logger.getLogger(HibernateStatsReporter.class);
+
+    public HibernateStatsReporter(EntityManagerFactory emf) {
+        this.emf = emf;
+    }
+
+
+    @Override
+    public void run(KeycloakSession session) {
+        SessionFactory sessionFactory = ((EntityManagerFactoryImpl) emf).getSessionFactory();
+        Statistics stats = sessionFactory.getStatistics();
+
+        logStats(stats);
+
+        stats.clear(); // For now, clear stats after each iteration
+    }
+
+
+    protected void logStats(Statistics stats) {
+        String lineSep = System.getProperty("line.separator");
+        StringBuilder builder = new StringBuilder(lineSep).append(stats.toString()).append(lineSep);
+        builder.append(lineSep).append("Queries statistics: ").append(lineSep).append(lineSep);
+
+        for (String query : stats.getQueries()) {
+            QueryStatistics queryStats = stats.getQueryStatistics(query);
+
+            builder.append(query).append(lineSep)
+                    .append("executionCount=" + queryStats.getExecutionCount()).append(lineSep)
+                    .append("executionAvgTime=" + queryStats.getExecutionAvgTime()).append(" ms").append(lineSep)
+                    .append(lineSep);
+
+            builder.append(lineSep);
+        }
+
+        logger.infof(builder.toString());
+    }
+
+}

testsuite/integration-arquillian/tests/base/src/test/resources/META-INF/keycloak-server.json

@@ -83,7 +83,8 @@
             "password": "${keycloak.connectionsJpa.password:}",
             "databaseSchema": "${keycloak.connectionsJpa.databaseSchema:update}",
             "showSql": "${keycloak.connectionsJpa.showSql:false}",
-            "formatSql": "${keycloak.connectionsJpa.formatSql:true}"
+            "formatSql": "${keycloak.connectionsJpa.formatSql:true}",
+            "globalStatsInterval": "${keycloak.connectionsJpa.globalStatsInterval:-1}"
         }
     },
 

testsuite/integration-arquillian/tests/other/jpa-performance/src/test/java/org/keycloak/testsuite/user/ManyUsersTest.java

@@ -66,9 +66,7 @@ public class ManyUsersTest extends AbstractUserTest {
         }
 
         realmTimer.reset("create realm before test");
-        RealmRepresentation realm = new RealmRepresentation();
+        createRealm(REALM);
-        realm.setRealm(REALM);
-        realmsResouce().create(realm);
 
         refreshToken();
     }

testsuite/integration-arquillian/tests/other/jpa-performance/src/test/resources/log4j.properties

@@ -0,0 +1,61 @@
+#
+# Copyright 2016 Red Hat, Inc. and/or its affiliates
+# and other contributors as indicated by the @author tags.
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+# http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+#
+
+log4j.rootLogger=info
+
+log4j.appender.keycloak=org.apache.log4j.ConsoleAppender
+log4j.appender.keycloak.layout=org.apache.log4j.PatternLayout
+log4j.appender.keycloak.layout.ConversionPattern=%d{HH:mm:ss,SSS} %-5p [%c] %m%n
+
+log4j.appender.testsuite=org.apache.log4j.ConsoleAppender
+log4j.appender.testsuite.layout=org.apache.log4j.PatternLayout
+log4j.appender.testsuite.layout.ConversionPattern=%d{HH:mm:ss,SSS} %-5p %m%n
+
+log4j.logger.org.keycloak=off, keycloak
+
+log4j.logger.org.keycloak.testsuite=debug, testsuite
+log4j.additivity.org.keycloak.testsuite=false
+
+# Enable to view events
+# log4j.logger.org.keycloak.events=debug
+
+# Enable to view loaded SPI and Providers
+# log4j.logger.org.keycloak.services.DefaultKeycloakSessionFactory=debug
+# log4j.logger.org.keycloak.provider.ProviderManager=debug
+# log4j.logger.org.keycloak.provider.FileSystemProviderLoaderFactory=debug
+
+# Liquibase updates logged with "info" by default. Logging level can be changed by system property "keycloak.liquibase.logging.level"
+keycloak.liquibase.logging.level=info
+log4j.logger.org.keycloak.connections.jpa.updater.liquibase=${keycloak.liquibase.logging.level}
+log4j.logger.org.keycloak.connections.jpa=debug
+
+# Enable to view database updates
+# log4j.logger.org.keycloak.connections.mongo.updater.DefaultMongoUpdaterProvider=debug
+# log4j.logger.org.keycloak.connections.jpa.DefaultJpaConnectionProviderFactory=debug
+# log4j.logger.org.keycloak.migration.MigrationModelManager=debug
+
+# Enable to view kerberos/spnego logging
+# log4j.logger.org.keycloak.broker.kerberos=trace
+
+# Enable to view detailed AS REQ and TGS REQ requests to embedded Kerberos server
+# log4j.logger.org.apache.directory.server.kerberos=debug
+
+log4j.logger.org.xnio=off
+log4j.logger.org.hibernate=off
+log4j.logger.org.jboss.resteasy=warn
+log4j.logger.org.apache.directory.api=warn
+log4j.logger.org.apache.directory.server.core=warn

testsuite/integration/src/test/resources/META-INF/keycloak-server.json

@@ -63,7 +63,8 @@
             "password": "${keycloak.connectionsJpa.password:}",
             "databaseSchema": "${keycloak.connectionsJpa.databaseSchema:update}",
             "showSql": "${keycloak.connectionsJpa.showSql:false}",
-            "formatSql": "${keycloak.connectionsJpa.formatSql:true}"
+            "formatSql": "${keycloak.connectionsJpa.formatSql:true}",
+            "globalStatsInterval": "${keycloak.connectionsJpa.globalStatsInterval:-1}"
         }
     },
 

testsuite/integration/src/test/resources/log4j.properties

@@ -52,6 +52,9 @@ log4j.logger.org.keycloak.connections.jpa.updater.liquibase=${keycloak.liquibase
 # log4j.logger.org.keycloak.connections.jpa.DefaultJpaConnectionProviderFactory=debug
 # log4j.logger.org.keycloak.migration.MigrationModelManager=debug
 
+# Enable to view hibernate statistics
+log4j.logger.org.keycloak.connections.jpa.HibernateStatsReporter=debug
+
 # Enable to view kerberos/spnego logging
 # log4j.logger.org.keycloak.federation.kerberos=trace