Re: Logging

[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