hibernate缓存相关问题排查

*文中表和字段均为虚构

一、问题现象描述

1、某次需求中，给tb_student表增加字段nick_name(NOT NULL DEFAULT ‘’)，并且只有在这条链路才会写nick_name：
INSERT INTO tb_student (name,nick_name,gender,status) VALUES (‘jack’,‘jjjjack’,1,1);
之前原有链路（后文称链路2）均为
INSERT INTO tb_student (name,gender,status) VALUES (‘ming’,1,1);

id	name	nick_name	gender	status
1	jack	jjjjack	1	1
3	ming		1	1

2、测试无问题，线上观察无问题
3、同事在做其他需求时，跑单测时，发现链路2必现报错(详细异常堆栈省略)：

org.springframework.dao.DataIntegrityViolationException: could not execute statement; SQL [n/a]; constraint [null]; nested exception is org.hibernate.exception.ConstraintViolationException: could not execute statement
......
Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLIntegrityConstraintViolationException: Column 'nick_name' cannot be null
......

但是如果启动服务，直接请求http接口，则无问题
4、某天线上也出现类似报错，但是之前一礼拜包括之后一礼拜再未出现报错（能查到日志）。

因此以上可以总结为两个问题：

• 问题1：http调用和单测现象不一致
• 问题2：线上偶发报错

二、问题排查

就这个诡异的现象，让排查无从下手。

1、异常定位

首先定位异常发生代码，发现流程为：
1、生成student数据，初始状态为1，插入tb_student表
2、事务中更新tb_course表、tb_teacher表。
3、更新步骤1中student状态为2，并update到tb_student表。上述异常，就是发生在这一步。

    public void deal() {
        Student student = Student.builder()
                .name("ming")
                .gender(1)
                .status(1)
                .build();
        studentRepo.save(student);
        studentRepo.flush();

        try {

            transactionTemplate.execute(t -> {
                QCourse qCourse = QCourse.course;
                jpaQueryFactory.update(qCourse);

                QTeacher qTeacher = QTeacher.teacher;
                jpaQueryFactory.update(qTeacher);
                return t;
            });
        } catch (Exception e) {

        } finally {
            student.setStatus(2);
            studentRepo.save(student);
            studentRepo.flush();
        }
    }

2、止损

因为线上也出现相似报错，为了尽快止损，所以在该链路中生成student并插入tb_student时，给student的nickName赋予默认值空字符串“”，这样在后续更新时，student的nickName就不是null，就不会再报错Column ‘nick_name’ cannot be null。

        Student student = Student.builder()
                .name("ming")
                .nickName("")
                .gender(1)
                .status(1)
                .build();
        studentRepo.save(student);
        studentRepo.flush();

3、具体原因排查

3.1 问题1：http调用和单测现象不一致

假想1 ：单测并不会真正启动spring容器，所以单测不行，http接口可以

经排查和实践，该假想错误。

假想2：缓存影响

通过搜索引擎查询，发现hibernate是有缓存机制的，一级缓存自动开启，二级缓存需要手动配置。
并且通过单测和http调用反复对比，终于发现了些许蛛丝马迹：
1）单测调用时，执行到步骤三的update时，hibernate会打印两条sql：

• select from tb_student where id=?
• update tb_student set nick_name=?, status=? where id=?

也就是说这种方式下，需要先查询数据库中最新数据，再和当前数据进行对比，决定需要更新哪些字段。这个时候数据库里的nick_name是“”，而程序里nickName是null，所以hibernate理解为nickName也要更新为null，也就报错了。
2）http接口调用时，则只打印一条：

• update tb_student set status=? where id=?

而在这种方式下，不需要查询数据库，说明一定是存在了缓存，而且缓存里nick_name也是null，所以不更新nick_name，只有status发生了改变，只需要更新status。
3）所以，我就想是不是有某些缓存配置，是只有在真正部署后才会生效。于是我去查询配置文件里的hibernate的各种配置

  jpa:
    properties:
      hibernate:
        hbm2ddl.auto: none
        show_sql: true
        format_sql: true
        dialect: org.hibernate.dialect.MySQLDialect
        enable_lazy_load_no_trans: true
    open-in-view: true

这里面看起来比较像的就是enable_lazy_load_no_trans和open-in-view。于是我分别试了一下，终于被我发现了端倪！
将open-in-view改为false后，无论是单测还是http调用，都会必现不能为null异常！
那么open-in-view这个配置是做什么的：
jpa总结
总的来说，open-in-view=true时，就是能在web请求进来时，通过OpenEntityManagerInViewInterceptor创建一个session，并且之后这个请求处理过程中都不会关闭，直到全部执行完毕后才会关闭。

原因最终定位：

那么结合hibernate打印的sql，单测报错而http调用不报错的原因显而易见：

流程	open-in-view=true	false
生成并插入student	session1	session2
事务更新teacher和course	session1	session3
更新student状态	session1	session4

当启动服务之后调用http接口时，就能通过OpenEntityManagerInViewInterceptor创建session并在之后和db交互中一直沿用同一个session，也就是一直存在一级缓存，当步骤3再去更新student时，就会直接读取一级缓存里的值，和更新数据作比较，发现只有status需要更新，也就只执行这样的update sql，所以不会报错：

• update tb_student set status=? where id=?

	id	name	nick_name	gender	status
缓存	3	ming	null	1	1
更新数据	3	ming	null	1	2

而如果是跑单测，就相当于调用内部方法，无法被这个interceptor拦截，每一次和数据库交互都会开启一个新session；新session里是不存在之前的缓存的，所以就会去读取数据库里的数据，再和更新数据作比较，判断出需要更新nick_name和status，进而发生了不能为null的异常：

• select from tb_student where id=?
• update tb_student set nick_name=?, status=? where id=?

	id	name	nick_name	gender	status
数据库中数据	3	ming	“”	1	1
更新数据	3	ming	null	1	2

3.2 问题2：线上偶发报错

线上都是通过外部服务对该服务进行http接口调用的，又已知线上配置open-in-view=true，那为什么线上还会出现报错？
通过对日志进行排查，发现报错前，步骤二都出现了异常，事务发生了回滚。揪住这个线索，我又产生了两个猜想：

假想1：由于事务回滚，session被关闭，更新student时新建了另一个session

针对该猜想，我对该场景进行了debug，发现整个请求，包括回滚前和回滚后，都是同一个session，并未发生清除和新建的情况，所以该猜想不成立。

假想2：由于事务回滚，session中的缓存被清除

同样的，直接debug，从org.hibernate.engine.transaction.internal.TransactionImpl#rollback开始：

• TransactionImpl

	@Override
	public void rollback() {
		// todo : may need a "JPA compliant" flag here

		TransactionStatus status = getStatus();
		if ( status == TransactionStatus.ROLLED_BACK || status == TransactionStatus.NOT_ACTIVE ) {
			// Allow rollback() calls on completed transactions, just no-op.
			LOG.debug( "rollback() called on an inactive transaction" );
			return;
		}

		if ( !status.canRollback() ) {
			throw new TransactionException( "Cannot rollback transaction in current status [" + status.name() + "]" );
		}

		LOG.debug( "rolling back" );
		if ( status != TransactionStatus.FAILED_COMMIT || allowFailedCommitToPhysicallyRollback() ) {
			internalGetTransactionDriverControl().rollback();
		}
	}

• JdbcResourceLocalTransactionCoordinatorImpl

		@Override
		public void rollback() {
			if ( rollbackOnly || getStatus() == TransactionStatus.ACTIVE ) {
				rollbackOnly = false;
				jdbcResourceTransaction.rollback();
				JdbcResourceLocalTransactionCoordinatorImpl.this.afterCompletionCallback( false );
			}

			// no-op otherwise.
		}
		
	private void afterCompletionCallback(boolean successful) {
		log.tracef( "ResourceLocalTransactionCoordinatorImpl#afterCompletionCallback(%s)", successful );
		final int statusToSend = successful ? Status.STATUS_COMMITTED : Status.STATUS_UNKNOWN;
		synchronizationRegistry.notifySynchronizationsAfterTransactionCompletion( statusToSend );

		transactionCoordinatorOwner.afterTransactionCompletion( successful, false );
		for ( TransactionObserver observer : observers() ) {
			observer.afterCompletion( successful, false );
		}
	}

• SessionImpl

	@Override
	public void afterTransactionCompletion(boolean successful, boolean delayed) {
		log.tracef( "SessionImpl#afterTransactionCompletion(successful=%s, delayed=%s)", successful, delayed );

		if ( !isClosed() || waitingForAutoClose ) {
			if ( autoClear ||!successful ) {
				internalClear();
			}
		}
    //省略
	}
	
	private void internalClear() {
		persistenceContext.clear();
		actionQueue.clear();

		final ClearEvent event = new ClearEvent( this );
		for ( ClearEventListener listener : listeners( EventType.CLEAR ) ) {
			listener.onClear( event );
		}
	}

• StatefulPersistenceContext

	@Override
	public void clear() {
		//省略
		arrayHolders.clear();
		entitiesByKey.clear();
		entitiesByUniqueKey.clear();
		entityEntryContext.clear(); //清除缓存
//		entityEntries.clear();
		parentsByChild.clear();
		entitySnapshotsByKey.clear();
		collectionsByKey.clear();
		collectionEntries.clear();
		if ( unownedCollections != null ) {
			unownedCollections.clear();
		}
		proxiesByKey.clear();
		nullifiableEntityKeys.clear();
		if ( batchFetchQueue != null ) {
			batchFetchQueue.clear();
		}
		// defaultReadOnly is unaffected by clear()
		hasNonReadOnlyEntities = false;
		if ( loadContexts != null ) {
			loadContexts.cleanup();
		}
		naturalIdXrefDelegate.clear();
	}

可以发现，在数据库回滚结束后，还会去清除session中所有缓存！这也就说明了，线上报错的原因：
因为前置事务出现异常，发生回滚，回滚结束后，还会将所有的缓存都清除。所以此时步骤三更新数据时，因为不存在缓存，还是会先去数据库查询，和问题1单测的现象一致，发生异常

• select from tb_student where id=?
• update tb_student set nick_name=?, status=? where id=?

	id	name	nick_name	gender	status
数据库中数据	3	ming	“”	1	1
更新数据	3	ming	null	1	2

三、总结

该问题无法稳定复现，而且由于对hibernate基本不了解，定位和排查也是比较困难。排查问题还是得大胆猜想，仔细验证，问题总能定位的。今天又学到了！