cocoon-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Peter Donald <dona...@apache.org>
Subject Re: Performance of loggin
Date Wed, 07 Mar 2001 14:24:01 GMT
At 06:06  7/3/01 -0800, Giacomo Pati wrote:
>I've recently made a copy of C2 without any log.debug() statements in it
for a 
>test how much performance we loose using it that extensively. I've written a 
>script that comments out every possible .debug() use in the sources (I
confess I 
>had to edit the sitemap.xsl manually but this wasn't much effort) I've
used the 
>ApacheBench tool for the mesurement. 
>
>Well, probably someone else should made this test independantly (I may 
>have done something wrong) because I haven't found *ANY* significant
differences 
>??!! I've tested it several time with and without XSLT on the welcome page
and 
>everytime I get the same differences (less that 10ms per request). 
>
>Does anybody may have a reason why?

Short Answer: Because I designed it that way ;) (It was originally designed
for logging in performance sensitive servlet environments).

Long Answer: Depends on the VM but the structure is optimized for inlining.
ie All the methods are final and don't return anything.

log.debug( "foo" );

In most JVMs will be optimized to 

String data = "foo";
if( m_category.getPriority().isLowerOrEqual( Priority.DEBUG ) &&
    LogKit.getGlobalPriority().isLowerOrEqual( Priority.DEBUG ) )
{
  output( Priority.DEBUG, data , null );
}


(ie no method call). Some JVMS (supposedly the HOTSPOT ones - well at least
the server version) will optimize this further because
m_category.getPriority().isLowerOrEqual( ... ) is a final method. The
result would look something like 


(ie everything becomes an integer operation). Some JVMS will rearrange the
order of things aswell (accessing static value in logkit is faster than
accessing instance variable in category). They may also force evaluation of
"datat" inside if statement.

So the final method for

log.debug( "foo" + 2 );

is something like

if( LogKit.c_globalPriority.m_value <= Priority.DEBUG.m_value &&
    m_category.m_priority.m_value <= Priority.DEBUG.m_value )
{
  output( Priority.DEBUG, "foo" + 2, null );
}

Also similar optimisations can be made with output as it is also a final
method...

So it really depends on your JVM. However if you want a way to JVM
independently optimize then you can use 

if( DEBUG ) log.debug( "foo" );

which works great.

The 10ms difference is most likely due to actually writing to the log file
(which is slow). I have an (uncommitted) AsyncLogTarget that will write
LogEntrys in another thread which should reduce that 10s to less ;)

Cheers,

Pete

*-----------------------------------------------------*
| "Faced with the choice between changing one's mind, |
| and proving that there is no need to do so - almost |
| everyone gets busy on the proof."                   |
|              - John Kenneth Galbraith               |
*-----------------------------------------------------*


Mime
View raw message