Log4j2线程在OutputStreamManager.write上阻塞。

huangapple go评论85阅读模式
英文:

Log4j2 Thread blocking on OutputStreamManager.write

问题

背景
我正在使用 log4j2(版本2.12.1),同时使用同步根日志记录器和异步日志记录器。Lmax 环形缓冲区大小默认为 256*1024。我的日志记录器是 Console。我记录的是带有 JSON 布局的 MapMessage。我的日志消息平均大小约为100字节。

根据以上的详细信息,我注意到一些线程在以下位置被阻塞:

"http-nio-8080-exec-172" #451
   线程状态:BLOCKED(在对象监视器上)被 "http-nio-8080-exec-148" 拥有,ID=429
  在 org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:231) 处被阻塞
  - 阻塞在 <0x000000003eb936ae>(一个 org.apache.logging.log4j.core.appender.OutputStreamManager)
  在 org.apache.logging.log4j.core.appender.OutputStreamManager.writeBytes(OutputStreamManager.java:206) 处
  在 org.apache.logging.log4j.core.layout.AbstractLayout.encode(AbstractLayout.java:211) 处进行编码
  在 org.apache.logging.log4j.core.layout.AbstractLayout.encode(AbstractLayout.java:37) 处进行编码
  在 org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(AbstractOutputStreamAppender.java:197) 处对事件进行直接编码
  在 org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(AbstractOutputStreamAppender.java:190) 处尝试追加
  在 org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:181) 处
  在 org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:156) 处
  在 org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:129) 处
  在 org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:120) 处
  在 org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84) 处
  在 org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:543) 处
  在 org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:502) 处
  在 org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:485) 处
  在 org.apache.logging.log4j.core.config.LoggerConfig.logParent(LoggerConfig.java:534) 处
  在 org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:504) 处
  在 org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:485) 处
  在 org.apache.logging.log4j.core.async.AsyncLoggerConfig.log(AsyncLoggerConfig.java:121) 处
  在 org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:460) 处
  在 org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:82) 处
  在 org.apache.logging.log4j.core.Logger.log(Logger.java:162) 处
  在 org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2190) 处
  在 org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2144) 处
  在 org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2127) 处
  在 org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1828) 处
  在 org.apache.logging.log4j.spi.AbstractLogger.info(AbstractLogger.java:1282) 处

我的问题是:

  1. 环形缓冲区是否很快就会变满,从而对主线程(在我的情况下是 servlet 容器线程 http-nio-8080-exec-148)产生背压?堆转储显示 RingBuffer 一直占用 7MB(测试前后都是如此)。
  2. 如果环形缓冲区很快变满,我该如何增加其大小?还是可以丢弃事件吗?
  3. 根据 Log4j 的性能报告,我知道不推荐使用 Console appender,但在这里我确实没有选择。是否有更好的写入标准输出的 appender?

欢迎提出任何建议或想法。

英文:

Background
I am using log4j2(2.12.1) with Sync root and Async logger. Lmax ring buffer size is default which is 256*1024. My appender in Console. I am logging MapMessage with JSON layout. Average size of my log message is approx 100 bytes.

With above details I am noticing few threads ar blocked at

"http-nio-8080-exec-172" #451
   Thread State: BLOCKED (on object monitor) owned by "http-nio-8080-exec-148" Id=429
  at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:231)
  - blocked on <0x000000003eb936ae> (a org.apache.logging.log4j.core.appender.OutputStreamManager)
  at org.apache.logging.log4j.core.appender.OutputStreamManager.writeBytes(OutputStreamManager.java:206)
  at org.apache.logging.log4j.core.layout.AbstractLayout.encode(AbstractLayout.java:211)
  at org.apache.logging.log4j.core.layout.AbstractLayout.encode(AbstractLayout.java:37)
  at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(AbstractOutputStreamAppender.java:197)
  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.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.config.LoggerConfig.processLogEvent(LoggerConfig.java:502)
  at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:485)
  at org.apache.logging.log4j.core.config.LoggerConfig.logParent(LoggerConfig.java:534)
  at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:504)
  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.config.LoggerConfig.log(LoggerConfig.java:460)
  at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:82)
  at org.apache.logging.log4j.core.Logger.log(Logger.java:162)
  at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2190)
  at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2144)
  at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2127)
  at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1828)
  at org.apache.logging.log4j.spi.AbstractLogger.info(AbstractLogger.java:1282)

My question is..

  1. Is Ring Buffer is getting full very fast which is causing back pressure to main thread(In . my case servlet container thread which is http-nio-8080-exec-148)? Heap dump shows RingBuffer took 7MB(Before and After test) always.
  2. If ring buffer is getting full very fast, how can I increase size of it ? or may be drop events ??
  3. Looking at the Log42 performance report I know Console appender is not suggested, But i really dont have a choice here.Is here any better appender which writes to STDOUT?

Any suggestion or thoughts is appreciated.

答案1

得分: 4

以下是翻译好的内容:

那个锁存在是为了防止多个线程同时向同一个OutputStream写入数据,因为这可能导致数据混合在一起。虽然不能保证,但许多OutputStream的实现都会锁定写入调用,所以即使移除锁定,它也会在OutputStream实现中被阻塞。

显然,这是因为正在使用的OutputStream正在从其他线程写入数据。该线程没有指示环形缓冲区已满,但可能有其他线程因此被阻塞。我不清楚为什么您必须写入控制台,但是在云中记录提供了关于为什么不应该在云环境中运行时进行日志记录以及替代方案的更多数据。

更新:在查看完整的线程转储后,我有一些观察结果:

  1. 许多线程正在等待 com.xxxx.apie.library.InternalRequest.execute(InternalRequest.java:273)。这些线程似乎正在等待另一个线程上的工作,但从线程转储中并不清楚具体是什么。
  2. 有几个线程正在记录到被阻塞的输出流。调用发起自几个类中的各个点,但都是以信息级别进行记录。
  3. 您正在使用JsonLayout。
  4. 您没有发布您的Log4j配置,但在上面的堆栈跟踪中,您可以看到AsyncLoggerConfig正在调用LoggerConfig的日志方法。在审查AsyncLogger中的代码时,似乎您配置了一个没有Appender引用的AsyncLogger,因此Logger正在委托给其父Logger,该父Logger不是异步Logger,因此日志事件甚至没有被排队到环形缓冲区,而是直接从应用程序线程中记录。

总之,您正在同步记录到OutputStream(可能是控制台),线程正在因此被阻塞,因为I/O速度较慢。

英文:

That lock is there to prevent multiple threads from writing to the same OutputStream simultaneously as that could cause the data to be co-mingled. Although it isn't guaranteed, many of the OutputStream implementations will lock the calls to write anyway - so even if the lock were removed it would just block in the OutputStream implementation.

This is obviously happening because the OutputStream being used is writing data from some other thread. This thread does not indicate that the ring buffer is full, but it is possible that some other thread is blocked due to that. It isn't clear to me why you must write to the Console but Logging in the Cloud provides more data on why you shouldn't do it and what alternatives you have when running in a cloud environment.

Update: After reviewing the full thread dump I have some observations:

  1. There are many threads waiting at com.xxxx.apie.library.InternalRequest.execute(InternalRequest.java:273). These appear to be waiting for work to be performed on another thread but it isn't clear from the thread dump exactly what that is.
  2. There are several threads logging to the output stream that are blocked. The calls originate from various points in a couple of classes but all are logging at info level.
  3. You are using JsonLayout.
  4. You didn't post your Log4j configuration but in the stack trace above you can see that AsyncLoggerConfig is calling LoggerConfig's log method. In reviewing the code in AsyncLogger it would appear that you have configured an AsyncLogger that has no Appender References, so the Logger is delegating to its parent, which is NOT an asynchronous logger so the log event is not even being queued to the ring buffer but is being logged directly from the application thread.

The bottom line is that you are logging synchronously to the OutputStream (probably the Console) and threads are blocking on that because the I/O is slow.

huangapple
  • 本文由 发表于 2020年5月5日 05:31:48
  • 转载请务必保留本文链接:https://go.coder-hub.com/61601989.html
匿名

发表评论

匿名网友

:?: :razz: :sad: :evil: :!: :smile: :oops: :grin: :eek: :shock: :???: :cool: :lol: :mad: :twisted: :roll: :wink: :idea: :arrow: :neutral: :cry: :mrgreen:

确定