1 结论
先说一下结论:
- 有一个方法分批的从数据库中查询数据, 然后放到一个 ArrayList 中, 最后拿着这个全量数据的 ArrayList 再做其他的操作
- 而这次事故中, 在分批查询过程中, 查询出了大量的数据, 触发了 GC, 但因为强引用无法回收, 结果整个应用一直都在 GC
2 过程
2.1 告警
下午, 运维提示线上出现了大量的 50000 告警 (响应结果里面的状态码, 50000 在我们系统中, 基本都是非业务异常)。
登上网关日志平台, 发现的确有大量的错误:
2.2 排查
2.2.1 接口异常直接原因
通过网关请求日志发现异常基本集中在几个动态相关的接口上, 于是随机抽出一个接口, 从代码中得到对应的 Controller 和方法。
进入到 APM 平台(应用性能监控平台), 搜索对应时间范围内 + 对应的 Controller 和方法的异常日志。
这里也可以直接通过请求的 traceId 到应用日志平台搜索, 这种非业务异常的日志, 通常都会打印到日志中。
发现异常日志如下:
大体的意思: 调用 192.168.1.2 机器上应用的 Dubbo 接口超时了。
2.2.2 接口提供方超时原因定位
根据日志上的地址 + 接口找到对应的应用。
直接进入到应用日志, 看看能找到什么信息, 发现整个日志都停在了 15:14 (也是大量告警出现的时间点), 后面没有任何的日志输出。
日志无收获, 只能从应用自身的入手了。
- 先获取一下当前 Java 程序的进程 Id
jps -l
可以得到当前的进程 Id 为 74。
- 通过 top, 查看一下当前机器的 CPU 情况
top
发现当前 CPU 很高, 达到了 248, 进程 ID 为 74, 和我们应用的进程 Id 一致。
- 进一步查看当前进程的线程情况:
top -Hp 进程 Id
发现有 4 个线程的 CPU 都很高, 其他的几乎为 0 (当时没截图, 上面的数据凭印象造的, 主要的 CPU 和 PID, 不会有很大偏差)。
- 抽取一个线程 Id, 查看当前它的堆栈信息进行分析:
因为 Java JVM 中线程 Id 是 16 进制的, 而 top -Hp 查看到的是 10 进制的, 所以需要先转转换一下
printf "%x\n" 抽取的线程 Id得到线程 Id 108 对应的 16 进制 Id 为 6c
- 通过 jstack 查看当前线程的堆栈信息
jstack 进程 Id | grep 上面的线程 16 进制 Id -C 10
找到 nid= 处, 发现是 gc 线程。
查看另外 3 个高 CPU 的线程, 发现也是 gc 线程。
到这里, 原因基本可以确定了: 当前应用一直在 GC, 导致其他线程无法调度, 从而导致了大量的接口超时。
2.2.3 GC 原因定位
那么为什么会一直在 GC 呢? 可以通过当前的堆栈信息进行分析。
- 先通过 jmap 获取当前的堆栈信息
jmap -dump:format=b,file=heapdump.hprof 进程 Id获取到堆栈信息的文件: heapdump.hprof, 将其下载到本地, 然后导入到堆栈分析工具中查看, 这里使用的是 JProfile。
- 导入后,一进来界面的是这样的
- 直接选择最大对象
发现最大对象的前几个中, 有 2 个 ArrayList, 结合当前应用一直在 GC 中, 选择其中一个的 ArrayList, 查看里面的内容。
查看内容的步骤大体如下:
选中查看的对象 -> 右键 -> 使用选定对象
在弹窗中, 选择引用 -> 传出引用 -> 确定
发现里面的内容是业务数据, 有 15 万多条数据。
查看另一个 ArrayList, 发现里面的内容是也是业务的家长打卡数据, 有 4 万多条数据。
备注:
下面有用户对应的操作步骤, 可以点击对应的步骤, 回到上一次操作的界面。
到这一步可以确定问题出在了这 2 个 ArrayList 了。
程序一直往这 2 个 ArrayList 里面塞数据, 内存逐渐不够用, 触发了 GC, 而 ArrayList 中的数据又无法回收。
- 定位 ArrayList 数据产生的位置
将上面的传出引用, 变为传入引用
拖到最右边, 选择显示更多
这样就可以查看到堆栈信息
最终定位到实际代码位置:
com.xxx.yyyy.broadcast.service.api.impl.SchoolStudentArchiveServiceApiImpl.getClassPunchAnswerWithPhoto(java.lang.String, long, long)分析代码发现是一个汇总分析的方法, 里面会查询出某个时间段的全部的数据, 然后汇总分析。
解决方案: 就根据具体业务进行分析解决。
至此, 结束。
