[
https://issues.apache.org/jira/browse/LOG4J2-2031?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16158590#comment-16158590
]
Remko Popma commented on LOG4J2-2031:
-------------------------------------
I think I know what is happening with the messages appearing out-of-order in
the log file.
The test uses an async appender. This appender has a queue, and a background
thread that reads from the queue and writes to the file. Adding log events to
that queue is very fast, but rendering these objects into bytes and writing
data to the disk is slower. So at some point during the test the queue becomes
full. (The async appender queue size is 128 by default, not very large...)
When the async logging queue is full, Log4j2 needs to decide what to do with
the current log event. There are several options:
# Wait until space becomes available in the queue
# Log the event synchronously (bypass the queue, go directly to the underlying
appender)
# Discard the log event
The original behaviour was #1: to wait until space in the queue becomes
available. However, there was a problem when an object performs logging from
its {{toString}} method when the queue was full (LOG4J2-1518). This could cause
the application to deadlock...
At the time, the best thing I could think of was to change the default
behaviour from (#1) to (#2) and log the event synchronously when the queue is
full. This is not great... :-( The hope is that the queue is large enough to
absorb bursts of events so users would rarely see out-of-order messages in the
log. We should probably make the async appender default queue size larger...
I have not been able to come up with a better solution yet.
You have a number of options, each has its pros and cons:
* Change the queue size to something large enough to handle bursts of events.
This is a good idea anyway.
* You can configure Log4j2's behaviour via system property
{{log4j2.AsyncQueueFullPolicy}}. See
[AsyncQueueFullPolicy|https://logging.apache.org/log4j/2.0/log4j-core/apidocs/org/apache/logging/log4j/core/async/AsyncQueueFullPolicy.html]
and
[AsyncQueueFullPolicyFactory|https://logging.apache.org/log4j/2.0/log4j-core/apidocs/org/apache/logging/log4j/core/async/AsyncQueueFullPolicyFactory.html].
The "Discard" policy with some log level may be of interest.
* If you are confident that your applications do not perform logging from their
{{toString}} method, so there is no risk of deadlock, you can create a custom
{{AsyncQueueFullPolicy}} that always return {{EventRoute.ENQUEUE}}. This policy
will block until space becomes available in the queue.
* Some applications frequently experience long sustained bursts of log events.
When the application logs at a sustained rate that is faster than the
underlying appender, even a large queue will fill up during normal operation,
and much of the logging takes place with a full queue. For such applications
asynchronous logging is not the best choice, and synchronous logging may be
more appropriate. Log4j2 should still give performance benefits with
multi-threaded applications.
> Log4j2 log file not reflecting application log function calls
> -------------------------------------------------------------
>
> Key: LOG4J2-2031
> URL: https://issues.apache.org/jira/browse/LOG4J2-2031
> Project: Log4j 2
> Issue Type: Bug
> Components: Appenders
> Affects Versions: 2.8.2, 2.9.0
> Environment: Windows, Sun Java 8.
> Reporter: Colin McDowell
> Attachments: CapacityTest.java, log4j2.xml, pom2.xml
>
> Original Estimate: 672h
> Remaining Estimate: 672h
>
> Was hoping to move our numerous J2EE projects from Log4j to Log4j2 for the
> performance improvements. I put together a small test case that writes a
> string pattern to a Rolling File. There is a 6 digit sequence number at the
> start of the log message. This allows me to quickly see if all the log
> requests are making it into the log file. I attach the test case and
> log4j2.xml. The log4j2.xml uses an asynchronous appender.
> What I observe in the output log file is that after a short interval (120 or
> so entries) the logged are appearing in the wrong order, and entries can be
> missing. The missing entries issues especially shows up when rolling to the
> next log file.
> Perhaps there is a deliberate decision to not to guarantee log file
> accurately for speed. However we need the logs to accurately reflect what
> the application is logging. I have also noticed the performance is 25% worse
> in Log4j2 than Log4j when not using the asynchronous appender. So that
> rather kills us using Log4j2 at the moment.
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)
