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

[Laurent Bourgès]

Sorry for my previous comment: JavaLoggerProxy static initialization is not
called (false argument);

I made the test:
JavaLoggerProxy: static initialization...
LoggingSupport.isAvailable: true
java.lang.Throwable
    at
sun.util.logging.PlatformLogger$JavaLoggerProxy.<clinit>(PlatformLogger.java:562)
    at
sun.util.logging.PlatformLogger.redirectToJavaLoggerProxy(PlatformLogger.java:200)
    at
sun.util.logging.PlatformLogger.redirectPlatformLoggers(PlatformLogger.java:190)
    at java.util.logging.LogManager$2.run(LogManager.java:290)
    at java.util.logging.LogManager$2.run(LogManager.java:285)
    at java.security.AccessController.doPrivileged(Native Method)
    at
java.util.logging.LogManager.readPrimordialConfiguration(LogManager.java:285)
    at java.util.logging.LogManager.getLogManager(LogManager.java:267)
    at java.util.logging.Logger.<init>(Logger.java:280)
    at java.util.logging.LogManager$RootLogger.<init>(LogManager.java:1372)
    at java.util.logging.LogManager$RootLogger.<init>(LogManager.java:1370)
    at java.util.logging.LogManager$1.run(LogManager.java:198)
    at java.security.AccessController.doPrivileged(Native Method)
    at java.util.logging.LogManager.<clinit>(LogManager.java:175)
    at test.PlatformLoggerBenchmark.main(PlatformLoggerBenchmark.java:39)

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

        // force loading of all JavaLoggerProxy (sub)classes to make JIT
de-optimizations
        // less probable.  Don't initialize JavaLoggerProxy class since
        // java.util.logging may not be enabled.
        try {

Class.forName("sun.util.logging.PlatformLogger$DefaultLoggerProxy",
                          initialize,
                          PlatformLogger.class.getClassLoader());
            Class.forName("sun.util.logging.PlatformLogger$JavaLoggerProxy",
                          initialize,
                          PlatformLogger.class.getClassLoader());
        } catch (ClassNotFoundException ex) {
            throw new InternalError(ex);
        }

Laurent


2013/3/28 Laurent Bourgès <bourges.laurent at gmail.com>

> Dear Mandy & Peter,
>
> I will test your patch asap (+ benchmark)
>
> Few comments 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.
>>
>
> I think it leads to early initialization of JUL Levels (when JUL is maybe
> not available or initialized) from PlatformLogger static initialization:
>
>         // initialize javaLevel fields for mapping from Level enum ->
> j.u.l.Level object
>         static {
>             for (Level level : Level.values()) {
>                 level.javaLevel = LoggingSupport.parseLevel(level.name());
>             }
>         }
>
> I thought Level.javaLevel should only be defined ONCE JUL is available
> i.e. once PlatformLogger.redirectPlatformLoggers() is called.
> I propose to move the javaLevel initialization in this method:
>
>     public static synchronized void redirectPlatformLoggers() {
>         if (loggingEnabled || !LoggingSupport.isAvailable()) return;
>
>             // Resolve JUL Levels ONLY when JUL is initialized by
> application code:
>             for (Level level : Level.values()) {
>                 level.javaLevel = LoggingSupport.parseLevel(level.name());
>             }
>
> ...
> }
>
>
>
>>
>> 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.
>>
>
> Good idea.
>
>
>>
>> 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.
>>
>
> If getLevel() is useless, why keep it in this proprietary API ? (only for
> test purposes) ?
>
>
>>
>>
>>  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).
>>
>
> I disagree Peter: JUL has its own formatting code: patterns ... and more
> efficient than DefaultLoggerProxy.formatMessage().
>
> The good question relies in the comment: why convert object args into
> String early as JUL can do formatting / conversion?
> What does mean:
>             // only pass String objects to the j.u.l.Logger which may
>             // be created by untrusted code
> ?
> to avoid security issues ?
>
> Laurent
>
>