azkaban内存泄露问题排查&解决记录

2022-03-14早上9点，刚到公司，就收到反馈说azkban查看某些任务的时候很卡，有些任务一直处于running状态，还没法kill

打开页面发现，确实很卡，主要是下面这个接口响应慢，超过1分钟才响应：
/executor?execid=2510370&ajax=fetchExecFlowLogs&offset=0&length=50000
查看azkaban的代码，发现这个接口是会去请求azkaban-exec的，而且看页面是请求的azkaban2节点

登录azkaban2这台服务器，发现azkaban-exec占用cpu很高
尝试用jstack pid查看线程栈，发现已经连不进去了
用jmap -heap pid命令查看堆内存情况，结果吓一跳

可以看到老年代可用内存只有0.14M了

这时候想起去看JVM监控，才发现监控端口早就挂了(早上8点的时候就已经没有监控数据了)
再拉长监控时间，几天前就已经开始频繁触发full gc了

没办法先紧急进行重启，再去页面查看，响应很快了，这个节点也能够正常执行任务了
然后发现azkaban1这台节点也有点危险，也进行了紧急重启。

然后开始进行问题排查
生产环境重启后线索已经断了，但是这个问题应该是各个环境都存在的，于是跑去测试环境看

首先执行jmap -heap pid命令，查看堆内存情况

可以看到老年代堆大小已经400多M了，明显也是不正常的
执行jmap -dump:live,format=b,file=/tmp/azkaban-exec.hprof pid命令dump堆快照，并下载到本地
通过mat工具打开，可以自动进行内存泄漏检测，如下图：

可以很明显看到，log4j Hierarchy这个对象占用了将近98%的内存
基本可以确定是使用log4j不当导致的内存泄漏

GitHub上也有类似的issue：
https://github.com/azkaban/azkaban/issues/835
https://github.com/azkaban/azkaban/issues/1970
可以看到是好多年就发现的问题了，但是很可惜，这两个issue至今仍处于open状态，也就是说这个问题到现在都还没解决

网上也有针对这个问题的分析：
https://www.cnblogs.com/barneywill/p/14870181.html
这篇文章还针对log4j的代码进行了分析，但是居然也没有给解决方案

先简单说下导致这个问题的原因
首先要理解azkaban的flow和job的概念，flow可以理解为工作流，由一系列的job串联组成，job则是执行任务的最小单元
azkaban在执行任务时，要记录任务的日志，并能在页面展示，如下图：

而记录日志的方式，azkaban采用了使用log4j打印日志到文件，每个flow和job都单独一个文件，因为job是可以并行执行的
为了并发完全，所以必须每个flow和job执行时都使用一个唯一的Logger
如下图所示的代码：


这里分别是FlowRunner和JobRunner的createLogger()方法里面的代码截图

关键点就在Logger.getLogger(loggerName)这里，
log4j默认使用的Hierarchy来创建Logger,为了提升性能，会针对Logger进行一个缓存
每次创建一个Logger，都会缓存到一个Hashtable里面
而这里每次创建的Logger都不同，使用完也不会释放，就会一直堆积，直到OOM

可以通过jmap -histo:live pid| grep "org.apache.log4j.Logger"命令来进行验证：

可以看到测试环境有58W+个Logger对象实例，这在任何程序中都是不正常的

知道问题所在，就可以着手研究如何解决了

有几个可选方案：

1、创建Logger能不能不要每次都是新的，而是尽量复用
2、log4j可以设置使用NOPLoggerRepository来创建Logger,这个类是每次都new一个新的Logger，不会担心不释放
3、在flow和job的日志打印场景，每次使用完手动把hashtable里面的key进行remove，就可以正常释放了

经过评估:
方案一对azkaban代码改动比较大，风险较高
方案二虽然简单，但是这个设置是全局的，flow和job的日志打印，只是log4j一部分使用场景，NOPLoggerRepository每次都创建新Logger，可能会有性能影响，而且也不确定会不会有其他潜在问题
综合来说方案三的代码改动比较小，影响面也比较小

方案三的代码改动：
1、新增一个Log4jHelper类
提供一个closeLogger方法，用于remove前面说的Hashtable里面缓存的Logger
由于Hierarchy的ht字段是private的，因此只能通过反射去进行操作

package azkaban.execapp.yzhelper;
 
import org.apache.log4j.Hierarchy;
import org.apache.log4j.Logger;
import org.apache.log4j.spi.LoggerRepository;
 
import java.lang.reflect.Constructor;
import java.lang.reflect.Field;
import java.util.Hashtable;
 
public class Log4jHelper {
 
    private static final Logger LOGGER = Logger.getLogger(Log4jHelper.class);
 
    /**
     * 对于需要回收的Logger，需要清除Hierarchy.ht里面的缓存
     */
    public static void closeLogger(Logger log) {
        if(log == null) {
            return;
        }
 
        try {
            LoggerRepository loggerRepository = log.getLoggerRepository();
            if(loggerRepository instanceof Hierarchy) {
                Hierarchy hierarchy = (Hierarchy) loggerRepository;
                Class<?> cls = hierarchy.getClass();
                Field field = cls.getDeclaredField("ht");
                field.setAccessible(true);
 
                Hashtable ht = (Hashtable) field.get(hierarchy);
 
                Class<?> clsCategoryKey = Class.forName("org.apache.log4j.CategoryKey");
                Constructor<?> constructor = clsCategoryKey.getDeclaredConstructor(String.class);
                constructor.setAccessible(true);
                constructor.newInstance(log.getName());
 
                ht.remove(constructor.newInstance(log.getName()));
            }
        } catch (Exception e) {
            LOGGER.error("Log4jHelper closeLogger error", e);
        }
    }
}

2、修改FlowRunner和JobRunner的closeLogger()方法
在方法最后一行添加：Log4jHelper.closeLogger(this.logger);

3、修改FlowRunner和JobRunner的createLogger()方法
原来的loggerName采用的".“分隔，用点分隔会导致log4j认为Logger是有继承层次关系的，会导致上面Log4jHelper的closeLogger回收不干净
参考文章：https://blog.csdn.net/Pun_C/article/details/45622083
看azkaban的使用场景，明显是一种误用
这里把”.“改成”_"，避免这个继承层次导致的混乱

//JobRunner.createLogger()
final String loggerName = System.currentTimeMillis() + "." + this.executionId + "."+ this.jobId;
改为==>
final String loggerName = System.currentTimeMillis() + "_" + this.executionId + "_"+ this.jobId;
 
//FlowRunner.createLogger()
final String loggerName = this.execId + "." + flowId;
改为==>
final String loggerName = this.execId + "_" + flowId;

4、重新打包azkaban-exec-server并替换jar包，重启azkaban-exec

开发环境跑一天任务后，再通过jmap -histo:live pid| grep "org.apache.log4j.Logger"命令来进行验证：

之前Logger的实例数是会不断增加的，现在是维持在80不变

---

后面想到其实还有个更简单的方法，直接获取Logger的时候不用Logger.getLogger()方法，直接new一个，改起来还更方便。
不过懒得再去折腾了，就这么先用着吧～～