I have a requirement where a request is going to read a row from a MySQL database and update it based on the value it read from the row and while that request is being served, if there's any other request that's trying to do the same on that particular row, it would be halted until the first request is served. This would mean that if TXN1 comes and reads the value 1 from the row and updates it to 2, if there are other transactions trying to do the same at the same time, they should not even be able to read that particular row until the first transaction is done.
I was going through different levels of isolation in Springboot's @Transactional
annotation and Isolation.SERIALIZABLE
sounded a lot like what I wanted.
So I created the following TestEntity.java
@Entity(name = "test")
@Getter
@Setter
@ToString
@NoArgsConstructor
@AllArgsConstructor
public class TestEntity {
@GeneratedValue(strategy = GenerationType.AUTO)
@Id
private Long id;
@Column(unique = true)
private String name;
private Long count;
}
Along with that, I also created the following TestRepository.java
public interface TestRepository extends JpaRepository<TestEntity, Long> {
TestEntity findByName(final String name);
}
Along with that I have a simple controller that receives a request and tries to update the count
TestV2Controller.java
@RestController
@RequestMapping("test/v2")
@Slf4j
public class TestV2Controller {
@Autowired
private TestRepository testRepository;
@GetMapping
@Transactional(isolation = Isolation.SERIALIZABLE)
public void test() {
log.info("Reading from DB");
final var entity = testRepository.findByName("Jake");
log.info("Retrieved Entity: {}", entity);
entity.setCount(entity.getCount() 1);
log.info("Modified Entity: {}", entity);
}
.........
.........
}
I test my API with 5 concurrent requests.
If my understanding is correct, the @Transactional(isolation = Isolation.SERIALIZABLE)
should cause 5 separate transactions, all trying to read and modify the row. At this point, one should succeed and acquire a lock on the row, causing every other transactions to wait (not even able to read).
But as you can see from the logs below, all 5 transactions are able to read the row all at the same time. What is ever more puzzling is that, except for one transaction, all other transactions are failing to update rather than wait and update. And in the DB, the count becomes only 2 from 1 instead of 6.
2021-09-25 19:59:00.878 INFO 42623 --- [nio-8001-exec-3] i.t.t.a.test.TestV2Controller : Reading from DB
2021-09-25 19:59:00.878 INFO 42623 --- [nio-8001-exec-4] i.t.t.a.test.TestV2Controller : Reading from DB
2021-09-25 19:59:00.878 INFO 42623 --- [nio-8001-exec-5] i.t.t.a.test.TestV2Controller : Reading from DB
2021-09-25 19:59:00.879 INFO 42623 --- [nio-8001-exec-7] i.t.t.a.test.TestV2Controller : Reading from DB
2021-09-25 19:59:00.879 INFO 42623 --- [nio-8001-exec-6] i.t.t.a.test.TestV2Controller : Reading from DB
2021-09-25 19:59:00.938 INFO 42623 --- [nio-8001-exec-3] i.t.t.a.test.TestV2Controller : Retrieved Entity: TestEntity(id=31, name=Jake, count=1)
2021-09-25 19:59:00.938 INFO 42623 --- [nio-8001-exec-6] i.t.t.a.test.TestV2Controller : Retrieved Entity: TestEntity(id=31, name=Jake, count=1)
2021-09-25 19:59:00.938 INFO 42623 --- [nio-8001-exec-5] i.t.t.a.test.TestV2Controller : Retrieved Entity: TestEntity(id=31, name=Jake, count=1)
2021-09-25 19:59:00.938 INFO 42623 --- [nio-8001-exec-7] i.t.t.a.test.TestV2Controller : Retrieved Entity: TestEntity(id=31, name=Jake, count=1)
2021-09-25 19:59:00.938 INFO 42623 --- [nio-8001-exec-3] i.t.t.a.test.TestV2Controller : Modified Entity: TestEntity(id=31, name=Jake, count=2)
2021-09-25 19:59:00.938 INFO 42623 --- [nio-8001-exec-6] i.t.t.a.test.TestV2Controller : Modified Entity: TestEntity(id=31, name=Jake, count=2)
2021-09-25 19:59:00.938 INFO 42623 --- [nio-8001-exec-5] i.t.t.a.test.TestV2Controller : Modified Entity: TestEntity(id=31, name=Jake, count=2)
2021-09-25 19:59:00.938 INFO 42623 --- [nio-8001-exec-7] i.t.t.a.test.TestV2Controller : Modified Entity: TestEntity(id=31, name=Jake, count=2)
2021-09-25 19:59:00.938 INFO 42623 --- [nio-8001-exec-4] i.t.t.a.test.TestV2Controller : Retrieved Entity: TestEntity(id=31, name=Jake, count=1)
2021-09-25 19:59:00.938 INFO 42623 --- [nio-8001-exec-4] i.t.t.a.test.TestV2Controller : Modified Entity: TestEntity(id=31, name=Jake, count=2)
2021-09-25 19:59:00.940 WARN 42623 --- [nio-8001-exec-3] o.h.engine.jdbc.spi.SqlExceptionHelper : SQL Error: 1213, SQLState: 40001
2021-09-25 19:59:00.940 WARN 42623 --- [nio-8001-exec-4] o.h.engine.jdbc.spi.SqlExceptionHelper : SQL Error: 1213, SQLState: 40001
2021-09-25 19:59:00.940 WARN 42623 --- [nio-8001-exec-6] o.h.engine.jdbc.spi.SqlExceptionHelper : SQL Error: 1213, SQLState: 40001
2021-09-25 19:59:00.940 WARN 42623 --- [nio-8001-exec-7] o.h.engine.jdbc.spi.SqlExceptionHelper : SQL Error: 1213, SQLState: 40001
2021-09-25 19:59:00.940 ERROR 42623 --- [nio-8001-exec-3] o.h.engine.jdbc.spi.SqlExceptionHelper : Deadlock found when trying to get lock; try restarting transaction
2021-09-25 19:59:00.940 ERROR 42623 --- [nio-8001-exec-4] o.h.engine.jdbc.spi.SqlExceptionHelper : Deadlock found when trying to get lock; try restarting transaction
2021-09-25 19:59:00.940 ERROR 42623 --- [nio-8001-exec-6] o.h.engine.jdbc.spi.SqlExceptionHelper : Deadlock found when trying to get lock; try restarting transaction
2021-09-25 19:59:00.940 ERROR 42623 --- [nio-8001-exec-7] o.h.engine.jdbc.spi.SqlExceptionHelper : Deadlock found when trying to get lock; try restarting transaction
2021-09-25 19:59:00.945 ERROR 42623 --- [nio-8001-exec-3] o.a.c.c.C.[.[.[/].[dispatcherServlet] : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is org.springframework.dao.CannotAcquireLockException: could not execute statement; SQL [n/a]; nested exception is org.hibernate.exception.LockAcquisitionException: could not execute statement] with root cause
com.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:123) ~[mysql-connector-java-8.0.26.jar:8.0.26]
at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:122) ~[mysql-connector-java-8.0.26.jar:8.0.26]
at com.mysql.cj.jdbc.ClientPreparedStatement.executeInternal(ClientPreparedStatement.java:953) ~[mysql-connector-java-8.0.26.jar:8.0.26]
at com.mysql.cj.jdbc.ClientPreparedStatement.executeUpdateInternal(ClientPreparedStatement.java:1092) ~[mysql-connector-java-8.0.26.jar:8.0.26]
at com.mysql.cj.jdbc.ClientPreparedStatement.executeUpdateInternal(ClientPreparedStatement.java:1040) ~[mysql-connector-java-8.0.26.jar:8.0.26]
at com.mysql.cj.jdbc.ClientPreparedStatement.executeLargeUpdate(ClientPreparedStatement.java:1350) ~[mysql-connector-java-8.0.26.jar:8.0.26]
at com.mysql.cj.jdbc.ClientPreparedStatement.executeUpdate(ClientPreparedStatement.java:1025) ~[mysql-connector-java-8.0.26.jar:8.0.26]
at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeUpdate(ProxyPreparedStatement.java:61) ~[HikariCP-4.0.3.jar:na]
at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeUpdate(HikariProxyPreparedStatement.java) ~[HikariCP-4.0.3.jar:na]
at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:197) ~[hibernate-core-5.5.7.Final.jar:5.5.7.Final]
at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3574) ~[hibernate-core-5.5.7.Final.jar:5.5.7.Final]
at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:3436) ~[hibernate-core-5.5.7.Final.jar:5.5.7.Final]
at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3850) ~[hibernate-core-5.5.7.Final.jar:5.5.7.Final]
at org.hibernate.action.internal.EntityUpdateAction.execute(EntityUpdateAction.java:201) ~[hibernate-core-5.5.7.Final.jar:5.5.7.Final]
at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:604) ~[hibernate-core-5.5.7.Final.jar:5.5.7.Final]
at org.hibernate.engine.spi.ActionQueue.lambda$executeActions$1(ActionQueue.java:478) ~[hibernate-core-5.5.7.Final.jar:5.5.7.Final]
at java.base/java.util.LinkedHashMap.forEach(LinkedHashMap.java:723) ~[na:na]
at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:475) ~[hibernate-core-5.5.7.Final.jar:5.5.7.Final]
at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:344) ~[hibernate-core-5.5.7.Final.jar:5.5.7.Final]
at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:40) ~[hibernate-core-5.5.7.Final.jar:5.5.7.Final]
at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:107) ~[hibernate-core-5.5.7.Final.jar:5.5.7.Final]
at org.hibernate.internal.SessionImpl.doFlush(SessionImpl.java:1391) ~[hibernate-core-5.5.7.Final.jar:5.5.7.Final]
at org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:482) ~[hibernate-core-5.5.7.Final.jar:5.5.7.Final]
at org.hibernate.internal.SessionImpl.flushBeforeTransactionCompletion(SessionImpl.java:3274) ~[hibernate-core-5.5.7.Final.jar:5.5.7.Final]
at org.hibernate.internal.SessionImpl.beforeTransactionCompletion(SessionImpl.java:2409) ~[hibernate-core-5.5.7.Final.jar:5.5.7.Final]
at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.beforeTransactionCompletion(JdbcCoordinatorImpl.java:449) ~[hibernate-core-5.5.7.Final.jar:5.5.7.Final]
at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.beforeCompletionCallback(JdbcResourceLocalTransactionCoordinatorImpl.java:183) ~[hibernate-core-5.5.7.Final.jar:5.5.7.Final]
at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.access$300(JdbcResourceLocalTransactionCoordinatorImpl.java:40) ~[hibernate-core-5.5.7.Final.jar:5.5.7.Final]
at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.commit(JdbcResourceLocalTransactionCoordinatorImpl.java:281) ~[hibernate-core-5.5.7.Final.jar:5.5.7.Final]
at org.hibernate.engine.transaction.internal.TransactionImpl.commit(TransactionImpl.java:101) ~[hibernate-core-5.5.7.Final.jar:5.5.7.Final]
at org.springframework.orm.jpa.JpaTransactionManager.doCommit(JpaTransactionManager.java:562) ~[spring-orm-5.3.10.jar:5.3.10]
at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:743) ~[spring-tx-5.3.10.jar:5.3.10]
at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:711) ~[spring-tx-5.3.10.jar:5.3.10]
at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:654) ~[spring-tx-5.3.10.jar:5.3.10]
at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:407) ~[spring-tx-5.3.10.jar:5.3.10]
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119) ~[spring-tx-5.3.10.jar:5.3.10]
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.10.jar:5.3.10]
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750) ~[spring-aop-5.3.10.jar:5.3.10]
at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:692) ~[spring-aop-5.3.10.jar:5.3.10]
at in.turls.teenyurl.apigatewayservice.test.TestV2Controller$$EnhancerBySpringCGLIB$$c3571c40.test(<generated>) ~[classes/:na]
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:78) ~[na:na]
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na]
at java.base/java.lang.reflect.Method.invoke(Method.java:567) ~[na:na]
at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205) ~[spring-web-5.3.10.jar:5.3.10]
at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:150) ~[spring-web-5.3.10.jar:5.3.10]
at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:117) ~[spring-webmvc-5.3.10.jar:5.3.10]
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:895) ~[spring-webmvc-5.3.10.jar:5.3.10]
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:808) ~[spring-webmvc-5.3.10.jar:5.3.10]
at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87) ~[spring-webmvc-5.3.10.jar:5.3.10]
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1067) ~[spring-webmvc-5.3.10.jar:5.3.10]
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:963) ~[spring-webmvc-5.3.10.jar:5.3.10]
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006) ~[spring-webmvc-5.3.10.jar:5.3.10]
at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:898) ~[spring-webmvc-5.3.10.jar:5.3.10]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:655) ~[tomcat-embed-core-9.0.53.jar:4.0.FR]
at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883) ~[spring-webmvc-5.3.10.jar:5.3.10]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:764) ~[tomcat-embed-core-9.0.53.jar:4.0.FR]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:227) ~[tomcat-embed-core-9.0.53.jar:9.0.53]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162) ~[tomcat-embed-core-9.0.53.jar:9.0.53]
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53) ~[tomcat-embed-websocket-9.0.53.jar:9.0.53]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189) ~[tomcat-embed-core-9.0.53.jar:9.0.53]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162) ~[tomcat-embed-core-9.0.53.jar:9.0.53]
at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100) ~[spring-web-5.3.10.jar:5.3.10]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.3.10.jar:5.3.10]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189) ~[tomcat-embed-core-9.0.53.jar:9.0.53]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162) ~[tomcat-embed-core-9.0.53.jar:9.0.53]
at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93) ~[spring-web-5.3.10.jar:5.3.10]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.3.10.jar:5.3.10]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189) ~[tomcat-embed-core-9.0.53.jar:9.0.53]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162) ~[tomcat-embed-core-9.0.53.jar:9.0.53]
at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.doFilterInternal(WebMvcMetricsFilter.java:96) ~[spring-boot-actuator-2.6.0-SNAPSHOT.jar:2.6.0-SNAPSHOT]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.3.10.jar:5.3.10]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189) ~[tomcat-embed-core-9.0.53.jar:9.0.53]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162) ~[tomcat-embed-core-9.0.53.jar:9.0.53]
at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201) ~[spring-web-5.3.10.jar:5.3.10]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.3.10.jar:5.3.10]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189) ~[tomcat-embed-core-9.0.53.jar:9.0.53]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162) ~[tomcat-embed-core-9.0.53.jar:9.0.53]
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:197) ~[tomcat-embed-core-9.0.53.jar:9.0.53]
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97) ~[tomcat-embed-core-9.0.53.jar:9.0.53]
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:540) ~[tomcat-embed-core-9.0.53.jar:9.0.53]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:135) ~[tomcat-embed-core-9.0.53.jar:9.0.53]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92) ~[tomcat-embed-core-9.0.53.jar:9.0.53]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78) ~[tomcat-embed-core-9.0.53.jar:9.0.53]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:357) ~[tomcat-embed-core-9.0.53.jar:9.0.53]
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:382) ~[tomcat-embed-core-9.0.53.jar:9.0.53]
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65) ~[tomcat-embed-core-9.0.53.jar:9.0.53]
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:893) ~[tomcat-embed-core-9.0.53.jar:9.0.53]
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1726) ~[tomcat-embed-core-9.0.53.jar:9.0.53]
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) ~[tomcat-embed-core-9.0.53.jar:9.0.53]
at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191) ~[tomcat-embed-core-9.0.53.jar:9.0.53]
at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659) ~[tomcat-embed-core-9.0.53.jar:9.0.53]
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-embed-core-9.0.53.jar:9.0.53]
at java.base/java.lang.Thread.run(Thread.java:831) ~[na:na]
2021-09-25 19:59:00.945 ERROR 42623 --- [nio-8001-exec-6] o.a.c.c.C.[.[.[/].[dispatcherServlet] : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is org.springframework.dao.CannotAcquireLockException: could not execute statement; SQL [n/a]; nested exception is org.hibernate.exception.LockAcquisitionException: could not execute statement] with root cause
com.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
... same error stack as the one above ...
2021-09-25 19:59:00.945 ERROR 42623 --- [nio-8001-exec-4] o.a.c.c.C.[.[.[/].[dispatcherServlet] : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is org.springframework.dao.CannotAcquireLockException: could not execute statement; SQL [n/a]; nested exception is org.hibernate.exception.LockAcquisitionException: could not execute statement] with root cause
com.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
... same error stack as the one above ...
2021-09-25 19:59:00.945 ERROR 42623 --- [nio-8001-exec-7] o.a.c.c.C.[.[.[/].[dispatcherServlet] : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is org.springframework.dao.CannotAcquireLockException: could not execute statement; SQL [n/a]; nested exception is org.hibernate.exception.LockAcquisitionException: could not execute statement] with root cause
com.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
... same error stack as the one above ...
This behavior, however, changes and becomes sequential when I issue an update command just before reading
So my modified TestRepository.java looks like this
public interface TestRepository extends JpaRepository<TestEntity, Long> {
TestEntity findByName(final String name);
@Modifying
@Query("UPDATE test t SET t.name = ?1 WHERE t.name = ?1")
void updateName(final String name);
}
And my modified controller method becomes like this:
@GetMapping
@Transactional(isolation = Isolation.SERIALIZABLE)
public void test() {
log.info("Reading from DB");
testRepository.updateName("Jake");
final var entity = testRepository.findByName("Jake");
log.info("Retrieved Entity: {}", entity);
entity.setCount(entity.getCount() 1);
log.info("Modified Entity: {}", entity);
}
I run the same concurrent requests with initial count value in DB as 2 and below are the logs of it:
2021-09-25 20:30:08.338 INFO 44754 --- [nio-8001-exec-4] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring DispatcherServlet 'dispatcherServlet'
2021-09-25 20:30:08.338 INFO 44754 --- [nio-8001-exec-4] o.s.web.servlet.DispatcherServlet : Initializing Servlet 'dispatcherServlet'
2021-09-25 20:30:08.339 INFO 44754 --- [nio-8001-exec-4] o.s.web.servlet.DispatcherServlet : Completed initialization in 1 ms
2021-09-25 20:30:08.359 INFO 44754 --- [nio-8001-exec-2] i.t.t.a.test.TestV2Controller : Reading from DB
2021-09-25 20:30:08.359 INFO 44754 --- [nio-8001-exec-1] i.t.t.a.test.TestV2Controller : Reading from DB
2021-09-25 20:30:08.359 INFO 44754 --- [nio-8001-exec-5] i.t.t.a.test.TestV2Controller : Reading from DB
2021-09-25 20:30:08.359 INFO 44754 --- [nio-8001-exec-4] i.t.t.a.test.TestV2Controller : Reading from DB
2021-09-25 20:30:08.359 INFO 44754 --- [nio-8001-exec-3] i.t.t.a.test.TestV2Controller : Reading from DB
2021-09-25 20:30:08.394 INFO 44754 --- [nio-8001-exec-2] i.t.t.a.test.TestV2Controller : Retrieved Entity: TestEntity(id=31, name=Jake, count=2)
2021-09-25 20:30:08.394 INFO 44754 --- [nio-8001-exec-2] i.t.t.a.test.TestV2Controller : Modified Entity: TestEntity(id=31, name=Jake, count=3)
2021-09-25 20:30:08.423 INFO 44754 --- [nio-8001-exec-4] i.t.t.a.test.TestV2Controller : Retrieved Entity: TestEntity(id=31, name=Jake, count=3)
2021-09-25 20:30:08.423 INFO 44754 --- [nio-8001-exec-4] i.t.t.a.test.TestV2Controller : Modified Entity: TestEntity(id=31, name=Jake, count=4)
2021-09-25 20:30:08.428 INFO 44754 --- [nio-8001-exec-5] i.t.t.a.test.TestV2Controller : Retrieved Entity: TestEntity(id=31, name=Jake, count=4)
2021-09-25 20:30:08.428 INFO 44754 --- [nio-8001-exec-5] i.t.t.a.test.TestV2Controller : Modified Entity: TestEntity(id=31, name=Jake, count=5)
2021-09-25 20:30:08.432 INFO 44754 --- [nio-8001-exec-3] i.t.t.a.test.TestV2Controller : Retrieved Entity: TestEntity(id=31, name=Jake, count=5)
2021-09-25 20:30:08.432 INFO 44754 --- [nio-8001-exec-3] i.t.t.a.test.TestV2Controller : Modified Entity: TestEntity(id=31, name=Jake, count=6)
2021-09-25 20:30:08.435 INFO 44754 --- [nio-8001-exec-1] i.t.t.a.test.TestV2Controller : Retrieved Entity: TestEntity(id=31, name=Jake, count=6)
2021-09-25 20:30:08.435 INFO 44754 --- [nio-8001-exec-1] i.t.t.a.test.TestV2Controller : Modified Entity: TestEntity(id=31, name=Jake, count=7)
As a matter of fact, I don't even need Isolation.SERIALIZABLE
. It behaves the same way with that @Transactional
annotation.
The count value in the DB becomes 7 from 2 as expected.
So what is going on here? Why is isolation level SERIALIZABLE
allowing concurrent reads and then allowing only one to succeed, failing all others? Should it not allow all operations to go through one after another?
To me it seems like, unless I issue an update command, all transactions have a shared read-lock, which allows all of them to read. And in the next scenario, when an update command is issued before read, it creates an exclusive write-lock, which forces every other transaction to wait and go through sequentially.
Is there something wrong with my understanding of serializable? Is this how it's supposed to behave? How can I achieve the same behavior (read-update exclusively) without issuing an update command before reading?
Thank you for your time
CodePudding user response:
What you are looking for is a pessimistic write lock. Remove isolation = Isolation.SERIALIZABLE
, the updateName()
method, and add the @Lock(LockModeType.PESSIMISTIC_WRITE)
annotation to your findByName()
repository method (or create a new method if you don't want to alter the default functionality provided by Spring Data JPA). There are different flavors of pessimistic write locks but this one meets your criteria. See this Baeldung article for more information about pessimistic locking.
CodePudding user response:
You have a deadlock — it's in the logs:
com.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
From MySQL docs:
Deadlocks are a classic problem in transactional databases, but they are not dangerous unless they are so frequent that you cannot run certain transactions at all. Normally, you must write your applications so that they are always prepared to re-issue a transaction if it gets rolled back because of a deadlock.
One possible solution would be to restart the transaction.
Additionally:
Isolation.SERIALIZABLE
in MySQL means that everySELECT..
becomeSELECT ... FOR SHARE
- in MySQL docs there is an example similar to yours and the recommendation is to use
FOR UPDATE
instead ofFOR SHARE
:
Here, FOR SHARE is not a good solution because if two users read the counter at the same time, at least one of them ends up in deadlock when it attempts to update the counter.
To implement reading and incrementing the counter, first perform a locking read of the counter using FOR UPDATE, and then increment the counter.
So you might also want to try FOR UPDATE
as well (this might how the update command fixes the problem in your 2nd example).
As written in the answer above, LockModeType.PESSIMISTIC_WRITE
should do that.
Unfortunatelly, I don't know if FOR UPDATE
eliminates deadlocks entirely or just reduces their frequency.