8010309 : PlatformLogger: isLoggable performance / waste due to HashMap<Integer, Level> leads to Integer allocations (boxing)
Laurent Bourgès
bourges.laurent at gmail.com
Thu Mar 21 15:06:08 UTC 2013
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>
> 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 the LevelEnum into JavaLogger should help and check nulls on LevelEnum.object field.
>
> Thanks for your feedback,Laurent
>
> 2013/3/21 Peter Levart <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/
>>>
>>> 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