SpringBoot工程假死,如何揪出幕后真凶的?
工作中经常会遇到程序不响应,但是进程依然存活的现象。原因有很多,比如
- 内存、CPU占满了(500,连接超时)
- 磁盘满了(500,连接超时)
今天笔者遇到的不是前两种,原因也很稀奇,tomcat线程池耗尽了,导致500连接超时。
我们是一个spring boot工程,对外提供rest接口服务,但是隔三差五的就会出现500连接超时的现象。
排除了内存、CPU、磁盘占满的case后,有个同事无意中发现这台机器出现了大量的网络连接CLOSE_WAIT。查询资料后得知,当一个请求方主动发起close连接,但是服务方还没有返回ack这个时间差,连接状态就是close_wait。这是底层tcp的解释。
按说这个时间差是很短的,不足以让整个应用不能对外响应,除非一种情况,那就是某个时刻并发量达到了tomcat的处理请求的极限,同一时间,整个处理请求的线程池全部被占用,并且等待close。刚好我们应用基本符合这个场景。
笔者解决思路是,通过jstack查询线程信息,看http究竟阻塞在哪里了
ps -ef |grep `pwd`
jstck $PID > stack.txt
先找到该进程的pid,然后通过jstack命令导出线程信息。
在stack.txt中搜索DeadThread无果。继续搜索BLOCKED,发现了大量线程阻塞。
grep "BLOCKED" -C 3 |grep "http-nio-exec"
http-nio-xx-exec-是tomcat处理请求的线程名称,可以看出,大多数线程都被blocked。这就是发生假死的根源。
线程信息里面也可以看到栈信息,明确告诉我们阻塞发生在了代码哪一行。跟进代码果然,代码中请求了两个已经ping不通的地址。
修改代码后,发布到开发环境,继续观察CLOSE_WAIT情况:
lsof -i:8091 |grep "CLOSE_WAIT" |wc -l
统计close_wait的连接数量
修改前是67,而且还在增长。修改后变成了0。基本可以确定close_wait的问题已经解决了。