I've been doing a stress test to determine if Keycloak can handle the load we foresee at some point. Using an older version (v.4.8.3) we noticed that Keycloak would freeze for a few minutes when the client screen was accessed for the first time after startup. This was with ~2500 clients.
After upgrading this older version to the latest version of Keycloak, it did not start up, so I tried starting without those 2500 clients first and then load test-users and clients via the Rest interface using JMeter.
Keycloak was set-up like this:
- standalone config
- Postgresql v.12 (localhost)
- deployed one extra .jar containing our BCrypt password encryption algorithm (confirmed to work) plus some library modules that that requires
So, I added 10k users and 10k clients. This went without any problem, and it even seemed that the freezing issue had been resolved in v. 10.0.2, because the clients listed immediately on the page when I clicked it.
Then I tried adding just one more of each via the Keycloak UI. Adding another client was no problem, but adding another user was. After clicking the "Save" button, Keycloak freezes for about 5 minutes, and then produces this stacktrace (truncated to fit within max post lenght):
2020-06-16 16:09:39,653 WARN [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX 0:ffff7f000001:-6370960e:5ee8cef7:36a in state RUN
2020-06-16 16:09:39,658 WARN [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012095: Abort of action id 0:ffff7f000001:-6370960e:5ee8cef7:36a invoked while multiple threads active within it.
2020-06-16 16:09:39,660 WARN [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012381: Action id 0:ffff7f000001:-6370960e:5ee8cef7:36a completed with multiple threads - thread default task-8 was in progress with org.hibernate@5.3.15.Final//org.hibernate.tuple.entity.AbstractEntityTuplizer.getPropertyValue(AbstractEntityTuplizer.java:577)
org.hibernate@5.3.15.Final//org.hibernate.persister.entity.AbstractEntityPersister.getPropertyValue(AbstractEntityPersister.java:4997)
org.hibernate@5.3.15.Final//org.hibernate.engine.internal.Cascade.cascade(Cascade.java:180)
<snip>
org.keycloak.keycloak-model-jpa@10.0.2//org.keycloak.models.jpa.ClientAdapter.getClientScopes(ClientAdapter.java:381)
org.keycloak.keycloak-model-infinispan@10.0.2//org.keycloak.models.cache.infinispan.entities.CachedClient.<init>(CachedClient.java:117)
org.keycloak.keycloak-model-infinispan@10.0.2//org.keycloak.models.cache.infinispan.RealmCacheSession.cacheClient(RealmCacheSession.java:1091)
org.keycloak.keycloak-model-infinispan@10.0.2//org.keycloak.models.cache.infinispan.RealmCacheSession.getClientById(RealmCacheSession.java:1051)
org.keycloak.keycloak-model-jpa@10.0.2//org.keycloak.models.jpa.JpaRealmProvider.getClients(JpaRealmProvider.java:632)
org.keycloak.keycloak-model-jpa@10.0.2//org.keycloak.models.jpa.JpaRealmProvider.getClients(JpaRealmProvider.java:640)
org.keycloak.keycloak-services@10.0.2//org.keycloak.storage.ClientStorageManager.getClients(ClientStorageManager.java:186)
org.keycloak.keycloak-model-infinispan@10.0.2//org.keycloak.models.cache.infinispan.RealmCacheSession.getClients(RealmCacheSession.java:546)
org.keycloak.keycloak-model-infinispan@10.0.2//org.keycloak.models.cache.infinispan.RealmAdapter.getClients(RealmAdapter.java:733)
org.keycloak.keycloak-server-spi@10.0.2//org.keycloak.models.utils.DefaultRoles.getDefaultRoles(DefaultRoles.java:38)
org.keycloak.keycloak-server-spi@10.0.2//org.keycloak.models.utils.DefaultRoles.addDefaultRoles(DefaultRoles.java:47)
org.keycloak.keycloak-model-jpa@10.0.2//org.keycloak.models.jpa.JpaUserProvider.addUser(JpaUserProvider.java:110)
org.keycloak.keycloak-model-jpa@10.0.2//org.keycloak.models.jpa.JpaUserProvider.addUser(JpaUserProvider.java:130)
org.keycloak.keycloak-services@10.0.2//org.keycloak.storage.UserStorageManager.addUser(UserStorageManager.java:152)
org.keycloak.keycloak-model-infinispan@10.0.2//org.keycloak.models.cache.infinispan.UserCacheSession.addUser(UserCacheSession.java:797)
org.keycloak.keycloak-services@10.0.2//org.keycloak.services.resources.admin.UsersResource.createUser(UsersResource.java:129)
...
...
org.wildfly.extension.undertow@19.1.0.Final//org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1541)
org.wildfly.extension.undertow@19.1.0.Final//org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$879/0x0000000800cc1440.call(Unknown Source)
...
...
io.undertow.servlet@2.1.0.Final//io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:249)
io.undertow.servlet@2.1.0.Final//io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:78)
io.undertow.servlet@2.1.0.Final//io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:99)
io.undertow.core@2.1.0.Final//io.undertow.server.Connectors.executeRootHandler(Connectors.java:370)
io.undertow.core@2.1.0.Final//io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:830)
org.jboss.threads@2.3.3.Final//org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
org.jboss.threads@2.3.3.Final//org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1982)
org.jboss.threads@2.3.3.Final//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1486)
org.jboss.threads@2.3.3.Final//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1377)
java.base@11.0.6/java.lang.Thread.run(Thread.java:834) ```
2020-06-16 16:09:39,674 WARN [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012108: CheckedAction::check - atomic action 0:ffff7f000001:-6370960e:5ee8cef7:36a aborting with 1 threads active!
2020-06-16 16:09:39,678 WARN [org.hibernate.resource.transaction.backend.jta.internal.synchronization.SynchronizationCallbackCoordinatorTrackingImpl] (Transaction Reaper Worker 0) HHH000451: Transaction afterCompletion called by a background thread; delaying afterCompletion processing until the original thread can handle it. [status=4]
2020-06-16 16:09:39,679 WARN [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012121: TransactionReaper::doCancellations worker Thread[Transaction Reaper Worker 0,5,main] successfully canceled TX 0:ffff7f000001:-6370960e:5ee8cef7:36a
2020-06-16 16:09:39,713 WARN [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (default task-8) IJ000609: Attempt to return connection twice: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@1854447[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@70689a22 connection handles=0 lastReturned=1592316579713 lastValidated=1592315711533 lastCheckedOut=1592316279657 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@717d396a mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@19f9ce2e[pool=KeycloakDS] xaResource=LocalXAResourceImpl@4ee761ed[connectionListener=1854447 connectionManager=304cc4b8 warned=false currentXid=null productName=PostgreSQL productVersion=12.3 jndiName=java:jboss/datasources/KeycloakDS] txSync=null]: java.lang.Throwable: STACKTRACE
at org.jboss.ironjacamar.impl@1.4.20.Final//org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreConcurrentLinkedDequeManagedConnectionPool.returnConnection(SemaphoreConcurrentLinkedDequeManagedConnectionPool.java:725)
at org.jboss.ironjacamar.impl@1.4.20.Final//org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreConcurrentLinkedDequeManagedConnectionPool.returnConnection(SemaphoreConcurrentLinkedDequeManagedConnectionPool.java:614)
at org.jboss.ironjacamar.impl@1.4.20.Final//org.jboss.jca.core.connectionmanager.pool.AbstractPool.returnConnection(AbstractPool.java:847)
at org.jboss.ironjacamar.impl@1.4.20.Final//org.jboss.jca.core.connectionmanager.AbstractConnectionManager.returnManagedConnection(AbstractConnectionManager.java:725)
at org.jboss.ironjacamar.impl@1.4.20.Final//org.jboss.jca.core.connectionmanager.AbstractConnectionManager.managedConnectionDisconnected(AbstractConnectionManager.java:1113)
at org.jboss.ironjacamar.impl@1.4.20.Final//org.jboss.jca.core.connectionmanager.AbstractConnectionManager.disconnectManagedConnection(AbstractConnectionManager.java:1069)
at org.jboss.ironjacamar.impl@1.4.20.Final//org.jboss.jca.core.connectionmanager.AbstractConnectionManager.reconnectManagedConnection(AbstractConnectionManager.java:1046)
at org.jboss.ironjacamar.impl@1.4.20.Final//org.jboss.jca.core.connectionmanager.AbstractConnectionManager.allocateConnection(AbstractConnectionManager.java:792)
at org.jboss.ironjacamar.jdbcadapters@1.4.20.Final//org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:151)
at org.jboss.as.connector@19.1.0.Final//org.jboss.as.connector.subsystems.datasources.WildFlyDataSource.getConnection(WildFlyDataSource.java:64)
at org.hibernate@5.3.15.Final//org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:122)
at org.hibernate@5.3.15.Final//org.hibernate.internal.NonContextualJdbcConnectionAccess.obtainConnection(NonContextualJdbcConnectionAccess.java:35)
at org.hibernate@5.3.15.Final//org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:106)
at org.hibernate@5.3.15.Final//org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:136)
...
...
at org.keycloak.keycloak-model-jpa@10.0.2//org.keycloak.models.jpa.ClientAdapter.getClientScopes(ClientAdapter.java:381)
at org.keycloak.keycloak-model-infinispan@10.0.2//org.keycloak.models.cache.infinispan.entities.CachedClient.<init>(CachedClient.java:117)
at org.keycloak.keycloak-model-infinispan@10.0.2//org.keycloak.models.cache.infinispan.RealmCacheSession.cacheClient(RealmCacheSession.java:1091)
at org.keycloak.keycloak-model-infinispan@10.0.2//org.keycloak.models.cache.infinispan.RealmCacheSession.getClientById(RealmCacheSession.java:1051)
at org.keycloak.keycloak-model-jpa@10.0.2//org.keycloak.models.jpa.JpaRealmProvider.getClients(JpaRealmProvider.java:632)
at org.keycloak.keycloak-model-jpa@10.0.2//org.keycloak.models.jpa.JpaRealmProvider.getClients(JpaRealmProvider.java:640)
at org.keycloak.keycloak-services@10.0.2//org.keycloak.storage.ClientStorageManager.getClients(ClientStorageManager.java:186)
at org.keycloak.keycloak-model-infinispan@10.0.2//org.keycloak.models.cache.infinispan.RealmCacheSession.getClients(RealmCacheSession.java:546)
at org.keycloak.keycloak-model-infinispan@10.0.2//org.keycloak.models.cache.infinispan.RealmAdapter.getClients(RealmAdapter.java:733)
at org.keycloak.keycloak-server-spi@10.0.2//org.keycloak.models.utils.DefaultRoles.getDefaultRoles(DefaultRoles.java:38)
at org.keycloak.keycloak-server-spi@10.0.2//org.keycloak.models.utils.DefaultRoles.addDefaultRoles(DefaultRoles.java:47)
at org.keycloak.keycloak-model-jpa@10.0.2//org.keycloak.models.jpa.JpaUserProvider.addUser(JpaUserProvider.java:110)
at org.keycloak.keycloak-model-jpa@10.0.2//org.keycloak.models.jpa.JpaUserProvider.addUser(JpaUserProvider.java:130)
at org.keycloak.keycloak-services@10.0.2//org.keycloak.storage.UserStorageManager.addUser(UserStorageManager.java:152)
at org.keycloak.keycloak-model-infinispan@10.0.2//org.keycloak.models.cache.infinispan.UserCacheSession.addUser(UserCacheSession.java:797)
at org.keycloak.keycloak-services@10.0.2//org.keycloak.services.resources.admin.UsersResource.createUser(UsersResource.java:129)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at org.jboss.resteasy.resteasy-jaxrs@3.11.2.Final//org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:138)
at org.jboss.resteasy.resteasy-jaxrs@3.11.2.Final//org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:535)
at org.jboss.resteasy.resteasy-jaxrs@3.11.2.Final//org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:424)
...
...
at javax.servlet.api@2.0.0.Final//javax.servlet.http.HttpServlet.service(HttpServlet.java:590)
at io.undertow.servlet@2.1.0.Final//io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:74)
at io.undertow.servlet@2.1.0.Final//io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:129)
at org.keycloak.keycloak-services@10.0.2//org.keycloak.services.filters.KeycloakSessionServletFilter.doFilter(KeycloakSessionServletFilter.java:91)
at io.undertow.servlet@2.1.0.Final//io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
...
...
at org.jboss.threads@2.3.3.Final//org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1982)
at org.jboss.threads@2.3.3.Final//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1486)
at org.jboss.threads@2.3.3.Final//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1377)
at java.base/java.lang.Thread.run(Thread.java:834)
2020-06-16 16:09:39,728 WARN [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-8) SQL Error: 0, SQLState: null
2020-06-16 16:09:39,728 ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-8) javax.resource.ResourceException: IJ000457: Unchecked throwable in managedConnectionReconnected() cl=org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@1854447[state=DESTROYED managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@70689a22 connection handles=0 lastReturned=1592316579713 lastValidated=1592315711533 lastCheckedOut=1592316279657 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@717d396a mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@19f9ce2e[pool=KeycloakDS] xaResource=LocalXAResourceImpl@4ee761ed[connectionListener=1854447 connectionManager=304cc4b8 warned=false currentXid=null productName=PostgreSQL productVersion=12.3 jndiName=java:jboss/datasources/KeycloakDS] txSync=null]
2020-06-16 16:09:39,752 ERROR [org.keycloak.services.error.KeycloakErrorHandler] (default task-8) Uncaught server error: javax.persistence.PersistenceException: org.hibernate.HibernateException: Transaction was rolled back in a different thread!
at org.hibernate@5.3.15.Final//org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:154)
at org.hibernate@5.3.15.Final//org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1515)
at org.hibernate@5.3.15.Final//org.hibernate.query.Query.getResultList(Query.java:132)
at org.keycloak.keycloak-model-jpa@10.0.2//org.keycloak.models.jpa.ClientAdapter.getClientScopes(ClientAdapter.java:381)
at org.keycloak.keycloak-model-infinispan@10.0.2//org.keycloak.models.cache.infinispan.entities.CachedClient.<init>(CachedClient.java:117)
at org.keycloak.keycloak-model-infinispan@10.0.2//org.keycloak.models.cache.infinispan.RealmCacheSession.cacheClient(RealmCacheSession.java:1091)
at org.keycloak.keycloak-model-infinispan@10.0.2//org.keycloak.models.cache.infinispan.RealmCacheSession.getClientById(RealmCacheSession.java:1051)
at org.keycloak.keycloak-model-jpa@10.0.2//org.keycloak.models.jpa.JpaRealmProvider.getClients(JpaRealmProvider.java:632)
at org.keycloak.keycloak-model-jpa@10.0.2//org.keycloak.models.jpa.JpaRealmProvider.getClients(JpaRealmProvider.java:640)
at org.keycloak.keycloak-services@10.0.2//org.keycloak.storage.ClientStorageManager.getClients(ClientStorageManager.java:186)
at org.keycloak.keycloak-model-infinispan@10.0.2//org.keycloak.models.cache.infinispan.RealmCacheSession.getClients(RealmCacheSession.java:546)
at org.keycloak.keycloak-model-infinispan@10.0.2//org.keycloak.models.cache.infinispan.RealmAdapter.getClients(RealmAdapter.java:733)
at org.keycloak.keycloak-server-spi@10.0.2//org.keycloak.models.utils.DefaultRoles.getDefaultRoles(DefaultRoles.java:38)
at org.keycloak.keycloak-server-spi@10.0.2//org.keycloak.models.utils.DefaultRoles.addDefaultRoles(DefaultRoles.java:47)
at org.keycloak.keycloak-model-jpa@10.0.2//org.keycloak.models.jpa.JpaUserProvider.addUser(JpaUserProvider.java:110)
at org.keycloak.keycloak-model-jpa@10.0.2//org.keycloak.models.jpa.JpaUserProvider.addUser(JpaUserProvider.java:130)
at org.keycloak.keycloak-services@10.0.2//org.keycloak.storage.UserStorageManager.addUser(UserStorageManager.java:152)
at org.keycloak.keycloak-model-infinispan@10.0.2//org.keycloak.models.cache.infinispan.UserCacheSession.addUser(UserCacheSession.java:797)
at org.keycloak.keycloak-services@10.0.2//org.keycloak.services.resources.admin.UsersResource.createUser(UsersResource.java:129)
...
...
at org.jboss.threads@2.3.3.Final//org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
at org.jboss.threads@2.3.3.Final//org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1982)
at org.jboss.threads@2.3.3.Final//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1486)
at org.jboss.threads@2.3.3.Final//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1377)
at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: org.hibernate.HibernateException: Transaction was rolled back in a different thread!
at org.hibernate@5.3.15.Final//org.hibernate.resource.transaction.backend.jta.internal.synchronization.SynchronizationCallbackCoordinatorTrackingImpl.processAnyDelayedAfterCompletion(SynchronizationCallbackCoordinatorTrackingImpl.java:90)
at org.hibernate@5.3.15.Final//org.hibernate.internal.SessionImpl.delayedAfterCompletion(SessionImpl.java:658)
at org.hibernate@5.3.15.Final//org.hibernate.internal.SessionImpl.list(SessionImpl.java:1532)
at org.hibernate@5.3.15.Final//org.hibernate.query.internal.AbstractProducedQuery.doList(AbstractProducedQuery.java:1538)
at org.hibernate@5.3.15.Final//org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1506)
... 91 more
2020-06-16 16:09:39,769 WARN [com.arjuna.ats.arjuna] (default task-8) ARJUNA012077: Abort called on already aborted atomic action 0:ffff7f000001:-6370960e:5ee8cef7:36a
... after which the user is not created. Searching for a solution I came across a number of suggestions to increase the (idle) timeout value, and some tweaks to the datasource configuration, none of which had any effect on the problem, apart from increasing the time it was frozen before producing that stack trace.
There was one other hint that I found, which was to add jta=false to the datasource, like this:
<datasource jta="false" jndi-name="java:jboss/datasources/KeycloakDS" ...
With that added, the Keycloak UI still froze, but I could see that a lot of communication was happening with Postgresql: the transactions per second shot up to around 700 and then tapered off:
Still, a user had now indeed been created, albeit without the first and last names I had filled in. The "username" was copied from the email address that I had entered for that user (but maybe that is the usual behaviour).
This was where I was last week with v. 10.0.1, and today I tried upgrading to 10.0.2 but, alas, no difference.
I also posted this on the keycloak discourse forum a week ago, but have had no reply there, so therefore I'm asking here. It might of course just as well be a JBoss issue, I have no idea.
Any suggestions would be great!