From 22ce20ff6b68c9bb50d9daaa19a1f8adada38813 Mon Sep 17 00:00:00 2001 From: mposolda Date: Wed, 23 Mar 2016 18:01:35 +0100 Subject: [PATCH 1/2] KEYCLOAK-2710 Possibility to log some hibernate statistics --- .../en/en-US/modules/server-installation.xml | 9 +++ .../DefaultJpaConnectionProviderFactory.java | 19 ++++- .../jpa/HibernateStatsReporter.java | 73 +++++++++++++++++++ .../resources/META-INF/keycloak-server.json | 3 +- .../testsuite/user/ManyUsersTest.java | 4 +- .../src/test/resources/log4j.properties | 61 ++++++++++++++++ .../resources/META-INF/keycloak-server.json | 3 +- .../src/test/resources/log4j.properties | 3 + 8 files changed, 169 insertions(+), 6 deletions(-) create mode 100644 model/jpa/src/main/java/org/keycloak/connections/jpa/HibernateStatsReporter.java create mode 100644 testsuite/integration-arquillian/tests/other/jpa-performance/src/test/resources/log4j.properties diff --git a/docbook/auth-server-docs/reference/en/en-US/modules/server-installation.xml b/docbook/auth-server-docs/reference/en/en-US/modules/server-installation.xml index 9d3237d50d..b2b1e5fbd0 100755 --- a/docbook/auth-server-docs/reference/en/en-US/modules/server-installation.xml +++ b/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 -p + + globalStatsInterval + + + 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. + + + schema diff --git a/model/jpa/src/main/java/org/keycloak/connections/jpa/DefaultJpaConnectionProviderFactory.java b/model/jpa/src/main/java/org/keycloak/connections/jpa/DefaultJpaConnectionProviderFactory.java index 444e891031..25401f6c13 100755 --- a/model/jpa/src/main/java/org/keycloak/connections/jpa/DefaultJpaConnectionProviderFactory.java +++ b/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 Stian Thorgersen @@ -179,11 +181,20 @@ 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() { diff --git a/model/jpa/src/main/java/org/keycloak/connections/jpa/HibernateStatsReporter.java b/model/jpa/src/main/java/org/keycloak/connections/jpa/HibernateStatsReporter.java new file mode 100644 index 0000000000..fbe09ae47e --- /dev/null +++ b/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 Marek Posolda + */ +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()); + } + +} diff --git a/testsuite/integration-arquillian/tests/base/src/test/resources/META-INF/keycloak-server.json b/testsuite/integration-arquillian/tests/base/src/test/resources/META-INF/keycloak-server.json index ae0f5f9a07..111d5103fc 100755 --- a/testsuite/integration-arquillian/tests/base/src/test/resources/META-INF/keycloak-server.json +++ b/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}" } }, diff --git a/testsuite/integration-arquillian/tests/other/jpa-performance/src/test/java/org/keycloak/testsuite/user/ManyUsersTest.java b/testsuite/integration-arquillian/tests/other/jpa-performance/src/test/java/org/keycloak/testsuite/user/ManyUsersTest.java index 914f748555..f882879269 100644 --- a/testsuite/integration-arquillian/tests/other/jpa-performance/src/test/java/org/keycloak/testsuite/user/ManyUsersTest.java +++ b/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(); - realm.setRealm(REALM); - realmsResouce().create(realm); + createRealm(REALM); refreshToken(); } diff --git a/testsuite/integration-arquillian/tests/other/jpa-performance/src/test/resources/log4j.properties b/testsuite/integration-arquillian/tests/other/jpa-performance/src/test/resources/log4j.properties new file mode 100644 index 0000000000..979584600b --- /dev/null +++ b/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 \ No newline at end of file diff --git a/testsuite/integration/src/test/resources/META-INF/keycloak-server.json b/testsuite/integration/src/test/resources/META-INF/keycloak-server.json index e9bb97f419..ec7690418f 100755 --- a/testsuite/integration/src/test/resources/META-INF/keycloak-server.json +++ b/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}" } }, diff --git a/testsuite/integration/src/test/resources/log4j.properties b/testsuite/integration/src/test/resources/log4j.properties index fd730de9eb..f5b3e24a2d 100755 --- a/testsuite/integration/src/test/resources/log4j.properties +++ b/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 From 50f8846c3d575defa7af9a8d6c95662bd13267db Mon Sep 17 00:00:00 2001 From: mposolda Date: Wed, 23 Mar 2016 22:18:10 +0100 Subject: [PATCH 2/2] KEYCLOAK-2610 Improve performance of creating users with MySQL --- .../jpa/updater/JpaUpdaterProvider.java | 2 +- .../META-INF/db2-jpa-changelog-master.xml | 1 + .../META-INF/jpa-changelog-1.9.2.xml | 28 +++++++++++++++++++ .../META-INF/jpa-changelog-master.xml | 1 + 4 files changed, 31 insertions(+), 1 deletion(-) create mode 100644 model/jpa/src/main/resources/META-INF/jpa-changelog-1.9.2.xml diff --git a/model/jpa/src/main/java/org/keycloak/connections/jpa/updater/JpaUpdaterProvider.java b/model/jpa/src/main/java/org/keycloak/connections/jpa/updater/JpaUpdaterProvider.java index 0e0dea2e7e..f253684a20 100755 --- a/model/jpa/src/main/java/org/keycloak/connections/jpa/updater/JpaUpdaterProvider.java +++ b/model/jpa/src/main/java/org/keycloak/connections/jpa/updater/JpaUpdaterProvider.java @@ -28,7 +28,7 @@ public interface JpaUpdaterProvider extends Provider { public String FIRST_VERSION = "1.0.0.Final"; - public String LAST_VERSION = "1.9.0"; + public String LAST_VERSION = "1.9.2"; public String getCurrentVersionSql(String defaultSchema); diff --git a/model/jpa/src/main/resources/META-INF/db2-jpa-changelog-master.xml b/model/jpa/src/main/resources/META-INF/db2-jpa-changelog-master.xml index a69e443710..2d0117efc6 100644 --- a/model/jpa/src/main/resources/META-INF/db2-jpa-changelog-master.xml +++ b/model/jpa/src/main/resources/META-INF/db2-jpa-changelog-master.xml @@ -31,4 +31,5 @@ + diff --git a/model/jpa/src/main/resources/META-INF/jpa-changelog-1.9.2.xml b/model/jpa/src/main/resources/META-INF/jpa-changelog-1.9.2.xml new file mode 100644 index 0000000000..141d7cbd6b --- /dev/null +++ b/model/jpa/src/main/resources/META-INF/jpa-changelog-1.9.2.xml @@ -0,0 +1,28 @@ + + + + + + + + + + + + + \ No newline at end of file diff --git a/model/jpa/src/main/resources/META-INF/jpa-changelog-master.xml b/model/jpa/src/main/resources/META-INF/jpa-changelog-master.xml index c107b8ef58..fd1f0f6e72 100755 --- a/model/jpa/src/main/resources/META-INF/jpa-changelog-master.xml +++ b/model/jpa/src/main/resources/META-INF/jpa-changelog-master.xml @@ -31,4 +31,5 @@ +