性能文章>一次线上 FGC 问题排查,最后问题竟然是这个!>

一次线上 FGC 问题排查,最后问题竟然是这个!转载

1周前
200201

导语

线上的虚拟机出现了回滚的问题,通过一步步排查发现竟然是Metaspace的问题,本篇详细解读了对FGC问题的排查过程。

1.背景

先介绍下背景。服务部署在弹性云上面。弹性云是一种动态可伸缩的服务器,底层是通过docker的方式创建的虚拟机而不是物理机。
本次发布的应用 Maybach 共五台机器,分为3批发布,第一批和第二批各一台机器,第三批3台机器。

2.现象描述

1、14:34分开始发布第一批机器,14:35第一批机器部署成功。
2、14:45发布第二批机器,14:46发布成功。
登录已经发布的两台线上机器查看,服务正常运行(进程还在),且能正常打印请求log(能正常接收服务),调用方无明显异常,业务数据无明显异常,无业务监控报警。
3、14:58发布最后一批机器。
4、14:59第三台(最后一批第一台)机器发布成功。
5、15:01第四台(最后一批第二台)机器发布成功。
6、15:02最后一台机器发布成功。
7、15:02加油订单支付成功率 BI一级报警。
8、15:04SRM新导购、油站检索、门店列表、门店详情标红成功率下降延迟增高
9、15:06调用方反馈刚发布的服务全部连接超时。

这个时候刚发布的系统已经线上全挂了。接下来就是回滚了。

回滚的时候又出现了问题,导致整个回滚过程花了半个小时,也就是说线上服务全挂半个小时,15:31终于回滚成功,造成了不少的资损,不过这就是另外一件事了。

事后查看发布之后那段时间内的机器监控,以第一台机器为例:

内存使用情况:

一次线上 FGC 问题排查,最后问题竟然是这个数据图表-heapdump性能社区

rpc调用统计:

一次线上 FGC 问题排查,最后问题竟然是这个数据图表-heapdump性能社区

流出流量:

一次线上 FGC 问题排查,最后问题竟然是这个数据图表-heapdump性能社区

请求流量:

一次线上 FGC 问题排查,最后问题竟然是这个数据图表-heapdump性能社区

3. 排查分析

既然这次上线之后引起了故障,肯定得看下代码的改动点,通过mr记录发现这次上线了如下的改动点:

一次线上 FGC 问题排查,最后问题竟然是这个数据图表-heapdump性能社区

初步估计跟修改 jvm 参数有关,既然如此的话,第一反应应该是去查看GC日志,但是由于 maybach 没有配置 gc.log,且没有配置相应的 jvm 监控,没办法查看故障发生时候的 gc 情况,这个方法行不通,那就想办法复现吧。


在预发环境部署有问题的代码,很容易就可以复现了。


首先使用 top 命令查看机器的系统情况:

一次线上 FGC 问题排查,最后问题竟然是这个数据图表-heapdump性能社区

可以看到我们的服务(pid=433)占用了大量的cpu,进一步查看是哪个线程在占用cpu,使用top -H -p433查看结果如下:

一次线上 FGC 问题排查,最后问题竟然是这个数据图表-heapdump性能社区

可以看到pid尾478的线程在占用cpu,转换成十六进制为1de,使用命令查看线程堆栈情况,找到nid=0x1de的线程

"VM Thread" os_prio=0 tid=0x00007f95f825b800 nid=0x1de runnable
"Gang worker#0 (Parallel GC Threads)" os_prio=0 tid=0x00007f95f801c800 nid=0x1b3 runnable
"Gang worker#1 (Parallel GC Threads)" os_prio=0 tid=0x00007f95f801e000 nid=0x1b4 runnable
"Gang worker#2 (Parallel GC Threads)" os_prio=0 tid=0x00007f95f8020000 nid=0x1b5 runnable
"Gang worker#3 (Parallel GC Threads)" os_prio=0 tid=0x00007f95f8022000 nid=0x1b6 runnable
"Gang worker#4 (Parallel GC Threads)" os_prio=0 tid=0x00007f95f8023800 nid=0x1b7 runnable
"Gang worker#5 (Parallel GC Threads)" os_prio=0 tid=0x00007f95f8025800 nid=0x1b8 runnable
"Gang worker#6 (Parallel GC Threads)" os_prio=0 tid=0x00007f95f8027800 nid=0x1b9 runnable
..........
JNI global references: 10200


可以看到,”VM Thread”就是该cpu消耗较高的线程,查看相关文档我们得知,VM Thread是JVM层面的一个线程,主要工作是对其他线程的创建,分配和对象的清理等工作的。从后面几个线程也可以看出,JVM正在进行大量的GC工作。这里的原因已经比较明显了,即大量的GC工作导致项目运行缓慢。

继续查看jvm的gc情况,如下图所示:

一次线上 FGC 问题排查,最后问题竟然是这个数据图表-heapdump性能社区

这里已经很明了了,可以清晰的看到,jvm 一直在 fgc 。

从上面那张图也可以看到,发生 fgc 的时候,新生代,老年代实际上占用的内存并不多,反倒是Metaspace,总共内存是 65536 k,目前已经使用了64098k,且 jvm 设置了-XX:MaxMetaspaceSize=64,即 Metaspace 最大可使用内存空间为64m,这个时候已经使用了97%,如果继续增大,就会发生fgc。

一次线上 FGC 问题排查,最后问题竟然是这个数据图表-heapdump性能社区

上面这张图是线上正常的时候 Metaspace 使用的大小保持在76m左右,是大于64m的,所以每次来了请求之后,Metaspace就会超过64m,这个时候jvm就会忙于fgc,造成stw,以至于调用方超时。

故障原因已清晰明了:由于本次上线设置了Metaspace最大能使用的大小为64m,Metaspace使用空间只要超过64m就会发生fgc,而这个应用Metaspace正常使用大小为76m左右,导致jvm一直忙于fgc造成stw现象而无法去处理请求,导致线上请求超时。


现在需要解释两个问题:
为什么在第三批机器发布前调用方没有异常报警?也没有业务异常报警?
为什么第三批机器发布完成之后全线连接超时?
先来看一张图,这张图展示了整个发布上线过程中的整体的流量变化情况

一次线上 FGC 问题排查,最后问题竟然是这个数据图表-heapdump性能社区

可以看到,第一二批机器发布之后,打到这两台机器上面的流量大幅减少(而且发布的时候正好是业务低峰期,本身流量就不多),另外三台未发布的机器的流量整体大幅增长(相对之前的流量)。

现在来解释第一个问题:为什么在第三批机器发布前调用方没有异常报警?也没有业务异常报警?

从图中可以看到,前两批机器发布之后,大部分流量都流向了还未发布的三台机器,只有较少部分流量会流向已经发布的两台机器,这个时候这两台机器所有的请求都会超时,但是这对整体业务影响不大,所以并没有业务异常报警。而且调用方配置的报警策略是每秒有超过十个的异常才报警,这个时候流量很少,并没有达到这个报警阈值,所以调用方也没有收到接口异常报警。

继续解释第二个问题:为什么第三批机器发布完成之后全线连接超时?

第三批机器全部发布完成之后,流向这三台机器的流量大幅降低,且这三台机器上的请求会全部超时(jvm一直处于stw状态)。大部分的流量都流向了第一台机器,本来这个时候第一台机器的所有请求都会超时,大幅流量打过来,全部超时。所以这个时候线上所有请求都会超时,导致全线挂掉。

4. 其他:关于Metaspace

Metaspace是Java8中引入的用来替代PermGen(永久带)的一块内存区域,其与永久带一个最明显的区别就是Metaspace使用的是本地内存而不是堆内存,因此,Metaspace的大小仅受限于机器本身的内存大小。

下面几个JVM参数跟Metaspace有关:

  • -XX:MetaspaceSize:默认20.8M左右,主要是控制Metaspace GC发生的初始阈值,也是最小阈值。
  • -XX:MaxMetaspaceSize:最大空间,默认是没有限制的。
  • -XX:MinMetaspaceFreeRatio:在GC之后,最小的Metaspace剩余空间容量的百分比,减少为分配空间所导致的垃圾收集。
  • -XX:MaxMetaspaceFreeRatio:在GC之后,最大的Metaspace剩余空间容量的百分比,减少为释放空间所导致的垃圾收集。

 

更多思考

经过排查竟然发现是Metaspace的问题,更多jvm相关的知识大家可以阅读以下内容加深阅读:

JVM源码分析之Attach机制实现完全解读

JVM源码分析之JDK8下的僵尸(无法回收)类加载器

分类:
标签:
请先登录,再评论

暂无回复,快来写下第一个回复吧~

为你推荐

警惕大量类加载器的创建导致诡异的Full GC
概述 今天有个同事找我,其实好像之前就找过我,一直因为太忙,后面就忘记他的事了,到今天还没查出原因就又找了过来,现象是系统老是进行Full GC,在启动没过多久就会发生Full GC,这个现象相
一次超诡异的FGC,这个原因找了好久!
正撸着代码,公司内的聊天工具弹出一条信息: “狼哥,我这个机器总是频繁FGC...” 我赶紧打开对话框,机智的回复一个表情 然后继续默默撸码。 随后,小伙伴砸了一段GC日志过来 ```java
JVM源码分析之Metaspace解密
概述metaspace,顾名思义,元数据空间,专门用来存元数据的,它是jdk8里特有的数据结构用来替代perm,这块空间很有自己的特点,前段时间公司这块的问题太多了,主要是因为升级了中间件所致,看到大
GC日志中,Metaspace的这几个参数分得清吗?
在GC日志中,Metaspace这一行的 used ,capacity ,committed ,reserved 具体都代表什么?```JAVAHeapPSYoungGen total 10
深入理解堆外内存 Metaspace
在之前介绍的分代垃圾回收算法中,我们一直有一个永久代存在,叫 PermGen,内存上它是挨着堆的。为了垃圾回收方便,HotSpot 在永久代上一直是使用老年代的垃圾回收算法。永久代主要存放以下数据:-
解决服务器进程退出问题(metaspace溢出)实战
现象策划反应服务器进不去,远程看了一下进程消失了(crash),有时候也会出现能登录,但是无法执行操作(进程还在),无法被正常shutdown,进程根目录下出现了```java_pid16298.hp
JVM Metaspace内存溢出排查与总结
现象前段时间公司线上环境的一个Java应用因为OOM的异常报警,导致整个服务不可用被拉出集群,本地模拟重现的现象如下:当时的解决方案是增加metaspace的容量:-XX:MaxMetaspaceSi
大量生成字节码导致元空间溢出问题排查
前几天生产环境出现了一个问题,gc日志里面某一个时间段出现了大量的Full GC,而且都是回收元空间内存失败了,最终导致了JVM停止运行,微服务中的某个服务发生了宕机。下面记录下排查该问题的过程。首先