Expired session clean-up job causes deadlocks

[MichoFelipe]

Hi All,

We are having the following issue in our production environment.

Subject: ERROR: PreparedStatementCallback; SQL [UPDATE SPRING_SESSION SET LAST_ACCESS_TIME = ?, MAX_INACTIVE_INTERVAL = ?, PRINCIPAL_NAME = ? WHERE SESSION_ID = ?]; Deadlock found when trying to get lock; try restarting transaction; nested exception is com.mysq...

Thread's Attributes Found:

DeadlockLoserDataAccessException Message: PreparedStatementCallback; SQL [UPDATE SPRING_SESSION SET LAST_ACCESS_TIME = ?, MAX_INACTIVE_INTERVAL = ?, PRINCIPAL_NAME = ? WHERE SESSION_ID = ?]; Deadlock found when trying to get lock; try restarting transaction; nested exception is com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction

org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.doTranslate(SQLErrorCodeSQLExceptionTranslator.java:263)
org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:73)
org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:649)
org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:870)
org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:931)
org.springframework.session.jdbc.JdbcOperationsSessionRepository$2.doInTransactionWithoutResult(JdbcOperationsSessionRepository.java:318)
org.springframework.transaction.support.TransactionCallbackWithoutResult.doInTransaction(TransactionCallbackWithoutResult.java:34)
org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:133)
org.springframework.session.jdbc.JdbcOperationsSessionRepository.save(JdbcOperationsSessionRepository.java:314)
org.springframework.session.jdbc.JdbcOperationsSessionRepository.save(JdbcOperationsSessionRepository.java:130)
org.springframework.session.web.http.SessionRepositoryFilter$SessionRepositoryRequestWrapper.commitSession(SessionRepositoryFilter.java:244)
org.springframework.session.web.http.SessionRepositoryFilter$SessionRepositoryRequestWrapper.access$100(SessionRepositoryFilter.java:214)
org.springframework.session.web.http.SessionRepositoryFilter$SessionRepositoryResponseWrapper.onResponseCommitted(SessionRepositoryFilter.java:202)
org.springframework.session.web.http.OnCommittedResponseWrapper.doOnResponseCommitted(OnCommittedResponseWrapper.java:226)
org.springframework.session.web.http.OnCommittedResponseWrapper.checkContentLength(OnCommittedResponseWrapper.java:216)
org.springframework.session.web.http.OnCommittedResponseWrapper.access$200(OnCommittedResponseWrapper.java:37)
org.springframework.session.web.http.OnCommittedResponseWrapper$SaveContextServletOutputStream.write(OnCommittedResponseWrapper.java:562)
com.fasterxml.jackson.core.json.UTF8JsonGenerator._flushBuffer(UTF8JsonGenerator.java:2033)
com.fasterxml.jackson.core.json.UTF8JsonGenerator.flush(UTF8JsonGenerator.java:1045)
com.fasterxml.jackson.databind.ObjectWriter.writeValue(ObjectWriter.java:942)
org.springframework.http.converter.json.AbstractJackson2HttpMessageConverter.writeInternal(AbstractJackson2HttpMessageConverter.java:267)
org.springframework.http.converter.AbstractGenericHttpMessageConverter.write(AbstractGenericHttpMessageConverter.java:100)
org.springframework.web.servlet.mvc.method.annotation.AbstractMessageConverterMethodProcessor.writeWithMessageConverters(AbstractMessageConverterMethodProcessor.java:232)
org.springframework.web.servlet.mvc.method.annotation.RequestResponseBodyMethodProcessor.handleReturnValue(RequestResponseBodyMethodProcessor.java:173)
org.springframework.web.method.support.HandlerMethodReturnValueHandlerComposite.handleReturnValue(HandlerMethodReturnValueHandlerComposite.java:81)
org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:130)
org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:827)
org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:738)
org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85)
org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:963)
org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:897)
org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970)
org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:861)
javax.servlet.http.HttpServlet.service(HttpServlet.java:622)
org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846)
javax.servlet.http.HttpServlet.service(HttpServlet.java:729)

We don't get the error in our local/DEV/QA/Non-Prod environment just in prod. env. We're replicating the data across nodes there. Could be that the reason?

Furthermore, we think that it's related to session expired.

Please, we appreciate your support :)

Thanks!

Michael

[vpavic]

Hi @MichoFelipe - can you provide more details about your environment? I assume you are using MySQL in a multi-master setup, such as Galera?

From my experience such setup can be quite problematic in high workloads when dealing with many writes (which are common with session stores).

Also this looks like a duplicate of #676.

[MichoFelipe]

Hi vpavic, yes We are using MySQL with Percona for data replication. The problem doesn't look to be due to the workload, as there wasn't much traffic when we got the error, seems to be related to the session expiration.
could you please explain us how the session expiration works?

[vpavic]

The expirations are handled by JdbcOperationsSessionRepository#cleanUpExpiredSessions:

@Scheduled(cron = "${spring.session.cleanup.cron.expression:0 * * * * *}")
public void cleanUpExpiredSessions() {
	int deletedCount = this.transactionOperations.execute(transactionStatus ->
			JdbcOperationsSessionRepository.this.jdbcOperations.update(
					JdbcOperationsSessionRepository.this.deleteSessionsByLastAccessTimeQuery,
					System.currentTimeMillis()));

	if (logger.isDebugEnabled()) {
		logger.debug("Cleaned up " + deletedCount + " expired sessions");
	}
}

This is a @Scheduled operation which runs minutely by default and uses the following SQL statement to delete expired sessions:

DELETE FROM %TABLE_NAME%
WHERE MAX_INACTIVE_INTERVAL < (? - LAST_ACCESS_TIME) / 1000;

[vpavic]

Closing as answered. If you have additional questions or feel that your original question isn't properly answered, please re-open the issue.

As a side note, we've recently introduced some optimizations of session cleanup SQL statement which might have a positive impact on reducing the possibility of deadlocks in multi-master setup like yours. See #847 and #872 for more details.

[vanekat]

Hi @vpavic, how is that scheduled operation supposed to work on a cluster environment?
In our case we have deployed our application in 4 instances. And it looks to me that we are getting that error because the scheduled operation will be executed 4 times each minute, so as they could be running simultaneously if one instance is trying to update a record and another one is trying to delete the same record that could be causing the issue.
Reviewing the db logs the dba team identified that the update and delete statements keep following each other, showing that the application is working on the same record and hence the deadlock error is generated.

[vpavic]

@vanekat Take a look at this comment and the @Scheduled annotation in particular - you can see that the cron expression is parameterized and can be customized using spring.session.cleanup.cron.expression property.

[vpavic]

@MichoFelipe @vanekat It might be of your interest that there are proposed changes to Spring Session JDBC configuration too add first-class support for configuring cleanup cron via @EnableJdbcHttpSession. You can track that effort in #907.