8010309 : PlatformLogger: isLoggable performance / waste due to HashMap<Integer, Level> leads to Integer allocations (boxing)

[Mandy Chung]

Hi Peter,

It looks better.   I want to wrap up this patch and push the changeset 
tomorrow.   I have made slight modification and clean up some comments 
and the test.  See my comments inlined below.

Webrev at:
http://cr.openjdk.java.net/~mchung/jdk8/webrevs/8010309/webrev.00/

Please let me know if you don't agree with these changes or you find any 
performance issue.

I have retained the part in webrev.08 that only defines loggerProxy and 
javaLoggerProxy.  I don't think the new defaultLoggerProxy variable is 
needed.  I prefer to use Class.forName to force load JavaLoggerProxy 
class to make very explicit that we don't want the class be 
initialized.  JavaLoggerProxy.<clinit> calls LoggingProxy.parseLevel 
unconditionally that will throw an AssertionError if java.util.logging 
is not available. If JavaLoggerProxy class is initialized, j.u.logging 
should be present and I want to catch error if otherwise.  Also 
Class.forName will load its superclass LoggerProxy.

As for the PlatformLogger.Level enums, having the members to be defined 
in ascending order is fragile.  It'd be more reliable to specify the 
value in the constructor so that it can be used as the isLoggable 
comparsion in the same way as in the Level implementation.

I am running the jdk core regression tests on all platforms and should 
have the result by tomorrow.

On 3/27/2013 9:44 AM, Peter Levart wrote:
> Hi Mandy, Laurent,
>
> It turns out that the API change (change of type for level parameter 
> int -> enum Level) is entirely source-compatible. The tip of JDK8 (tl 
> repo) builds without a problem. So no-one is currently using 
> PlatformLogger.getLevel() method and assigning it to a variable or such...
>

Great thanks.  That is what I expect too.

> Here's the webrev for this change:
>
> http://dl.dropbox.com/u/101777488/jdk8-tl/PlatformLogger/webrev.enumapi.01/index.html
>
> Besides doing the replacement of type and renaming and removing of the 
> unneeded stuff, I also did some re-arrangements:
>
> - introduced a common abstract superclass for both types of 
> LoggerProxys (DefaultLoggerProxy, JavaLoggerProxy), since 
> JavaLoggerProxy does not need the fields of DefaultLoggerProxy and now 
> both concrete subclasses can be declared final (makes JIT even more 
> happy). Also the abstract LoggerProxy could host some common logic 
> (see below about formatting)...

That's a good idea.

> - DefaultLoggerProxy's levelValue/effectiveLevel were given names just 
> the opposite of their meaning. I aligned them with terminology used in 
> j.u.l.Logger and renamed levelValue to plain level.

Swapping these 2 variables makes sense.

> - introduced private method 
> DefaultLoggerProxy.deriveEffectiveLevel(level) that currently just 
> returns defaultLevel (INFO) when given null.

Ok.

> I think with a little more effort, it could be possible to emulate the 
> behaviour of j.u.l.Logger which inherits from 1st parent logger that 
> has non-null level assigned. Of course with all the caching and 
> invalidation...

The only way to change the level to a non-default one is via the logging 
configuration and enable logging.  That's why there is no need for 
DefaultLoggerProxy to inherit level from its parent logger.  Also there 
is no parent logger hierarchy maintained in DefaultLoggerProxy.

> - instead of static final DefaultLoggerProxy.defaultStream I created a 
> private static method outputStream() that returns System.err. To 
> accomodate for the situation when System.err is changed dynamically.

Ok.

> - fixed the JavaLoggerProxy.isEnabled() method. Original code was:
>
>   532         boolean isEnabled() {
>   533             Object level = LoggingSupport.getLevel(javaLogger);
>   534             return level == null || level.equals(levelObjects.get(OFF)) == false;
>   535         }
>
> If 'level' is null then it can be that 1st parent that has a non-nul 
> level is "OFF". I think that in such situation all the children that 
> don't override the level should be disabled too. The following does 
> exactly that:
>
>   597         boolean isEnabled() {
>   598             return LoggingSupport.isLoggable(javaLogger, Level.OFF.javaLevel);
>   599         }
>

That is right.  Good catch.

> That's all for 1st rev. Besides the effective level inheritance, the 
> following method in JavaLoggerProxy also caught my eye:
>
>         void doLog(Level level, String msg, Object... params) {
>             if (!isLoggable(level)) {
>                 return;
>             }
>             // only pass String objects to the j.u.l.Logger which may
>             // be created by untrusted code
>             int len = (params != null) ? params.length : 0;
>             Object[] sparams = new String[len];
>             for (int i = 0; i < len; i++) {
>                 sparams [i] = String.valueOf(params[i]);
>             }
>             LoggingSupport.log(javaLogger, level.javaLevel, msg, sparams);
>         }
>
> I think this could be improved if the 
> DefaultLoggerProxy.formatMessage() is used instead of turning each 
> parameter into a String. The method could be moved up to abstract 
> LoggerProxy and used in both implementations so that common formatting 
> is applied regardless of back-end used.
>

Let's do this in a separate clean up as it's better to keep 8010309 
focus on performance improvement (although we have mixed this bag with 
some renaming).

> The benchmarks still show stable performance:
>

Great.  Hope we will wrap up tomorrow.

thanks for the contribution.
Mandy

>
>
> Regards, Peter
>
>
> On 03/26/2013 10:37 PM, Mandy Chung wrote:
>> Hi Peter,
>>
>>> http://dl.dropbox.com/u/101777488/jdk8-tl/PlatformLogger/webrev.08/index.html
>> I'm glad that you observe similar performance improvement without the 
>> need of method handles.  I reviewed this version and realize that the 
>> map from j.u.l.Level object to LevelEnum can be removed entirely.
>>
>> sun.util.logging.PlatformLogger is an internal API that should only 
>> be used by JDK.  The static final int fields representing the level 
>> value can be changed to be static final LevelEnum type instead.  I 
>> checked the JDK code that uses PlatformLogger and no code will be 
>> impacted by the change of the type of these static fields.  So it 
>> removes the need to map from an integer value to LevelEnum.  Mapping 
>> from a j.u.l.Level to LevelEnum is trivial - the name of the 
>> LevelEnum is the same as j.u.l.Level (e.g. LevelEnum.FINEST and 
>> Level.FINEST), you can call LoggingSupport.getLevelName(javaLevel) to 
>> find its name and LevelEnum.valueOf(levelName) returns the LevelEnum 
>> instance.  However, this would require more changes - basically the 
>> methods taking "int level" as a parameter would be modified to take 
>> LevelEnum and getLevel() would return LevelEnum too.  I think it's 
>> worth doing this cleanup to get rid of the unnecessary conversion 
>> from int -> enum -> j.u.l.Level and vice versa.  I also recommend to 
>> rename LevelEnum to Level which is an inner class of PlatformLogger. 
>> What do you think of this alternative to get rid of the map?
>>
>> Some other comments of your patch:
>> - it renames the class JavaLogger to JavaLoggerProxy and the variable 
>> from logger to loggerProxy. I'm fine with that.
>> - L162: JavaLoggerProxy.init() to force load of the class which leads 
>> to separating the initialization of LevelEnum.javaLevel in a new 
>> JavaLevel class.  The JavaLevel utility methods are not needed if we 
>> change the static final fields to LevelEnum.
>>
>> Have you tried:
>> Class.forName("sun.util.logging.PlatformLogger.JavaLoggerProxy", 
>> false, PlatformLogger.getClassLoader());
>>
>> would this give you the same performance improvement?  If so, you can 
>> keep the static initialization in the JavaLoggerProxy class.
>>
>> Thanks for expanding the PlatformLoggerTest to cover additional test 
>> cases.  It's good that you compare the value of the PlatformLogger 
>> static final fields with j.u.l.Level.intValue().  You now can use the 
>> API to compare the LevelEnum with Level rather than reflection.  
>> Perhaps you can add the getName() and intValue() methods in LevelEnum 
>> class (just a thought).
>>
>> Mandy
>>
>>
>> On 3/25/13 9:31 AM, Peter Levart wrote:
>>> Well, Laurent, Mandy,
>>>
>>> It turns out that the dispatch speed-up (or lack of slow-down to be 
>>> precise) is possible without MethodHandles too. Maybe some VM guru 
>>> could shed some light on this, but the following is currently the 
>>> fastest variant:
>>>
>>> http://dl.dropbox.com/u/101777488/jdk8-tl/PlatformLogger/webrev.08/index.html
>>>
>>> What I did is a simple "if" deciding between two call-sites, making 
>>> sure that each is only dispatching to single class. This only works, 
>>> if both classes (LoggerProxy and JavaLoggerProxy) are loaded in 
>>> advance, before 1st invocation on any of them is made (might be that 
>>> using MethodHandles forced initialization of both classes beforehand 
>>> and hence the speed-up). If I don't load JavaLoggerProxy before 
>>> warming-up with LoggerProxy, then when j.u.logging is enabled, speed 
>>> drops for a factor of almost 4 and never catches up even after very 
>>> long time.
>>> This pre-loading also helps for a normal single call site dispatch 
>>> that dispatches to two distinct classes, but the speed 1st drops 
>>> when the class changes, and only catches-up after several billions 
>>> of iterations (30s tight loop on i7).
>>> Now, because JavaLoggerProxy is initialized early, I had to move the 
>>> initialization of j.u.logging.Level objects and mappings to a 
>>> separate class "JavaLevel".
>>>
>>> Here are the benchmark results for this last iteration...
>>>
>>
>