一次线上GC问题排查

  • 发现问题

早上还没到公司就收到短信告警,提示订单接收接口频繁报错. 立即介入看告警信息,一般都会拿到报错的基本信息,例如堆栈或则关键日志等等查看错误日志量。
一次线上GC问题排查
这里初步从八点开始发现错误在变多,然后查看峰值最高的时间段的异常日志。发现一个很关键的信息lock wait.
一次线上GC问题排查
这初步说明是DB的锁超时导致的接单报错。
这个时候查看整个集群的信息,很多机器已经出现飙红的情况。
一次线上GC问题排查
CPU的负载非常高,我们尝试重启机器,避免影响线上业务,批量重启之后机器恢复一段正常时间。
但是异常信息又继续报出来,好了,继续排查刚才的锁的问题。首先分析这张表的写入是否是量增加了,
这个表是订单表,属于外域调用进来,首先关注几个点。

  1. 接口QPS, 是否由于某种业务,例如大促或则其他商家入驻导致的QPS剧增
    接单接口我们有QPS监控,查看大盘发现单量环比并没明显增加,排除这个可能
  2. 是否IO出问题
  3. 是否是DB出问题
    DB我们可以去看慢SQL信息
  4. 是否是机器出问题
    如果是机器出问题,不会导致整个集群都同时报错
    分析代码如下发现有一个循环写入表的操作,根据订单分析发现这个循环并没增加。

这个时候发现很多机器的已经CPU升高。

一次线上GC问题排查
因为考虑到要首先止血,首先看昨天有没有发布,如果有需要紧急回滚。
这个接口的代码昨天没有发布, 判断是否是昨天发布引起的。查询该异常信息在发布前的同一个时间段的环比。
发现果然之前不存在这个异常信息。初步判断是前一天的日常发布导致的。进行回滚。
随着回滚机器的增加,异常信息在减少. 回滚完毕之后异常消息。这次确信是因为前一天发布导致的。接下来就有几个方案了。1.代码compare看一下到底发布了什么。2.看了接单的这一块接口,发现的确没有改动,只是不相关的几个功能点有改动。我们再次回到系统指标上来。我们找到了当时cpu负载最高的几台机器中其中一台。

发现其中一台机器的cpu与内存情况:
一次线上GC问题排查
看这个cpu与内存的曲线基本一致。这里引起注意,看下当时JVM的情况,看看GC情况。
一次线上GC问题排查
比较正常情况下同一时间段的GC情况。
一次线上GC问题排查
发现GC的频率增加不少,而且线程丢的很快,GC耗时剧增,感觉像是大数据GC导致。进一步看JVM堆情况。
一次线上GC问题排查
作为对比,看看正常时间段的堆情况.
一次线上GC问题排查
惊讶的发现,堆在频繁GC。看来应该是前天发布的代码应该有大对象查询。
经过代码比较,发现果然一个查询没有做分页操作,导致大数据加载到内存。

现在可以回答几个前面告警的疑惑了。
为什么首先告警的是接单接口。
因为接单接口有一个比较大的事务,后来翻看日志其他所有的写入操作都或多或少有影响,
由于接单是QPS维持在比较稳定的水位,一旦出错上游会进行重试,GC导致事务没被提交线程被挂起会拉大事务耗时,再加上接单没做分布式锁,耗时太久上游重复下发会获取同一锁增加等待。