一次现网服务挂掉定位-HikariPool-1 - Connection is not available, request timed out after 30000ms.

shuxiaohua

已于 2024-08-05 17:32:37 修改

阅读量1.2k

点赞数 21

分类专栏：现网问题定位文章标签： spring java 后端数据库 jvm

于 2024-07-20 11:36:42 首次发布

本文链接：https://blog.csdn.net/shuxiaohua/article/details/140566527

版权

现网问题定位专栏收录该内容

7 篇文章 0 订阅

订阅专栏

概述

运维接到用户反馈无法登录，拉我上线一起定位。
首先我们先拉上用户进行复现，发现登录接口超时导致登录失败。遂让运维先查查有无错误日志，我这边通过啄木鸟(调用链查询系统)确认是哪一段耗时。还未等我打开啄木鸟，运维就发现有大量数据库连接报错。

 [http-nio-8003-exec-64] WARN  c.e.w.org.encrypt.CustomInterceptor - 
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.
	at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:84)
	at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:643)
	at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:713)
	at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:744)
	at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:757)
	... ...

虽然该报错并不是登录服务(该报错是下图服务C的)的，但我知道登录接口肯定受这个报错影响了，因此就不再查看啄木鸟直接定位该报错了。
在这里插入图片描述

解释
心跳接口是服务B提供的，它会找服务C查一个标识，且该接口QPS有点高。服务C因为数据库操作阻塞，会导致心跳接口也阻塞，最终整个服务B雪崩，进而影响到登录接口。

寻找根因的过程

获取数据库连接超时，有以下三种原因

连接泄漏
连接池配置的最大连接数不够
连接数据库失败

首先确认是否是连接泄漏，因此让运维隔离故障节点恢复业务后，就立马DUMP了内存。
分析后(分析方法见之前的的博客)发现并没有连接泄漏.

然后确认是否是最大连接数不够。如果是最大连接数不够的话，系统的响应速度应该是逐渐的变慢，调用链中获取连接的时间也逐渐变大。简单点来讲，如果是连接数不够，系统过载，那应该是个逐步雪崩的过程。遂通过啄木鸟中调用链的数据进行佐证。
通过查询啄木鸟发现，接口是突然一下就不行的。前面都是10ms以下，突然一下子就开始全部超时。而且该接口很简单就是查询表里面的一个标识，该表很小（100条左右数据）。前面接口响应时间也说明了这一点（未超时的都小于10ms）。理论上可以支撑400QPS（4台实例，每台配置的连接数是10），现网请求量是远远小于该值的。因此该怀疑点也暂时被排除。

排除了前面两点，那只能是连接数据库失败，遂找平台确认这段时间是否有网络问题。
首先我们登录了被隔离的容器，使用telnet命令测试数据库连接，发现没有问题，因此该条猜测也无法真正站住脚。因为不太可能就那一小会网络有问题，隔离后就恢复了，而且平台的人也查了宿主机的监控（服务是部署在docker中的），宿主机中其他docker实例网络流量正常。

经过以上步骤，仍然是没有找到根因；当前掌握的信息2、3都无法实锤，而且3属于网络问题一般也不好定位，因此决定先找到足够证据排除2的可能，然后让平台花大力气去自证3.

对于2，虽然上述分析很合理，但实际上缺了一个关键信息，就是当前系统堆栈。因为使用数据库连接除了外部的HTTP请求，内部的异步处理也可能会使用数据库，因此需要获取到出问题时的堆栈，确认确实除了外部请求，没有其他异步线程使用数据库连接，才能彻底的排除2.

因此通知运维，等下一次出问题时，打印系统堆栈，并通过netstat -ntpa | grep 3306命令查看一下系统数据库连接。
之前所以使用网络命令查询数据库连接，是因为如果确实是网络问题，当前系统数据库连接应该也会有异常，比如没有数据库连接，或者连接都处于异常状态（非ESTABLISHED状态）.

后面问题复现后，找运维分别做了以上两点。发现网络确实没问题，遂开始分析堆栈，初步发现所有线程，只有外部请求的线程(http-nio-xx-exec-xx)涉及数据库操作.
到目前为止，仍未找到嫌疑点。因此仔细分析堆栈寻找疑点，分析的过程中突然想起一段问题代码，遂找齐证据论证2，并在测试环境复现。
在这里插入图片描述
如上图所示，本接口业务很简单就是一个数据库查询操作，有点特殊的是，该表的查询有一段解密逻辑，在JPA的Interceptor中(就类似于spring mvc中的HandlerInterceptor，框架的钩子函数用于一些切面处理，使业务代码更简洁)。

public class CustomInterceptor extends EmptyInterceptor {
    # 代码有省略
    
    @Override
    public boolean onLoad(Object entity, Serializable id, Object[] state, String[] propertyNames, Type[] types) {
        decryptInfo(entity, state, propertyNames);
        return super.onLoad(entity, id, state, propertyNames, types);
    }

解密用的秘钥是通过JdbcTemplate去查询，而且JdbcTemplate使用的数据源与JPA是同一个。(通过之前dump出来的内存确认的)
在这里插入图片描述
通过上述分析，很可能是由于死锁（类似死锁，把获取数据库连接当做获取锁），10条线程同时达到红线逻辑，此时查询秘钥时，也需要获取数据库连接，但是该逻辑是包在整个JPA查询逻辑中的，换句话说JPA查询仍未结束，前面获取的连接并未释放。因此红线逻辑哪里无法获取数据库连接。
在这里插入图片描述