记一次线上FullGC问题排查
问题起因
2022-03-13在钉钉工作通知中收到申请其中一台机器的预警。预警信息显示FullGC的次数持续超过指定的阈值。
我们知道FullGC非常耗时。当一个GC线程执行FullGC时，会严重影响其他线程的正常工作，造成系统卡顿的现象。通常情况下，它被认为可以停止这个世界。
所以这台机器果断重启，但是没过多久，其他机器就开始陆续报出FullGC警告。实在没办法，于是重启了整个应用，重启后应用运行恢复正常。虽然暂时恢复正常了，但不能保证以后不会再出问题，所以要追根溯源，从根源上解决问题。
问题排查
1. 分析JVM指标
我们知道JVM为了有效实施堆内存回收，通常会将堆划分为新生代和老年代，一般当老年代空间不足时会引发FullGC。
所以先去监控上看了下运行应用的JVM相关指标，着重看了堆内存指标。
最近半天JVM相关指标
最近一周JVM相关指标
先看近半天的指标，从下午4点开始，FullGC就开始频繁出现，GC耗时也跟着涨了上去，然后就一直居高不下。再看最近一周JVM的堆内存情况，发现老年代的占用成逐步上升的态势，初步怀疑是哪里存在内存泄漏。从这里也可以看到，如果不去管它，过一段时间又会出现FullGC问题了。
2. 分析堆内存
接下来分析下堆内存，先去dump了JVM堆，然后在内存分析平台上进行分析
我们知道JVM一般采用可达性分析算费确定一个对象是否可以被回收，被GC根对象强引用的对象是不会被回收的。
所以我们从GC根对象作为切入点进行分析。可以看到， java.lang.Thread @ 0x6c7baadf0 ConsumeMessageThread_14这个类对象占用的内存非常多，这是一个Thread类型的对象，从ConsumeMessageThread_14这个名字可以猜测这是一个MQ的消费者线程对象。这种对象一般是由线程池管理的，创建后一般不会销毁，这就会导致这类对象一旦存储了大量信息，将很难被回收。那么Thread中哪个字段会有可能存大量信息呢？没错，就是线程本地变量threadLocals java.lang.ThreadLocal$ThreadLocalMap。
我们知道ThreadLocal是被设计用来解决多线程并发时的线程安全问题的，如果用的不好可能会引起内存泄漏。
继续往下追，发现有一个java.lang.ThreadLocal$ThreadLocalMap$Entry对象占据的内存特别大，里面存储的value值是com.alibaba.common.lang.diagnostic.Profiler$Entry类型的对象，该对象有个subEntries字段，是个ArrayList类型，竟然存储了13.8W+个元素。
3. 结合代码
既然是com.alibaba.common.lang.diagnostic.Profiler$Entry类对象出了问题，就到源码里找一下相关的代码看看。
import com.alibaba.common.lang.diagnostic.Profiler;import static com.alibaba.common.lang.diagnostic.Profiler.enter;import static com.alibaba.common.lang.diagnostic.Profiler.getEntry;import static com.alibaba.common.lang.diagnostic.Profiler.release;@Aspect@Order(2)@Componentpublic class ProfilerAspect { private static final Logger DIGEST_LOGGER = LoggerFactory.getLogger("digest"); @Pointcut("execution(public * com.alibaba.onetouch.tax.order.integration.service..*.*(..)) " + "|| execution(public * com.alibaba.onetouch.tax.order.service..*.*(..)) " + "|| execution(public * com.alibaba.onetouch.tax.order.persistence.mapper..*.*(..)) " + "|| execution(public * com.alibaba.onetouch.tax.order.persistence.demeter.mapper..*.*(..)) " ) public void pointcut() {} @Around("pointcut()") public Object entrance(ProceedingJoinPoint joinPoint) throws Throwable { MethodSignature methodSignature = (MethodSignature) joinPoint.getSignature(); Method invokedMethod = methodSignature.getMethod(); boolean profiler = getEntry() != null; String methodName = getString(invokedMethod); try { if (profiler) { enter(methodName); }else{ Profiler.start(methodName); } return joinPoint.proceed(); } finally { release(); long duration = Profiler.getDuration(); if(duration>1000L){ DIGEST_LOGGER.info("invoike {} {}",methodName,Profiler.getDuration()); } } }}public final class Profiler { private static final ThreadLocal entryStack = new ThreadLocal(); public static void start(String message) { entryStack.set(new Entry(message, null, null)); } public static void start(Message message) { entryStack.set(new Entry(message, null, null)); } public static void enter(String message) { Entry currentEntry = getCurrentEntry(); if (currentEntry != null) { currentEntry.enterSubEntry(message); } } public static final class Entry { private final List subEntries = new ArrayList(4); private final Object message; private final Entry parentEntry; private final Entry firstEntry; private final long baseTime; private final long startTime; private long endTime;private Entry getUnreleasedEntry() { Entry subEntry = null; if (!subEntries.isEmpty()) { subEntry = (Entry) subEntries.get(subEntries.size() - 1); if (subEntry.isReleased()) { subEntry = null; } } return subEntry; } }}可以看到这里做了一个切面处理，我猜它这里是想统计下每个方法的调用时长，监控那些慢处理方法。通过分析代码发现，这段逻辑每走一次，都会往Profiler$Entry的subEntries里增加一条记录，同时Profiler$Entry又是存放在线程本地变量entryStack里的，这将导致这些内容难以被回收，这和前面分析堆内存时观察到结果是一致的。
我们写一个单元测试验证一下。
@Test public void test() { f1(); f3(); } private void f1() { entryMethod("f1"); f2(); } private void f2() { entryMethod("f2"); } private void f3() { entryMethod("f2"); } private void entryMethod(String name) { boolean profiler = getEntry() != null; try { if (profiler) { enter(name); }else{ Profiler.start(name); } } finally { release(); } Profiler.Entry entry = getEntry(); System.out.println(JSON.toJSONString(entry)); System.out.println(name + ": " + entry.getSubEntries().size()); }测试方法模拟调用方法f1()和f3()，其中f1()中又会调用方法f2()，每个方法都会调用entryMethod()模拟切面的调用，看下结果：
可以看到的确是每调用一次，subEntries中就会被增加一条记录的哈，这样日积月累总有一天内存会不够用的。
解决方案
既然根因找到了，出解决方案就不难了。切面处理完后，可以将subEntries中的记录移除，或者将entry对象指空，以达到回收内存的目的。
