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 13:59:37 UTC 2013
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