You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@logging.apache.org by "Remko Popma (JIRA)" <ji...@apache.org> on 2017/09/10 13:43:02 UTC
[jira] [Commented] (LOG4J2-2031) Messages appear out of order in
log file (was: Log4j2 log file not reflecting application log function
calls)
[ 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)
Re: [jira] [Commented] (LOG4J2-2031) Messages appear out of order in log file (was: Log4j2 log file not reflecting application log function calls)
Posted by Remko Popma <re...@gmail.com>.
I don't think that this should be the responsibility of the users. The library needs to be safe to use even when used "wrongly".
Cases in point:
* we prevent infinite recursion when a collection is logged that contains itself
* we agreed to catch and suppress exceptions thrown from domain objects' {{toString}} method
Preventing deadlock when application objects log from their {{toString}} method is also the job of the library.
Our current solution results in messages appearing out of sequence in the log file. This is better than deadlocking the application. It is also better than throwing an exception or reducing the service level to allow only primitive values to be logged.
But the current solution is still surprising and inconvenient for users. We can do better, which is what the ticket aims to achieve.
I hope this clarifies things.
PS.
Your comments are not visible on the JIRA ticket. (Just letting you know in case you want to add something there.)
(Shameless plug) Every java main() method deserves http://picocli.info
> On Sep 10, 2017, at 23:15, Dominik Psenner <dp...@gmail.com> wrote:
>
> In addition to that a less aggressive (or lazy) mode of operation could
> detect rogue recursions and throw in such a situation to prevent deadlocks.
>
> The last mode of operation could do no checks at all, but that mode would
> not prevent from deadlocks or infinite recursions at all.
>
>> On 10 Sep 2017 4:06 p.m., "Dominik Psenner" <dp...@gmail.com> wrote:
>>
>> I opt that everyone should use the library in a way that makes sure
>> deadlocks cannot happen. Trying to solve this by fancy "deadlock could
>> occur" mechanisms feels wrong.
>>
>> A very restrictive mode of operation could enforce that all arguments
>> passed into a log event must be limited to immutable primitive types. In
>> this mode deadlocks could no longer occur because rogue recursions would
>> actively prevented.
>>
>> On 10 Sep 2017 3:43 p.m., "Remko Popma (JIRA)" <ji...@apache.org> wrote:
>>
>>
>> [ https://issues.apache.org/jira/browse/LOG4J2-2031?page=com.
>> atlassian.jira.plugin.system.issuetabpanels:comment-tabpane
>> l&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/log4
>> j/2.0/log4j-core/apidocs/org/apache/logging/log4j/core/asyn
>> c/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)
>>
>>
>>
Re: [jira] [Commented] (LOG4J2-2031) Messages appear out of order in
log file (was: Log4j2 log file not reflecting application log function calls)
Posted by Dominik Psenner <dp...@gmail.com>.
In addition to that a less aggressive (or lazy) mode of operation could
detect rogue recursions and throw in such a situation to prevent deadlocks.
The last mode of operation could do no checks at all, but that mode would
not prevent from deadlocks or infinite recursions at all.
On 10 Sep 2017 4:06 p.m., "Dominik Psenner" <dp...@gmail.com> wrote:
> I opt that everyone should use the library in a way that makes sure
> deadlocks cannot happen. Trying to solve this by fancy "deadlock could
> occur" mechanisms feels wrong.
>
> A very restrictive mode of operation could enforce that all arguments
> passed into a log event must be limited to immutable primitive types. In
> this mode deadlocks could no longer occur because rogue recursions would
> actively prevented.
>
> On 10 Sep 2017 3:43 p.m., "Remko Popma (JIRA)" <ji...@apache.org> wrote:
>
>
> [ https://issues.apache.org/jira/browse/LOG4J2-2031?page=com.
> atlassian.jira.plugin.system.issuetabpanels:comment-tabpane
> l&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/log4
> j/2.0/log4j-core/apidocs/org/apache/logging/log4j/core/asyn
> c/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)
>
>
>
Re: [jira] [Commented] (LOG4J2-2031) Messages appear out of order in
log file (was: Log4j2 log file not reflecting application log function calls)
Posted by Dominik Psenner <dp...@gmail.com>.
I opt that everyone should use the library in a way that makes sure
deadlocks cannot happen. Trying to solve this by fancy "deadlock could
occur" mechanisms feels wrong.
A very restrictive mode of operation could enforce that all arguments
passed into a log event must be limited to immutable primitive types. In
this mode deadlocks could no longer occur because rogue recursions would
actively prevented.
On 10 Sep 2017 3:43 p.m., "Remko Popma (JIRA)" <ji...@apache.org> wrote:
[ 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)