Log4J调用kafka时JVM堆 内存溢出问题定位

Posted 2021-04-20 架构师图谱

参与、沟通、记录

【使用场景】

很多应用程序使用Log4j记录日志，如何使用Kafka实时地收集与存储这些Log4j产生的日志呢？一种方案是使用其他组件（比如Flume，或者自己开发程序）实时监控这些日志文件，然后发送至Kafka。而另外一种比较便捷的方案是使用已封装 Kafka 的Log4jAppender：只需在Log4j配置文件中进行简单配置，即可完成将Log4j产生的日志实时发送至Kafka中。但在log4j推送kafka程序的过程中，因log4j其对底层封装的比较好，底层的队列和内存管理对开发者几乎透明，导致使用过程中对出现的内存溢出定位带来一定的障碍。

【现场还原】

场景描述：某柜台产生了一大批历史日志文件，用户希望把这部分历史数据进行深度分析：如用户的购买情况，用户交易的集中时间频率等，进行潜在价值挖掘。但在模拟用户现场导入历史数据的过程中，当历史数据的数量超过一定阀值时(测试数据为800百万)，就会出现jvm堆内存不够的异常。
启动命令如下：

运行过程中出现如下错误：

【错误定位】

1、引入利器
（1）为了追踪内存的泄露问题，引入jvm内存排查定位工具： JProfiler。
【Tip：JProfiler把CPU、执行绪和内存的剖析组合在一个强大的应用中。其可提供许多IDE整合和应用服务器整合用途，其是一个独立的应用程序，但其提供Eclipse和IntelliJ等IDE的插件。它允许两个内存剖面评估内存使用情况和动态分配泄漏和CPU剖析，以评估线程冲突。】
2、异常定位

（一）调整启动命令行，把内存的溢出信息输出到本地：

（二）然 后 打 开“JProfiler”分 析 工 具，把.hprof结尾的日志导入分析：

（三）JProfiler工具中分析的结果如下：

（四）问题分析定位

通过jprofile工具能快速定位到占用内存最大的类(如上图中红线最长的类：org.apache.logging.log4j.core.async.AsyncLoggerConfigHelper$Log4jEventWrapper)，只知道Log4jEventWrapper这个内部类使用中出现了错误，但具体是哪行代码引起的该错误，笔者也不清楚。
为了追踪具体的代码，通过IntelliJ idea等开发工具进行log4j的源码追踪来进一步定位问题：
（1）首先根据jprofile的提示，已经明确哪个类占用了最大内存：org.apache.logging.log4j.core.async.AsyncLoggerConfigHelper$Log4jEventWrapper

（2）通过阅读该内部类：Log4jEventWrapper，发现其有被外部初始化所调用的方法：

（3）然后在initDisruptor进行源码上设置断点，进行单步调试测试：

（4）通过单步调试，发现在calculateRingBufferSize()方法，有个设置默认属性值的操作，如下所示：

【Tip：这里发现底层实现时，如果没有设置系统参数，默认会给 ringBufferSize设置值：262144条】

（5）到这里猜测可能是ringBufferSize值默的过大，即本地缓存数据过多导致申请的jvm不够用，重新梳理下流程，大致过程如下:

【问题解决】

1、调参及测试

修改启动脚本，并修改默认的RingBufferSize条数大小，往小的数量调整：

【Tip ： 把 RingBufferSize 设 置 较 小 值 ( 如4096时)，经过测试对于历史数据采集没有出现再内存溢出，也没有出现缓存较小出现超时数据丢失的问题，基本断定是RingBufferSize过大造成的堆内存溢出。但具体配置RingBufferSize多小合适，以及太小所带来的影响内容，笔者尚未验证，待后续有机会再把log4j的源码再进行深入阅读及调试，再继续分享。】

【使用小结】

对于java调用过程中，可以通过如下步骤进行堆内存溢出定位。

（1）在 java 启动命令中，增加：-XX:+HeapDumpOnOutOfMemoryError，当现内存溢出时，会在当前目录下产生.hprof的日志文件，具体命令参照如下：

（2）通过Jprofile把对应.hprof文件导入分析，确定内存溢出的类。
（3）结合Eclipse或IntelliJ idea等开发工具来进行源码追踪，用来定位最终导致内存溢出的问题。
Jprofile 安装使用参考网址 ： http://blog.csdn.net/shiyong1949/article/details/52574896

「往期回顾」

d

---

欢迎投稿：[e-mail]