事故

一天下午龙誊，一條生產(chǎn)環(huán)境的告警打亂了所有人的開發(fā)節(jié)奏：“服務(wù)器處理請求的失敗率增高至7%”趟大。正要打開監(jiān)控系統(tǒng)看看情況，又一條告警出現(xiàn)了：“服務(wù)響應(yīng)時間已增加到了每個請求30秒”罕伯。趕緊看一眼監(jiān)控叽讳，發(fā)現(xiàn)并不是某一個 api 出現(xiàn)問題岛蚤，而是遍地開花。搜一下錯誤日志吧，如下：

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.

數(shù)據(jù)庫連接池請求不到届腐，等了30秒然后掛掉了蜂奸。好吧犁苏，初步猜測是哪些請求處理太慢了，把數(shù)據(jù)庫連接全部占著扩所，導(dǎo)致其他請求等待數(shù)據(jù)庫連接池超時引發(fā)的吧围详。這時候新的告警又來了：“訪問外界系統(tǒng)請求失敗率提升”。進去看一眼，發(fā)現(xiàn)是我們在調(diào)用第三方驗證碼系統(tǒng)的請求助赞，失敗率已逐漸提高至100%买羞，全是502，他們掛了雹食。神奇的是畜普，這個時候我們自己的服務(wù)恢復(fù)了群叶，請求響應(yīng)時間回到了正常水平吃挑，失敗率也逐漸只剩下發(fā)驗證碼的 api 居高不下〗至ⅲ看一眼這個調(diào)用第三方服務(wù)的 api 監(jiān)控舶衬，發(fā)現(xiàn)在過去的10分鐘里，該 api 響應(yīng)極慢赎离，后來逐漸崩掉逛犹。

初步猜測落空

乍一看事故的原因似乎已經(jīng)很明晰了，上面的現(xiàn)象也基本符合關(guān)于數(shù)據(jù)庫連接池超時占用的猜測蟹瘾。舉例來說（示例代碼如下）圾浅，在一個 @Transactional （數(shù)據(jù)庫事務(wù)）中，先進行了數(shù)據(jù)庫的調(diào)用憾朴，然后又進行了對外界服務(wù) name-service 的調(diào)用狸捕，然后更新名字。在第三方服務(wù)完全掛掉之前众雷，響應(yīng)時間很長的時候灸拍，該 api 對數(shù)據(jù)庫連接超時占用，這樣的請求多起來以后砾省，數(shù)據(jù)庫連接池會被占滿鸡岗。其他線程都需要等待數(shù)據(jù)庫連接，導(dǎo)致響應(yīng)時間變長编兄，或因等待超時而失敗轩性。等到第三方服務(wù)掛掉后，由于我們能直接拿到失敗響應(yīng)狠鸳，便不會繼續(xù)占用數(shù)據(jù)庫連接揣苏，所以其他接口又好了起來。

@Transactional
public void changeName(String id) {
    // db io
    String abc = someRepository.findById(id);
    // outgoing http io
    String newName = nameServiceClient.fetchNewName(id);
    abc.setName(newName);
}

上面的代碼我們一般稱為數(shù)據(jù)庫和外界系統(tǒng)的混合 IO件舵，是我們?nèi)粘ｉ_發(fā)中極力避免的卸察，可是為什么還是發(fā)生了呢？話不多說快去看一眼代碼吧铅祸，以下是簡化邏輯坑质。

// 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，把它存到數(shù)據(jù)庫涡扼，然后使用 http 請求通過第三方系統(tǒng)發(fā)短信給終端用戶稼跳。通過查看代碼我們發(fā)現(xiàn)，數(shù)據(jù)庫 IO 和 http 請求已經(jīng)被分開了壳澳，并沒有上面猜測中的問題岂贩。

本地復(fù)現(xiàn)

這個時候我們有點懵了，搞不清楚這個請求能夠占用數(shù)據(jù)庫連接的原因巷波。想不到好辦法萎津，開始本地復(fù)現(xiàn)吧！為了模擬線上超時請求抹镊，我們把 OtpSender 的 send 方法改成強制等待：

// OtpSender
public void send(String code) {
    try {
        TimeUnit.SECONDS.sleep(100);
    } catch (InterruptedException e) {
        throw new RuntimeException(e);
    }
}

既然是 HikariPool 的問題锉屈，那我們把 com.zaxxer 包的 debug 日志打開，然后啟動本地服務(wù)垮耳，看下數(shù)據(jù)庫連接池的占用情況吧颈渊。我們發(fā)現(xiàn) com.zaxxer.hikari.pool.HikariPool 每隔30秒會打印一次連接池的狀態(tài)信息：

HikariPool-1 - Pool stats (total=10, active=0, idle=10, waiting=0)

Hikari 連接池的默認狀態(tài)是有10個連接，當(dāng)前是有10個空閑终佛。服務(wù)在本地啟動了以后俊嗽，我們先發(fā)送一個請求，過了一會連接池的狀態(tài)更新如下：

HikariPool-1 - Pool stats (total=10, active=1, idle=9, waiting=0)

我們發(fā)現(xiàn)铃彰，即使過了很長時間绍豁，仍有一個連接被占用著。很奇怪但它能夠反映生產(chǎn)環(huán)境上的情況牙捉，讓我們多加幾個請求竹揍，試一下能否產(chǎn)生同樣的報錯。由于連接池一共10個連接邪铲，我們先試上11個請求芬位，如果到目前為止我們的理論正確的話，它們足夠產(chǎn)生相應(yīng)的報錯了带到。另外10個請求發(fā)出昧碉，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.

如生產(chǎn)環(huán)境一樣揽惹，后面的請求會因等不到數(shù)據(jù)庫連接池而失敗晌纫，甚至其他接口，只要是需要訪問數(shù)據(jù)庫的請求也都會失敗永丝，直至超時的訪問三方 api 的請求完成，數(shù)據(jù)庫連接得到釋放以后箭养，其他接口才能正常訪問慕嚷。

找到原因

復(fù)現(xiàn)是復(fù)現(xiàn)了，可這是為什么呢？理解不了就上網(wǎng)搜一下吧喝检！很快我們發(fā)現(xiàn)答案都指向了一個概念：Spring Open Session In View (OSIV)嗅辣。簡單來說，Session per request 是一種事務(wù)模式挠说，將存儲層的會話與所處理的請求的生命周期綁在一起澡谭，從而將業(yè)務(wù)組件與數(shù)據(jù)庫連接的管理代碼解耦。這種模式方便了 hibernate 中 lazy load 的使用损俭。Spring 為此有自己的實現(xiàn)蛙奖，叫 OpenSessionInViewInterceptor，用以提高開發(fā)者的生產(chǎn)效率杆兵。

這個 OpenSessionInViewInterceptor 是默認開啟的雁仲，它開啟時會對服務(wù)器處理的請求有以下影響：

1. 當(dāng)請求到達 spring 時，OpenSessionInViewInterceptor 會開啟一個 Hibernate session琐脏，這些 session 并不會直接連接數(shù)據(jù)庫畜挥。
2. 本次請求的處理過程中介却，每次用到存儲層會話時，都會使用上面已經(jīng)創(chuàng)建了的 session。
3. 當(dāng)請求處理結(jié)束時诵竭，OpenSessionInViewInterceptor 會把之前開啟的那個 session 關(guān)閉。

它的邏輯是碟绑，讓框架來處理存儲層的會話剖膳，讓開發(fā)者更注重業(yè)務(wù)相關(guān)的實現(xiàn)，而非數(shù)據(jù)庫連接這種看起來比較底層的操作政钟，從而提升開發(fā)效率路克。

了解了 OSIV 以后，我們再回過頭來看自己的代碼养交，發(fā)現(xiàn)雖然我們沒有在數(shù)據(jù)庫 IO 和外界系統(tǒng) IO 共同存在的方法外加 @Transactional 來讓它們共處一次事務(wù)精算，但在 service 層的事務(wù)結(jié)束后，hibernate session 并沒有結(jié)束碎连，服務(wù)與數(shù)據(jù)庫之間的連接也并沒有關(guān)閉灰羽，而是等到了外界請求結(jié)束，我們的服務(wù)返回響應(yīng)時鱼辙，才關(guān)閉數(shù)據(jù)庫連接廉嚼。

為了進一步理解并證實這個邏輯，我們更改本地代碼為：

// 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"));
}

可以看到關(guān)鍵的日志順序與相關(guān)解讀如下：

# 進入請求
Mapped to xxxxxx#sendOtp()
# 啟用 OpenEntityManagerInViewInterceptor
Opening JPA EntityManager in OpenEntityManagerInViewInterceptor
sleep 1 start
# 在 sleep 1 期間倒戏，雖然有 hibernate session怠噪，但是此時并沒有過數(shù)據(jù)庫訪問，因此也沒有占用數(shù)據(jù)庫連接池
HikariPool-1 - Pool stats (total=10, active=0, idle=10, waiting=0)
sleep 1 end
connect db start
# 復(fù)用已有 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
# 開啟事務(wù)
begin
# 查詢語句
select xxxxxx from xxxxxx
# 提交事務(wù)
committing
Resetting read-only flag of JDBC Connection [HikariProxyConnection@917818296 wrapping conn0: url=jdbc:h2:mem:db user=TEST]
# 沒有關(guān)閉 EntityManager (hibernate session)
Not closing pre-bound JPA EntityManager after transaction
connect db end
sleep 2 start
# 在訪問過數(shù)據(jù)庫之后杜跷，雖然事務(wù)已經(jīng)提交傍念，但是 hibernate session 并沒有關(guān)閉矫夷，且仍然占用連接池
HikariPool-1 - Pool stats (total=10, active=1, idle=9, waiting=0)
sleep 2 end
# 在響應(yīng)返回之前才關(guān)掉 EntityManager (hibernate session)
Closing JPA EntityManager in OpenEntityManagerInViewInterceptor
Completed 200 OK

看起來 OSIV 的確是這次事故的根源了。

問題解決

既然道理明白了憋槐，我們就關(guān)閉 OSIV 來看下問題是否解決双藕。在 application.yml 里面加上 spring.jpa.open-in-view=false，然后重新啟動服務(wù)阳仔，安排上20個并發(fā)請求忧陪，發(fā)現(xiàn)此時并不會造成數(shù)據(jù)庫連接的長期占用，Hikari 連接池也始終在用的時候才會 active近范，在測試中所有的連接池日志中 active 都是 0嘶摊，問題得到了解決。

需要注意的是顺又，在禁用 OSIV 以后更卒，它所帶來的便利也沒有了，比如一些默認為 lazy fetch 的 ToMany 關(guān)系可能會拋出 LazyInitializationException稚照。由于項目中有較多的集成測試蹂空，只要測試全過，便可以保證現(xiàn)有代碼中沒有 lazy fetch 的情況果录。再加上大家一起看了實體間的關(guān)系上枕，更加確認了此項更改的安全性。

將更改部署到 staging 環(huán)境弱恒，并做全面的端到端回歸測試以后辨萍，我們將更改部署到了生產(chǎn)環(huán)境，一切又恢復(fù)了平靜返弹。

其他

如前面所說锈玉，Session per request 可以讓開發(fā)者更關(guān)注業(yè)務(wù)，減少在管理數(shù)據(jù)庫連接上浪費時間义起，從而提升開發(fā)效率拉背。多數(shù)情況確實是這樣的，但也正是因為一些工具的過于便捷默终，導(dǎo)致一些本該由開發(fā)者積極思考的問題被忽略椅棺。正如這次的數(shù)據(jù)庫連接池問題，或許默認關(guān)閉 OSIV齐蔽，可以更好地讓開發(fā)者去主動思考連接的建立與釋放呢两疚？