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 David McVicar <da...@yahoo.com> on 2003/10/29 15:20:52 UTC
Performance of not logging in Log4J vs. JDK 1.4 Logging
Hi,
I have written a basic test to exercise the effect of
adding logging to an application but configuring no
logging to be output. The test consists of some JUnit
tests that repeatedly call both the Log4J and JDK 1.4
Logger.log(Level.INFO, "Hello") method 10million times
(its just a test so please don't flame me for using
Property to pass the loopCount!). The tests are
configured using log4j.xml (Log4J) and
logging.properties (JDK 1.4). I used the JUnitPerf
classes from Clarkware.com to measure the performance.
Unforunately I have found that Log4J 1.2.8 took 2023ms
while JDK 1.4.2 took only 892ms.
The performance while not logging is a concern in my
application. I am aware that I could instrument the
generated byte code using Just4Log but would prefer
not to add a post compilation step.
I have read through the code and it appears that the
effort of evaluating the priority.isGreaterOrEqual()
is where the time is being lost.
public
void log(Priority priority, Object message) {
if(repository.isDisabled(priority.level)) {
return;
}
if(priority.isGreaterOrEqual(this.getEffectiveLevel()))
forcedLog(FQCN, priority, message, null);
}
Would it be possible during configuration of Log4J
that a flag be set to disable the entire repository if
all of the Categories are turned OFF?
Although I think that I have configured both Log4J and
JDK 1.4 not to log using a specific class name the
costs of not logging are greater in Log4J. I may
however have made an error in my configuration - if so
I apologise in advance.
I have enclosed the tests for reference.
I have been a user of Log4J for about 3 years and
would like to say a quick thanks for all of your good
work.
Thanks in advance for any assistance you can provide
in improving the performance of Log4J.
David
__________________________________
Do you Yahoo!?
Exclusive Video Premiere - Britney Spears
http://launch.yahoo.com/promos/britneyspears/
Re: Performance of not logging in Log4J vs. JDK 1.4 Logging
Posted by Ceki Gülcü <ce...@qos.ch>.
At 10:42 AM 10/29/2003 -0800, David McVicar wrote:
>Toby, Yoav,
>
>Thanks for the responses.
>
>Yoav:
>
>Thanks for explaining the Hierarchy.setThreshold()
>method - if I was to change the config to effectively
>set this would I get a performance gain? I would
>prefer not to have to call this method in Java and
>would like to do this via configuration.
You can set the hierarchy-wide threshold as follows:
log4j.threshold=someLevel
where someLevel can be any of ALL, DEBUG, INFO, ..., OFF.
Set to it to INFO and see the impact on performance.
(My guess would be a 3 to 4 fold improvement.)
>Toby:
>
>You are right, I shouldn't have been mixing properties
>files with xml files, it wasn't a fair comparison. I
>have changed to using both properties files.
>
>I have also updated the code to explicitly display the
>time taken to execute just the Log4J and JDK 1.4 code
>using direct calls to Date().getTime(). Strictly
>speaking this was not necessary as I was reusing the
>JUnitPerf classes from Mike Clark (www.clarkware.com).
> JUnitPerf is an Open Source add on to JUnit that
>allows you to measure the performance of JUnit tests,
>as I was initialising the Logger in the constructor of
>the JUnit TestCase class and not in the method that
>JUnitPerf was timing the differences between
>properties and xml config files shouldn't have made a
>difference. Anyway for clarity its changed now and
>you can run each test directly.
>
>I also take your point that "benchmarking by
>iteration" is not the best way to measure the overall
>performance of Log4J however the specific test that I
>am performing here is to understand the difference in
>duration between leaving JDK 1.4 and Log4J logging
>code in place and configuring it not to log any
>messages. As I said before the only reason that I am
>iterating 10 million times is to get a significantly
>measurable result as to perform the division and
>calculate the cost of leaving a single logging
>statement that is configured not to log.
>
>Unfortunately the changes didn't make any difference
>to the results, this time for 10 million iterations it
>was:
>
>JDK 1.4 : 441 ms
>Log4J : 901 ms
>
>I think that this illustrates that for a comparable
>test where the general configuration of both JDK 1.4
>and Log4J is to log messages BUT a specific class has
>been configured NOT to log that JDK 1.4 is faster. If
>Log4J was enhanced to check earlier comparable
>performance results could be acheived.
Two short comments:
1) Spending under 1 second for 10 million trials is not bad. Your
tests show that in a single threaded application calling disabled log
statements is hardly an issue.
Btw, I am not saying this as a sore loser because log4j seems to be
slower on this test. With the hierarchy-wide threshold the figures
should be in log4j's favor.
2) The really interesting question is how both API perform on a loaded
server...
--
Ceki Gülcü
For log4j documentation consider "The complete log4j manual"
ISBN: 2970036908 http://www.qos.ch/shop/products/clm_t.jsp
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@jakarta.apache.org
For additional commands, e-mail: log4j-dev-help@jakarta.apache.org
Re: Performance of not logging in Log4J vs. JDK 1.4 Logging
Posted by David McVicar <da...@yahoo.com>.
Toby, Yoav,
Thanks for the responses.
Yoav:
Thanks for explaining the Hierarchy.setThreshold()
method - if I was to change the config to effectively
set this would I get a performance gain? I would
prefer not to have to call this method in Java and
would like to do this via configuration.
Toby:
You are right, I shouldn't have been mixing properties
files with xml files, it wasn't a fair comparison. I
have changed to using both properties files.
I have also updated the code to explicitly display the
time taken to execute just the Log4J and JDK 1.4 code
using direct calls to Date().getTime(). Strictly
speaking this was not necessary as I was reusing the
JUnitPerf classes from Mike Clark (www.clarkware.com).
JUnitPerf is an Open Source add on to JUnit that
allows you to measure the performance of JUnit tests,
as I was initialising the Logger in the constructor of
the JUnit TestCase class and not in the method that
JUnitPerf was timing the differences between
properties and xml config files shouldn't have made a
difference. Anyway for clarity its changed now and
you can run each test directly.
I also take your point that "benchmarking by
iteration" is not the best way to measure the overall
performance of Log4J however the specific test that I
am performing here is to understand the difference in
duration between leaving JDK 1.4 and Log4J logging
code in place and configuring it not to log any
messages. As I said before the only reason that I am
iterating 10 million times is to get a significantly
measurable result as to perform the division and
calculate the cost of leaving a single logging
statement that is configured not to log.
Unfortunately the changes didn't make any difference
to the results, this time for 10 million iterations it
was:
JDK 1.4 : 441 ms
Log4J : 901 ms
I think that this illustrates that for a comparable
test where the general configuration of both JDK 1.4
and Log4J is to log messages BUT a specific class has
been configured NOT to log that JDK 1.4 is faster. If
Log4J was enhanced to check earlier comparable
performance results could be acheived.
I have attached my updated tests and config.
Thanks again,
David
--- Toby Butzon <to...@ilc.com> wrote:
> David McVicar wrote:
>
> > The tests are configured using log4j.xml (Log4J)
> and
> > logging.properties (JDK 1.4).
>
> You should either (a) time JUST the log() method
> calls or (b) use the
> same kind of configuration file in both tests. XML
> is significantly
> harder to process than the .properties format. So,
> try using
> log4j.properties and let's see what your timing
> results are then.
>
> Also try timing ONLY the loop and not the
> initialization. You should be
> able to use ``new java.util.Date().getTime()''
> before and after the
> loop, subtracting the two values to get the elapsed
> time in
> milliseconds. (It'd be nice to have nano precision,
> but that's not
> supported; you could do it natively, if you were
> keen on it.)
>
> Note also that benchmarking by iteration is not
> usually the best way to
> do it; though it seems to sheild you from having to
> think about other
> factors, looping differs a good bit from normal
> usage, so it won't
> necessarily reflect actual real-world performance.
>
> --
> Toby Butzon <to...@ilc.com>
> ILC R&D Co-op / Georgia Tech CS / KKPsi Iota Sp03
> 678.904.2413 work / 678.362.6483 mobile
> Fifteen Piedmont Center, Suite 700 / Atlanta, GA
> 30305
>
>
>
---------------------------------------------------------------------
> To unsubscribe, e-mail:
> log4j-dev-unsubscribe@jakarta.apache.org
> For additional commands, e-mail:
> log4j-dev-help@jakarta.apache.org
>
__________________________________
Do you Yahoo!?
Exclusive Video Premiere - Britney Spears
http://launch.yahoo.com/promos/britneyspears/
Re: Performance of not logging in Log4J vs. JDK 1.4 Logging
Posted by Toby Butzon <to...@ilc.com>.
David McVicar wrote:
> The tests are configured using log4j.xml (Log4J) and
> logging.properties (JDK 1.4).
You should either (a) time JUST the log() method calls or (b) use the
same kind of configuration file in both tests. XML is significantly
harder to process than the .properties format. So, try using
log4j.properties and let's see what your timing results are then.
Also try timing ONLY the loop and not the initialization. You should be
able to use ``new java.util.Date().getTime()'' before and after the
loop, subtracting the two values to get the elapsed time in
milliseconds. (It'd be nice to have nano precision, but that's not
supported; you could do it natively, if you were keen on it.)
Note also that benchmarking by iteration is not usually the best way to
do it; though it seems to sheild you from having to think about other
factors, looping differs a good bit from normal usage, so it won't
necessarily reflect actual real-world performance.
--
Toby Butzon <to...@ilc.com>
ILC R&D Co-op / Georgia Tech CS / KKPsi Iota Sp03
678.904.2413 work / 678.362.6483 mobile
Fifteen Piedmont Center, Suite 700 / Atlanta, GA 30305
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@jakarta.apache.org
For additional commands, e-mail: log4j-dev-help@jakarta.apache.org