记一次Log4j2引发的线程阻塞
Posted DataRain
tags:
篇首语:本文由小常识网(cha138.com)小编为大家整理,主要介绍了记一次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 Generation
Eden Space:
capacity = 502792192 (479.5MB)
used = 426164176 (406.4218292236328MB)
free = 76628016 (73.07817077636719MB)
used
From Space:
capacity = 8388608 (8.0MB)
used = 7928048 (7.5607757568359375MB)
free = 460560 (0.4392242431640625MB)
used
To Space:
capacity = 11534336 (11.0MB)
used = 0 (0.0MB)
free = 11534336 (11.0MB)
used
PS Old Generation
capacity = 1409286144 (1344.0MB)
used = 131088 (0.1250152587890625MB)
free = 1409155056 (1343.874984741211MB)
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)
以上是关于记一次Log4j2引发的线程阻塞的主要内容,如果未能解决你的问题,请参考以下文章
Kafka 异步消息也会阻塞?记一次 Dubbo 频繁超时排查过程