log.isTraceEnabled()

[timfox]

One other (easy) change I would really appreciate being in remoting before jboss messaging 1.0 is released, is, (in SocketClientInvoker and SocketServerInvoker especially) is to use the following idiom:

public void foo()
{
 private boolean trace = log.isTraceEnabled();

 if (trace)
 {
 log.trace("whatever");
 }
}

as opposed to:

if (log.isTraceEnabled())
{
 log.trace("whatever");
}

Believe it or not, this make about a 4-5% difference on our bottom line performance :)

[timfox]

To state the obvious, the first example should, of course read:

private boolean trace = log.isTraceEnabled();


public void foo()
{

 if (trace)
 {
 log.trace("whatever");
 }
}

[ovidiu.feodorov]

This will make impossible run-time logging re-configuration.

[starksm64]

Its a tradeoff between performance and being able to configure this dynamically.

[timfox]

Well... I guess we could change the value of trace at runtime by listening for redeployments of the logging config., checking a member should be quicker than a stack jump.

BTW, overall in JBossMessaging (not just remoting) calls to log.isTraceEnabled() contribute about 15% to the overall time for running threads in my test case (if I remember the profiler results rightly), so this is not something we should ignore IMHO.

[adrian.brock]

Unless you are doing something ridiculous like calling
log.isTraceEnabled()
inside an inner loop,
I refuse to believe that this is taking 15% of the time of a network call or database operation.

Sounds to me that there is something like :-)

// Write a byte to the network
public void writeByte(byte byte)
{
 if (log.isTraceEnabled())
 log.trace("Writing byte " + byte);
}

[adrian.brock]

"timfox" wrote:
Well... I guess we could change the value of trace at runtime by listening for redeployments of the logging config., checking a member should be quicker than a stack jump.

If that was a real problem, hotspot should inline the method, to avoid the stack push/pop.
I'm assuming that only one implementation of the Logger interface is loaded
so it can discard polymorphic considerations.

[adrian.brock]

Also, profiling with exaggerate simple methods that are called a lot.

// Profiler disables optimizations
public boolean isTraceEnabled()
{
 // profiler logs entry
 return true;
 // profiler logs exit
}

Most of the time it taken in the profiler, not the method.

[timfox]

The differences are observed where we have a jms producer in one vm, sending to a server in other vm but on the same box.

The messages are non persistent so there is no db access but there are calls to socket.write/read although they don't actually go across the network.

Most of the time is obviously spent in socket.write and socket.read.

The messages are small with no payload.

The stack is pretty deep with all the interceptors and other stuff, most of which call log.isTraceEnabled() at least once, and some many times.

So each message send corresponds to many invocations of log.isTraceEnabled().

I also verified there was a difference without using a profiler so I don't think it's due to influence of the profiler.

I'm going to double check though, in case I have been hallucinating or something :)

[timfox]

I have just retested without a profiler.

Ok, it's not 15%, it's about 4.5%


with if (trace): (msgs/sec)

5150
5224
5289
5229
5246
5289
5182
5224

mean: 5229

with if (log.isTraceEnabled())

4812
5059
5018
4980
5100
5039
5018
5000

mean: 5003

% difference = 4.5%

So smaller than i thought (maybe the profiler was making a difference) but significant nevertheless.

BTW we are not calling log.isTraceEnabled() in any inner loops.

[timfox]

Moved to:

http://www.jboss.com/index.html?module=bb&op=viewtopic&p=3920740#3920740

Since this is not exclusively about remoting any more