发布后第二天上午,接口全卡在 3 秒
12 月 18 号那次上线加了个订单导出功能,第二天上午十点,运维在群里 @ 我:订单查询接口 P99 从 40ms 涨到了 3000ms,超时率 12%。
第一反应是慢 SQL。打开 Druid 监控页(我们一直开着 /druid),看到的画面不太对:
ActiveCount : 20 / 20
PoolingCount : 0
WaitThreadCount : 137
MaxWait : 3000 ms
连接池被打满,137 个线程在排队。慢 SQL 的表现应该是活跃连接忽高忽低,我这个是死死贴着上限不动。
再看应用日志,满屏都是同一条:
Caused by: com.alibaba.druid.pool.GetConnectionTimeoutException:
wait millis 3000, active 20, maxActive 20, creating 0, runningSqlCount 20
注意 creating 0:说明池子不是"正在扩容中",而是彻底拿不出来了。
先分清是连接不够用,还是连接没还
这两种情况表现很像,处理方式完全不同。我的区分办法是重启后盯 ActiveCount 曲线:并发不够的话,高峰上去、高峰过后会回落;泄漏则是只涨不落。
重启一次,每 15 分钟记一个数:
| 时间 | QPS | ActiveCount |
|---|---|---|
| 10:05(重启) | 180 | 3 |
| 10:20 | 310 | 11 |
| 10:40 | 420 | 20(满) |
| 11:10 | 240 | 20(满) |
| 11:40 | 150 | 20(满) |
QPS 都掉回 150 了,活跃连接还挂在上限,基本可以断定是泄漏。
用 removeAbandoned 把"借条"打出来
Druid 有个 removeAbandoned 机制:连接被借出超过指定秒数还没归还,就强制回收,并在日志里打印这个连接被借出时的堆栈。这玩意儿是排查利器,但它是兜底回收,不是修复手段。
spring:
datasource:
druid:
remove-abandoned: true
remove-abandoned-timeout: 180
log-abandoned: true
打开后等了三分钟,日志里出来了:
2018-12-19 10:52:31 ERROR [Druid-ConnectionPool-Destroy-1987402336] -
abandon connection, owner thread: http-nio-8080-exec-7, connected at :
java.lang.Thread.getStackTrace(Thread.java:1552)
com.alibaba.druid.pool.DruidDataSource.getConnectionDirect(DruidDataSource.java:1231)
com.alibaba.druid.filter.FilterChainImpl.connection_connect(FilterChainImpl.java:156)
com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:1140)
com.xxx.service.ExportService.queryDetail(ExportService.java:68)
com.xxx.controller.ExportController.export(ExportController.java:31)
直接指到了 ExportService.java 第 68 行,就是我前一天写的代码。
问题代码:循环里的 return 把 close 跳过了
导出模块没走 MyBatis,是自己写的 JDBC 大批量查询,代码长这样:
public List<ExportRow> queryDetail(Long orderId) throws SQLException {
Connection conn = dataSource.getConnection();
PreparedStatement ps = conn.prepareStatement(DETAIL_SQL);
ps.setLong(1, orderId);
ResultSet rs = ps.executeQuery();
List<ExportRow> rows = new ArrayList<>();
while (rs.next()) {
if (rows.size() >= MAX_ROW) {
return rows; // 提前返回,下面三行 close 全被跳过
}
rows.add(buildRow(rs));
}
rs.close();
ps.close();
conn.close(); // 第 68 行拿的连接,永远走不到这里
return rows;
}
导出行数超过 5 万就会命中那个 return,三个 close 一个都不会执行。连接被业务线程一直捏着不撒手,Druid 池子里的 PoolingCount 慢慢归零。
隐蔽的地方在于:测试环境订单最多几千行,永远走不到这一行。上线后只有大客户的导出请求会触发,而且一次泄漏一个连接,攒够 20 个才炸,所以隔了一整晚才出事。
顺带说一句,while 循环里如果抛异常,同样会跳过 close,只是我们这次没踩到。
改法:try-with-resources
JDK 7 就有的语法,编译器会帮你生成 finally 里的 close,不管从哪个出口离开都会执行:
public List<ExportRow> queryDetail(Long orderId) throws SQLException {
List<ExportRow> rows = new ArrayList<>();
try (Connection conn = dataSource.getConnection();
PreparedStatement ps = conn.prepareStatement(DETAIL_SQL)) {
ps.setLong(1, orderId);
ps.setFetchSize(1000);
try (ResultSet rs = ps.executeQuery()) {
while (rs.next()) {
if (rows.size() >= MAX_ROW) {
break; // 改成 break,从循环出去而不是从方法出去
}
rows.add(buildRow(rs));
}
}
}
return rows;
}
这里有个我一开始搞混的点:try-with-resources 调用的 conn.close(),实际执行的是 DruidPooledConnection.close(),它不会真的断开 TCP 连接,只是把物理连接归还给池子并且把 abandoned 标记清掉。我专门翻了源码确认过,不然还真不敢这么改。
顺带把池子参数重算了一遍
之前的 maxActive: 200 是照着网上抄的,被 DBA 骂过一次。这次认真算了一下。
思路是:一条连接在理想状态下每秒能执行 1 / 平均耗时 条 SQL。从 Druid 监控的 SQL 执行时间分布看,我们订单库单次查询平均 18ms,那单连接理论上限约 55 QPS。单机目标峰值 400 QPS,纯计算 400 / 55 ≈ 7.3 条。再考虑三个因素:
- 一个请求里往往串行执行 3 到 5 条 SQL
- 慢查询会长时间占着连接不放
- 留 30% 余量应对毛刺
最后定在 20。DBA 给的硬上限是单库 100 个连接,我们 4 个应用实例,20 × 4 = 80,还有余量。
spring:
datasource:
druid:
initial-size: 5
min-idle: 5
max-active: 20
max-wait: 3000
time-between-eviction-runs-millis: 60000
min-evictable-idle-time-millis: 300000
validation-query: SELECT 1
test-while-idle: true
test-on-borrow: false # 千万别开,下面说原因
test-on-return: false
几个参数的实测体会:
maxWait 3000:拿不到连接最多等 3 秒就快速失败。拖着不报错会把 Tomcat 的 200 个工作线程全堵死,那才是真灾难。testOnBorrow:每次借连接都跑一次SELECT 1,我们压测时 TPS 从 4200 掉到 3600,掉了 14%。用testWhileIdle让后台线程 60 秒扫一次空闲连接就够。minIdle和initialSize设成一样,避免高峰期临时创建连接造成抖动。removeAbandoned我只在排查期开着,定位完就关了。它每 180 秒要全池扫描一次,而且会掩盖真实问题:连接被强制回收了,业务却不知道自己写错了。
修复前后在同一台机器上跑了压测(400 并发,持续 5 分钟):
| 指标 | 修复前 | 修复后 |
|---|---|---|
| TPS | 60 | 1350 |
| 错误率 | 12.3% | 0% |
| P99 响应时间 | 3000ms | 47ms |
小结
这次踩坑记下三条。
第一,判断"不够用"还是"没归还",看的是活跃连接曲线会不会回落,不是看峰值有多高。这个判断决定了后续是调参数还是改代码,方向搞反了会浪费大量时间。
第二,JDBC 手动关闭资源一律用 try-with-resources,别信自己写的 finally。项目里还有几处老代码是手写 close 的,我用这个命令扫了一遍:
grep -rn "getConnection()" --include=*.java src/ | grep -v "try ("
一共 6 处,都改成 try-with-resources 了。
第三,连接池不是越大越好。连接数超过数据库 CPU 能扛的并行度之后,加连接只会让上下文切换变多、每条 SQL 都变慢,最后集体超时。20 这个数字是算出来的,不是抄来的。