[slf4j-user] Java 5 version of SLF4J?

[Simon Kitching]

Hi Erik,

You're right that the correspondence between bytecode and actual machine
instructions is not direct. And in fact, the machine instructions
could even vary during a program's run if the JVM is doing dynamic
optimisation.

But in this specific case,
(a) Whether the formatting parameters are used or not depends upon the
current setting of the logging threshold level for that category. There
is no way the caller can determine that, so AFAICT the params will
really have to be passed somehow. [1]
(b) If the params are used, then they are passed as an object array to
java.util.Formatter so an object array does need to be created at that
point. *Possibly* a clever runtime optimiser could pass the params in
registers, and delay creating of the object array until after the
threshold test is done. That would be seriously smart optimisation
though. For a start, doing this means changing the way that callers
invoke the method, so would need to dynamically be patched into every
callsite, not just optimise the internal implementation of a method. And
different Logger objects can theoretically have different concrete
implementations at runtime, so the mechanism used to invoke the call
would need to vary depending upon the concrete implementation
referenced. I can't see that being feasable.

[1] Unless the runtime optimiser sees that the first thing the called
method does is invoke isXXXEnabled, before using any params. When the
calling site is using a final reference to the logger object, it would
then be possible to migrate that call up into the calling site, and the
effect would be like wrapping every call in isXXXEnabled, which would be
nice. I have no idea whether any existing JVMs do this; it's fairly
clever work. Hmm.. it would also mean presumably rewriting the called
method so that the isXXXEnabled does not get called multiple times. But
that would then break other callers. Ouch, this makes my head hurt  :-) 

I'd be willing to bet that in everything except specialist jvms (and
maybe there too), the log5j approach has a significant performance
penalty due to the creation of an object array for each call, and
therefore manually wrapping in isXXXEnabled is needed.

But
   // standard SLF4J or JCL
   if (log.isDebugEnabled())
      log.debug(String.format("...", arg1, arg2, arg3, arg4));
and
   // log5j only
   if (log.isDebugEnabled())
      log.debug("...", arg1, arg2, arg3, arg4);
are identical in performance, and not much different aesthetically.

The mere existence of the varargs method, however, is a performance trap
just waiting for users to fall into, tempting them to omit the
isDebugEnabled call. A small trap, but nevertheless there. By *not*
providing a varargs option, the SLF4J/JCL API instead makes it obvious
that the isDebugEnabled is necessary. I think the lack of varargs
support is a feature, and good api design.

Regards,

Simon

Erik van Oosten schrieb:
> Hi Simon,
>
> You should never confuse Java byte code with compiled byte code. I
> understand there are a few superfluous byte codes, but in the end the
> JVM determines how to compile it to CPU instructions. Unfortunately I am
> not aware of what the JVM actually does with unused values. Does it do
> escape analysis already?
>
> Regards,
>     Erik.
>
>
> Simon Kitching schreef:
>   
>> Erik van Oosten schrieb:
>>   
>>     
>>> Christopher,
>>>
>>> As I wrote already on Feb 17:
>>> 	There is another aproach, as taken by http://code.google.com/p/log5j/. It is
>>> 	a wrapper around log4j. I wish they had made it for SLF4J!
>>>
>>> I am still waiting for someone to this for SLF4J. It should not be hard. I did not yet find the time myself :(
>>>   
>>>     
>>>       
>> Sigh. Broken broken broken.
>>
>> Re the "feature" for determining which category to create a logger for,
>> see the documentation for Exception.getStackTrace. There is no guarantee
>> that valid info about the callstack is available. So this code will work
>> fine under unit testing, then may start emitting messages to the wrong
>> categories when run in a high-performance environment. That will be fun
>> to debug...
>>
>> Re the printf-style formatting:
>>
>>   log.debug("format str", arg0, arg1, arg2);
>>
>> is exactly equivalent to:
>>
>>   push "format str" onto stack
>>   tmp = new Object[3];
>>   tmp[0] = arg0;
>>   tmp[1] = arg1;
>>   tmp[2] = arg2;
>>   push tmp onto stack
>>   invoke log.debug
>>   (and of course garbage-collect the tmp object later..)
>>
>> So in practice, for good performance you need
>>   if (log.isDebugEnabled())
>> around each call anyway. In which case, the printf-style stuff gives no
>> performance benefits at all; if something is going to be logged then the
>> formatting is nowhere near the bottleneck step.
>>
>> The SLF4J fake-varargs approach, where the api allows 0,1 or 2 params is
>> slightly better, as it avoids the "new Object[]" call. But for best
>> performance, isDebugEnabled should be used anyway.
>>
>> Regards,
>> Simon
>>
>> _______________________________________________
>> user mailing list
>> user at slf4j.org
>> http://www.slf4j.org/mailman/listinfo/user
>>   
>>     
>
>