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

[Mandy Chung]

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) {