记一次Log4j2引发的线程阻塞

vlambda
2021-05-16

记一次Log4j2引发的线程阻塞

最近在执行一个多线程程序的时候，会偶现程序发生阻塞的问题，这个可能的情况有挺多，可能是使用外部资源的时候导致访问时间过长引发超时、可能是内存使用量过大占满堆上限引发JVM假死、也可能就是因为某个共享的变量或者资源引发的死锁。

排查期间主要使用ps -ef/jps、jmap、jstack这几个命令。

其中使用ps -ef | grep 执行时的部分关键命令，得到程序的进程号，并且查看到程序提交时所使用的命令，查看该命令是否有什么异常会引发程序阻塞。

使用jmp命令主要是用于查看执行程序的JVM的堆内存使用情况，如新生代、老年代的使用比例，是否接近或者达到了所能申请到的堆内存的最大值等。很明显在发生阻塞的时候JVM所使用的内存还是很少的，并不存在因为JVM堆满了而发生假死的问题。

jmap -heap 3059 > jmap.log
Heap Configuration: MinHeapFreeRatio = 0 MaxHeapFreeRatio = 100 MaxHeapSize = 32210157568 (30718.0MB) NewSize = 704643072 (672.0MB) MaxNewSize = 10736369664 (10239.0MB) OldSize = 1409286144 (1344.0MB) NewRatio = 2 SurvivorRatio = 8 MetaspaceSize = 21807104 (20.796875MB) CompressedClassSpaceSize = 1073741824 (1024.0MB) MaxMetaspaceSize = 17592186044415 MB G1HeapRegionSize = 0 (0.0MB)
Heap Usage:PS Young GenerationEden Space: capacity = 502792192 (479.5MB) used = 426164176 (406.4218292236328MB) free = 76628016 (73.07817077636719MB) 84.75950557322895% usedFrom Space: capacity = 8388608 (8.0MB) used = 7928048 (7.5607757568359375MB) free = 460560 (0.4392242431640625MB) 94.50969696044922% usedTo Space: capacity = 11534336 (11.0MB) used = 0 (0.0MB) free = 11534336 (11.0MB) 0.0% usedPS Old Generation capacity = 1409286144 (1344.0MB) used = 131088 (0.1250152587890625MB) free = 1409155056 (1343.874984741211MB) 0.00930173056466239% used

Jstack命令主要是看各个线程的一个执行情况，在发生线程阻塞时比较容易通过这个命令获得的日志看出问题。对进程号为3059的JVM进程执行命令如下：

jstack 3059 > jstack.log

在查看这个日志的时候主要注意有没有Blocked的线程日志，这就是正在阻塞的线程并且会显示出为什么而发生阻塞。例如下面中的信息就表示这个线程正在阻塞，阻塞的原因是正在等待锁：

waiting to lock <0x00000005a4598b48> (a org.apache.logging.log4j.core.appender.OutputStreamManager)

这是由于在多线程情况下使用log4j2而发生的一个阻塞情况，在调用Logger对象打印日志的时候加入synchronized同步锁就可以避免发生这种情况。

"pool-3-thread-11" #34 prio=5 os_prio=0 tid=0x00007f171c821000 nid=0xfc2 waiting for monitor entry [0x00007f16e6902000] java.lang.Thread.State: BLOCKED (on object monitor) at org.apache.logging.log4j.core.appender.OutputStreamManager.writeBytes(OutputStreamManager.java:361) - waiting to lock <0x00000005a4598b48> (a org.apache.logging.log4j.core.appender.OutputStreamManager) at org.apache.logging.log4j.core.layout.TextEncoderHelper.writeEncodedText(TextEncoderHelper.java:96) at org.apache.logging.log4j.core.layout.TextEncoderHelper.encodeText(TextEncoderHelper.java:65) at org.apache.logging.log4j.core.layout.StringBuilderEncoder.encode(StringBuilderEncoder.java:68) at org.apache.logging.log4j.core.layout.StringBuilderEncoder.encode(StringBuilderEncoder.java:32) at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:220) at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:58) at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(AbstractOutputStreamAppender.java:177) at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(AbstractOutputStreamAppender.java:170) at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:161) 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:448) at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:433) at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:417) at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:403) at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:63) at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:146) at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2163) at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2118) at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2101) at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2000) at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1859) at org.apache.logging.slf4j.Log4jLogger.info(Log4jLogger.java:179) at com.baidu.ensec.util.InfoLogger.info(InfoLogger.java:17) at com.baidu.ensec.UpdatePathThread.run(UpdatePathThread.java:125) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748)