Home > Mobile >  How can I ensure sequential access to data in Springboot with @Transactional?
How can I ensure sequential access to data in Springboot with @Transactional?

Time:09-26

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:

  1. Isolation.SERIALIZABLE in MySQL means that every SELECT.. become SELECT ... FOR SHARE
  2. in MySQL docs there is an example similar to yours and the recommendation is to use FOR UPDATE instead of FOR 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.

  • Related