问题:每日0点系统内存占用飙升,大量挂起线程,系统停顿, log4j2版本:2.7
Thread Stack:
AsyncAppender-async
at sun.misc.Unsafe.park(ZJ)V (Native Method)
at java.util.concurrent.locks.LockSupport.park(Ljava/lang/Object;)V (LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt()Z (AbstractQueuedSynchronizer.java:836)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(I)V (AbstractQueuedSynchronizer.java:997)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(I)V (AbstractQueuedSynchronizer.java:1304)
at java.util.concurrent.Semaphore.acquire()V (Semaphore.java:312)
at org.apache.logging.log4j.core.appender.rolling.RollingFileManager.rollover(Lorg/apache/logging/log4j/core/appender/rolling/RolloverStrategy;)Z (RollingFileManager.java:247)
at org.apache.logging.log4j.core.appender.rolling.RollingFileManager.rollover()V (RollingFileManager.java:192)
at org.apache.logging.log4j.core.appender.rolling.RollingFileManager.checkRollover(Lorg/apache/logging/log4j/core/LogEvent;)V (RollingFileManager.java:175)
at org.apache.logging.log4j.core.appender.RollingFileAppender.append(Lorg/apache/logging/log4j/core/LogEvent;)V (RollingFileAppender.java:280)
at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(Lorg/apache/logging/log4j/core/LogEvent;)V (AppenderControl.java:156)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(Lorg/apache/logging/log4j/core/LogEvent;)V (AppenderControl.java:129)
at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(Lorg/apache/logging/log4j/core/LogEvent;)V (AppenderControl.java:120)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(Lorg/apache/logging/log4j/core/LogEvent;)V (AppenderControl.java:84)
at org.apache.logging.log4j.core.appender.AsyncAppender$AsyncThread.callAppenders(Lorg/apache/logging/log4j/core/LogEvent;)Z (AsyncAppender.java:451)
at org.apache.logging.log4j.core.appender.AsyncAppender$AsyncThread.run()V (AsyncAppender.java:404)
Leak Report:
One instance of **"java.util.concurrent.ArrayBlockingQueue"** loaded by **"<system class loader>"** occupies **897,341,688 (95.23%)** bytes. The instance is referenced by **org.apache.logging.log4j.core.appender.AsyncAppender$AsyncThread @ 0xc0700150 AsyncAppender-async** , loaded by **"org.springframework.boot.loader.LaunchedURLClassLoader @ 0xc0400000"**. The memory is accumulated in one instance of **"java.lang.Object[]"** loaded by **"<system class loader>"**.
The stacktrace of this Thread is available. [See stacktrace](../pages/24.html).
**Keywords**
java.util.concurrent.ArrayBlockingQueue
java.lang.Object[]
org.springframework.boot.loader.LaunchedURLClassLoader @ 0xc0400000
原因:每日0点触发log4j的rollover策略,semaphore设置的1个,所有的log输出都会在未完成切割任务时挂起等待切割完成。程序中多线程任务很多且打印日志的地方也很多,就早成瞬间积压超过了承受能力。
try {
// Block until the asynchronous operation is completed.
semaphore.acquire();
} catch (final InterruptedException e) {
logError("Thread interrupted while attempting to check rollover", e);
return false;
}
解决:
升级log4j2到2.14版本并且启用Disruptor异步处理,这是一种无锁的线程间通信库
- 启用的方式有两种,一种是在vm参数中加入
-Dlog4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
一种是在xml文件中不再使用Root标签,而改用:
<AsyncRoot level="info" includeLocation="true">
<appender-ref ref="Console"/>
<appender-ref ref="RollingFileInfo"/>
<appender-ref ref="RollingFileError"/>
</AsyncRoot>
两种方式以第一种性能更佳,差别不大
- 在classpath下新建文件:log4j2.component.properties
增加配置:
log4j2.AsyncQueueFullPolicy=Discard #队列满时放弃日志操作
AsyncLoggerConfig.SynchronizeEnqueueWhenQueueFull=true #当队列满时同步入列,这是默认值,实际还是走AsyncQueueFullPolicy策略
AsyncLoggerConfig.RingBufferSize=131072 #队列长度,Disruptor使用的不是真正意义上的队列,而是类似于计数器+事件的方式。