ARTICLE DETAIL

资讯详情

深耕网站建设与运营推广的一线实战洞察。

Druid连接池打满排查:从超时异常到连接泄漏定位

Druid连接池打满排查:从超时异常到连接泄漏定位 凌晨两点四十监控群里开始刷接口超时登录、订单查询、支付回调三个业务上完全不相干的接口同时开始变慢紧接着大面积报错。上去翻日志最扎眼的就是这一行com.alibaba.druid.pool.GetConnectionTimeoutException: wait millis 60000, active 20, maxActive 20, creating 0很多人看到这行异常的第一反应是连接池太小了把 maxActive 从 20 调到 100 就好了。我踩过这个坑那天我确实先调到了 100系统撑了大概四十分钟又挂了而且挂得更难看——数据库侧的连接数直接顶到了实例上限把隔壁两个服务一起拖下水。连接池打满这件事绝大多数时候不是池子小而是有连接借出去没还回来也就是典型的连接泄漏。这行异常里的每个数字都在告诉你现场发生了什么只是大部分人不愿意读它。这篇内容适合所有用 Java 连数据库的人看不管你是刚学 JDBC 的新手还是带团队的老兵只要你的系统里出现过GetConnectionTimeoutException、wait millis、active和maxActive打平的情况下面这套从日志到代码行的排查链路就能直接用。我会先讲清楚这行日志怎么读再讲三种池子耗尽的本质区别然后是完整的排查实录、最容易漏掉的几类代码写法最后是修复之后的参数加固和验证方式。1. 先把这行异常当成现场笔录来读这行异常不是一句废话它其实是连接池在超时那一刻给你做的现场笔录。Druid 在getConnectionInternal里等不到可用连接、maxWait耗尽之后会把当时的几个核心计数一起塞进异常消息里。字段不多但每一个都能帮你砍掉一半的排查方向。先把这几个数字的含义咬死后面所有判断都建立在它们之上。1.1 active 和 maxActive 同时到顶说明池子确实被人占着active20表示当前已经被借出去、还没归还的连接数maxActive20是池子的上限。这两个值相等说明池子里一条空闲连接都没有了全部在业务手里。但这里有个容易被忽略的推论连接是被借出去了不是创建不出来。如果数据库挂了、账号密码错了、网络不通你看到的会是SQLException、CommunicationsException或者ConnectException而不是一个干干净净的等待超时。等待超时意味着池子曾经是健康的只是它的存量被消耗光了。再往下推一层被借出去的 20 条连接是正在被使用还是被忘记归还从这一行还看不出来。这就要看下一个字段。1.2 creating 等于 0直接排除建连慢这条路creating表示当前正在创建中的连接数量。这个字段的价值极高因为它是区分两种完全不同的故障的分水岭creating 0 且长时间不降有人正在建连接但建得很慢。常见原因是数据库握手慢、DNS 解析慢、TLS 协商慢、或者数据库侧已经打到了max_connections在排队。这时候池子的容量其实是够的问题在建连环节加maxActive反而会让情况更糟。creating 0根本没有人在建连接因为池子已经满了新来的请求连进入创建阶段的机会都没有直接卡在等待队列里。这就是我们要处理的情况。那天我看到的正是creating 0。这个 0 一出来数据库连不上这条线就可以直接划掉了排查范围一下子缩到了一件事那 20 条连接现在在谁手里为什么没还回来。1.3 wait millis 60000 决定了故障的表现形态wait millis 60000是你配的maxWait单位毫秒。它决定了故障长什么样。配 60000意味着每一个拿不到连接的请求都要干等 60 秒才报错。在这 60 秒里请求线程既不释放也不返回Tomcat 的线程池会被迅速吃满然后整条调用链路自下而上雪崩——一个数据库连接池的问题最后表现为网关 502、Nginx 报 upstream timeout。你会看到一堆看起来毫无关联的服务一起报警就是因为大家都在等。所以maxWait这个参数不只是等多久的问题它其实是在配置故障的传播速度。后面第 5 节我会讲为什么我在生产环境里会把它从 60000 改成 3000这个改动带来的收益比修 bug 本身还大。2. 池子耗尽其实是三种病别急着加 maxActive拿到active maxActive之后很多人就直接开始调参数了。但同样是池子满背后可能是三种完全不同的问题处理方式差得很远。把它们分清能省掉大量无效折腾。2.1 真泄漏借出去的那根线再也没回来这是最经典的一种。代码里getConnection()拿到了连接但因为异常、提前 return、finally写错位置、连接被塞进异步任务等原因close()永远没被调用。真泄漏的特征很明显池子里的 active 数只涨不跌。你重启服务active 从 0 慢慢爬升爬满之后开始报错再重启重复这个过程。这个重启就好、跑一阵又挂的锯齿形曲线基本可以确诊。真泄漏还有一个隐蔽的危害它不会立刻报错。可能泄漏发生在上线当天下午三点但池子到第二天早上才满中间隔了十几个小时。等你收到告警的时候触发泄漏的那个请求早就淹没在日志里了所以要靠工具把现场捞出来不能靠眼睛翻日志。2.2 假泄漏线回来了但回来得太晚第二种情况更常见也更难修。连接最终是还了的问题在于持有的时间太长。典型的例子是把一段远程调用、一个文件导出、一次大批量循环处理放在了事务里。Transactional一开Spring 就从池子里借一条连接绑到当前线程上整个方法执行期间这条连接都占着哪怕中间那段代码压根不碰数据库。一个耗时 8 秒的 HTTP 调用被包在事务里就等于这条连接被白白占了 8 秒。这种问题的特征是active 数会波动高峰期顶到 maxActive低峰期又掉下来。它不像是泄漏更像容量不够所以特别容易骗人去加maxActive。加了之后能撑更久但只是把爆发时间往后推。2.3 卡死型连接卡在某个永远不会返回的调用上第三种最少见但最凶险。连接被借出去之后卡在了一个不会返回的操作上——比如等一把永远不会释放的锁、读一个没有超时的 socket、或者在while(true)里转。这时候 active 数会牢牢钉在 maxActive 上不动重启前永远不降。判断方式很简单如果重启后 active 数在极短时间内几秒直接冲到顶且纹丝不动而不是慢慢爬升那大概率不是泄漏是卡死。这时你要找的是某个调用没有超时设置而不是某处忘了 close。把三种情况整理成一张对照表方便你在现场快速对号入座特征真泄漏假泄漏长持有卡死型active 曲线只涨不跌重启才归零有涨有落高峰顶格秒级冲到顶后不动出现时间上线后数小时至数天业务高峰期故障发生后立刻单条连接持有时间无限长明显偏长秒级到分钟级无限长主要排查手段removeAbandoned 打堆栈慢 SQL 日志 事务边界梳理jstack 看线程栈加 maxActive 的效果拖延不解决拖延高峰期照样满无效3. 一次从日志挖到代码行的排查实录下面是我那天真实的排查顺序。我刻意把顺序写出来因为排查顺序本身就是经验——先做成本低的、能砍掉大范围的动作再做精确打击。很多人一上来就翻代码二十万行业务代码里找一个漏掉的 close那是大海捞针。3.1 先确认是不是慢 SQL把慢日志和 StatFilter 打开成本最低的一步是排除假泄漏。如果池子是被慢 SQL 长时间占着那修的方向完全不同而且排查成本很低。Druid 自带 StatFilter开启之后能直接看到每条 SQL 的执行次数、总耗时、最慢耗时、执行出错数。配置大概是这样spring: datasource: druid: filters: stat,wall filter: stat: enabled: true log-slow-sql: true slow-sql-millis: 1000 merge-sql: true stat-view-servlet: enabled: true url-pattern: /druid/* login-username: monitor login-password: 换成一个强口令 allow: 127.0.0.1配好之后访问监控页重点看三个地方SQL 列表里按最慢排序的前几名、以及连接持有时间分布。如果慢 SQL 列表干干净净那基本可以排除假泄漏如果发现某条 SQL 最慢耗时 30 秒以上那就不用往下查了先去优化那条 SQL。那天我打开监控页慢 SQL 一片空白最慢的一条 SQL 只有 40 毫秒。这一步大概花了我五分钟帮我把方向锁死在了真泄漏上。注意生产环境开 StatFilter 是有性能开销的因为它要做 SQL 归一化和统计。用完之后记得评估是否保留或者把slow-sql-millis调大只记录真正的问题 SQL。3.2 用 removeAbandoned logAbandoned 让泄漏现场自己说话确定是真泄漏之后最有价值的一步是让连接池自己把证据吐出来。Druid 提供了removeAbandoned机制当一条连接被借出超过removeAbandonedTimeout秒仍未归还时池子会把它标记为被遗弃强制回收并且在logAbandoned打开的情况下打印出这条连接当初被借出时的堆栈。这一点非常关键。普通的日志只能告诉你这里关了没而借出时的堆栈直接指到那一行getConnection()的调用者精确到类名和行号。这是所有排查手段里性价比最高的一个。配置如下临时开启用于排查spring: datasource: druid: remove-abandoned: true remove-abandoned-timeout: 120 log-abandoned: true开启之后日志里会出现类似这样的内容abandon connection, owner thread: http-nio-8080-exec-37, connected at 2024-05-11 02:41:07, open stackTrace: at com.alibaba.druid.pool.DruidPooledConnection.init(...) at com.example.order.OrderQueryService.queryByUser(OrderQueryService.java:88) at com.example.order.OrderController.list(OrderController.java:41)看到OrderQueryService.java:88这一行剩下的事情就是打开这个文件看第 88 行在干什么了。那天我们就是这么定位到的一个导出接口在处理用户为空的分支时提前return绕过了后面的close()。提示removeAbandoned需要谨慎使用它并不是给生产环境长期开着的开关。我在第 6 节专门写了它的两个副作用动手之前务必看完那一段。3.3 arthas 和 jstack 交叉验证到底是谁攥着连接removeAbandoned有个前提被遗弃的连接必须真的静止在某个线程里。如果连接是被几个线程来回倒手或者卡在某个 native 调用上它的表现可能不够典型。这时候用线程栈做交叉验证。我常用的顺序是先jstack抓一份快照然后 grep 业务包名jstack -l pid /tmp/stack.txt grep -n com.example /tmp/stack.txt | head -50重点看那些停在socketRead0、park、wait上的业务线程。如果几十个线程都停在同一个业务方法里那这个方法就是嫌疑人。用 arthas 会更方便直接看线程和调用链arthas dashboard # 看线程数、CPU、内存概况 arthas thread -n 10 # 列出最忙的 10 个线程及其栈 arthas thread -b # 直接找出阻塞其他线程的那个家伙 arthas trace com.example.order.OrderQueryService queryByUser -n 5thread -b这个命令特别适合卡死型问题它会直接告诉你某个线程持有锁正在等待一个不会到来的通知。3.4 最后才去翻代码几个高嫌疑的借出点工具给出线索之后才是翻代码的时候。但翻代码也要有优先级不要从头看。我一般按下面的清单挨个过命中率从高到低所有手写DataSource.getConnection()的地方尤其是没走try-with-resources的所有标记了Transactional的方法看方法体里有没有远程调用、文件 IO、大循环所有手动创建SqlSession、EntityManager的地方所有把连接或SqlSession当参数传给异步任务的地方所有在循环里调用数据库的批量任务这五类地方覆盖了我这几年遇到过的九成以上的连接泄漏。4. 那几行最有嫌疑的代码写法对比与逐条拆解知道去哪儿找还不够得知道长什么样。下面这几类写法我几乎每次排查都会碰到把它们背下来下次看代码会快很多。4.1 finally 里 close 写错位置异常一抛就漏一个这是最经典的泄漏写法看起来像是有异常处理的实际上完全没用Connection conn null; try { conn dataSource.getConnection(); PreparedStatement ps conn.prepareStatement(sql); ResultSet rs ps.executeQuery(); // 组装结果 conn.close(); // 一旦上面任何一行抛异常这行就执行不到 } catch (SQLException e) { log.error(查询失败, e); }问题在于close()写在了try块的末尾而不是finally里。业务逻辑里任何一个异常、任何一个提前returnclose()就永远不会执行。正确写法用try-with-resources让编译器帮你保证释放try (Connection conn dataSource.getConnection(); PreparedStatement ps conn.prepareStatement(sql)) { ps.setLong(1, userId); try (ResultSet rs ps.executeQuery()) { // 组装结果 } } catch (SQLException e) { log.error(查询失败, userId{}, userId, e); }还有一个更隐蔽的变体close()写进了finally但写在了return语句后面或者被嵌套的try吞掉了。这类问题只能靠肉眼看所以我在团队里推的规范是只要不是框架托管的数据源一律用 try-with-resources不接受手写 close。另外要提醒一点Connection.close()在连接池场景下不是真的关闭物理连接而是把连接归还给池子。所以记得关这件事在池化环境下更关键忘了关不会报错只会悄悄把池子耗干。4.2 连接跨线程传递最隐蔽的一类泄漏这一类问题最坑因为代码看起来一点毛病都没有。踩坑的场景通常是这样的Transactional public void batchProcess(ListLong ids) throws Exception { ListFuture? futures new ArrayList(); for (Long id : ids) { futures.add(executor.submit(() - dao.updateStatus(id))); } for (Future? f : futures) { f.get(); // 等所有子任务完成 } // 事务方法结束连接才会归还 }这里的坑有两层。第一层外层Transactional方法从头到尾占着一条连接因为事务没提交连接就不能还。第二层每个子任务在dao.updateStatus时又各自借一条连接。如果ids有 50 个、线程池有 10 个线程、连接池只有 20 条那么外层占 1 条、子任务占 10 条看起来还撑得住但如果并发调用这个方法的是 5 个请求连接就瞬间见底了。更极端的情况是死锁线程池大小设成 30连接池大小设成 2030 个任务同时抢 20 条连接剩下 10 个任务卡住等待而外层的f.get()又在等这 10 个任务。如果连接池同时也被其他请求占着整个流程就互相卡死了。这种线程池大小 连接池大小的配置我在生产环境见过不止一次是个很容易被忽略的定时炸弹。正确的做法是把数据库操作和事务边界挪到同一个线程里异步任务只做非数据库的事情或者把批量操作改成一个批次一条连接用batchUpdate批量提交。4.3 手动 SqlSession 与多数据源切换的连环坑如果你还在用手写 MyBatis 的SqlSession那下面这两种写法要特别注意// 错误写法开了不关 SqlSession session sqlSessionFactory.openSession(); ListUser users session.selectList(queryUsers); // 忘了 session.close()连接一直挂着// 错误写法多数据源切换后没有清干净 DataSourceContextHolder.set(slave); try { // 业务逻辑 } finally { // 忘了 clear下一个请求可能拿到错误的上下文 }同一段代码里如果既有多数据源切换、又有手动SqlSession出问题的概率会翻倍。因为切换上下文是绑在ThreadLocal上的而ThreadLocal在 Tomcat 的线程复用模型下如果没清干净会跟着线程活下去影响下一个请求。我的建议是能用 MyBatis-Spring 的托管方式就用托管方式实在要手写SqlSession就老老实实用try-with-resources因为SqlSession实现了Closeabletry (SqlSession session sqlSessionFactory.openSession()) { ListUser users session.selectList(queryUsers); }4.4 事务边界把远程调用包进来等于把连接按在椅子上这一类不算是泄漏但造成的现象和泄漏一模一样。看这段代码Transactional(rollbackFor Exception.class) public void createOrder(OrderDTO dto) { orderMapper.insert(dto); // 借连接占用 inventoryClient.deduct(dto); // 远程调用可能耗时 3 秒 notifyClient.send(dto); // 再一个远程调用2 秒 // 方法结束才提交事务连接才归还 }这段代码里一条连接被占用了整整 5 秒以上而这 5 秒里它几乎什么都没干。如果 QPS 是 20那理论上同时需要 100 条连接才撑得住——而池子里只有 20 条。修法的核心思路是缩短连接的持有时间把远程调用挪到事务外面或者改成先提交事务再发通知。如果业务上必须保证一致性那就用本地消息表这类方案而不是把连接一直攥着。我顺手列一下我常用的三种收缩事务边界的写法手段做法适用场景拆分方法事务方法只包数据库写操作远程调用放外面大多数写场景缩小事务范围把Transactional从类级别挪到具体方法整个 Service 里只有一两个写方法缩短锁等待对update加超时、避免大范围update有并发写冲突的场景5. 修完代码不等于收工参数加固与验证定位到泄漏点、改完代码事情只做了一半。那天我改完代码之后还做了三件事才敢真正放下心。5.1 参数层面的兜底配置含配置示例代码修了但你不能保证下一个同事不会再写出一处漏关的代码。所以参数层面要有兜底原则是快速失败 能被观测 能自愈。maxWait我从 60000 改成了 3000。理由很直接等 60 秒的请求就算最后等到了连接用户早就走了而且这 60 秒里它一直占着 Tomcat 的工作线程会把上游一起拖垮。改成 3 秒之后故障表现从整站雪崩变成了少量接口报错影响面小了一个数量级。这就是所谓快速失败的实际价值。minIdle和keepAlive也值得配。minIdle保持一定数量的常备连接避免流量突增时集中建连keepAlive让池子主动保活空闲连接防止连接被数据库侧的超时机制悄悄掐断——这种服务端已经关掉了、客户端还以为是好的的连接用的时候会报Communications link failure也是很难查的一类问题。我最终用的配置大概是这样spring: datasource: druid: initial-size: 5 min-idle: 5 max-active: 20 max-wait: 3000 time-between-eviction-runs-millis: 30000 min-evictable-idle-time-millis: 300000 validation-query: SELECT 1 test-while-idle: true test-on-borrow: false test-on-return: false keep-alive: true phy-timeout-millis: 1200000这里有个取舍要说明test-on-borrow我关掉了因为它每次借连接都要发一次检测 SQLQPS 高的时候这是纯浪费。取而代之的是test-while-idle加上合适的检测间隔只在连接空闲时做检测既能保证拿到的连接是活的又没有额外开销。如果你用的是 HikariCP对应的思路是一样的maximumPoolSize控制上限connectionTimeout快速失败leakDetectionThreshold打开泄漏检测。Hikari 的leakDetectionThreshold比 Druid 的removeAbandoned温和一些它只是打日志告警不会强制回收连接所以更适合长期开着。5.2 把 active 做成指标别等报错才知道池子满了写完代码一定要加监控。我加了三类指标都是 Druid 现成的方法Scheduled(fixedDelay 60000) public void reportPoolStatus() { DruidDataSource ds (DruidDataSource) dataSource; log.info(连接池状态 active{}, pooling{}, waiters{}, maxActive{}, ds.getActiveCount(), ds.getPoolingCount(), ds.getWaitThreadCount(), ds.getMaxActive()); }getWaitThreadCount()这个指标特别有用它是当前在等待连接的线程数。只要这个值大于 0 并且持续时间超过几秒就说明池子已经不够用了这时候报警比等到GetConnectionTimeoutException抛出来要早得多。再配合 Spring Boot Actuator 的 druid 指标把active、pooling、waiters三个值打进监控系统设一条规则active / maxActive 0.8 持续 5 分钟就告警。这条规则帮我提前发现过两次连接缓慢增长的问题那两次都是在半夜之前就处理掉了没有惊动用户。5.3 怎么验证真的修好了压测与回归的做法改完之后我没有直接上线而是做了一轮针对性的验证。验证的目标不是功能对不对而是连接会不会还回去。具体做法是把removeAbandoned保持打开removeAbandonedTimeout设成 120 秒然后跑一轮覆盖主要接口的压测。压测结束后观察两个数据一是日志里有没有出现abandon connection二是压测停止后五分钟active是不是回到了接近minIdle的水平。如果压测期间有abandon connection日志说明还有没修干净的泄漏点堆栈里会直接告诉你位置。如果active在压测结束后迟迟不降那可能是还有长事务在跑。这两个检查我用了一份固定的脚本每次改完数据访问层代码都跑一遍成本不高但很安心。顺便说一个容易忽略的验证点重启后的冷启动阶段。有些泄漏只在应用刚启动、缓存还没热的时候出现。所以压测最好覆盖刚启动就压的场景而不是等应用跑热了再压。6. removeAbandoned 用错比不用更麻烦removeAbandoned是排查利器但它的副作用不小。我见过有人直接在生产的长期配置里打开它结果引入了一堆新问题。这里说两个我踩过的坑。6.1 它的代价检查开销和被误杀的长事务先说开销。开启removeAbandoned之后池子需要在每次借出连接时记录一条借出堆栈用于logAbandoned打印创建一个Throwable实例的代价在高并发下并不便宜。如果你的服务 QPS 上千这个开销是能测出来的。所以它应该只在排查期间短时开启排查完就关。再说误杀。removeAbandonedTimeout设得太短会把正常的长事务当成泄漏给强制回收掉。我有一次把它设成了 60 秒结果一个跑批量导入的接口正常执行需要 90 秒连接在 60 秒的时候被强行回收业务侧报了一堆connection closed排查起来比原来的泄漏还费劲。设置这个值的经验是先看你的业务里最长的一个正常数据库操作要多久然后取它的 1.5 到 2 倍。如果实在摸不准宁可设大一点比如 300 秒反正排查真泄漏不差这几个小时。6.2 我踩过的两个坑第一个坑是开着不管。有一次排查完忘了关这个开关一直在生产配置里躺了三个月。直到某天一个数据分析任务因为超过 180 秒被强行回收数据写了一半出了一批脏数据才知道问题出在这儿。所以我的规矩是removeAbandoned只允许通过配置中心临时开启并且必须带一个自动过期的开关。第二个坑更隐蔽。开启removeAbandoned之后被强制回收的连接如果业务代码后续还在用它比如那段代码卡在一个很慢的 IO 上之后才去执行 SQL就会抛出一个看起来完全不相干的异常比如statement is closed或者connection is closed。这类异常会让你误以为是框架的问题实际上根子在连接被提前回收了。判断方法很简单出现这类异常的时间点和abandon connection日志的时间点是不是能对上。最后补一个实用的小技巧。如果你恰好在用 Druid 的较新版本它在开启removeAbandoned之后会保留活跃连接的借出堆栈可以试试直接把它们打印出来省去翻日志的功夫ListStackTraceElement[] stacks ((DruidDataSource) dataSource) .getActiveConnectionStackTraces(); for (StackTraceElement[] stack : stacks) { log.warn(当前活跃连接借出位置:, new Throwable() { Override public StackTraceElement[] getStackTrace() { return stack; } }); }这个方法的具体可用性和返回内容跟版本有关用之前先在测试环境确认一下。但它背后的思路是通用的别去猜连接在谁手里让池子直接告诉你。我个人的体会是连接池打满这件事九成的情况不是容量问题而是代码里某一行少写了一个close。真正难的不是修而是找到它。所以与其每次都在慌乱中翻日志不如提前把maxWait调小、把指标埋好、把removeAbandoned当成随时可以拿出来的工具箱备着。这套东西平时看着没什么用关键时刻能帮你把一个通宵的排查压缩到二十分钟。
返回列表