服务响应超时，该如何排查？

Posted 2022-04-30 Java知音_

点击关注公众号，实用技术文章及时了解

来源：blog.csdn.net/insomsia/article/

details/84585441

问题描述：

部署在新搭建的服务器上的服务一直处于未响应状态，每次发送请求等待若干秒之后只能接收到底层返回的超时报错信息。

原因分析：

我们系统是一个服务化的单体应用，主要包含了一组业务服务和一个网关服务，外部请求一般都是先由网关服务做一些前置处理，然后根据请求格式和程序自定义配置路由到相应业务服务来进行业务处理，然后业务服务根据外部请求做完业务处理之后，也会将返回信息交给网关服务来统一返回。

所以正常情况下，一次服务调用引发的程序执行，网关服务与相应的业务服务配置好的日志文件都会有日志刷出来。

让测试重现场景后，监控日志可以看到网关服务是有接收到请求并最终把请求路由到了业务服务的，但是业务服务却始终没有动静，也就是时候没看到有被调用的痕迹。嗯，有点奇怪~

可以先总结下问题：网关服务应该是没问题的，反正接收到请求并且把请求转发出去了，已经做好自己的事了。那么问题很有可能出在业务服务上了。

不过还是要排除其他影响，比如说下面最常见的三个：

1、服务器内存、CPU影响？

先用用top查看服务器资源使用情况，CPU、内存使用率实在看不出什么问题来

2、JVM内存影响？

有可能JVM一直在做GC，导致应用暂停时间过长。所以先用jstat看了下JVM各个分代的使用情况和GC的大概频率（jstat -gccause pid 10000，这里当时忘记截图了，以平时的经验来看的话，都还比较正常，就先略过~）。

用jmap查看JVM内存使用情况（jmap -heap pid），新生代、老年大、持久带使用率都还算不太高。

这里提一下，从下面的图里可以看到老年代的标识是：concurrent mark-seeep generation，这就代表老年代使用的垃圾收集器是CMS，然后使用率已经接近70%了。有这么一种场景，当你老年代的垃圾回收器是CMS，然后你配置了JVM启动参数：

• -XX:CMSInitiatingOccupancyFraction=70

• -XX:+UseCMSInitiatingOccupancyOnly

这就代表着只要老年大使用率到达70%，JVM就会对老年代执行CMSGC来回收内存。如果老年代内存使用率一直大于等于70%，就会导致JVM频繁CMSGC~

但是当时我们并没有加这两个参数，所以JVM是否要执行CMSGC是会实时动态计算的，老年代使用率接近70%并不是什么大问题。

3、相应线程哪里被阻塞了？

查看JVM线程状态可以用jstack来打印线程快照（jstack pid）。将线程快照文件拉到本地来分析，发现在这个线程堆栈文件中，已经有5个请求业务服务的工作线程了，而且都是处于Object.wait()（这个就是在等待synchronized同步锁唤醒的情况了）的状态。

我们的各个业务服务呢，分别负责不同的业务处理部分（好像说了一句废话）。然后业务服务与业务服务之间，是采用线程池隔离的机制。即每个业务服务是会起一个线程池去处理路由过来的请求。线程池的核心线程数和最大线程数都是5,当请求数大于5会将剩下的请求先丢到队列中去，等待空闲线程来处理。

所以这就解释了为什么会看到业务服务没有被调用的现象，因为后续发的请求都丢到队列里面去了，还没来得及处理它们。

但是为什么前面的5个请求都会阻塞呢？看一下线程栈：

?????????????问号马赛克????????????????????? nid=0x29808 in Object.wait() [0x0000000002e8c000]
   java.lang.Thread.State: WAITING (on object monitor)
 at java.lang.Object.wait(Native Method)
 - waiting on <0x00000007d801a670> (a org.apache.commons.pool.impl.GenericObjectPool$Latch)
 at java.lang.Object.wait(Object.java:503)
 at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:1118)
 - locked <0x00000007d801a670> (a org.apache.commons.pool.impl.GenericObjectPool$Latch)
 at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:106)
 at org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.java:1044)
 at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:111)
 at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:77)
 at org.mybatis.spring.transaction.SpringManagedTransaction.openConnection(SpringManagedTransaction.java:82)
 at org.mybatis.spring.transaction.SpringManagedTransaction.getConnection(SpringManagedTransaction.java:68)
 at org.apache.ibatis.executor.BaseExecutor.getConnection(BaseExecutor.java:338)
 at org.apache.ibatis.executor.SimpleExecutor.prepareStatement(SimpleExecutor.java:84)
 at org.apache.ibatis.executor.SimpleExecutor.doQuery(SimpleExecutor.java:62)
 at org.apache.ibatis.executor.BaseExecutor.queryFromDatabase(BaseExecutor.java:326)
 at org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:156)
 at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:109)
 at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:83)
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
 at java.lang.reflect.Method.invoke(Method.java:606)
 at org.apache.ibatis.plugin.Invocation.proceed(Invocation.java:49)
 ?????????????问号马赛克?????????????????????
 at org.apache.ibatis.plugin.Plugin.invoke(Plugin.java:61)
 at com.sun.proxy.$Proxy19.query(Unknown Source)
 at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:148)
 at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:141)
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
 at java.lang.reflect.Method.invoke(Method.java:606)
 at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:433)
 at com.sun.proxy.$Proxy13.selectList(Unknown Source)
 at org.mybatis.spring.SqlSessionTemplate.selectList(SqlSessionTemplate.java:230)

从这个线程堆栈可以看出是在查询数据库获取连接的时候一直阻塞在那里了。所以从最开始的第一个请求卡顿到这里不能再往下执行，然后接下来四个也同样卡在这个位置执行不了，再到后面的请求干脆就全缓存在队列中来业务服务都无法进去。

但是为什么会阻塞在操作数据库拿连接的地方呢，继续往下挖，最终定位到GenericObjectPool。

GenericObjectPool是什么呢，它是一个对象池，而java很多池管理的概念，如线程池、数据库连接池其实都是继承自它的。因为这个是操作数据库时的线程栈，而且堆栈的顶层是阻塞到GenericObjectPool的逻辑内，所以这时候怀疑是数据源的配置有问题。

检查一下数据源配置，看到数据源的配置中的如下三个配置：

jdbc.maxActive = 0
jdbc.maxIdle = 0
jdbc.maxWait = -1

要知道maxActive（最大连接数）为0会让你永远从数据库拿不到连接；

maxIdle（最大空闲连接数）为0会导致连接池中永远没有空闲连接数，对象都是在需要的时候创建、用完的时候又立马destroy了；

而为maxWait（最大等待时间）-1，即如果拿不到连接会无限等待。尤其是在当被依赖的服务由于某些故障而响应极慢时，会有大量线程阻塞，最终导致线程耗尽，服务卡死，用户请求被拒绝。

解决方案：

找到问题之后我们再把maxActive、maxIdle都设为80，maxWait设为3000，单位为毫秒（当然要根据具体情况设值），然后重启数据源使其配置生效，再发请求调用业务服务就已经能正常处理了~

推荐

主流Java进阶技术（学习资料分享）

Java面试题宝典

加入Spring技术开发社区

PS：因为公众号平台更改了推送规则，如果不想错过内容，记得读完点一下“在看”，加个“星标”，这样每次新文章推送才会第一时间出现在你的订阅列表里。点“在看”支持我们吧！