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(a)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(a)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(a)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(a)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(a)lists.jboss.org
>>>
https://lists.jboss.org/mailman/listinfo/keycloak-dev
>>
>
> --
> Bill Burke
> JBoss, a division of Red Hat
>
http://bill.burkecentral.com