You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@hc.apache.org by Pfingstl Gernot <ge...@stmk.gv.at> on 2004/12/27 15:48:06 UTC
Logging
In httpclient-3.0-beta1 source I saw, that calls to the logging api is always done directly:
LOG.trace("some logging text");
This may produce a runtime overhead - see http://jakarta.apache.org/commons/logging/guide.html, chapter "Best Practices (General)", "Code Guards":
"Code guards are typically used to guard code that only needs to execute in support of logging, that otherwise introduces undesirable runtime overhead in the general case (logging disabled). Examples are multiple parameters, or expressions (i.e. string + " more") for parameters. Use the guard methods of the form log.is<Priority>() to verify that logging should be performed, before incurring the overhead of the logging method call. Yes, the logging methods will perform the same check, but only after resolving parameters."
Do you plan to refactor the above code to:
if(LOG.isTraceEnabled())
{
LOG.trace("some logging text");
}
Gernot
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-dev-unsubscribe@jakarta.apache.org
For additional commands, e-mail: httpclient-dev-help@jakarta.apache.org
Re: Logging
Posted by Eric Bloch <bl...@laszlosystems.com>.
This is just one of those cases where Java fails as a programming
language. You want to be able to write
LOG.trace("blah")
but effectively run
if (some bit) {
LOG.trace()
}
-Eric
Ortwin Glück wrote:
>
>
> Pfingstl Gernot wrote:
>
>> In httpclient-3.0-beta1 source I saw, that calls to the logging api is
>> always done directly:
>> LOG.trace("some logging text");
>>
>> This may produce a runtime overhead - see
>> http://jakarta.apache.org/commons/logging/guide.html, chapter "Best
>> Practices (General)", "Code Guards":
>> "Code guards are typically used to guard code that only needs to
>> execute in support of logging, that otherwise introduces undesirable
>> runtime overhead in the general case (logging disabled). Examples are
>> multiple parameters, or expressions (i.e. string + " more") for
>> parameters. Use the guard methods of the form log.is<Priority>() to
>> verify that logging should be performed, before incurring the overhead
>> of the logging method call. Yes, the logging methods will perform the
>> same check, but only after resolving parameters."
>>
>> Do you plan to refactor the above code to:
>> if(LOG.isTraceEnabled())
>> {
>> LOG.trace("some logging text");
>> }
>>
>> Gernot
>
>
> Gernot,
>
> I quickly hacked up a test case which compares an unguarded call to a
> guarded one. The log string is constant. I used Log4J with WARN level
> and a log.debug call. So no actual log was generated.
>
> I performed a 100 million calls to log.debug. I run the test 3 times in
> a row to give HotSpot a chance to kick in.
>
> unguarded: 6669ms
> guarded: 7431ms
> Difference: 762ms, 0.1142600089968511
>
> unguarded: 6660ms
> guarded: 7411ms
> Difference: 751ms, 0.11276276276276276
>
> unguarded: 6600ms
> guarded: 7460ms
> Difference: 860ms, 0.1303030303030303
>
> So we loose around 10% performance for an unguarded call, if the payload
> is not logged. Logging can take up as much as 40% of the CPU time in
> very extreme cases like our no-host test suite. So best we can achieve
> is a 4% performance gain. Is that worth the trouble?
>
> Ortwin Glück
>
>
> ------------------------------------------------------------------------
>
> package test;
>
> import org.apache.commons.logging.Log;
> import org.apache.commons.logging.LogFactory;
>
> /**
> *
> * @author Ortwin Glück, NOSE Applied Intelligence AG
> * @version $Id$
> */
> public class Test {
> public Test() {
> try {
> test();
> Thread.sleep(1000);
> test();
> Thread.sleep(1000);
> test();
> } catch (InterruptedException e) {
> e.printStackTrace();
> }
> }
>
> public static void main(String[] args) {
> new Test();
> }
>
> public void test() {
> long MAX = 10000000;
> Log log = LogFactory.getLog(Test.class);
> long s = System.currentTimeMillis();
> for (int i=0; i<MAX; i++) {
> log.debug("a constant string");
> }
> long e = System.currentTimeMillis();
> long unguarded = e-s;
> System.out.println("unguarded: "+ unguarded +"ms");
>
> s = System.currentTimeMillis();
> for (int i=0; i<MAX; i++) {
> if (log.isDebugEnabled()) {
> log.debug("a constant string");
> }
> }
> e = System.currentTimeMillis();
> long guarded = e-s;
> System.out.println("guarded: "+ guarded +"ms");
>
> long diff = guarded-unguarded;
> double pct = (double) diff / unguarded;
> System.out.println("Difference: "+ diff +"ms, "+ pct);
>
> }
> }
>
>
>
> ------------------------------------------------------------------------
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: httpclient-dev-unsubscribe@jakarta.apache.org
> For additional commands, e-mail: httpclient-dev-help@jakarta.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-dev-unsubscribe@jakarta.apache.org
For additional commands, e-mail: httpclient-dev-help@jakarta.apache.org
Re: Logging
Posted by Eric Johnson <er...@tibco.com>.
Ortwin's results do make some sense, but may not apply to general usage
a) adding the "guard" doubles the test to see whether anything should be
logged, so it would make sense that it seems to add overhead
b) in the particular case of using a constant string, there is no
computation involved - the only overhead is a function call, which is
one thing that Java has optimized extremely well
If there are logging invocations that involve significant computation
(String concatenation, for example), results might change significantly.
-Eric.
Ortwin Glück wrote:
>
>
> Pfingstl Gernot wrote:
>
>> In httpclient-3.0-beta1 source I saw, that calls to the logging api
>> is always done directly:
>> LOG.trace("some logging text");
>>
>> This may produce a runtime overhead - see
>> http://jakarta.apache.org/commons/logging/guide.html, chapter "Best
>> Practices (General)", "Code Guards":
>> "Code guards are typically used to guard code that only needs to
>> execute in support of logging, that otherwise introduces undesirable
>> runtime overhead in the general case (logging disabled). Examples are
>> multiple parameters, or expressions (i.e. string + " more") for
>> parameters. Use the guard methods of the form log.is<Priority>() to
>> verify that logging should be performed, before incurring the
>> overhead of the logging method call. Yes, the logging methods will
>> perform the same check, but only after resolving parameters."
>>
>> Do you plan to refactor the above code to:
>> if(LOG.isTraceEnabled())
>> {
>> LOG.trace("some logging text");
>> }
>>
>> Gernot
>
>
> Gernot,
>
> I quickly hacked up a test case which compares an unguarded call to a
> guarded one. The log string is constant. I used Log4J with WARN level
> and a log.debug call. So no actual log was generated.
>
> I performed a 100 million calls to log.debug. I run the test 3 times
> in a row to give HotSpot a chance to kick in.
>
> unguarded: 6669ms
> guarded: 7431ms
> Difference: 762ms, 0.1142600089968511
>
> unguarded: 6660ms
> guarded: 7411ms
> Difference: 751ms, 0.11276276276276276
>
> unguarded: 6600ms
> guarded: 7460ms
> Difference: 860ms, 0.1303030303030303
>
> So we loose around 10% performance for an unguarded call, if the
> payload is not logged. Logging can take up as much as 40% of the CPU
> time in very extreme cases like our no-host test suite. So best we can
> achieve is a 4% performance gain. Is that worth the trouble?
>
> Ortwin Glück
>
>------------------------------------------------------------------------
>
>package test;
>
>import org.apache.commons.logging.Log;
>import org.apache.commons.logging.LogFactory;
>
>/**
> *
> * @author Ortwin Glück, NOSE Applied Intelligence AG
> * @version $Id$
> */
>public class Test {
> public Test() {
> try {
> test();
> Thread.sleep(1000);
> test();
> Thread.sleep(1000);
> test();
> } catch (InterruptedException e) {
> e.printStackTrace();
> }
> }
>
> public static void main(String[] args) {
> new Test();
> }
>
> public void test() {
> long MAX = 10000000;
> Log log = LogFactory.getLog(Test.class);
> long s = System.currentTimeMillis();
> for (int i=0; i<MAX; i++) {
> log.debug("a constant string");
> }
> long e = System.currentTimeMillis();
> long unguarded = e-s;
> System.out.println("unguarded: "+ unguarded +"ms");
>
> s = System.currentTimeMillis();
> for (int i=0; i<MAX; i++) {
> if (log.isDebugEnabled()) {
> log.debug("a constant string");
> }
> }
> e = System.currentTimeMillis();
> long guarded = e-s;
> System.out.println("guarded: "+ guarded +"ms");
>
> long diff = guarded-unguarded;
> double pct = (double) diff / unguarded;
> System.out.println("Difference: "+ diff +"ms, "+ pct);
>
> }
>}
>
>
>
>------------------------------------------------------------------------
>
>---------------------------------------------------------------------
>To unsubscribe, e-mail: httpclient-dev-unsubscribe@jakarta.apache.org
>For additional commands, e-mail: httpclient-dev-help@jakarta.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-dev-unsubscribe@jakarta.apache.org
For additional commands, e-mail: httpclient-dev-help@jakarta.apache.org
Re: Logging
Posted by Ortwin Glück <or...@nose.ch>.
Pfingstl Gernot wrote:
> In httpclient-3.0-beta1 source I saw, that calls to the logging api is always done directly:
> LOG.trace("some logging text");
>
> This may produce a runtime overhead - see http://jakarta.apache.org/commons/logging/guide.html, chapter "Best Practices (General)", "Code Guards":
> "Code guards are typically used to guard code that only needs to execute in support of logging, that otherwise introduces undesirable runtime overhead in the general case (logging disabled). Examples are multiple parameters, or expressions (i.e. string + " more") for parameters. Use the guard methods of the form log.is<Priority>() to verify that logging should be performed, before incurring the overhead of the logging method call. Yes, the logging methods will perform the same check, but only after resolving parameters."
>
> Do you plan to refactor the above code to:
> if(LOG.isTraceEnabled())
> {
> LOG.trace("some logging text");
> }
>
> Gernot
Gernot,
I quickly hacked up a test case which compares an unguarded call to a
guarded one. The log string is constant. I used Log4J with WARN level
and a log.debug call. So no actual log was generated.
I performed a 100 million calls to log.debug. I run the test 3 times in
a row to give HotSpot a chance to kick in.
unguarded: 6669ms
guarded: 7431ms
Difference: 762ms, 0.1142600089968511
unguarded: 6660ms
guarded: 7411ms
Difference: 751ms, 0.11276276276276276
unguarded: 6600ms
guarded: 7460ms
Difference: 860ms, 0.1303030303030303
So we loose around 10% performance for an unguarded call, if the payload
is not logged. Logging can take up as much as 40% of the CPU time in
very extreme cases like our no-host test suite. So best we can achieve
is a 4% performance gain. Is that worth the trouble?
Ortwin Gl�ck
--
_________________________________________________________________
NOSE applied intelligence ag
ortwin gl�ck [www] http://www.nose.ch
software engineer
hardturmstrasse 171 [pgp id] 0x81CF3416
8005 z�rich [office] +41-1-277 57 35
switzerland [fax] +41-1-277 57 12