Mongodb数据库查询GC overhead limit exceeded异常定位与处理

1 业务场景

业务：导出业务，生产环境导出标注数据，由于批次数量没有限制，所以批次数据大小有时会变得很大
存储：MongoDB
批次大小：1.6W条数据
JDK版本：1.8

2 错误发生与定位

报错信息如下：

STDERR: Exception in thread "pool-4-thread-1" java.lang.OutOfMemoryError: GC overhead limit exceeded
STDERR: at org.bson.Document.<init>(Document.java:57)
STDERR: at org.bson.codecs.DocumentCodec.decode(DocumentCodec.java:146)
STDERR: at org.bson.codecs.DocumentCodec.decode(DocumentCodec.java:45)
STDERR: at org.bson.codecs.configuration.LazyCodec.decode(LazyCodec.java:47)
STDERR: at org.bson.codecs.DocumentCodec.readValue(DocumentCodec.java:222)
STDERR: at org.bson.codecs.DocumentCodec.decode(DocumentCodec.java:151)
STDERR: at org.bson.codecs.DocumentCodec.decode(DocumentCodec.java:45)
STDERR: at org.bson.codecs.configuration.LazyCodec.decode(LazyCodec.java:47)
STDERR: at org.bson.codecs.DocumentCodec.readValue(DocumentCodec.java:222)
STDERR: at org.bson.codecs.DocumentCodec.readList(DocumentCodec.java:229)
STDERR: at org.bson.codecs.DocumentCodec.readValue(DocumentCodec.java:218)
STDERR: at org.bson.codecs.DocumentCodec.decode(DocumentCodec.java:151)
STDERR: at org.bson.codecs.DocumentCodec.decode(DocumentCodec.java:45)
STDERR: at org.bson.codecs.configuration.LazyCodec.decode(LazyCodec.java:47)
STDERR: at org.bson.codecs.DocumentCodec.readValue(DocumentCodec.java:222)
STDERR: at org.bson.codecs.DocumentCodec.readList(DocumentCodec.java:229)
STDERR: at org.bson.codecs.DocumentCodec.readValue(DocumentCodec.java:218)
STDERR: at org.bson.codecs.DocumentCodec.decode(DocumentCodec.java:151)
STDERR: at org.bson.codecs.DocumentCodec.decode(DocumentCodec.java:45)
STDERR: at org.bson.codecs.configuration.LazyCodec.decode(LazyCodec.java:47)
STDERR: at org.bson.codecs.DocumentCodec.readValue(DocumentCodec.java:222)
STDERR: at org.bson.codecs.DocumentCodec.readList(DocumentCodec.java:229)
STDERR: at org.bson.codecs.DocumentCodec.readValue(DocumentCodec.java:218)
STDERR: at org.bson.codecs.DocumentCodec.decode(DocumentCodec.java:151)
STDERR: at org.bson.codecs.DocumentCodec.decode(DocumentCodec.java:45)
STDERR: at org.bson.codecs.configuration.LazyCodec.decode(LazyCodec.java:47)
STDERR: at org.bson.codecs.DocumentCodec.readValue(DocumentCodec.java:222)
STDERR: at org.bson.codecs.DocumentCodec.decode(DocumentCodec.java:151)
STDERR: at org.bson.codecs.DocumentCodec.decode(DocumentCodec.java:45)
at com.mongodb.operation.CommandResultArrayCodec.decode(CommandResultArrayCodec.java:52)
STDERR: at com.mongodb.operation.CommandResultDocumentCodec.readValue(CommandResultDocumentCodec.java:60)
STDERR: at org.bson.codecs.BsonDocumentCodec.decode(BsonDocumentCodec.java:84)

关键词：GC overhead limit exceeded；从上述报错信息不难看出是在最后的报错信息在com.mongodb.operation.CommandResultArrayCodec.decode()执行过程中出错了

2.1 GC overhead limit exceeded

Oracle官网解释：
Exception in thread thread_name: java.lang.OutOfMemoryError: GC Overhead limit exceeded
Cause: The detail message "GC overhead limit exceeded" indicates that the garbage collector is running all the time, and the Java program is making very slow progress. After a garbage collection, if the Java process is spending more than approximately 98% of its time doing garbage collection and if it is recovering less than 2% of the heap and has been doing so for the last 5 (compile time constant) consecutive garbage collections, then a java.lang.OutOfMemoryError is thrown. This exception is typically thrown because the amount of live data barely fits into the Java heap having little free space for new allocations.
Action: Increase the heap size. The java.lang.OutOfMemoryError exception for GC Overhead limit exceeded can be turned off with the command-line flag -XX:-UseGCOverheadLimit.

意思是在默认情况下，如果Java进程花费98%以上的时间执行GC，并且每次只有不到2%的堆被恢复，则JVM抛出此错误。也就是说，我们的应用程序几乎耗尽了所有可用内存，垃圾收集器花了太长时间试图清理它，并多次失败，这个是堆内存溢出

2.2 从JVM内存结构分析

原图地址：https://www.processon.com/view/link/5b61ea2ae4b0555b39cfa842
JDK1.8之前字符串放在永久代中（Perm），在JDK1.8中，字符串是存储在本地内存中，JDK1.8中程序默认执行的VM参数 -Xmx 的默认值为你当前机器最大内存的 1/4 -Xms 的默认值为你当前机器最大内存的 1/64，而生产机器的内存大小为128G，故程序可用堆内存理论上可达32G（实际达不到），按照正常的理解只要物理机内存够大，应当很难出现java.lang.OutOfMemoryError错误，当实际进程跑起来的时候观察了一下，内存飕飕的往上涨，大约在耗用24G内存的时候已经程序基本已经不动了

2.3 代码定位

之前导出逻辑（简化）：

第1步：MongoDB查询拉取全部数据
第2步：handler进行数据去重和好坏数据分组并进行过滤操作
第3补：对处理后的结果逐条生成xml文件导出到指定文件夹

可以很直观的判断出我们的程序是在第1步出了问题，闲话少叙，我们直接看代码

public List<Result> queryResultListByCurStep(ExportParam param) throws Exception {
    /*这里查询了所有的Result，问题就出在这里，所有的数据都load到内存中，一直没有释放，GC也无法回收*/
    List<Result> results = new ArrayList<>();
    CloseableIterator<Result> iterator = null;
    try {
        /*这里其实做过一次优化，采用的MongoDB的流式API获取数据，可以有效防止一次结果过多导致MongoDB查询卡顿问题，但是我们的问题很明显不是出在这里*/
        iterator = generateResultStream(param);
        while (iterator.hasNext()) {
            //问题出在这一句
            results.add(iterator.next());
        }
        iterator.close();
    } catch (Exception e) {
        log.error("查询出错 e：" + e.getMessage());
        iterator.close();
    }
    return results;
}

其实问题在注释里已经比较清楚了，我们可以着手改造了。
PS：网上有些让配置-XX:-UseGCOverheadLimit，关闭GC占用时间过长时报的异常，抑或增加堆内存空间，此乃饮鸩止渴、掩耳盗铃之法，不可取

3 改造

3.1 逻辑优化方案

第1步：启动命令追加启动参数resultType，枚举值【Default|null:原执行逻辑不变;Stream:传入handler直接传入stream迭代器】
第2步：更改对应业务线导出handle方法，接收CloseableIterator<Result>方式传值，代码中兼容streamExport（此外分页查询也是一种办法，这里直接跳过这种方案）
第3步：因逐条取数据，需在动态生成文件的时候冗余好坏数据过滤和多环节去重相关业务逻辑，因为是“逐张清点”，所以GC可以正常回收，自然也就解决了出现的问题

PS：我们在改造业务的时候不要轻易的重新推翻完全重写，我们需要在原来的基础上进行拓展，做好多重方案同时兼容

3.2 撸代码

参数接收类

@Parameter(names = {"-resultType"},description = "结果类型")
protected String resultType;

ResultType枚举

public enum ResultType {
    Default,
    Stream;
    
    public static ResultType vOf(String type) {
        try {
            return ResultType.valueOf(type);
        } catch (Exception e) {
            return Default;
        }
    }
}

handler代码选段

@Override
public void handle(ExportParam param) throws Exception {
    String zipPath = getZipPath(param, param.getResultList());
    switch (param.getResultType()) {
        case Stream:
            streamExport(param, zipPath);
            break;
        default:
            defaultExport(param, zipPath);
            break;
    }
}

private void streamExport(ExportParam param, String zipPath) {
    Map<String, SimpleResult> resultMap = new HashMap<>();
    //文件计数
    int i = 1;
    try (CloseableIterator<Result> iterator = param.getIterator()) {
        while (iterator.hasNext()) {
            if (i++ % 10 == 0) {
                log.info("============流处理进度：第{}个结果===============", i - 1);
            }
            Result result = iterator.next();

            /*重复数据过滤*/
            if (resultMap.containsKey(result.getFileId())) {
                i--;
                SimpleResult oldResult = resultMap.get(result.getFileId());
                //新老数据替换，如果有老数据则删除该文件重新生成
                dealEqualStep(oldResult, result, resultMap);
                continue;
            }
            resultMap.put(result.getFileId(), SimpleResult.builder().build());
            
            /*好坏数据过滤*/
            if (!filter(param, result)) {
                continue;
            }

            //单文件导出
            exportSingleResult(result, zipPath);
        }
    } catch (Exception e) {
        log.error("结果读取失败", e);
    }
}

改造完成，测试上线，总共生成了1.6W个xml文件，zip解压后文本文件大小约700M，平均每个60K，这些纯文本数据直接进了内存可不炸了。
目前已经解决此问题，程序运行内存占用也恢复正常，不过因为是单线程跑，1.6W个文件跑了近20分钟，速度有点慢，如果后期有优化需求，可以对结果数据进行切分，采用多线程的方式生成文件，理论上提速可达到(单线程耗时/线程数)。

参考连接：https://blog.csdn.net/qq_37598011/article/details/88182781