0%

一次FGC问题分析

双十一全链路压测过程中,收到应用的FGC的耗时告警,提示产生了一次耗时7秒的Full GC。

应用使用CMS GC,相关的JVM参数为:-server -Xms10g -Xmx10g -Xmn5g -XX:MetaspaceSize=512m -XX:MaxMetaspaceSize=512m -XX:MaxDirectMemorySize=1g -XX:SurvivorRatio=10 -XX:+UseConcMarkSweepGC -XX:CMSMaxAbortablePrecleanTime=5000 -XX:+CMSClassUnloadingEnabled -XX:CMSInitiatingOccupancyFraction=80 -XX:+UseCMSInitiatingOccupancyOnly

登陆机器,查看gc.log,发现是发生了promotion failed错误:

1
2020-11-05T00:08:40.890+0800: 766572.117: [GC (Allocation Failure) 2020-11-05T00:08:40.891+0800: 766572.117: [ParNew (promotion failed): 4678001K->4487571K(4806016K), 0.9033027 secs]2020-11-05T00:08:41.794+0800: 766573.021: [CMS: 2606708K->1804592K(5242880K), 7.6371053 secs] 7243557K->1804592K(10048896K), [Metaspace: 280447K->280447K(1306624K)], 8.5408666 secs] [Times: user=8.70 sys=0.09, real=8.54 secs]

promotion failed错误产生的原因:

  • CMS GC默认采用的是标记-清除算法,并不会在CMS GC的时候对老年代的空间进行内存整理,因此在应用长时间未重启的情况下,老年代会产生很多内存碎片。
  • 在进行YGC的时候,如果发现Survivor空间不够,则需要将一部分新生代的对象移动到老年代,但是由于内存碎片的原因,这些碎片无法存放大对象,因此对象晋升失败,产生promotion failed错误,并导致提前触发一次CMS GC。

更严重的情况是,当进行CMS GC的时候,YGC再次将年轻代中的对象晋升到老年代,并且晋升失败,则会触发concurrent mode failure错误,此时会中断正在进行中的CMS GC,转而使用全STW的Serial Old GC。

长耗时的FGC本身也算是一种可优化的正常情况(比如增加-XX:UseCMSCompactAtFullCollection相关参数,在CMS GC之后增加内存整理,防止碎片化过于严重),加上压测过程中只有1台机器提示有这个问题,因此当时并没有过于关注。

FGC频率异常

在压测持续进行中,又有额外三台机器发生了告警,并且再次观察到第一台发生告警的机器监控:
1
从监控中,发现机器的FGC频率严重异常,由之前的20小时FGC一次,变成不到3分钟FGC一次,即使压测结束之后,流量已经回到了正常线上流量,FGC的频率也并没有缓解。

老年代增长快原因

从监控中,可以看出老年代增长速度比之前加快了很多,从而导致了频繁的FGC,而对象进入老年代主要有以下几种方式:

  • YGC时,Survivor区放不下这么多对象,多余对象直接进入到老年代;

通过jstat -gcutil观察GC情况,发现Survivor区在每次YGC之后,使用率并不高,即是能够继续存放对象;

  • 超大的大对象,直接分配到老年代;

应用的业务逻辑里,并不会在处理请求的时候频繁产生超大对象。

  • 对象的晋升阈值(tenuring threshold)变小,导致对象在经历了少许几次YGC之后仍然存活,从而晋升到老年代。

CMS中,默认的晋升阈值是6(最大值是15,通过-XX:MaxTenuringThreshold设置),即是默认经过6次YGC之后,如果对象仍然存活,则会晋升到老年代。但是这个值并不是固定的,而是动态计算的,计算源码为compute_tenuring_threshold函数,部分核心代码为:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
uint ageTable::compute_tenuring_threshold(size_t survivor_capacity) {
// 应用JVM配置为-XX:SurvivorRatio=10 -Xmn5g
// 因此可以计算出survivor_capacity约为426M(5G/12)
// TargetSurvivorRatio并没有单独设置,默认值为50
// 因此得出desired_survivor_size大约为213M左右
size_t desired_survivor_size = (size_t)((((double) survivor_capacity)*TargetSurvivorRatio)/100);
size_t total = 0;
uint age = 1;
assert(sizes[0] == 0, "no objects with age zero should be recorded");
while (age < table_size) {
total += sizes[age];
// check if including objects of age 'age' made us pass the desired
// size, if so 'age' is the new threshold
if (total > desired_survivor_size) break;
age++;
}
uint result = age < MaxTenuringThreshold ? age : MaxTenuringThreshold;

// ...
}

计算逻辑主要是在while循环内,其中:

  • sizes:JVM会记录每个分代年龄的对象大小,存在sizes数组中;
  • table_size:表示sizes的大小。

每次都会从年龄为1开始,将不同年龄代存活的对象大小相加,直到相加的和超过了desired_survivor_size,那么这个年龄,便是下一次YGC晋升到老年代的阈值。

可以增加-XX:+PrintTenuringDistribution参数,在每次YGC之后,动态的打印出sizes的信息,更加直观。
如果应用没有增加这个参数,可以利用jinfo -flag动态修改参数,也可以利用gdb,修改变量内存地址的值,从而可以不用增加参数后重启,避免破坏现场。举个gdb的例子:

  • gdb -p {PID}

  • (gdb) p &PrintTenuringDistribution

    $2 = ( *) 0x7f7d50fc660f

  • (gdb) set *0x7f7d50fc660f = 1

增加PrintTenuringDistribution参数之后,更直观的从日志来查看:
2
可以看到每次YGC之后,年龄为1的存活对象大小有120M-200M之间,年龄小于等于2的存活对象大小就已经超过了desired_survivor_size(约213M),使得阈值基本上维持在2,因此对象在经过2次YGC仍没有被回收,则会晋升到老年代。
同时找了一台正常的机器做对比,晋升阈值几乎一直处于15左右,年龄为1的对象,基本上维持在几十M左右,则说明正常机器的YGC每次都能回收掉大量内存,有问题的机器YGC效率很低,每次回收之后都遗留了大量对象。

YGC效率低的原因

至此,基本上已经可以判断是存在有内存泄露,导致YGC时无法回收掉。
在诺曼底中,dump机器的内存(不带GC),利用一些dump分析工具进行分析,发现了异常点:

  • org.apache.tomcat.util.threads.TaskThead是Tomcat的连接线程池中的线程,dump出来中显示数量是200个;
  • 大部分TaskThread的ThreadLocal中都发现了有BizSessionImpl对象,并且这个对象持有了应用返回给PC的html内容,大小在1M到5M不等。

再dump一台正常的机器作为对比,发现正常机器的TaskThread数量在25个,同时TaskThread也持有了返回给PC的html内容。
所以,基本上可以判定是TaskThread中,BizSessionImpl没有从ThreadLocal移除,导致YGC时,这部分数据被GC Roots间接引用,无法回收。而正常情况下,只有25个线程,常驻内存占用不到100M,因此相对来说不会太影响YGC的效率,异常情况下,有200个线程,常驻内存占用会远超200M。

线程池增长的原因

Tomcat声明线程池的地方在org.apache.catalina.core.StandardThreadExecutor中,相关代码为:

1
2
3
4
5
6
7
8
9
10
11
12
protected void startInternal() throws LifecycleException {
taskqueue = new TaskQueue(maxQueueSize);
TaskThreadFactory tf = new TaskThreadFactory(namePrefix,daemon,getThreadPriority());
executor = new ThreadPoolExecutor(getMinSpareThreads(), getMaxThreads(), maxIdleTime, TimeUnit.MILLISECONDS,taskqueue, tf);
executor.setThreadRenewalDelay(threadRenewalDelay);
if (prestartminSpareThreads) {
executor.prestartAllCoreThreads();
}
taskqueue.setParent(executor);

setState(LifecycleState.STARTING);
}

其中:

  • TaskQueue是Tomcat自带的org.apache.tomcat.util.threads.TaskQueue,继承自LinkedBlockingQueue,但是重写了offer、poll、take等方法;
  • ThreadPoolExecutor是Tomcat自带的org.apache.tomcat.util.threads.ThreadPoolExecutor,继承自JDK的ThreadPoolExecutor;
  • 默认的corePoolSize为25,maximumPoolSize为200,keepAliveTime为60秒。

Tomcat线程池的线程分配机制跟JDK的不太一样:

  • JDK是先使用corePoolSize,满了之后往队列里面放,队列满了之后会继续分配线程,直到线程数达到maximumPoolSize之后,触发拒绝策略;
  • Tomcat的TaskQueue重写了LinkedBlockingQueue的offer方法,细节就不分析了,流程上是先使用corePoolSize,满了之后会继续分配线程,直到线程数达到maximumPoolSize之后,才开始往队列里放。

当发生一次超长耗时的FGC时,线程池中已经分配的线程会进入safe point,无法响应请求,同时新的请求不断到来,堆积在队列中,当GC结束之后,线程池便会分配新的线程来处理堆积的请求,从而导致线程池中线程数量的增加。
而由于keepAliveTime为60秒,因此理论上QPM如果达到200以上,则200个线程在向队列请求任务时,都会在keepAliveTime之前获得,不会超时,从而导致新分配出来的线程就永远不会被回收掉,因此dump出来的数据中,TaskThread显示的是200(就算压测结束,应用需要处理的HTTP请求的QPM也大于200)。

问题修复

BizSessionImpl是我们这边定义的一个公共的Session,继承自BizSession,本身并没有将自己放到ThreadLocal中,不过在BizSession的初始化中,发现了端倪:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
public class BizSession {
private static boolean useThreadLocalSession = true;
// 兼容老版本的
private static ThreadLocal<BizSession> localSession = new ThreadLocal<BizSession>();

public BizSession(ServletContext servletContext, final RequestContext requestContext) {
super(servletContext, requestContext);
initLocalSession();
}

public static void setUseThreadLocalSession(boolean useThreadLocalSession) {
BizSession.useThreadLocalSession = useThreadLocalSession;
}

private void initLocalSession() {
if (useThreadLocalSession) {
localSession.remove();
localSession.set(this);
}
}
}

BizSession在初始化的时候,会根据开关控制,判断是否将自己放入ThreadLocal中(从注释来看,也是一个历史遗留的逻辑)。

  • 开关默认为true,我们这边并没有显示将其设置为false;
  • 放入ThreadLocal之后,并没有提供相应的移除接口。

找到问题之后,就有办法重现了,在应用的配置文件中,修改tomcat的corePoolSize为200,然后写个shell脚本,不断请求HTTP接口,然后观察FGC情况,以及对dump数据进行分析,得到跟问题机器一样的情况。

修复

修复方式就比较简单了,跟创建BizSessionImpl的同事沟通,增加一个开关,由各自应用自行设置是否开启useThreadLocalSession。



-=全文完=-