事故
一天下午，一条生产环境的告警打乱了所有人的开发节奏：“服务器处理请求的失败率增高至7%”。正要打开监控系统看看情况，又一条告警出现了：“服务响应时间已增加到了每个请求30秒”。赶紧看一眼监控，发现并不是某一个 api 出现问题，而是遍地开花。搜一下错误日志吧，如下：
Unable to acquire JDBC Connection; nested exception is org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection] with root cause java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30000ms.
数据库连接池请求不到，等了30秒然后挂掉了。好吧，初步猜测是哪些请求处理太慢了，把数据库连接全部占着，导致其他请求等待数据库连接池超时引发的吧。这时候新的告警又来了：“访问外界系统请求失败率提升”。进去看一眼，发现是我们在调用第三方验证码系统的请求，失败率已逐渐提高至100%，全是502，他们挂了。神奇的是，这个时候我们自己的服务恢复了，请求响应时间回到了正常水平，失败率也逐渐只剩下发验证码的 api 居高不下。看一眼这个调用第三方服务的 api 监控，发现在过去的10分钟里，该 api 响应极慢，后来逐渐崩掉。
初步猜测落空
乍一看事故的原因似乎已经很明晰了，上面的现象也基本符合关于数据库连接池超时占用的猜测。举例来说（示例代码如下），在一个 @Transactional （数据库事务）中，先进行了数据库的调用，然后又进行了对外界服务 name-service 的调用，然后更新名字。在第三方服务完全挂掉之前，响应时间很长的时候，该 api 对数据库连接超时占用，这样的请求多起来以后，数据库连接池会被占满。其他线程都需要等待数据库连接，导致响应时间变长，或因等待超时而失败。等到第三方服务挂掉后，由于我们能直接拿到失败响应，便不会继续占用数据库连接，所以其他接口又好了起来。
@Transactional
public void changeName(String id) {
// db io
String abc = someRepository.findById(id);
// outgoing http io
String newName = nameServiceClient.fetchNewName(id);
abc.setName(newName);
}
上面的代码我们一般称为数据库和外界系统的混合 IO，是我们日常开发中极力避免的，可是为什么还是发生了呢？话不多说快去看一眼代码吧，以下是简化逻辑。
// Controller
@PostMapping("/one-time-passwords")
public ResponseEntity<SendOtpResponse> sendOtp(SendOtpRequest request) {
// 1. save db
String otp = otpService.createOtp(request.getTarget());
// 2. outgoing request
otpSender.send(otp);
return ResponseEntity.ok(SendOtpResponse.from(otp));
}
// Service
@Transactional
public String createOtp(String target) {
String code = createNew();
return otpRepository.save(new OTP(target, code));
}
// SmsSender
public void send(String code) {
sendHttpRequest(code);
}
我们的逻辑其实很简单，生成一个字符串作为 otp，把它存到数据库，然后使用 http 请求通过第三方系统发短信给终端用户。通过查看代码我们发现，数据库 IO 和 http 请求已经被分开了，并没有上面猜测中的问题。
本地复现
这个时候我们有点懵了，搞不清楚这个请求能够占用数据库连接的原因。想不到好办法，开始本地复现吧！为了模拟线上超时请求，我们把 OtpSender 的 send 方法改成强制等待：
// OtpSender
public void send(String code) {
try {
TimeUnit.SECONDS.sleep(100);
} catch (InterruptedException e) {
throw new RuntimeException(e);
}
}
既然是 HikariPool 的问题，那我们把 com.zaxxer 包的 debug 日志打开，然后启动本地服务，看下数据库连接池的占用情况吧。我们发现 com.zaxxer.hikari.pool.HikariPool 每隔30秒会打印一次连接池的状态信息：
HikariPool-1 - Pool stats (total=10, active=0, idle=10, waiting=0)
Hikari 连接池的默认状态是有10个连接，当前是有10个空闲。服务在本地启动了以后，我们先发送一个请求，过了一会连接池的状态更新如下：
HikariPool-1 - Pool stats (total=10, active=1, idle=9, waiting=0)
我们发现，即使过了很长时间，仍有一个连接被占用着。很奇怪但它能够反映生产环境上的情况，让我们多加几个请求，试一下能否产生同样的报错。由于连接池一共10个连接，我们先试上11个请求，如果到目前为止我们的理论正确的话，它们足够产生相应的报错了。另外10个请求发出，30秒过后，果然：
HikariPool-1 - Timeout failure stats (total=10, active=10, idle=0, waiting=1)
HikariPool-1 - Connection is not available, request timed out after 30002ms.
如生产环境一样，后面的请求会因等不到数据库连接池而失败，甚至其他接口，只要是需要访问数据库的请求也都会失败，直至超时的访问三方 api 的请求完成，数据库连接得到释放以后，其他接口才能正常访问。
找到原因
复现是复现了，可这是为什么呢？理解不了就上网搜一下吧！很快我们发现答案都指向了一个概念：Spring Open Session In View (OSIV)。简单来说，Session per request 是一种事务模式，将存储层的会话与所处理的请求的生命周期绑在一起，从而将业务组件与数据库连接的管理代码解耦。这种模式方便了 hibernate 中 lazy load 的使用。Spring 为此有自己的实现，叫 OpenSessionInViewInterceptor，用以提高开发者的生产效率。
这个 OpenSessionInViewInterceptor 是默认开启的，它开启时会对服务器处理的请求有以下影响：
- 当请求到达 spring 时，
OpenSessionInViewInterceptor会开启一个Hibernate session，这些 session 并不会直接连接数据库。 - 本次请求的处理过程中，每次用到存储层会话时，都会使用上面已经创建了的 session。
- 当请求处理结束时，
OpenSessionInViewInterceptor会把之前开启的那个 session 关闭。
它的逻辑是，让框架来处理存储层的会话，让开发者更注重业务相关的实现，而非数据库连接这种看起来比较底层的操作，从而提升开发效率。
了解了 OSIV 以后，我们再回过头来看自己的代码，发现虽然我们没有在数据库 IO 和外界系统 IO 共同存在的方法外加 @Transactional 来让它们共处一次事务，但在 service 层的事务结束后，hibernate session 并没有结束，服务与数据库之间的连接也并没有关闭，而是等到了外界请求结束，我们的服务返回响应时，才关闭数据库连接。
为了进一步理解并证实这个逻辑，我们更改本地代码为：
// OtpController
@PostMapping("/one-time-passwords")
public ResponseEntity<SendOtpResponse> sendOtp(SendOtpRequest request) throws InterruptedException {
log.info("sleep 1 start");
Thread.sleep(30_000);
log.info("sleep 1 end");
log.info("connect db start");
otpService.findAll();
log.info("connect db end");
log.info("sleep 2 start");
Thread.sleep(30_000);
log.info("sleep 2 end");
return ResponseEntity.ok(SendOtpResponse.from("hello"));
}
可以看到关键的日志顺序与相关解读如下：
# 进入请求
Mapped to xxxxxx#sendOtp()
# 启用 OpenEntityManagerInViewInterceptor
Opening JPA EntityManager in OpenEntityManagerInViewInterceptor
sleep 1 start
# 在 sleep 1 期间，虽然有 hibernate session，但是此时并没有过数据库访问，因此也没有占用数据库连接池
HikariPool-1 - Pool stats (total=10, active=0, idle=10, waiting=0)
sleep 1 end
connect db start
# 复用已有 hibernate session
Found thread-bound EntityManager [SessionImpl(473158969<open>)] for JPA transaction
Creating new transaction with name [org.springframework.data.jpa.repository.support.SimpleJpaRepository.findAll]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT,readOnly
# 开启事务
begin
# 查询语句
select xxxxxx from xxxxxx
# 提交事务
committing
Resetting read-only flag of JDBC Connection [HikariProxyConnection@917818296 wrapping conn0: url=jdbc:h2:mem:db user=TEST]
# 没有关闭 EntityManager (hibernate session)
Not closing pre-bound JPA EntityManager after transaction
connect db end
sleep 2 start
# 在访问过数据库之后，虽然事务已经提交，但是 hibernate session 并没有关闭，且仍然占用连接池
HikariPool-1 - Pool stats (total=10, active=1, idle=9, waiting=0)
sleep 2 end
# 在响应返回之前才关掉 EntityManager (hibernate session)
Closing JPA EntityManager in OpenEntityManagerInViewInterceptor
Completed 200 OK
看起来 OSIV 的确是这次事故的根源了。
问题解决
既然道理明白了，我们就关闭 OSIV 来看下问题是否解决。在 application.yml 里面加上 spring.jpa.open-in-view=false，然后重新启动服务，安排上20个并发请求，发现此时并不会造成数据库连接的长期占用，Hikari 连接池也始终在用的时候才会 active，在测试中所有的连接池日志中 active 都是 0，问题得到了解决。
需要注意的是，在禁用 OSIV 以后，它所带来的便利也没有了，比如一些默认为 lazy fetch 的 ToMany 关系可能会抛出 LazyInitializationException。由于项目中有较多的集成测试，只要测试全过，便可以保证现有代码中没有 lazy fetch 的情况。再加上大家一起看了实体间的关系，更加确认了此项更改的安全性。
将更改部署到 staging 环境，并做全面的端到端回归测试以后，我们将更改部署到了生产环境，一切又恢复了平静。
其他
如前面所说，Session per request 可以让开发者更关注业务，减少在管理数据库连接上浪费时间，从而提升开发效率。多数情况确实是这样的，但也正是因为一些工具的过于便捷，导致一些本该由开发者积极思考的问题被忽略。正如这次的数据库连接池问题，或许默认关闭 OSIV，可以更好地让开发者去主动思考连接的建立与释放呢？
