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

Peter Levart peter.levart at gmail.com
Thu Mar 21 13:59:37 UTC 2013


On 03/21/2013 12:12 PM, Laurent Bourgès wrote:
> Here is an improved patch tested on JDK7u13 and JDK8 internal build on my
> machine linux x64:
> http://jmmc.fr/~bourgesl/share/webrev-8010309/
>
> FYI, I removed completely the Map<Integer, Object> levelObjects and used
> two arrays to perform the PlatformLogger's level (int) to j.u.l.Level
> mapping:
>
> I decided to keep it simple as possible (no enum ...) and used a switch
> case based on current level occurences:

Hi Laurent,

In my experience enums are just the right and most compact tool for 
coding such constant associations. Here's a quick try (ripping off your 
optimized switch ;-):

http://dl.dropbox.com/u/101777488/jdk8-tl/PlatformLogger/webrev.01/index.html

...it adds 12 LOC to the original PlatformLogger and is 43 LOC less tha 
your patch. In addition:

- only one switch instead of two (to maintain)
- no parallel IDX_ constants

What do you think?

Regards, Peter

>
>   510         /**
>   511          * Return the corresponding j.u.l.Level instance
>   512          * @param level PlatformLogger level as integer
>   513          * @return Object (j.u.l.Level instance) or null if no
> matching level
>   514          */
>   515         private static Object getLevel(final int level) {
>   516             if (levelObjects == null) {
>   517                 return null;
>   518             }
>   519             // higher occurences first (finest, fine, finer, info)
>   520             // based on isLoggable(level) calls (03/20/2013)
>   521             // in jdk project only (including generated sources)
>   522             switch (level) {
>   523                 case FINEST  : return levelObjects[IDX_FINEST];
> // 116 + 2257 matches in generated files
>   524                 case FINE    : return levelObjects[IDX_FINE];    // 270
>   525                 case FINER   : return levelObjects[IDX_FINER];   // 157
>   526                 case INFO    : return levelObjects[IDX_INFO];    // 39
>   527                 case WARNING : return levelObjects[IDX_WARNING]; // 12
>   528                 case CONFIG  : return levelObjects[IDX_CONFIG];  // 6
>   529                 case SEVERE  : return levelObjects[IDX_SEVERE];  // 1
>   530                 case OFF     : return levelObjects[IDX_OFF];     // 0
>   531                 case ALL     : return levelObjects[IDX_ALL];     // 0
>   532                 default      : return null;
>   533             }
>   534         }
>
> I enhanced the PlatformLoggerTest class also and figured out that TLAB
> optimized Integer allocations but I think the patch is still useful.
>
> Can you have a look to the patch ?
> Should I write a jtreg test  (performance / GC issue) ?
>
> Cheers,
> Laurent
>
>
> 2013/3/20 Mandy Chung <mandy.chung at oracle.com>
>
>>   Hi Laurent,
>>
>> Thank you for signing the OCA.  Your contribution is very welcome.  You
>> can submit a patch for this bug (see [1]) to Core libraries group which
>> owns logging.  Jim Gish and I will sponsor it.
>>
>> Thanks
>> Mandy
>> [1] http://openjdk.java.net/contribute/
>>
>>
>> On 3/20/2013 5:45 AM, Laurent Bourgès wrote:
>>
>> Hi mandy,
>>
>> Do you want me to propose an improved patch to remove the former Map and
>> fix the getLevel() method ? or you prefer fix on your own ?
>>
>> Is it better to discuss the fix on the bug database (still not visible) ?
>>
>> Laurent
>>
>> 2013/3/19 Mandy Chung <mandy.chung at oracle.com>
>>
>>>   Hi Laurent,
>>>
>>> Thanks for the contribution.  I agree that the map can be replaced with a
>>> direct mapping from a int value to Level object and avoid the autoboxing
>>> conversion.
>>>
>>> I have filed a bug to track this and target this for JDK8:
>>>    http://bugs.sun.com/bugdatabase/view_bug.do?bug_id= 8010309
>>>
>>> Thanks
>>> Mandy
>>>
>>>
>>> On 3/19/13 5:19 AM, Laurent Bourgès wrote:
>>>
>>> Dear all,
>>>
>>> I run recently netbeans profiler on my swing application (Aspro2:http://www.jmmc.fr/aspro
>>> ) under linux x64 platform and figured out a
>>> performance and waste issue related to PlatformLogger.
>>>
>>> Actually, the JavaLogger implementation uses a Map<Integer, Object>
>>> levelObjects to store mapping between PlatformLogger's levels (int) and JUL
>>> Level instances.
>>>
>>> However, the isLoggable(int level) method is highly used by awt project and
>>> other JDK projects and it leads to many Integer allocations as autoboxing
>>> converts the level as int to an Integer instance used by the Map.get() call.
>>>
>>>      /**
>>>       * JavaLogger forwards all the calls to its corresponding
>>>       * java.util.logging.Logger object.
>>>       */
>>>      static class JavaLogger extends LoggerProxy {
>>>          private static final* Map<Integer, Object>* levelObjects = new
>>> HashMap<>();
>>> ...
>>>          public boolean isLoggable(*int level*) {
>>>              return LoggingSupport.isLoggable(javaLogger, *
>>> levelObjects.get(level)*);
>>>          }
>>>      }
>>>
>>> I wrote a simple test to illustrate that performance / waste problem:
>>> PlatformLoggerTest that simply performs 1 million DISABLED log statements:
>>>              if (log.isLoggable(PlatformLogger.FINEST)) {
>>>                  log.finest("test PlatformLogger.FINEST");
>>>              }
>>>
>>> As you can see in screenshots:
>>> - 5 million Integer instances are allocated
>>> - Integer.valueOf(int) is called 5 million times (autoboxing)
>>> - HashMap.get() represents 30% of the test time
>>> - patched PlatformLogger is 3x times faster
>>> [jvm options: -Xms8m -Xmx8m -verbose:gc]
>>>
>>> I suggest you to use an alternative way to map PlatformLogger's levels
>>> (int) and JUL Level instances to fix that performance / memory issue: I
>>> added the getLevel(int level) method that performs a switch case to return
>>> the corresponding Level object (quick and dirty solution).
>>>
>>> I advocate this is not a very clean solution but I prefer efficiency here:
>>> any better solution may be appropriate to avoid at least Integer allocation
>>> and maybe enhance performance.
>>>
>>> Best regards,
>>> Laurent Bourgès
>>>
>>> PS: here is the patch as text:
>>>
>>> # This patch file was generated by NetBeans IDE
>>> # It uses platform neutral UTF-8 encoding and \n newlines.
>>> --- PlatformLogger.java (6767)
>>> +++ PlatformLogger.java (6768)
>>> @@ -468,31 +468,13 @@
>>>        * java.util.logging.Logger object.
>>>        */
>>>       static class JavaLogger extends LoggerProxy {
>>> -        /** Note: using Integer keys leads to a lot of new Integer
>>> instances !! */
>>> -        private static final Map<Integer, Object> levelObjects = new
>>> HashMap<>();
>>> -        /** fastest mapping to Level instances from PlatformLogger level
>>> as integer */
>>> -        private static final Object[] fastLevelObjects;
>>> -
>>> -
>>> +        private static final Map<Integer, Object> levelObjects =
>>> +            new HashMap<>();
>>> +
>>>           static {
>>>               if (LoggingSupport.isAvailable()) {
>>>                   // initialize the map to Level objects
>>>                   getLevelObjects();
>>> -
>>> -                // initialize the fastLevelObjects:
>>> -                fastLevelObjects = new Object[] {
>>> -                    LoggingSupport.parseLevel(getLevelName(OFF)),       //
>>> 0
>>> -                    LoggingSupport.parseLevel(getLevelName(SEVERE)),    //
>>> 1
>>> -                    LoggingSupport.parseLevel(getLevelName(WARNING)),   //
>>> 2
>>> -                    LoggingSupport.parseLevel(getLevelName(INFO)),      //
>>> 3
>>> -                    LoggingSupport.parseLevel(getLevelName(CONFIG)),    //
>>> 4
>>> -                    LoggingSupport.parseLevel(getLevelName(FINE)),      //
>>> 5
>>> -                    LoggingSupport.parseLevel(getLevelName(FINER)),     //
>>> 6
>>> -                    LoggingSupport.parseLevel(getLevelName(FINEST)),    //
>>> 7
>>> -                    LoggingSupport.parseLevel(getLevelName(ALL))        //
>>> 8
>>> -                };
>>> -            } else {
>>> -                fastLevelObjects = null; // check null
>>>               }
>>>           }
>>>
>>> @@ -515,7 +497,7 @@
>>>               this.javaLogger = LoggingSupport.getLogger(name);
>>>               if (level != 0) {
>>>                   // level has been updated and so set the Logger's level
>>> -                LoggingSupport.setLevel(javaLogger, getLevel(level));
>>> +                LoggingSupport.setLevel(javaLogger,
>>> levelObjects.get(level));
>>>               }
>>>           }
>>>
>>> @@ -526,11 +508,11 @@
>>>           * not be updated.
>>>           */
>>>           void doLog(int level, String msg) {
>>> -            LoggingSupport.log(javaLogger, getLevel(level), msg);
>>> +            LoggingSupport.log(javaLogger, levelObjects.get(level), msg);
>>>           }
>>>
>>>           void doLog(int level, String msg, Throwable t) {
>>> -            LoggingSupport.log(javaLogger, getLevel(level), msg, t);
>>> +            LoggingSupport.log(javaLogger, levelObjects.get(level), msg,
>>> t);
>>>           }
>>>
>>>           void doLog(int level, String msg, Object... params) {
>>> @@ -544,12 +526,12 @@
>>>               for (int i = 0; i < len; i++) {
>>>                   sparams [i] = String.valueOf(params[i]);
>>>               }
>>> -            LoggingSupport.log(javaLogger, getLevel(level), msg, sparams);
>>> +            LoggingSupport.log(javaLogger, levelObjects.get(level), msg,
>>> sparams);
>>>           }
>>>
>>>           boolean isEnabled() {
>>>               Object level = LoggingSupport.getLevel(javaLogger);
>>> -            return level == null || level.equals(getLevel(OFF)) == false;
>>> +            return level == null || level.equals(levelObjects.get(OFF)) ==
>>> false;
>>>           }
>>>
>>>           int getLevel() {
>>> @@ -566,34 +548,12 @@
>>>
>>>           void setLevel(int newLevel) {
>>>               levelValue = newLevel;
>>> -            LoggingSupport.setLevel(javaLogger, getLevel(newLevel));
>>> +            LoggingSupport.setLevel(javaLogger,
>>> levelObjects.get(newLevel));
>>>           }
>>>
>>>           public boolean isLoggable(int level) {
>>> -            return LoggingSupport.isLoggable(javaLogger, getLevel(level));
>>> +            return LoggingSupport.isLoggable(javaLogger,
>>> levelObjects.get(level));
>>>           }
>>> -
>>> -        /**
>>> -         * Return the corresponding level object (fastest implementation)
>>> -         * @param level PlatformLogger level as primitive integer
>>> -         * @return Object (JUL Level instance)
>>> -         */
>>> -        private static Object getLevel(final int level) {
>>> -            // higher occurences first (finest, fine, finer, info):
>>> -            switch (level) {
>>> -                case FINEST  : return fastLevelObjects[7];
>>> -                case FINE    : return fastLevelObjects[5];
>>> -                case FINER   : return fastLevelObjects[6];
>>> -                case INFO    : return fastLevelObjects[3];
>>> -                case CONFIG  : return fastLevelObjects[4];
>>> -                case WARNING : return fastLevelObjects[2];
>>> -                case SEVERE  : return fastLevelObjects[1];
>>> -                case ALL     : return fastLevelObjects[8];
>>> -                case OFF     : return fastLevelObjects[0];
>>> -                default      : return null;
>>> -            }
>>> -        }
>>> -
>>>       }
>>>
>>>       private static String getLevelName(int level) {
>>>
>>>
>>>
>>




More information about the core-libs-dev mailing list