原文链接
出错问题复盘
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 方的接口里，一定要搞清楚他的返回信息，再抛出相应的信息，要不出现这种的就可能会出问题。
![[天堂之门+模拟执行]2021羊城杯oddcode](https://img2023.cnblogs.com/blog/3315787/202407/3315787-20240711170736944-40869214.png)
