今天早上,收到一个报警,有个服务器的http往返时延飙升,同时曝出大量404,很是折腾了一番,特记录下思考和排查经过。
1.这是单纯的时延增大,还是有什么其他情况还未掌握?
因为不知道是只有时延变大而已,还是同时有别的情况,第一反应是先看日志有没有异常。
看了一下,一片风平浪静,既是好消息也是坏消息。好消息是核心业务还在,不然一定会打日志,坏消息是日志提供不了任何信息。当然这也说明了我们的日志肯定有不到位的地方。
2.换个思路,日志风平浪静,是否只是服务器启动了什么任务,占用了大量cpu/IO等?GC呢?
于是去看监控,服务器CPU利用率、磁盘利用率、内存利用率、Swap交换次数都很正常。
那么会不会是一次长时间的FGC导致请求大量堆积了呢?又去看gc,结果发现也很正常,这段时间连fgc都没有触发过,minorGC的时间也在合理范围内。此路不通
3.再换个思路,往返时延增大,又没有全部404,看起来像是服务器处理不过来了,那么既然服务器资源充足,为什么处理不过来了呢?是不是tcp的问题
于是去查tcp连接和端口,果然发现了一点端倪,服务器上有大量的close_wait。熟悉tcp的人应该知道,close_wait是tcp连接时,被动关闭的一方会产生的状态。所以往返时延增大就有了一个合理的解释:大量处于close_wait的未关闭socket无法被释放,导致tomcat的可用连接非常少,从而请求堆积,往返时延增大,甚至超时。
4.继续思考,为何有大量的close_wait?
通常情况下,可能是程序员没有关闭socket,我们的项目里不存在这种情况。那么,目前最大的可能是:请求阻塞在什么地方了,客户端已经超时发送fin,所以服务端就变成了close_wait,在等待请求执行完之后才能切换状态。TCP的状态切换是排错基本功,同学们一定要掌握啊!
5.被阻塞的请求阻塞在了什么地方?
这个其实比较好处理,因为通常情况下,阻塞发生在IO处。再顺一下业务逻辑,最大的嫌疑是数据库。查一下sql执行时间,发现一条简单的select 1 from dual,执行时间都非常长。那就好解释了,sql执行太慢,连接池连接耗尽,后续请求只能阻塞。打电话给运维,运维:啊?我刚刚做表迁移来着,忘了告诉你们......我:*%&&@*@@&&¥&……()*
6.小插曲,sql超时是会报异常的,为何日志里没有报警呢?
答案是,服务器的主业务压根不走数据库,丫只是因为可用连接太少了所以才时延上升。走数据库的那个链接应该是报了异常的,只是有位大仙把测试时的日志输出到console的设置覆盖了线上输出到文件的设置...