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:57:28 UTC 2013
Hi Laurent, Mandy,
I think I've got it now. It's a middle-ground. It would be a shame to
loose the code-reuse (one switch instead of two). So I only moved the
levelObjects to JavaLogger, not the entire LevelEnum:
http://dl.dropbox.com/u/101777488/jdk8-tl/PlatformLogger/webrev.04/index.html
So this is basically similar to original code. It just uses LevelEnum
instead of java.lang.Integer and EnumMap instead of HashMap. Hopefully
these perform better. If I moved the LevelEnum into the JavaLogger, I
would have to re-instate the second switch for LoggerProxy and the
solution would not be much simpler than your patch, Laurent. This is
still just 20 LOC more than original code.
Regards, Peter
On 03/21/2013 05:09 PM, Peter Levart wrote:
> 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