[
https://issues.apache.org/jira/browse/LOG4J2-940?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14282179#comment-14282179
]
Remko Popma commented on LOG4J2-940:
------------------------------------
I see. The AsyncLoggers all share the same background thread, so all I/O for
140+ files is done by a single thread. If logging is distributed roughly random
over all loggers, the disk seek time (10-20 ms per occurrence) will dominate
the I/O.
So you essentially end up with a very slow appender group served by a single
thread. This may cause the RingBuffer to fill up.
Not sure about the CPU usage, it could be partially because the OS is switching
between files, but it could also be in the application. Once the RingBuffer is
full, logging becomes synchronous: the application call to
{{logger.log(message)}} blocks until a RingBuffer slot becomes available. So
your application thread is blocked. The JVM and OS work together to schedule
and pause these threads. This locking and unlocking may cause a lot of overhead
which shows as excessive CPU usage.
You can test if my theory is correct by writing to fewer files.
(Ideally just write to one file and separate the log statements later offline.)
An alternative is to add a layer of AsyncAppenders between the AsyncLogger and
the FileAppenders. Each AsyncAppender has its own thread and its own queue.
This will not solve the problem that I/O becomes dominated by disk seek time
when writing to so many files, but at least it will allow some of this I/O to
happen in parallel. You may need to do some experimentation to find the right
balance between the number of AsyncAppenders (too many threads also adds
overhead) and the benefit of having File I/O happening in parallel.
> Large number of RUNNABLE threads at "AsyncLoggerConfig.callAppenders" causing
> High CPU
> --------------------------------------------------------------------------------------
>
> Key: LOG4J2-940
> URL: https://issues.apache.org/jira/browse/LOG4J2-940
> Project: Log4j 2
> Issue Type: Bug
> Components: Appenders
> Affects Versions: 2.0-rc2
> Environment: RHEL 6.2
> Apache Tomcat 7
> Java 7
> Reporter: Siva B
>
> 336 threads are in RUNNING state with below stack trace causing the JVM to
> consume more CPU.
> "ajp-bio-15024-exec-138" daemon prio=10 tid=0x00007f5870046000 nid=0x52d7
> runnable [0x00007f5921f56000]
> java.lang.Thread.State: TIMED_WAITING (parking)
> at sun.misc.Unsafe.park(Native Method)
> at
> java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:349)
> at
> com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:133)
> at
> com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:102)
> at com.lmax.disruptor.RingBuffer.publishEvent(RingBuffer.java:466)
> at
> org.apache.logging.log4j.core.async.AsyncLoggerConfigHelper.callAppendersFromAnotherThread(AsyncLoggerConfigHelper.java:342)
> at
> org.apache.logging.log4j.core.async.AsyncLoggerConfig.callAppenders(AsyncLoggerConfig.java:111)
> at
> org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:407)
> at
> org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:365)
> at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:103)
> at
> org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:1336)
> at
> org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1325)
> at
> org.apache.logging.log4j.spi.AbstractLogger.log(AbstractLogger.java:1237)
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
