一次鞭辟入里的 Log4j2 异步日志输出阻塞问题的定位 (4)

image

在创建出来的新页中,按照线程分组查看,查看 Log4j2 的 disruptor 消费线程,可以得出下图:

image

可以看出:在出问题的时间段,采集到的写入日志文件的事件数量明显增多很多,并且,通过堆栈可以看到:

"Log4j2-TF-2-AsyncLoggerConfig-1" #26 [23680] daemon prio=5 os_prio=0 cpu=406.25ms elapsed=2.89s tid=0x0000022d6f3d4080 nid=0x5c80 runnable [0x000000399bbfe000] java.lang.Thread.State: RUNNABLE at java.io.FileOutputStream.writeBytes(java.base@17-loom/Native Method) at java.io.FileOutputStream.write(java.base@17-loom/FileOutputStream.java:365) at org.apache.logging.log4j.core.appender.OutputStreamManager.writeToDestination(OutputStreamManager.java:261) - eliminated <0x000000070ee0af40> (a org.apache.logging.log4j.core.appender.rolling.RollingFileManager) at org.apache.logging.log4j.core.appender.FileManager.writeToDestination(FileManager.java:272) - eliminated <0x000000070ee0af40> (a org.apache.logging.log4j.core.appender.rolling.RollingFileManager) at org.apache.logging.log4j.core.appender.rolling.RollingFileManager.writeToDestination(RollingFileManager.java:236) - eliminated <0x000000070ee0af40> (a org.apache.logging.log4j.core.appender.rolling.RollingFileManager) at org.apache.logging.log4j.core.appender.OutputStreamManager.flushBuffer(OutputStreamManager.java:293) - locked <0x000000070ee0af40> (a org.apache.logging.log4j.core.appender.rolling.RollingFileManager) at org.apache.logging.log4j.core.appender.OutputStreamManager.flush(OutputStreamManager.java:302) - locked <0x000000070ee0af40> (a org.apache.logging.log4j.core.appender.rolling.RollingFileManager) at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(AbstractOutputStreamAppender.java:199) at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(AbstractOutputStreamAppender.java:190) at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:181) at org.apache.logging.log4j.core.appender.RollingFileAppender.append(RollingFileAppender.java:312) at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:156) at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:129) at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:120) at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84) at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:543) at org.apache.logging.log4j.core.async.AsyncLoggerConfig.callAppenders(AsyncLoggerConfig.java:127) at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:502) at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:485) at org.apache.logging.log4j.core.async.AsyncLoggerConfig.log(AsyncLoggerConfig.java:121) at org.apache.logging.log4j.core.async.AsyncLoggerConfig.logToAsyncLoggerConfigsOnCurrentThread(AsyncLoggerConfig.java:169) at org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor$Log4jEventWrapperHandler.onEvent(AsyncLoggerConfigDisruptor.java:111) at org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor$Log4jEventWrapperHandler.onEvent(AsyncLoggerConfigDisruptor.java:97) at com.lmax.disruptor.BatchEventProcessor.processEvents(BatchEventProcessor.java:168) at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:125) at java.lang.Thread.run(java.base@17-loom/Thread.java:1521)

log4j2 调用了很多次 flush, JFR 显示采集到的事件,每次都调用了 flush。每次调用 flush,都会造成文件真正写的 native 调用。而消费慢的原因,其实就是这种 native 调用太多,系统写入不过来了。

问题解决

我们可以通过以下四个方向解决这个问题:

减少日志输出,精简日志,这是比较基础的方式,也是比较简单的方式,但是身为一个技术人,我们不能满足于此

增加硬盘 io,这个也是比较基础简单的解决方式

我们是否可以减少这个 flush 呢?答案是可以的,我们可以配置 Appender 的 immediateFlush 为 false

内容版权声明:除非注明,否则皆为本站原创文章。

转载注明出处:https://www.heiqu.com/zwwfdw.html