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

[Mandy Chung]

Hi Peter, Laurent,

Thanks for the performance run.  I'll push the changeset once I check 
the test result.

On 3/28/2013 2:52 AM, Peter Levart wrote:
>
> ...just a nit! In the test:
>
>     private static void checkPlatformLoggerLevelMapping(Level level) {
>         // map the given level to PlatformLogger.Level of the same 
> name and value
>         PlatformLogger.Level platformLevel = 
> PlatformLogger.Level.valueOf(level.getName());
>         if (platformLevel == null || platformLevel.intValue() != 
> level.intValue()) {
>             throw new RuntimeException("Mismatched level: " + level
>                     + " PlatformLogger.Level" + platformLevel);
>         }
>
> The Level.valueOf(String) is guaranteed to not return null.

That's right.  Will fix it.

Laurent Bourges wrote:
> Maybe you should introduce an explicit variable to make it more obvious:
>         boolean initialize = false; // lazy initialization

I'll check the comments and see how I can make it clearer.  I think it 
is.   I don't think the variable helps (perhaps add a comment next to 
'false').

>
> Do you plan to apply the fix on JDK7 updates ?

I don't have any issue backporting this to jdk7u.  I'll get back to you 
on this one how to coordinate on this once this is baked in jdk8 repo first.

Thanks
Mandy

>
>
>
>
> Regards, Peter
>
>>
>> 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...
>>>>>
>>>>
>>>
>>
>