生产事故排查标杆,必须写进你的简历里

4,810 阅读4分钟

本文已参与「新人创作礼」活动,一起开启掘金创作之路。

事情起因

某年某月的某一天,倒了一杯快乐的水。突然各个客户群突然暴雷,说我们的接口很多超时,作为一个职业道德满满的新世纪好青年,我立马查看了日志记录。

图片

啊这这这....商品校验信息的接口,这直接影响到了下单流程,说不好要被挂在城墙,暴晒三日的,于是开始了紧锣密鼓的排查。

排查

1、根据时间和接口关键词定位日志

此处使用的是阿里云的SLS日志服务

图片

通过日志发现,http status 为 499,这部分的原因很多可能是客户端关闭了连接。于是同各个客户的技术沟通得知,因为客户是设置了超时时间3s的限制,超过3s直接关闭请求,由此排除了业务上的代码逻辑问题。

2、 快速解决生产,统计接口时间,放开限制

由于这些接口直接影响到了下单流程,因此最先想到的是,能否由客户那边对时间限制进行放开,于是我统计了阿里云日志相关接口的最长时间,期望客户能对接口响应给更宽容的时间。

图片

对于我们提出的放开限制的要求,客户最终确认6s为他们的安全时间,因此,这对于我们多少还是起到了缓冲,让我们有一定的时间,来正式定位问题。但是日常200ms返回的接口,现在被冲上了6秒多,这无论如何都是不能够接受的,因此,进入了定位分析问题中

3、跟踪日志,正式定位原因

3.1、商品服务接口偶发性变慢

图片

经排查,服务流量过载,经常将商品服务的服务器CPU飚到190%,于是增加服务器,将商品服务的流量均衡一下。

3.2 java服务的GC或CPU问题

在商品服务增开流量之后,发现超时的问题并没有缓解,于是再次去到了调用链中查看。商品的响应很快,基本上100ms以内就可以返回,于是主观的判断了停顿是发生在对外交互的服务当中(这一主观的认为,也对后面的排查造成了极大的误导

图片

如图所示,门户网关最后拿到商品服务的结果是12:59:32,但是却在12:59:38才把结果返回去,但 是通过review代码,这里面并没有其他操作,因此猜测是门户网关卡住了,并没有继续,怀疑是 FULL GC的STW,导致恢复现场花费较多时间。

3.3 查看GC Log

图片

图片

从这里我们看出两个问题:

•FullGC的很频繁 •核对了发生时间和超时时间较为吻合

因此,运维把服务由原先的4核8G升级为8核16G,观察发现还是出现了超时,并且是 发生在没有fullgc的情况下。由此排除了是网关服务的GC问题造成的接口卡顿。

4、 接口测试

使用jmeter对接口进行测试复现。

4.1、 域名请求门户网关测试

由于网关服务提供了一个无业务逻辑的health接口,用来健康检测,本次通过域名来循环调用这个接口来测试问题

图片

通过调用接口发现,接口呈现有规律的卡顿,非常非常非常规律的2分钟超时一次,这时候 仿佛发现了新大陆。此时的方向有几个:

1.恶意流量(日志中可以排除)

图片

期间没有大批的流量涌入

2. 门户网关服务有类似2min的定时,可以再代码中排除3. 2min的时间刚好是之前GC的时间,但是在新增资源之后排除4. 网络问题,但实际排查下来,网络没有大范围的波动

图片

4.2、调用其他服务接口测试

图片

图片

发现各个服务的接口都呈现类似的规律,因此猜测是基础组件的一些问题,于是采用ip+port的方式来同样的测试。

4.3、 ip+port调用门户网关

图片

看到虽然,服务的请求时间偶有上升,但整体水平保持在500ms以下,绝大部分200ms以内返回了,因此推测有可能是ng出现了问题。

4.4、ip+port调用ng

图片

果不其然,出现了相同的规律。

5、ng的阻塞

从上面大致定位到了是ng的问题,于是开始排查ng的定时任务,这里处理请求使用的是阻塞函数,因此阻塞住了ng的主线程。至此整个问题定位到了。其实,在生产中,我们会遇到各种各样的问题,有着很多的干扰因素,但是只要我们能够有着清晰的思路,问题都有迹可循.