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

[Laurent Bourgès]

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