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 15:31:17 UTC 2013
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