前些日子小组内安排值班,轮流看顾我们的服务,主要做一些报警邮件处理、Bug 排查、运营 issue 处理的事。工作日还好,无论干什么都要上班的,若是轮到周末,那这一天算是毁了。
不知道是公司网络广了就这样还是网络运维组不给力,网络总有问题,不是这边交换机脱网了就是那边路由器坏了,还偶发地各种超时,而我们灵敏地服务探测服务总能准确地抓住偶现的小问题,给美好的工作加点料。好几次值班组的小伙伴们一起吐槽,商量着怎么避过服务保活机制,偷偷停了探测服务而不让人发现(虽然也并不敢)。
前些天我就在周末处理了一次探测服务的锅。
问题
网络问题?晚上七点多开始,我就开始不停地收到报警邮件,邮件显示探测的几个接口有超时情况。 多数执行栈都在:
Java.io.BufferedReader.readLine(BufferedReader.java:371) java.io.BufferedReader.readLine(BufferReader.java:389) java_io_BufferedReader$readLine.call(Unknown Source) com.domain.detect.http.HttpClient.getResponse(HttpClient.groovy:122) com.domain.detect.http.HttpClient.this$2$getResponse(HttpClient.groovy)
这个线程栈的报错我见得多了,我们设置的 HTTP DNS 超时是 1s, connect 超时是 2s, read 超时是 3s,这种报错都是探测服务正常发送了 HTTP 请求,服务器也在收到请求正常处理后正常响应了,但数据包在网络层层转发中丢失了,所以请求线程的执行栈会停留在获取接口响应的地方。这种情况的典型特征就是能在服务器上查找到对应的日志记录。而且日志会显示服务器响应完全正常。 与它相对的还有线程栈停留在 Socket connect 处的,这是在建连时就失败了,服务端完全无感知。
我注意到其中一个接口报错更频繁一些,这个接口需要上传一个 4M 的文件到服务器,然后经过一连串的业务逻辑处理,再返回 2M 的文本数据,而其他的接口则是简单的业务逻辑,我猜测可能是需要上传下载的数据太多,所以超时导致丢包的概率也更大吧。
根据这个猜想,群登上服务器,使用请求的 request_id 在近期服务日志中搜索一下,果不其然,就是网络丢包问题导致的接口超时了。
当然这样 leader 是不会满意的,这个结论还得有人接锅才行。于是赶紧联系运维和网络组,向他们确认一下当时的网络状态。网络组同学回复说是我们探测服务所在机房的交换机老旧,存在未知的转发瓶颈,正在优化,这让我更放心了,于是在部门群里简单交待一下,算是完成任务。
问题爆发本以为这次值班就起这么一个小波浪,结果在晚上八点多,各种接口的报警邮件蜂拥而至,打得准备收拾东西过周日单休的我措手不及。
这次几乎所有的接口都在超时,而我们那个大量网络 I/O 的接口则是每次探测必超时,难道是整个机房故障了么。
我再次通过服务器和监控看到各个接口的指标都很正常,自己测试了下接口也完全 OK,既然不影响线上服务,我准备先通过探测服务的接口把探测任务停掉再慢慢排查。
结果给暂停探测任务的接口发请求好久也没有响应,这时候我才知道没这么简单。
解决 内存泄漏于是赶快登陆探测服务器,首先是 top free df 三连,结果还真发现了些异常。
我们的探测进程 CPU 占用率特别高,达到了 900%。
我们的 Java 进程,并不做大量 CPU 运算,正常情况下,CPU 应该在 100~200% 之间,出现这种 CPU 飙升的情况,要么走到了死循环,要么就是在做大量的 GC。
使用 jstat -gc pid [interval] 命令查看了 java 进程的 GC 状态,果然,FULL GC 达到了每秒一次。