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:09:21 UTC 2013
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