JPA乐观锁ObjectOptimisticLockingFailureException异常后重试仍会异常的原因排查

乐观锁的概念不再赘述,在使用Spring Data JPA时,JPA提供了一种优雅实现乐观锁的方式,即@Version注解,需要额外注意一下的是,由于存在同名注解,有效的是hibernate-jpa-xx-api.jar包下的javax.persistence.Version,而不是org.springframework.data.annotation.Version。

乐观锁在db层面是没有加锁的,实际上是利用CAS原理在客户端去实现的锁逻辑,并发情况下发生冲突时,从db角度上来说,都能够正常执行不会报错,但ORM框架的处理各不相同,以下问题目前仅在特定工程条件下验证过,高版本是否还有该问题没有验证。

环境

spring-boot 1.5.22.RELEASE
spring-data-jpa 1.11.23.RELEASE
hibernate-core 5.0.12.Final
mysql 5.7
mysql连接池 tomcat-jdbc
IDE IDEA 2019.3

代码

  1. // 测试乐观锁的表模型
  2. @Entity
  3. @Table(name = "c_test")
  4. @Data
  5. public class LockTest {
  6. @Id
  7. @GeneratedValue
  8. private Long id;
  9. @Version
  10. @Column(name = "version")
  11. private Integer version;
  12. private Date updateTime;
  13. }
  1. // 测试方法
  2. public void testLock() {
  3. // 初始化一条数据
  4. long tid = 1L;
  5. LockTest lockTest = lockTestRepository.findOne(tid);
  6. if(null == lockTest){
  7. lockTest = new LockTest();
  8. lockTest.setUpdateTime(new Date());
  9. lockTest.setVersion(0);
  10. lockTestRepository.save(lockTest);
  11. }
  12. for (int i = 0; i < 3; i++) {
  13. lockTest = lockTestRepository.findOne(tid); // TAG3
  14. System.out.println(ObjectUtils.toJson(lockTest));
  15. lockTest.setUpdateTime(new Date());
  16. try {
  17. lockTest = lockTestRepository.save(lockTest); // TAG1
  18. } catch (Exception ex){
  19. System.out.println(ex.getMessage()); // TAG2
  20. }
  21. }
  22. }

测试过程

  1. IDEA中断点在TAG1、TAG2处,本地以调试方式启动服务后调用testLock方法,代码运行断点在TAG1处,此时mysql中测试数据的version为0,内存中lockTest变量的version也为0
  2. 手动改mysql中测试数据的version为1
  3. 继续执行断点在TAG1的代码,代码运行异常,跳入catch块,停留在TAG2处,异常具体类型为ObjectOptimisticLockingFailureException,错误描述具体为“Batch update returned unexpected row count from update [0]; actual row count: 0; expected: 1”,根据描述很容易理解,由于version已过时,此次更新操作实际影响的mysql数据行数为0,异常ObjectOptimisticLockingFailureException是JPA根据返回值主动抛出的,而非mysql执行sql语句的异常。
  4. 继续执行断点在TAG2的代码,进入到第2次循环,代码运行断点在TAG1处。由于TAG3处重新进行了查询,因此内存中lockTest变量的version字段值已同步更新到了1
  5. 继续执行断点在TAG1的代码,按照预估,应该能够正常执行保存操作的,但代码运行又出现了异常,跳入catch块,停留在TAG2处,异常具体类型为JpaSystemException,错误描述具体为“java.sql.SQLException: Statement closed. could not update: [package.path1.path2.LockTest#1L]”,根据描述的字面意思是连接已关闭,无法更新。
  6. 继续执行断点在TAG2的代码,进入到第3次循环,代码运行断点在TAG1处。
  7. 继续执行断点在TAG1的代码,这次保存操作正常执行了,查看mysql,对应的数据行的version字段也被更新为了2。

问题简述

第2次循环中,为何抛出了连接断开的异常。

问题解析

hibernate在执行sql语句前,底层是通过PreparedStatement对sql进行预编译的,这在批量操作时有利于提高效率,预编译后产生的PreparedStatement对象(实际是代理对象StatementFacade),会被缓存在org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl类的statements局部变量中,statements是一个LinkedHashMap,key就是要进行预编译的sql语句。因此在使用JPA的场景下,很容易理解到,对于同一个Entity的同类别操作(如insert、update),使用的都会是同一个PreparedStatement(StatementFacade)。

hibernate内部实际执行时是通过一个门面类StatementFacade来进行操作的,屏蔽不同Statment的实现细节,降低耦合。StatementFacade内部维护一个由StatementProxy生成的代理对象delegate,而这个delegate实际上就是我们刚说的预编译产生的PreparedStatement。

  • 在第1次循环中,JPA抛出ObjectOptimisticLockingFailureException后,StatementFacade对象中的delegate被置为了null,但是StatementFacade对象并没有从上文提到的LinkedHashMap类型的statements中移除
  • 在第2次循环中,因为还是执行LockTest的update操作,因此当对sql进行预编译时,发现在statements中已经有上一次预编译过的记录,于是就直接拿出来用了。但是当实际执行到sql参数解析时,即通过SqlTypeDescriptor的子类进行各个参数处理时(如本示例中updateTime是Date类型,因此对应的是TimestampTypeDescriptor),才发现StatementFacade对象中的delegate为null,无法执行实际的解析,因此抛出错误,而delegate为null对于hibernate来说就是连接已关闭。而这一次由于是hibernate主动发现了StatementFacade对象有问题,因此便从statements中将它移除掉了。(具体代码如下)
  • 在第3次循环中,对sql进行预编译时,由于上一次有问题的记录被移除了,因此hibernate要重新构建预编译PreparedStatement对象,因此这一次就能够正常执行了。
  1. package org.hibernate.engine.jdbc.batch.internal;
  2. public abstract class AbstractBatchImpl implements Batch {
  3. ......省略代码
  4. private LinkedHashMap<String,PreparedStatement> statements = new LinkedHashMap<String,PreparedStatement>();
  5. ......省略代码
  6. @Override
  7. public PreparedStatement getBatchStatement(String sql, boolean callable) {
  8. if ( sql == null ) {
  9. throw new IllegalArgumentException( "sql must be non-null." );
  10. }
  11. PreparedStatement statement = statements.get( sql );
  12. if ( statement == null ) {
  13. statement = buildBatchStatement( sql, callable );
  14. statements.put( sql, statement );
  15. }
  16. else {
  17. LOG.debug( "Reusing batch statement" );
  18. sqlStatementLogger().logStatement( sql );
  19. }
  20. return statement;
  21. }
  22. ......省略代码
  23. }

解决问题

知道了原因后,基本上也就知道对策了,那就是……重试至少要2次才有效,重试1次和不重试没有区别。因此实际业务代码里调整大致如下:

  1. private LockTest optimisticSaveLockTest(LockTest lockTest) {
  2. int i = 0;
  3. boolean success = false;
  4. while (!success) {
  5. lockTest.setUpdateTime(new Date());
  6. try {
  7. lockTest = lockTestRepository.save(lockTest);
  8. success = true;
  9. // 并发下乐观锁冲突第一次会报ObjectOptimisticLockingFailureException;
  10. // 第二次再保存时,由于JPA的bug导致第一次出错时已断开连接的PreparedStatement没有移除出缓存,第二次又取到了,于是会报Statement closed,
  11. // 第三次尝试保存才是实际意义上的二次尝试,因此至少尝试保存三次
  12. } catch (ObjectOptimisticLockingFailureException | JpaSystemException e) {
  13. if (i < 3) {
  14. i++;
  15. log.error(
  16. "LockTest乐观锁保存失败,尝试第{}次保存:{},数据为:{}",
  17. i + 1,
  18. e.getMessage(),
  19. ObjectUtils.toJson(lockTest));
  20. lockTest = lockTestRepository.findOne(lockTest.getId());
  21. } else {
  22. throw e;
  23. }
  24. }
  25. }
  26. return lockTest;
  27. }