[keycloak-dev] Deadlocks on /realms/{realm-name}/protocol/openid-connect/token

Bill Burke bburke at redhat.com
Wed Jul 8 12:14:25 EDT 2015 

What do you think we should do about this?  Do a paginated query within 
its own transaction and delete only a few of them at a time per 
transaction?  Maybe consider getting off of JPA and moving to 
Infinispan?  I know you guys are on the cloud, but Infinispan can be 
configured to use TCP instead of Multicast.

On 7/7/2015 12:04 PM, Scott Rossillo wrote:
> The removeUserSessionByExpired query is locking the USER_SESSION table to up to 1.2 seconds at a time and that’s enough to cause deadlocks since it acquires a table lock to do the delete. Indexes on started and lastSessionRefresh may help, but the query may have to be split up into two deletes to pick up the indexes correctly (at least with MySQL).
>
> ~ Scott
>
>> On Jul 6, 2015, at 12:47 PM, Scott Rossillo <srossillo at smartling.com> wrote:
>>
>> So,
>>
>> It would seem the cause is the ClearExpiredUserSessions scheduled task which is executing the named query, “removeUserSessionByExpired”:
>>
>> delete from UserSessionEntity s where s.realmId = :realmId and (s.started < :maxTime or s.lastSessionRefresh < :idleTime)
>>
>> This is doing a table scan, causing locks on the USER_SESSION table's primary key.
>>
>> Based on the stock keycloak-server.json, it seems to be done every 15 minutes. Further complicating things is that scheduled tasks are going to run on every Keycloak server in a given environment, so if you have 3 servers, each will try to execute this cleanup at 15 minute intervals from its startup.
>>
>> ~ Scott
>>
>>
>>> On Jul 6, 2015, at 11:10 AM, Bill Burke <bburke at redhat.com> wrote:
>>>
>>> Ugh, then there are a ton of inserts/updates happening to the same few tables.
>>>
>>> On 7/6/2015 11:03 AM, Scott Rossillo wrote:
>>>>
>>>> Yes, using JPA user session storage.
>>>>
>>>> May have to add some code to get a better stack trace.
>>>>
>>>>
>>>>
>>>>> On Jul 6, 2015, at 10:58 AM, Bill Burke <bburke at redhat.com> wrote:
>>>>>
>>>>> Are you using JPA user session storage?  Everything but session data
>>>>> should be read-only unless some write operation snuck in
>>>>>
>>>>> Stack trace doesn't really help :(
>>>>>
>>>>> On 7/6/2015 10:42 AM, Scott Rossillo wrote:
>>>>>> Hi,
>>>>>>
>>>>>> We’re seeing MySQL deadlocks on requests to /realms/{realm-name}/protocol/openid-connect/token ranging from 8 to > 40 per day causing internal server errors. The thrown exception doesn’t really give enough information on what caused the deadlock.
>>>>>>
>>>>>> This is on 1.2.0. Any thoughts? Stack below.
>>>>>>
>>>>>> 2015-07-06 08:46:01,599 [ERROR] [default task-1] (LoggingExceptionHandler.java:handleThrowable:80) UT005023: Exception handling request to /auth/realms/xyz/protocol/openid-connect/token: java.lang.RuntimeException: request path: /auth/realms/xyz/protocol/openid-connect/token
>>>>>> 	at org.keycloak.services.filters.KeycloakSessionServletFilter.doFilter(KeycloakSessionServletFilter.java:54)
>>>>>> 	at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:60) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
>>>>>> 	at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:132) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
>>>>>> 	at io.undertow.servlet.handlers.FilterHandler.handleRequest(FilterHandler.java:85) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
>>>>>> 	at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:61) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
>>>>>> 	at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
>>>>>> 	at org.wildfly.extension.undertow.security.SecurityContextAssociationHandler.handleRequest(SecurityContextAssociationHandler.java:78)
>>>>>> 	at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) [undertow-core-1.1.0.Final.jar:1.1.0.Final]
>>>>>> 	at io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:131) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
>>>>>> 	at io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.handleRequest(ServletAuthenticationCallHandler.java:56) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
>>>>>> 	at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) [undertow-core-1.1.0.Final.jar:1.1.0.Final]
>>>>>> 	at io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:45) [undertow-core-1.1.0.Final.jar:1.1.0.Final]
>>>>>> 	at io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:63) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
>>>>>> 	at io.undertow.security.handlers.AuthenticationMechanismsHandler.handleRequest(AuthenticationMechanismsHandler.java:58) [undertow-core-1.1.0.Final.jar:1.1.0.Final]
>>>>>> 	at io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:70) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
>>>>>> 	at io.undertow.security.handlers.SecurityInitialHandler.handleRequest(SecurityInitialHandler.java:76) [undertow-core-1.1.0.Final.jar:1.1.0.Final]
>>>>>> 	at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) [undertow-core-1.1.0.Final.jar:1.1.0.Final]
>>>>>> 	at org.wildfly.extension.undertow.security.jacc.JACCContextIdHandler.handleRequest(JACCContextIdHandler.java:61)
>>>>>> 	at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) [undertow-core-1.1.0.Final.jar:1.1.0.Final]
>>>>>> 	at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) [undertow-core-1.1.0.Final.jar:1.1.0.Final]
>>>>>> 	at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:261) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
>>>>>> 	at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:247) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
>>>>>> 	at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:76) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
>>>>>> 	at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:166) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
>>>>>> 	at io.undertow.server.Connectors.executeRootHandler(Connectors.java:197) [undertow-core-1.1.0.Final.jar:1.1.0.Final]
>>>>>> 	at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:759) [undertow-core-1.1.0.Final.jar:1.1.0.Final]
>>>>>> 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [rt.jar:1.7.0_79]
>>>>>> 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [rt.jar:1.7.0_79]
>>>>>> 	at java.lang.Thread.run(Thread.java:745) [rt.jar:1.7.0_79]
>>>>>> Caused by: org.keycloak.models.ModelException: javax.persistence.PersistenceException: org.hibernate.exception.LockAcquisitionException: could not execute statement
>>>>>> 	at org.keycloak.connections.jpa.PersistenceExceptionConverter.convert(PersistenceExceptionConverter.java:44) [keycloak-connections-jpa-1.2.Final.jar:1.2.0.Final]
>>>>>> 	at org.keycloak.connections.jpa.JpaKeycloakTransaction.commit(JpaKeycloakTransaction.java:30) [keycloak-connections-jpa-1.2.Final.jar:1.2.0.Final]
>>>>>> 	at org.keycloak.services.DefaultKeycloakTransactionManager.commit(DefaultKeycloakTransactionManager.java:55) [keycloak-services-1.2.Final.jar:1.2.0.Final]
>>>>>> 	at org.keycloak.services.filters.KeycloakSessionServletFilter.doFilter(KeycloakSessionServletFilter.java:43) [keycloak-services-1.2.Final.jar:1.2.0.Final]
>>>>>> 	... 28 more
>>>>>> Caused by: javax.persistence.PersistenceException: org.hibernate.exception.LockAcquisitionException: could not execute statement
>>>>>> 	at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1763) [hibernate-entitymanager-4.3.7.Final.jar:4.3.7.Final]
>>>>>> 	at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1677) [hibernate-entitymanager-4.3.7.Final.jar:4.3.7.Final]
>>>>>> 	at org.hibernate.jpa.internal.TransactionImpl.commit(TransactionImpl.java:82) [hibernate-entitymanager-4.3.7.Final.jar:4.3.7.Final]
>>>>>> 	at org.keycloak.connections.jpa.JpaKeycloakTransaction.commit(JpaKeycloakTransaction.java:28) [keycloak-connections-jpa-1.2.Final.jar:1.2.0.Final]
>>>>>> 	... 30 more
>>>>>> Caused by: org.hibernate.exception.LockAcquisitionException: could not execute statement
>>>>>> 	at org.hibernate.dialect.MySQLDialect$1.convert(MySQLDialect.java:451) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
>>>>>> 	at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:49) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
>>>>>> 	at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:126) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
>>>>>> 	at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:112) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
>>>>>> 	at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:211) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
>>>>>> 	at org.hibernate.engine.jdbc.batch.internal.NonBatchingBatch.addToBatch(NonBatchingBatch.java:62) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
>>>>>> 	at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3281) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
>>>>>> 	at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:3183) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
>>>>>> 	at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3525) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
>>>>>> 	at org.hibernate.action.internal.EntityUpdateAction.execute(EntityUpdateAction.java:159) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
>>>>>> 	at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:463) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
>>>>>> 	at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:349) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
>>>>>> 	at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:350) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
>>>>>> 	at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:56) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
>>>>>> 	at org.hibernate.internal.SessionImpl.flush(SessionImpl.java:1222) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
>>>>>> 	at org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:425) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
>>>>>> 	at org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.beforeTransactionCommit(JdbcTransaction.java:101) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
>>>>>> 	at org.hibernate.engine.transaction.spi.AbstractTransactionImpl.commit(AbstractTransactionImpl.java:177) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
>>>>>> 	at org.hibernate.jpa.internal.TransactionImpl.commit(TransactionImpl.java:77) [hibernate-entitymanager-4.3.7.Final.jar:4.3.7.Final]
>>>>>> 	... 31 more
>>>>>> Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
>>>>>> 	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) [rt.jar:1.7.0_79]
>>>>>> 	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57) [rt.jar:1.7.0_79]
>>>>>> 	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) [rt.jar:1.7.0_79]
>>>>>> 	at java.lang.reflect.Constructor.newInstance(Constructor.java:526) [rt.jar:1.7.0_79]
>>>>>> 	at com.mysql.jdbc.Util.handleNewInstance(Util.java:389)
>>>>>> 	at com.mysql.jdbc.Util.getInstance(Util.java:372)
>>>>>> 	at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:987)
>>>>>> 	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3835)
>>>>>> 	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3771)
>>>>>> 	at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2435)
>>>>>> 	at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2582)
>>>>>> 	at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2535)
>>>>>> 	at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1911)
>>>>>> 	at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2145)
>>>>>> 	at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2081)
>>>>>> 	at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2066)
>>>>>> 	at org.jboss.jca.adapters.jdbc.WrappedPreparedStatement.executeUpdate(WrappedPreparedStatement.java:493)
>>>>>> 	at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:208) [hibernate-core-4.3.7.Final.jar:4.3.7.Final]
>>>>>> 	... 45 more
>>>>>> _______________________________________________
>>>>>> keycloak-dev mailing list
>>>>>> keycloak-dev at lists.jboss.org
>>>>>> https://lists.jboss.org/mailman/listinfo/keycloak-dev
>>>>>>
>>>>>
>>>>> --
>>>>> Bill Burke
>>>>> JBoss, a division of Red Hat
>>>>> http://bill.burkecentral.com
>>>>> _______________________________________________
>>>>> keycloak-dev mailing list
>>>>> keycloak-dev at lists.jboss.org
>>>>> https://lists.jboss.org/mailman/listinfo/keycloak-dev
>>>>
>>>
>>> --
>>> Bill Burke
>>> JBoss, a division of Red Hat
>>> http://bill.burkecentral.com
>>
>

-- 
Bill Burke
JBoss, a division of Red Hat
http://bill.burkecentral.com

More information about the keycloak-dev mailing list