原文連結
出錯問題覆盤
1、問題回顧
早上 6:00 多開始報警，資料庫連線池獲取不到連線，日誌的報錯如下：
org.mybatis.spring.MyBatisSystemException: nested exception is org.apache.ibatis.exceptions.PersistenceException: ### Error querying database. Cause: org.springframework.jdbc.CannotGetJdbcConnectionException: Failed to obtain JDBC Connection; nested exception is java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30000ms. ### The error may exist in class path resource [com/ xxx/xxxMapper.xml] ### The error may involve xxx.getListByOrgIdOrRealName ### The error occurred while executing a query ### Cause: org.springframework.jdbc.CannotGetJdbcConnectionException: Failed to obtain JDBC Connection; nested exception is java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30000ms
導致的結果就是：
40 多筆提現失敗，因為那個時候剛好有客戶要提現
2、定位問題
2.1 首先看應用日誌
看應用日誌，最主要的資訊就是 Failed to obtain JDBC Connection、HikariPool-1 - Connection is not available，request timed out after 30000ms
1、看這個資訊的第一反應就是資料庫連線是不是被打滿了，先去看了資料庫監控，發現連線數很平穩，沒有太大的變化(zabbix 的監控)。
2、然後資料庫連線沒有很多的話，第 2 步去看看 Hikari 連線池的配置，配置如下：
spring.datasource.hikari.connectionTimeout = 100000
spring.datasource.hikari.validationTimeout = 300000
spring.datasource.hikari.maximum-pool-size = 200
spring.datasource.hikari.minimum-idle = 503、當時是想著把 maximum-pool-size=500(就是 200 調整為 500)，當然此時還沒有改，也就沒有釋出、重啟
2.2 看 jstack 日誌
2.1 jsatck 日誌如下
“xxxx_Worker-1” #206 prio=5 os_prio=0 tid=0x00007f508f6ab000 nid=0x1705 waiting on condition [0x00007f4f61818000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) parking to wait for <0x0000000720ab5208> (a java.util.concurrent.locks.AbstractQueuedSynchronizerC o n d i t i o n O b j e c t ) a t j a v a . u t i l . c o n c u r r e n t . l o c k s . L o c k S u p p o r t . p a r k ( L o c k S u p p o r t . j a v a : 175 ) a t j a v a . u t i l . c o n c u r r e n t . l o c k s . A b s t r a c t Q u e u e d S y n c h r o n i z e r ConditionObject) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) at java.util.concurrent.locks.AbstractQueuedSynchronizerConditionObject)atjava.util.concurrent.locks.LockSupport.park(LockSupport.java:175)atjava.util.concurrent.locks.AbstractQueuedSynchronizerConditionObject.await(AbstractQueuedSynchronizer.java:2039) at java.util.concurrent.ArrayBlockingQueue.put(ArrayBlockingQueue.java:353) at ch.qos.logback.core.AsyncAppenderBase.putUninterruptibly(AsyncAppenderBase.java:181) at ch.qos.logback.core.AsyncAppenderBase.puto r i g i n a l originaloriginalXaWJEOe0(AsyncAppenderBase.java:172) at ch.qos.logback.core.AsyncAppenderBase.puto r i g i n a l originaloriginalXaWJEOe0$accessor67 X f D E R 7 ( A s y n c A p p e n d e r B a s e . j a v a ) a t c h . q o s . l o g b a c k . c o r e . A s y n c A p p e n d e r B a s e 67XfDER7(AsyncAppenderBase.java) at ch.qos.logback.core.AsyncAppenderBase67XfDER7(AsyncAppenderBase.java)atch.qos.logback.core.AsyncAppenderBaseauxiliary$fPj3kqdc.call(Unknown Source) at org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance.InstMethodsInter.intercept(InstMethodsInter.java:86)
2.2 觀察 jstack 日誌分析
透過看 jstack 日誌發現，有幾百個 parking to wait for <0x0000000720ab5208> 這個日誌，而且下面也是相同的輸出，呼叫棧是在 logback 的一個 putUniteruptibly 方法上，然後去追蹤應用裡的呼叫棧，發現都是卡在了列印日誌的輸出上(log.info("{}", xxx))。
2.3 猜測
2.3.1 看日誌配置
因為都是卡在列印日誌上，所以想列印日誌是不是有什麼問題。然後就想到了前一天剛上線了應用日誌的非同步列印配置，配置如下 ：
<!--設定為非同步列印--> <appender name="debug-async-appender" class="ch.qos.logback.classic.AsyncAppender"> <!-- 更改預設的佇列的深度,該值會影響效能.預設值為256 --> <queueSize>512</queueSize> <appender-ref ref="debugAppender"/> </appender> <!--設定為非同步列印--> <appender name="error-async-appender" class="ch.qos.logback.classic.AsyncAppender"> <discardingThreshold >0</discardingThreshold> <!-- 更改預設的佇列的深度,該值會影響效能.預設值為256 --> <queueSize>512</queueSize> <appender-ref ref="errorAppender"/> </appender>
2.3.2 追蹤 logback 非同步列印方法
因為看 jstack 日誌的時候發現呼叫棧是：
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
at java.util.concurrent.ArrayBlockingQueue.put(ArrayBlockingQueue.java:353)
at ch.qos.logback.core.AsyncAppenderBase.putUninterruptibly(AsyncAppenderBase.java:181)可以看到是有一個阻塞佇列在阻塞排隊。我們直接看原始碼
2.3.3 看原始碼
//這個就是阻塞佇列的宣告。
BlockingQueue<E> blockingQueue;
private void putUninterruptibly(E eventObject) {
boolean interrupted = false;
//可以看到這裡就是一個 while true 的死迴圈，然後不斷的往 blockingQueue 中放物件
try {
while(true) {
try {
this.blockingQueue.put(eventObject);
return;
} catch (InterruptedException var7) {
interrupted = true;
}
}
} finally {
if (interrupted) {
Thread.currentThread().interrupt();
}
}
}
//再看一下 ArrayBlockingQueue 的 put 操作
public void put(E e) throws InterruptedException {
Objects.requireNonNull(e);
//可以看到這裡就是一個鎖操作，加鎖
final ReentrantLock lock = this.lock;
lock.lockInterruptibly();
try {
while (count == items.length)
notFull.await();//一直阻塞等待
enqueue(e);
} finally {
lock.unlock();
}
}
由此可以看出，因為配置的是有界佇列，512，然後此時可能滿了，然後新來的物件就要阻塞等待出隊，然後自己才能入隊。所以才會在 jstack 日誌中看到 400 多個 wait for 同一個物件的日誌
2.4 嘗試解決
2.4.1 修改 logback 配置
<!--設定為非同步列印--> <appender name="debug-async-appender" class="ch.qos.logback.classic.AsyncAppender"> <!-- 更改預設的佇列的深度,該值會影響效能.預設值為256 --> <queueSize>512</queueSize> <appender-ref ref="debugAppender"/> <neverBlock>true</neverBlock> </appender> <!–設定為非同步列印–> <appender name=“error-async-appender” class=“ch.qos.logback.classic.AsyncAppender”> <discardingThreshold >0</discardingThreshold> <!-- 更改預設的佇列的深度,該值會影響效能.預設值為256 --> <queueSize>512</queueSize> <appender-ref ref=“errorAppender”/> <neverBlock>true</neverBlock> </appender>
//AsyncAppenderBase 的方法
private void put(E eventObject) {
//配置了之後，就走 offer 方法
if (this.neverBlock) {
this.blockingQueue.offer(eventObject);
} else {
this.putUninterruptibly(eventObject);
}
}
//看一下 offer 方法
public boolean offer(E e) {
Objects.requireNonNull(e);
final ReentrantLock lock = this.lock;
lock.lock();
try {
//如果列隊滿了，直接返回 false
if (count == items.length)
return false;
else {
//否則入隊
enqueue(e);
return true;
}
} finally {
lock.unlock();
}
}
也就是說，設定了 neverBlock 之後，就會把這些丟棄掉，不入隊，也就是說可能會丟日誌
2.5 測試環境還原
測試環境還原的時候，因為猜測是資料庫連線池的問題，所以修改了連線池配置，最小、最大設定為 5，去壓測，還是沒有還原這個情況。然後繼續看應用日誌有新發現
2.6 日誌大小跟其他同區間的比很大
相同的日誌切割，發現 6 點的那個時間點特別大，其他的就幾十 M,但是 6 點區間的有 100 多 M，快 200M了，所以就看看到底是啥情況。然後就發現了，有一個身份證認證的異常資訊，返回的異常資訊特別大，導致了 log 的時候卡了。
就是說，本來 log.error("", e)，這個最多幾十 ms 左右就左右了，但是呢，這個物件特別大，然後就導致最終 io 寫入日誌資訊的時候耗時太長。
2.7 找到原因，分析驗證
2.7.1 找出程式碼中這種情況的日誌列印，然後把這段程式碼去除
2.7.2 分析
1)、因為這個是呼叫第 3 方的人臉識別的介面，介面返回的 Base64 的照片資訊，這個資訊很大，導致 logback 列印日誌寫這個日誌的時候很耗時。
2)、因為有些類、方法上加了 @Transactional，導致在 logback 執行的時候(logger.info/logger.error 在 finally 中執行)，連線沒有被釋放，所以其他的請求執行的時候獲取不到連線。
2.8 釋出上線
上線之後，第 2 天相同時間發現沒有再出現這樣的問題，至此解決
2.9 模擬那種場景，還原異常
2.9.1 程式碼
1.application.properties
#這裡為了模擬極限場景，直接將連線數置為 1 spring.datasource.hikari.connectionTimeout = 10000 spring.datasource.hikari.validationTimeout = 300000 spring.datasource.hikari.maximum-pool-size = 1 spring.datasource.hikari.minimum-idle = 1
2.logback-spring.xml
<appender name="error-async-appender" class="ch.qos.logback.classic.AsyncAppender">
<discardingThreshold >0</discardingThreshold>
<!-- 更改預設的佇列的深度,該值會影響效能.預設值為256 -->
<queueSize>512</queueSize>
<appender-ref ref="errorAppender"/>
</appender>
3.controller/service/mapper
//Controller
@Slf4j
@RequestMapping("/hikari-demo/")
@RestController
public class TestController {
@Resource
private TaskOrderService taskOrderService;
@GetMapping(“list”)
public List<TaskOrder> getList() {
return taskOrderService.selectByAll();
}
@GetMapping(“order”)
public TaskOrder selectById() {
return taskOrderService.selectById();
}
}
@Service
@Slf4j
public class TaskOrderServiceImpl implements TaskOrderService {
@Resource
private OrderMapper orderMapper;
@Transactional(readOnly = true)
@Override
public List<TaskOrder> selectByAll() {
List<TaskOrder> taskOrders = orderMapper.selectAll();
try {
log.info(“{}”, 1);
//這裡就是模擬日誌寫很大檔案的操作(大於資料庫連線池的連線超時時間)
TimeUnit.SECONDS.sleep(15);
} catch (Exception e) {
} finally {
}
return taskOrders;
}
@Override
public TaskOrder selectById() {
Long id = RandomUtil.randomLong(1000);
TaskOrder taskOrder = orderMapper.selectById(id);
try {
log.info(“{}”, id);
TimeUnit.SECONDS.sleep(15);
} catch (Exception e) {
} finally {
}
return taskOrder;
}
}
2.9.2 壓測
--同時用 10 個使用者 100 個請求去測試
ab -c 10 -n 100 http://localhost:8089/hikari-demo/order
ab -c 10 -n 100 http://localhost:8089/hikari-demo/list2.9.3 場景還原
2021-07-15 11:25:34.915 ERROR 31485 — [nio-8089-exec-2] o.a.c.c.C.[.[.[/].[dispatcherServlet] : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is org.mybatis.spring.MyBatisSystemException: nested exception is org.apache.ibatis.exceptions.PersistenceException:
Error querying database. Cause: org.springframework.jdbc.CannotGetJdbcConnectionException: Failed to obtain JDBC Connection; nested exception is java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 10004ms.
The error may exist in file [/Users/zhuzi/Desktop/hikari-demo/target/classes/mapper/OrderMapper.xml]
The error may involve com.bamboo.hikaridemo.mapper.OrderMapper.selectById
The error occurred while executing a query
Cause: org.springframework.jdbc.CannotGetJdbcConnectionException: Failed to obtain JDBC Connection; nested exception is java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 10004ms.] with root cause
java.sql.SQLTransientConnectionException**: HikariPool-1 - Connection is not available, request timed out after 10004ms**.
可以看到壓測開始 1 次執行後，第 2 次的時候就報了連線超時，獲取不到連線的錯誤
2.10 總結
至此，這個問題解決了，然後也還原了問題發出的場景，所以以後還是要注意引入一個技術的時候要多瞭解更多的核心原理。
2.10.1 列印日誌一定要注意，不能列印太大的資訊
尤其是呼叫第 3 方的介面裡，一定要搞清楚他的返回資訊，再丟擲相應的資訊，要不出現這種的就可能會出問題。