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:57:33 UTC 2013
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 former getLevelName() (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("PlatformLogger.INFO: LoggerProxy");
}
final Logger logger = Logger.getLogger("test");
// calls PlatformLogger.redirectPlatformLoggers(); // 2 : JavaLogger
if (log.isLoggable(PlatformLogger.INFO)) {
log.info("PlatformLogger.INFO: JavaLogger");
}
logger.info("done");
}
Laurent
2013/3/21 Peter Levart <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>
>
>> 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