You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-dev@logging.apache.org by ceki <ce...@qos.ch> on 2012/09/22 15:21:03 UTC
performance comparison
Hello,
Looking at the log4j/log42/logback comparison [1], I have noticed a
number of inaccuracies.
item 2) The performance of deciding whether to log or not to log when
logging is turned on.
Logback does not walk the hierarchy. No, really. It doesn't.
item 2) Actually outputting log messages
For the log4j2 figures your have the "immediateFlush" property set to
false. For the logback figures you have "immediateFlush" property set
to true.
Quoting from [2] and [3]
By default, the OutputStream is immediately flushed, unless the
immediateFlush property is explicitly set to 'false'. Setting the
immediateFlush property to false can significantly improve logging
throughput.
The default value for immediateFlush is 'true'. Immediate flushing of
the output stream ensures that logging events are immediately written
to disk and will not be lost in case your application exits without
properly closing appenders. On the other hand, setting this property
to 'false' is likely to quintuple (your mileage may vary) logging
throughput. As mentioned previously, if immediateFlush is set to
'false' and if appenders are not closed properly when your application
exits, then logging events not yet written to disk may be lost. ===
====
For an honest comparison, both frameworks should use comparable
settings. In this particular case, the setting is called
"immediateFlush" and carries the same name in both frameworks.
[1] http://logging.apache.org/log4j/2.x/performance.html
[2] http://logback.qos.ch/manual/encoders.html#LayoutWrappingEncoder
[3] http://logback.qos.ch/manual/encoders.html#immediateFlush
--
Ceki
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: performance comparison
Posted by ceki <ce...@qos.ch>.
On 22.09.2012 15:48, Christian Grobmeier wrote:
> On Sat, Sep 22, 2012 at 3:46 PM, Ralph Goers <ra...@dslextreme.com> wrote:
>> Thank, Ceki. I obviously take your concerns very seriously and will look into these asap.
>
> Maybe we can push the used configuration/code for the perfomance test to github?
> That way it is more easy to follow which version has been used and
> which settings.
>
The relevant files can be found under:
http://svn.apache.org/repos/asf/logging/log4j/log4j2/trunk/core/src/test/
The resources/logback-perf.xml file should be modified to read:
<configuration>
<appender name="TestLogfile" class="ch.qos.logback.core.FileAppender">
<file>target/testlogback.log</file>
<encoder>
<pattern>%d{ISO8601} %5p [%t] %c{0} %X{transactionId} - %m%n</pattern>
<!-- this quadruples logging throughput -->
<immediateFlush>false</immediateFlush>
</encoder>
</appender>
<root level="debug">
<appender-ref ref="TestLogfile" />
</root>
</configuration>
HTH,
--
Ceki
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: performance comparison
Posted by ceki <ce...@qos.ch>.
On 22.09.2012 17:29, Ralph Goers wrote:
> Well, Ceiki's statement about Logback not walking a hierarchy is
> partially correct and partially incorrect. In Logback each Logger has
> an "effectiveLevel" that is either set or inherited from its parent so
> the logger hierarchy isn't "walked" for level filtering. However, if
> a Logger has not been configured it will have no appenders and will
> have its additivity will default to true. callAppenders will perform
> the for loop to call all the appenders (there won't be any) and then
> because addictive is true it will delegate to its parent's
> callAppenders method, which will do the same. Thus if you have a
> hierarchy of 5 or 6 levels with only a root logger configured you will
> "walk the hierarchy". However, since the hierarchy is mentioned in a
> section on "deciding" (i.e. - filtering) Ceki is absolutely correct
> that this should be changed. FWIW, Log4j 2 also has the equivalent of
> the effectiveLevel on each Logger.
Thank you for the quick and detailed response. Indeed, the append loop
goes through the list of attached appenders. However, as you point out
that happens after the decision to log has been taken. This decision
is made extremely quickly and involves no "hierarchy walk".
I understand that log4j2 configuration is atomic. this might indeed be
an improvement upon logback. However, the devil might be in the
details.
> The next issue is with regard to immediateFlush. Prior to Logback
> 1.0.3 the immediateFlush parameter was not available in Logback as an
> option on LayoutWrappingEncoder, which is long after I wrote the text
> on the performance of writing log events. However, since the option
> is now available I have changed the test and rerun it. Note that the
> point of that section is not to highlight the differences between the
> frameworks but to point out that actually doing logging is
> considerably more costly than calling the logging framework and having
> the events filtered.
Makes sense.
> The results from rerunning the test are (I have a much faster MacBook
> than when I first wrote the doc):
>
> Log4j: 1427
> Logback: 1401
> Log4j 2.0: 1963
>
> Interestingly, I made a mistake the first time I tried it and
> configured it as
>
> <encoder immediateFlush="false">
>
> and didn't get an error and still got the slower results.
Joran is very much element oriented. It will ignore XML attributes it
does not know about. It will complain about unknown elements though.
Again, thank you for the quick response.
--
Ceki
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: performance comparison
Posted by Ralph Goers <ra...@dslextreme.com>.
Well, Ceiki's statement about Logback not walking a hierarchy is partially correct and partially incorrect. In Logback each Logger has an "effectiveLevel" that is either set or inherited from its parent so the logger hierarchy isn't "walked" for level filtering. However, if a Logger has not been configured it will have no appenders and will have its additivity will default to true. callAppenders will perform the for loop to call all the appenders (there won't be any) and then because addictive is true it will delegate to its parent's callAppenders method, which will do the same. Thus if you have a hierarchy of 5 or 6 levels with only a root logger configured you will "walk the hierarchy". However, since the hierarchy is mentioned in a section on "deciding" (i.e. - filtering) Ceki is absolutely correct that this should be changed. FWIW, Log4j 2 also has the equivalent of the effectiveLevel on each Logger.
The next issue is with regard to immediateFlush. Prior to Logback 1.0.3 the immediateFlush parameter was not available in Logback as an option on LayoutWrappingEncoder, which is long after I wrote the text on the performance of writing log events. However, since the option is now available I have changed the test and rerun it. Note that the point of that section is not to highlight the differences between the frameworks but to point out that actually doing logging is considerably more costly than calling the logging framework and having the events filtered.
The results from rerunning the test are (I have a much faster MacBook than when I first wrote the doc):
Log4j: 1427
Logback: 1401
Log4j 2.0: 1963
Interestingly, I made a mistake the first time I tried it and configured it as
<encoder immediateFlush="false">
and didn't get an error and still got the slower results.
Ralph
On Sep 22, 2012, at 6:48 AM, Christian Grobmeier wrote:
> On Sat, Sep 22, 2012 at 3:46 PM, Ralph Goers <ra...@dslextreme.com> wrote:
>> Thank, Ceki. I obviously take your concerns very seriously and will look into these asap.
>
> Maybe we can push the used configuration/code for the perfomance test to github?
> That way it is more easy to follow which version has been used and
> which settings.
>
> Cheers
>
>> Ralph
>>
>> On Sep 22, 2012, at 6:21 AM, ceki wrote:
>>
>>> Hello,
>>>
>>> Looking at the log4j/log42/logback comparison [1], I have noticed a
>>> number of inaccuracies.
>>>
>>> item 2) The performance of deciding whether to log or not to log when
>>> logging is turned on.
>>>
>>> Logback does not walk the hierarchy. No, really. It doesn't.
>>>
>>> item 2) Actually outputting log messages
>>>
>>> For the log4j2 figures your have the "immediateFlush" property set to
>>> false. For the logback figures you have "immediateFlush" property set
>>> to true.
>>>
>>> Quoting from [2] and [3]
>>>
>>> By default, the OutputStream is immediately flushed, unless the
>>> immediateFlush property is explicitly set to 'false'. Setting the
>>> immediateFlush property to false can significantly improve logging
>>> throughput.
>>>
>>> The default value for immediateFlush is 'true'. Immediate flushing of
>>> the output stream ensures that logging events are immediately written
>>> to disk and will not be lost in case your application exits without
>>> properly closing appenders. On the other hand, setting this property
>>> to 'false' is likely to quintuple (your mileage may vary) logging
>>> throughput. As mentioned previously, if immediateFlush is set to
>>> 'false' and if appenders are not closed properly when your application
>>> exits, then logging events not yet written to disk may be lost. ===
>>> ====
>>>
>>> For an honest comparison, both frameworks should use comparable
>>> settings. In this particular case, the setting is called
>>> "immediateFlush" and carries the same name in both frameworks.
>>>
>>>
>>> [1] http://logging.apache.org/log4j/2.x/performance.html
>>> [2] http://logback.qos.ch/manual/encoders.html#LayoutWrappingEncoder
>>> [3] http://logback.qos.ch/manual/encoders.html#immediateFlush
>>>
>>> --
>>> Ceki
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
>>> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>>>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
>> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>>
>
>
>
> --
> http://www.grobmeier.de
> https://www.timeandbill.de
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: performance comparison
Posted by Christian Grobmeier <gr...@gmail.com>.
On Sat, Sep 22, 2012 at 3:46 PM, Ralph Goers <ra...@dslextreme.com> wrote:
> Thank, Ceki. I obviously take your concerns very seriously and will look into these asap.
Maybe we can push the used configuration/code for the perfomance test to github?
That way it is more easy to follow which version has been used and
which settings.
Cheers
> Ralph
>
> On Sep 22, 2012, at 6:21 AM, ceki wrote:
>
>> Hello,
>>
>> Looking at the log4j/log42/logback comparison [1], I have noticed a
>> number of inaccuracies.
>>
>> item 2) The performance of deciding whether to log or not to log when
>> logging is turned on.
>>
>> Logback does not walk the hierarchy. No, really. It doesn't.
>>
>> item 2) Actually outputting log messages
>>
>> For the log4j2 figures your have the "immediateFlush" property set to
>> false. For the logback figures you have "immediateFlush" property set
>> to true.
>>
>> Quoting from [2] and [3]
>>
>> By default, the OutputStream is immediately flushed, unless the
>> immediateFlush property is explicitly set to 'false'. Setting the
>> immediateFlush property to false can significantly improve logging
>> throughput.
>>
>> The default value for immediateFlush is 'true'. Immediate flushing of
>> the output stream ensures that logging events are immediately written
>> to disk and will not be lost in case your application exits without
>> properly closing appenders. On the other hand, setting this property
>> to 'false' is likely to quintuple (your mileage may vary) logging
>> throughput. As mentioned previously, if immediateFlush is set to
>> 'false' and if appenders are not closed properly when your application
>> exits, then logging events not yet written to disk may be lost. ===
>> ====
>>
>> For an honest comparison, both frameworks should use comparable
>> settings. In this particular case, the setting is called
>> "immediateFlush" and carries the same name in both frameworks.
>>
>>
>> [1] http://logging.apache.org/log4j/2.x/performance.html
>> [2] http://logback.qos.ch/manual/encoders.html#LayoutWrappingEncoder
>> [3] http://logback.qos.ch/manual/encoders.html#immediateFlush
>>
>> --
>> Ceki
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
>> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>
--
http://www.grobmeier.de
https://www.timeandbill.de
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: performance comparison
Posted by Ralph Goers <ra...@dslextreme.com>.
Thank, Ceki. I obviously take your concerns very seriously and will look into these asap.
Ralph
On Sep 22, 2012, at 6:21 AM, ceki wrote:
> Hello,
>
> Looking at the log4j/log42/logback comparison [1], I have noticed a
> number of inaccuracies.
>
> item 2) The performance of deciding whether to log or not to log when
> logging is turned on.
>
> Logback does not walk the hierarchy. No, really. It doesn't.
>
> item 2) Actually outputting log messages
>
> For the log4j2 figures your have the "immediateFlush" property set to
> false. For the logback figures you have "immediateFlush" property set
> to true.
>
> Quoting from [2] and [3]
>
> By default, the OutputStream is immediately flushed, unless the
> immediateFlush property is explicitly set to 'false'. Setting the
> immediateFlush property to false can significantly improve logging
> throughput.
>
> The default value for immediateFlush is 'true'. Immediate flushing of
> the output stream ensures that logging events are immediately written
> to disk and will not be lost in case your application exits without
> properly closing appenders. On the other hand, setting this property
> to 'false' is likely to quintuple (your mileage may vary) logging
> throughput. As mentioned previously, if immediateFlush is set to
> 'false' and if appenders are not closed properly when your application
> exits, then logging events not yet written to disk may be lost. ===
> ====
>
> For an honest comparison, both frameworks should use comparable
> settings. In this particular case, the setting is called
> "immediateFlush" and carries the same name in both frameworks.
>
>
> [1] http://logging.apache.org/log4j/2.x/performance.html
> [2] http://logback.qos.ch/manual/encoders.html#LayoutWrappingEncoder
> [3] http://logback.qos.ch/manual/encoders.html#immediateFlush
>
> --
> Ceki
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org