记一次读取文件后ibatis执行SQL时的OOM异常

问题背景

编写工具解析文件包及文件内容，获取SQL文件并根据配置数据库连接进行更新，涉及到文件流读取和mybatis.SqlSession等。在编码完成并且在win验证后，找了台Linux环境进行自测，在运行时报错

java.lang.OutOfMemoryError: Java heap space
at java.util.Arrays.copyOf(Arrays.java:3332)
at java.lang.AbstractStringBuilder.ensureCapacityInternal(AbstractStringBuilder.java:124)
at java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:448)
at java.lang.StringBuilder.append(StringBuilder.java:136)
at org.apache.ibatis.logging.LogFactory.getLog(LogFactory.java:54)
at org.apache.ibatis.mapping.MappedStatement.Builder.(MappedStatement.java:81)
at org.apache.ibatis.session.defaults.DefaultSqlSession.getMappedStatement(DefaultSqlSession.java:409)
at org.apache.ibatis.session.defaults.DefaultSqlSession.update(DefaultSqlSession.java:254)
at org.apache.ibatis.session.defaults.DefaultSqlSession.update(DefaultSqlSession.java:247)
at sun.reflect.GeneratedMethodAccessor31.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.mybatis.spring.SqlSessionTemplate.SqlSessionInterceptor.invoke(SqlSessionTemplate.java:466)
at com.sun.proxy.$Proxy45.update(Unknown Source)
at org.mybatis.spring.SqlSessionTemplate.update(SqlSessionTemplate.java:314)

• 本机win是16G内存，报错的linux是8G
• 脚本启动jvm时未指定内存大小，未指定gc
• sql文件个数在几十不等，每个文件在kb至mb（个位数）不等

过程

之前没接触过此类问题，只能边查边学习边分析。

看日志是在ibatis的logfactory.getlog中，stringbuilder在进行扩容的时候发生内存溢出。不确定的是什么内容占用了如此大的内存，因为本身文件大小不是很大。

JVM初始分配的内存由-Xms指定,默认是物理内存的1/64;JVM最大分配的内存由-Xmx指定,默认是物理内存的1/4.默认空余堆内存小于40%时,JVM就会增大堆直到-Xmx的最大限制;空余堆内存大于70%时, JVM会减少堆直到-Xms的最小限制.因此服务器一般设置-Xms,-Xmx相等以避免在每次GC 后调整堆的大小.
相关博客文档

free -m 查看linux内存大小是7822m，堆默认最大值为2000m不到，OOM是内存占用已经接近2G…在我指定如下堆大小参数后，运行是正常。

-Xmx3550m -Xms3550m

结合visualVM和dump文件进行分析

• 增加OOM时的dump文件

-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/

• visualvm监控运行时的内存变化

https://blog.csdn.net/weixin_42740530/article/details/98983229

在拿到jprof文件后，可以通过visualvm,jprofiler或者eclipse的memory analyse等工具进行分析查看，字符串占用空间太大，有太多的实例化次数，占用了接近1.5G的内存。


可能是文件流读取或者stringbuilder()的使用方式不对产生了大量冗余string且没有被回收？在比较多种实现方式后，目前bufferreader+stringbuilder的编写逻辑是没有问题的，是否在构造时候指定大小并没有影响。

排除法分析内存消耗较高的代码逻辑

• 只保留读取文件的逻辑，内存占用在200m
• 保留读取文件和解析文件SQL的逻辑，内存占用成波形，最高不到700m，可能和文件流的释放有关系？
• 放开sqlsession.update逻辑执行SQL之后，内存占用很快飙升到接近2G，并产生OOM错误

ibatis执行时候为什么会需要这么大的内存呢？在前边分析的过程中已经查看源码进行了分析，怀疑和它的日志处理有关系。

    package org.apache.ibatis.session.defaults;
    public int update(String statement, Object parameter) {
        int var4;
        try {
            this.dirty = true;
            // mybatis的核心类，存储了sql的所有相关信息
            MappedStatement ms = this.getMappedStatement(statement, parameter == null ? Object.class : parameter.getClass());
            var4 = this.executor.update(ms, this.wrapCollection(parameter));
        } catch (Exception var8) {
            throw ExceptionFactory.wrapException("Error updating database.  Cause: " + var8, var8);
        } finally {
            ErrorContext.instance().reset();
        }

        return var4;
    }
    
    private MappedStatement getMappedStatement(String sql, Class<?> parameterType) {
        if (this.configuration.hasStatement(sql)) {
            return this.configuration.getMappedStatement(sql);
        } else {
            SqlSource sqlSource = new RawSqlSource(this.configuration, sql, parameterType);
            // 静态构造类
            Builder builder = new Builder(this.configuration, sql, sqlSource, SqlCommandType.UPDATE);
            return builder.build();
        }
    }

        public Builder(Configuration configuration, String id, SqlSource sqlSource, SqlCommandType sqlCommandType) {
            this.mappedStatement.configuration = configuration;
            this.mappedStatement.id = id;
            this.mappedStatement.sqlSource = sqlSource;
            this.mappedStatement.statementType = StatementType.PREPARED;
            this.mappedStatement.resultSetType = ResultSetType.DEFAULT;
            this.mappedStatement.parameterMap = (new org.apache.ibatis.mapping.ParameterMap.Builder(configuration, "defaultParameterMap", (Class)null, new ArrayList())).build();
            this.mappedStatement.resultMaps = new ArrayList();
            this.mappedStatement.sqlCommandType = sqlCommandType;
            this.mappedStatement.keyGenerator = (KeyGenerator)(configuration.isUseGeneratedKeys() && SqlCommandType.INSERT.equals(sqlCommandType) ? Jdbc3KeyGenerator.INSTANCE : NoKeyGenerator.INSTANCE);
            String logId = id;
            if (configuration.getLogPrefix() != null) {
                logId = configuration.getLogPrefix() + id;
            }
            // 获取当前sql的日志
            this.mappedStatement.statementLog = LogFactory.getLog(logId);
            this.mappedStatement.lang = configuration.getDefaultScriptingLanguageInstance();
        }

    public static Log getLog(String logger) {
        try {
            // 获取当前日志实现类构造实例，slf4j
            return (Log)logConstructor.newInstance(logger);
        } catch (Throwable var2) {
            // 实际报错是这一行，catch到的也是内存溢出错误，在此处append字符串的时候再次报错内存溢出
            throw new LogException("Error creating logger for logger " + logger + ".  Cause: " + var2, var2);
        }
    }
    static {
    	// 静态方法区，在启动时获取当前环境的日志实现，工具用到了slf4j
        tryImplementation(LogFactory::useSlf4jLogging);
        tryImplementation(LogFactory::useCommonsLogging);
        tryImplementation(LogFactory::useLog4J2Logging);
        tryImplementation(LogFactory::useLog4JLogging);
        tryImplementation(LogFactory::useJdkLogging);
        tryImplementation(LogFactory::useNoLogging);
    }

mybatis官网的日志说明
知道了ibatis的日志框架之后，大概率是在处理日志的时候占用了大量内存。在环境只记录程序日志不需要开启mybatis的debug模式时，可以先把日志关掉，在定义sqlsession的时候，指定日志的实现类

sqlSession.getConfiguration().setLogImpl(NoLoggingImpl.class);

再次在环境验证正常，内存占用又回到了之前的波形…ibatis的日志记录为什么会消耗这么大的内存呢？后续继续分析这块，有大佬也欢迎多指教。目前来看，先这样处理，在大多数的开发环境和生产配置也都是比较高的，理论上不会有这样的问题。