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
代码
// 测试乐观锁的表模型
@Entity
@Table(name = "c_test")
@Data
public class LockTest {
@Id
@GeneratedValue
private Long id;
@Version
@Column(name = "version")
private Integer version;
private Date updateTime;
}
// 测试方法
public void testLock() {
// 初始化一条数据
long tid = 1L;
LockTest lockTest = lockTestRepository.findOne(tid);
if(null == lockTest){
lockTest = new LockTest();
lockTest.setUpdateTime(new Date());
lockTest.setVersion(0);
lockTestRepository.save(lockTest);
}
for (int i = 0; i < 3; i++) {
lockTest = lockTestRepository.findOne(tid); // TAG3
System.out.println(ObjectUtils.toJson(lockTest));
lockTest.setUpdateTime(new Date());
try {
lockTest = lockTestRepository.save(lockTest); // TAG1
} catch (Exception ex){
System.out.println(ex.getMessage()); // TAG2
}
}
}
测试过程
- IDEA中断点在TAG1、TAG2处,本地以调试方式启动服务后调用testLock方法,代码运行断点在TAG1处,此时mysql中测试数据的version为0,内存中lockTest变量的version也为0
- 手动改mysql中测试数据的version为1
- 继续执行断点在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语句的异常。
- 继续执行断点在TAG2的代码,进入到第2次循环,代码运行断点在TAG1处。由于TAG3处重新进行了查询,因此内存中lockTest变量的version字段值已同步更新到了1
- 继续执行断点在TAG1的代码,按照预估,应该能够正常执行保存操作的,但代码运行又出现了异常,跳入catch块,停留在TAG2处,异常具体类型为JpaSystemException,错误描述具体为“java.sql.SQLException: Statement closed. could not update: [package.path1.path2.LockTest#1L]”,根据描述的字面意思是连接已关闭,无法更新。
- 继续执行断点在TAG2的代码,进入到第3次循环,代码运行断点在TAG1处。
- 继续执行断点在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对象,因此这一次就能够正常执行了。
package org.hibernate.engine.jdbc.batch.internal;
public abstract class AbstractBatchImpl implements Batch {
......省略代码
private LinkedHashMap<String,PreparedStatement> statements = new LinkedHashMap<String,PreparedStatement>();
......省略代码
@Override
public PreparedStatement getBatchStatement(String sql, boolean callable) {
if ( sql == null ) {
throw new IllegalArgumentException( "sql must be non-null." );
}
PreparedStatement statement = statements.get( sql );
if ( statement == null ) {
statement = buildBatchStatement( sql, callable );
statements.put( sql, statement );
}
else {
LOG.debug( "Reusing batch statement" );
sqlStatementLogger().logStatement( sql );
}
return statement;
}
......省略代码
}
解决问题
知道了原因后,基本上也就知道对策了,那就是……重试至少要2次才有效,重试1次和不重试没有区别。因此实际业务代码里调整大致如下:
private LockTest optimisticSaveLockTest(LockTest lockTest) {
int i = 0;
boolean success = false;
while (!success) {
lockTest.setUpdateTime(new Date());
try {
lockTest = lockTestRepository.save(lockTest);
success = true;
// 并发下乐观锁冲突第一次会报ObjectOptimisticLockingFailureException;
// 第二次再保存时,由于JPA的bug导致第一次出错时已断开连接的PreparedStatement没有移除出缓存,第二次又取到了,于是会报Statement closed,
// 第三次尝试保存才是实际意义上的二次尝试,因此至少尝试保存三次
} catch (ObjectOptimisticLockingFailureException | JpaSystemException e) {
if (i < 3) {
i++;
log.error(
"LockTest乐观锁保存失败,尝试第{}次保存:{},数据为:{}",
i + 1,
e.getMessage(),
ObjectUtils.toJson(lockTest));
lockTest = lockTestRepository.findOne(lockTest.getId());
} else {
throw e;
}
}
}
return lockTest;
}