[keycloak-user] All realms will all linked entities being read at bootstrap

Wed Nov 20 03:54:08 EST 2019

KC startups longer then default JBoss 5 min limit and got rolled back.
>From jstack, I see application is busy with multiple queries initiated by
all realms fetch
from org.keycloak.services.managers.UserStorageSyncManager#bootstrapPeriodic

Sequence is following:
 1. KeycloakApplication.setupScheduledTasks is called on bootstrap
 2. All realms are fetched inside UserStorageSyncManager#bootstrapPeriodic
 3. During each realm fetch, RealmEntity is wrapped to CachedRealm by
RealmCacheSession#getRealm
 4. In CachedRealm constructor, it reads all RealmEntity collections
 5. Sql selects fired for all RealmEntity collections
(RealmAttributeEntity, AuthenticationFlowEntity, RequiredCredentialEntity,
etc)

I see there was optimization to fetch only realms with user storages:
https://issues.jboss.org/browse/KEYCLOAK-8555. This didn't help me because
I have user federation provider in each realm.
Also I see hibernate 1st level cache clear was advised here:
https://github.com/keycloak/keycloak/pull/6012. This also did not help,
probably because too much data is being read.

I suggest to modify realm-extraction code at
UserStorageSyncManager#bootstrapPeriodic so it will select only required
info from DB. I am ready to develop this change, what do you think about it?
-------------- next part --------------
"ServerService Thread Pool -- 63" #159 prio=5 os_prio=0 cpu=9619.51ms elapsed=99.23s tid=0x0000000009829000 nid=0x244 runnable  [0x00007fbc7755f000]
   java.lang.Thread.State: RUNNABLE
	at java.net.SocketInputStream.socketRead0(java.base at 11.0.1/Native Method)
	at java.net.SocketInputStream.socketRead(java.base at 11.0.1/SocketInputStream.java:115)
	at java.net.SocketInputStream.read(java.base at 11.0.1/SocketInputStream.java:168)
	at java.net.SocketInputStream.read(java.base at 11.0.1/SocketInputStream.java:140)
	at sun.security.ssl.SSLSocketInputRecord.read(java.base at 11.0.1/SSLSocketInputRecord.java:448)
	at sun.security.ssl.SSLSocketInputRecord.bytesInCompletePacket(java.base at 11.0.1/SSLSocketInputRecord.java:68)
	at sun.security.ssl.SSLSocketImpl.readApplicationRecord(java.base at 11.0.1/SSLSocketImpl.java:1104)
	at sun.security.ssl.SSLSocketImpl$AppInputStream.read(java.base at 11.0.1/SSLSocketImpl.java:823)
	- locked <0x00000000cb9525a0> (a sun.security.ssl.SSLSocketImpl$AppInputStream)
	at org.postgresql.core.VisibleBufferedInputStream.readMore(VisibleBufferedInputStream.java:140)
	at org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:109)
	at org.postgresql.core.VisibleBufferedInputStream.read(VisibleBufferedInputStream.java:67)
	at org.postgresql.core.PGStream.receiveChar(PGStream.java:293)
	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1947)
	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:306)
	- locked <0x00000000cb94f328> (a org.postgresql.core.v3.QueryExecutorImpl)
	at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:441)
	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:365)
	at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:155)
	at org.postgresql.jdbc.PgPreparedStatement.executeQuery(PgPreparedStatement.java:118)
	at org.jboss.jca.adapters.jdbc.CachedPreparedStatement.executeQuery(CachedPreparedStatement.java:113)
	at org.jboss.jca.adapters.jdbc.WrappedPreparedStatement.executeQuery(WrappedPreparedStatement.java:504)
	at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:60)
	at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.getResultSet(AbstractLoadPlanBasedLoader.java:419)
	at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeQueryStatement(AbstractLoadPlanBasedLoader.java:191)
	at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeLoad(AbstractLoadPlanBasedLoader.java:121)
	at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeLoad(AbstractLoadPlanBasedLoader.java:86)
	at org.hibernate.loader.collection.plan.AbstractLoadPlanBasedCollectionInitializer.initialize(AbstractLoadPlanBasedCollectionInitializer.java:87)
	at org.hibernate.persister.collection.AbstractCollectionPersister.initialize(AbstractCollectionPersister.java:691)
	at org.hibernate.event.internal.DefaultInitializeCollectionEventListener.onInitializeCollection(DefaultInitializeCollectionEventListener.java:75)
	at org.hibernate.internal.SessionImpl.initializeCollection(SessionImpl.java:2245)
	at org.hibernate.collection.internal.AbstractPersistentCollection$4.doWork(AbstractPersistentCollection.java:585)
	at org.hibernate.collection.internal.AbstractPersistentCollection.withTemporarySessionIfNeeded(AbstractPersistentCollection.java:263)
	at org.hibernate.collection.internal.AbstractPersistentCollection.initialize(AbstractPersistentCollection.java:581)
	at org.hibernate.collection.internal.AbstractPersistentCollection.read(AbstractPersistentCollection.java:148)
	at org.hibernate.collection.internal.PersistentBag.iterator(PersistentBag.java:303)
	at org.keycloak.models.jpa.ClientScopeAdapter.getProtocolMappers(ClientScopeAdapter.java:106)
	at org.keycloak.models.cache.infinispan.entities.CachedClientScope.<init>(CachedClientScope.java:50)
	at org.keycloak.models.cache.infinispan.RealmCacheSession.getClientScopeById(RealmCacheSession.java:1162)
	at org.keycloak.models.jpa.RealmAdapter.getClientScopes(RealmAdapter.java:1840)
	at org.keycloak.models.cache.infinispan.entities.CachedRealm.cacheClientScopes(CachedRealm.java:297)
	at org.keycloak.models.cache.infinispan.entities.CachedRealm.<init>(CachedRealm.java:244)
	at org.keycloak.models.cache.infinispan.RealmCacheSession.getRealm(RealmCacheSession.java:399)
	at org.keycloak.models.jpa.JpaRealmProvider.getRealms(JpaRealmProvider.java:117)
	at org.keycloak.models.jpa.JpaRealmProvider.getRealmsWithProviderType(JpaRealmProvider.java:104)
	at org.keycloak.models.cache.infinispan.RealmCacheSession.getRealmsWithProviderType(RealmCacheSession.java:459)
	at org.keycloak.services.managers.UserStorageSyncManager$1.run(UserStorageSyncManager.java:61)
	at org.keycloak.models.utils.KeycloakModelUtils.runJobInTransaction(KeycloakModelUtils.java:227)
	at org.keycloak.services.managers.UserStorageSyncManager.bootstrapPeriodic(UserStorageSyncManager.java:57)
	at org.keycloak.services.resources.KeycloakApplication.setupScheduledTasks(KeycloakApplication.java:340)
	at org.keycloak.services.resources.KeycloakApplication.<init>(KeycloakApplication.java:174)
	at jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(java.base at 11.0.1/Native Method)
	at jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(java.base at 11.0.1/NativeConstructorAccessorImpl.java:62)
	at jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(java.base at 11.0.1/DelegatingConstructorAccessorImpl.java:45)
	at java.lang.reflect.Constructor.newInstance(java.base at 11.0.1/Constructor.java:490)
	at org.jboss.resteasy.core.ConstructorInjectorImpl.construct(ConstructorInjectorImpl.java:152)
	at org.jboss.resteasy.spi.ResteasyProviderFactory.createProviderInstance(ResteasyProviderFactory.java:2750)
	at org.jboss.resteasy.spi.ResteasyDeployment.createApplication(ResteasyDeployment.java:364)
	at org.jboss.resteasy.spi.ResteasyDeployment.startInternal(ResteasyDeployment.java:277)
	at org.jboss.resteasy.spi.ResteasyDeployment.start(ResteasyDeployment.java:89)
	at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.init(ServletContainerDispatcher.java:119)
	at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.init(HttpServletDispatcher.java:36)
	at io.undertow.servlet.core.LifecyleInterceptorInvocation.proceed(LifecyleInterceptorInvocation.java:117)
	at org.wildfly.extension.undertow.security.RunAsLifecycleInterceptor.init(RunAsLifecycleInterceptor.java:78)
	at io.undertow.servlet.core.LifecyleInterceptorInvocation.proceed(LifecyleInterceptorInvocation.java:103)
	at io.undertow.servlet.core.ManagedServlet$DefaultInstanceStrategy.start(ManagedServlet.java:303)
	- locked <0x00000000cbef6670> (a io.undertow.servlet.core.ManagedServlet$DefaultInstanceStrategy)
	at io.undertow.servlet.core.ManagedServlet.createServlet(ManagedServlet.java:143)
	at io.undertow.servlet.core.DeploymentManagerImpl$2.call(DeploymentManagerImpl.java:583)
	at io.undertow.servlet.core.DeploymentManagerImpl$2.call(DeploymentManagerImpl.java:554)
	at io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:42)
	at io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43)
	at org.wildfly.extension.undertow.security.SecurityContextThreadSetupAction.lambda$create$0(SecurityContextThreadSetupAction.java:105)
	at org.wildfly.extension.undertow.security.SecurityContextThreadSetupAction$$Lambda$1111/0x0000000840f7a840.call(Unknown Source)
	at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1502)
	at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$1112/0x0000000840f7ac40.call(Unknown Source)
	at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1502)
	at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$1112/0x0000000840f7ac40.call(Unknown Source)
	at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1502)
	at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$1112/0x0000000840f7ac40.call(Unknown Source)
	at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1502)
	at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$1112/0x0000000840f7ac40.call(Unknown Source)
	at io.undertow.servlet.core.DeploymentManagerImpl.start(DeploymentManagerImpl.java:596)
	at org.wildfly.extension.undertow.deployment.UndertowDeploymentService.startContext(UndertowDeploymentService.java:97)
	at org.wildfly.extension.undertow.deployment.UndertowDeploymentService$1.run(UndertowDeploymentService.java:78)
	at java.util.concurrent.Executors$RunnableAdapter.call(java.base at 11.0.1/Executors.java:515)
	at java.util.concurrent.FutureTask.run(java.base at 11.0.1/FutureTask.java:264)
	at org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
	at org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1982)
	at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1486)
	at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1377)
	at java.lang.Thread.run(java.base at 11.0.1/Thread.java:834)
	at org.jboss.threads.JBossThread.run(JBossThread.java:485)