[
https://issues.apache.org/jira/browse/LOG4J2-2031?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16160342#comment-16160342
]
Remko Popma commented on LOG4J2-2031:
-------------------------------------
After thinking about this some more, I think it should be possible to prevent
messages from appearing out of order in most cases.
The reason Log4j2 logs directly to the appender, bypassing the async queue when
the queue is full, is to prevent deadlock.
However, when exactly is deadlock possible? Only when an application object is
logged that itself invokes a logging call in its {{toString}} method. If the
logging call from the {{toString}} method would block until it was able to add
a new LogEvent to the queue, then the object that is being logged could never
return from its {{toString}} method, resulting in deadlock.
For "normal" logging calls (not from a {{toString}}) it is fine to block when
the queue is full, because the background thread will eventually make a slot
available.
Currently the
[DefaultAsyncQueueFullPolicy|https://logging.apache.org/log4j/2.0/log4j-core/apidocs/org/apache/logging/log4j/core/async/DefaultAsyncQueueFullPolicy.html]
is very conservative and logs directly to the underlying appender for _all_
events when the queue is full. This can be improved by trying to rule out cases
where deadlock could not occur, and in such cases, block until space in the
queue becomes available.
Ways to detect potential deadlock situations when the queue is full:
* the logging thread is a background thread (of any of the Async Appenders, or
a Disruptor) - this is the original solution for LOG4J2-471
* set a thread-local flag when logging is invoked (specifically, before calling
{{Disruptor.tryPublish}}). If the flag has already been set then deadlock is
possible - this should cover LOG4J2-1518
If deadlock is possible, the current behaviour (log directly to the underlying
appender) is the safe thing to do. Perhaps a suffix should be appended to such
log events to the effect that "(Log4j2) This message appears out of order to
prevent deadlock: logging inside the toString() method is not recommended."
Thoughts?
> Messages appear out of order in log file (was: 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
> Assignee: Remko Popma
> 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)
