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 16:09:21 UTC 2013


You're right, loggingEnabled can change afterwards. I'll correct the 
code as suggested...

Peter

On 03/21/2013 04:57 PM, Laurent Bourgès wrote:
> Peter,
>
> I am convinced it is better if the LevelEnum belongs to JavaLogger 
> class (encapsulated so defered initialization).
>
> Here is a typical scenario:
> 1 - PlatformLogger initialized (not JUL) => LoggerProxy must work so 
> LevelEnum can not be used and the formergetLevelName() (switch case) 
> is required.
> 2 - JUL initialized: calls redirectPlatformLogger() => JavaLoggers 
> created => LevelEnum initialized (Level object can be retrieved from 
> LoggingSupport)
>
> For example, JUL can be started programmatically so the loggingEnabled 
> flag is not enough to initialize the LevelEnum.object at step 1 and it 
> will be null. Then at step 2, LevelEnum.object are null so the 
> JavaLogger is broken.
>
> Here is a test of this scenario:
> public static void main(String[] args) {
>
>     final PlatformLogger log = 
> PlatformLogger.getLogger("sun.awt.X11"); // 1: LoggerProxy
>
>     if (log.isLoggable(PlatformLogger.INFO)) {
> log.info <http://log.info>("PlatformLogger.INFO: LoggerProxy");
>     }
>
>     final Logger logger = Logger.getLogger("test");
> //   calls PlatformLogger.redirectPlatformLoggers(); // 2 : JavaLogger
>
>     if (log.isLoggable(PlatformLogger.INFO)) {
> log.info <http://log.info>("PlatformLogger.INFO: JavaLogger");
>     }
>
> logger.info <http://logger.info>("done");
> }
>
> Laurent
>
> 2013/3/21 Peter Levart <peter.levart at gmail.com 
> <mailto:peter.levart at gmail.com>>
>
>     Hi Laurent, Mandy,
>
>     Let me try one more time (it would be less optimal to have 2
>     switch statements instead of one). Here's the 3rd webrev:
>
>     http://dl.dropbox.com/u/101777488/jdk8-tl/PlatformLogger/webrev.03/index.html
>
>     The changes:
>     - added the comments
>     - made LevelEnum private (to not be tempted to be used from
>     outside the PlatformLogger)
>     - used the loggingEnabled flag as a pre-check when trying to parse
>     the level objects
>
>
>     What do you think?
>
>     Regards, Peter
>
>     On 03/21/2013 04:06 PM, Laurent Bourgès wrote:
>>     Thanks Mandy for the clarifications !
>>
>>     Peter, I propose to:
>>     - move the LevelEnum into the JavaLogger class in order to
>>     initialize it as later as possible i.e. after j.u.l calls
>>     redirectPlatformLoggers()
>>     - only use it in JavaLogger class (private enum) so revert
>>     changes to PlatformLogger and LoggerProxy classes
>>     - add few comments in the code to explain lazy initialization
>>     (see mandy's answer)
>>
>>     Finally, could you keep my comment before the switch case (high
>>     occurences first) ?
>>     +        static LevelEnum forValue(int levelValue) {
>>
>>     +            // higher occurences first (finest, fine, finer, info)
>>     +            // based on isLoggable(level) calls (03/20/2013)
>>     +            // in jdk project only (including generated sources)
>>
>>     +            switch (levelValue) {
>>     +                case PlatformLogger.FINEST:  return FINEST;  // 116 + 2257 matches in generated files
>>     +                case PlatformLogger.FINE:    return FINE;    // 270
>>
>>     +                case PlatformLogger.FINER:   return FINER;   // 157
>>     +                case PlatformLogger.INFO:    return INFO;    // 39
>>     +                case PlatformLogger.WARNING: return WARNING; // 12
>>
>>     +                case PlatformLogger.CONFIG:  return CONFIG;  // 6
>>     +                case PlatformLogger.SEVERE:  return SEVERE;  // 1
>>     +                case PlatformLogger.OFF:     return OFF;     // 0
>>
>>     +                case PlatformLogger.ALL:     return ALL;     // 0
>>     +                default:                     return UNKNOWN;
>>     +            }
>>
>>     +        }
>>
>>     cheers,
>>     Laurent
>>
>>     2013/3/21 Mandy Chung <mandy.chung at oracle.com
>>     <mailto:mandy.chung at oracle.com>>
>>
>>         Laurent, Peter,
>>
>>         I haven't looked at the patch yet.  One thing worths
>>         mentioning is that PlatformLogger was added for the platform
>>         code to use so as to avoid the initialization of
>>         java.util.logging since logging is not turned on by default
>>         and that to reduce the startup overhead.   In addition, it
>>         also enables the elimination of the core classes dependency
>>         from java.util.logging for modularization effort.  Therefore
>>         the PlatformLogger only lazily looks up the Level object when
>>         java.util.logging is present and also has been initialized by
>>         application code.
>>
>>         Mandy
>>
>>
>>         On 3/21/2013 7:45 AM, Peter Levart wrote:
>>>         On 03/21/2013 03:30 PM, Laurent Bourgès wrote:
>>>>         Peter,
>>>>
>>>>         your solution looks better; I wanted my patch to be simple,
>>>>         efficient and only modify the JavaLogger class (localized
>>>>         changes).
>>>>
>>>>         In your patch, I have doubts related to lazy and
>>>>         conditional initialization in JavaLogger (static
>>>>         initialization):
>>>>         if (LoggingSupport.isAvailable()) {
>>>>              // initialize ...
>>>>         }
>>>
>>>         In original code, if LoggingSupport.isAvailable() returned
>>>         false, levelObjects map remained empty and consequently null
>>>         was used as the level object passed to LoggingSupport
>>>         methods. In LevelEnum I try to keep this logic. When
>>>         LevelEnum is first used, it's constants are initialized and
>>>         level objects with them. If
>>>         LoggingSupport.isAvailable() returns false, level objects
>>>         are initialized to null.
>>>
>>>         I just noticed there's a bug in initialization of the
>>>         LevelEnum.UNKNOWN member constant. It should not try to
>>>         parse level object. Here's an update:
>>>
>>>         http://dl.dropbox.com/u/101777488/jdk8-tl/PlatformLogger/webrev.02/index.html
>>>
>>>         But your concern might be correct. In my code LevelEnum is
>>>         also used from the LoggerProxy.format() method (in addition
>>>         to all the places in JavaLogger) to obtain the level name
>>>         for formatting. If this method is called the first time
>>>         while LoggingSupport.isAvailable() returns false and that
>>>         happens before JavaLogger uses LevelEnum for the first time
>>>         (and at that time LoggingSupport.isAvailable() would return
>>>         true), then level objects will not be initialized correctly.
>>>
>>>         Lazy initialization of level objects might help (for the
>>>         price of added complexity)...
>>>
>>>         Regards, Peter
>>>
>>>>         Does somebody have the knowledge about LoggingSupport.isAvailable()
>>>>
>>>>         and the lazy PlatformLogger initialization (JavaLogger are only used when j.u.l is initialized) ?
>>>>
>>>>
>>>>         What's happening if LoggingSupport.isAvailable() returns false in your patch ?
>>>>         - LevelEnum  instances are incorrectly initialized:object field is null !
>>>>
>>>>         - PlatformLogger is then broken ... as Level object are required by j.u.l calls
>>>>
>>>>
>>>>         To fix both problems, moving theLevelEnum  into JavaLogger should help and check nulls onLevelEnum.object field.
>>>>
>>>>
>>>>         Thanks for your feedback,
>>>>         Laurent
>>>>
>>>>
>>>>         2013/3/21 Peter Levart <peter.levart at gmail.com
>>>>         <mailto:peter.levart at gmail.com>>
>>>>
>>>>             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/
>>>>                 <http://jmmc.fr/%7Ebourgesl/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
>>>>                 <mailto: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
>>>>                     <mailto: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