CODEWITHSUNDEEP
javamultithreadingperformancespring-bootlog4j2
Arajit
Arajit

Reputation: 143

Log4j2 Thread blocking on OutputStreamManager.write

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.

Upvotes: 3

Views: 3472

Answers (1)

rgoers
rgoers

Reputation: 9151

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.

Upvotes: 5

Related Questions