8010309 : PlatformLogger: isLoggable performance / waste due to HashMap<Integer, Level> leads to Integer allocations (boxing)
Peter Levart
peter.levart at gmail.com
Thu Mar 28 09:52:54 UTC 2013
On 03/28/2013 04:02 AM, Mandy Chung wrote:
> Hi Peter,
>
> It looks better. I want to wrap up this patch and push the changeset
> tomorrow. I have made slight modification and clean up some comments
> and the test. See my comments inlined below.
>
> Webrev at:
> http://cr.openjdk.java.net/~mchung/jdk8/webrevs/8010309/webrev.00/
>
> Please let me know if you don't agree with these changes or you find
> any performance issue.
Hi Mandy,
Your changes make sense. The performance impact (using 2 volatile fields
instead of 3) is negligable. It is actually a little faster on i7 CPU
and a little slower on T2-sparc, but only affects the speed of
DefaultLoggerProxy code-path (see my previous mail for comparison):
##############################################################
# Java: 1.8.0-internal-peter_2013_01_16_13_44-b00
# VM: OpenJDK 64-Bit Server VM 25.0-b14 (mixed mode)
# OS: Linux 3.7.9-104.fc17.x86_64 (amd64)
# CPUs: 8 (virtual)
#
#-------------------------------------------------------------
# isLoggableFinest: run duration: 3,000 ms
#
# Warm up:
# 1 threads, Tavg = 1.42 ns/op (? = 0.00 ns/op) [ 1.42]
# 1 threads, Tavg = 1.42 ns/op (? = 0.00 ns/op) [ 1.42]
# Measure:
1 threads, Tavg = 1.47 ns/op (? = 0.00 ns/op) [
1.47]
2 threads, Tavg = 1.46 ns/op (? = 0.01 ns/op) [
1.48, 1.45]
3 threads, Tavg = 1.46 ns/op (? = 0.01 ns/op) [
1.47, 1.45, 1.45]
4 threads, Tavg = 1.47 ns/op (? = 0.01 ns/op) [
1.48, 1.46, 1.48, 1.45]
#
#-------------------------------------------------------------
# java.util.logging enabled
#
#
#-------------------------------------------------------------
# isLoggableFinest: run duration: 3,000 ms
#
# Measure:
1 threads, Tavg = 1.74 ns/op (? = 0.00 ns/op) [
1.74]
2 threads, Tavg = 1.59 ns/op (? = 0.01 ns/op) [
1.60, 1.58]
3 threads, Tavg = 1.59 ns/op (? = 0.01 ns/op) [
1.59, 1.58, 1.58]
4 threads, Tavg = 1.61 ns/op (? = 0.01 ns/op) [
1.62, 1.60, 1.60, 1.61]
1 threads, Tavg = 1.59 ns/op (? = 0.00 ns/op) [
1.59]
2 threads, Tavg = 1.59 ns/op (? = 0.01 ns/op) [
1.59, 1.58]
3 threads, Tavg = 1.59 ns/op (? = 0.00 ns/op) [
1.59, 1.59, 1.59]
4 threads, Tavg = 1.64 ns/op (? = 0.02 ns/op) [
1.64, 1.64, 1.62, 1.67]
1 threads, Tavg = 1.59 ns/op (? = 0.00 ns/op) [
1.59]
2 threads, Tavg = 1.59 ns/op (? = 0.01 ns/op) [
1.60, 1.58]
3 threads, Tavg = 1.69 ns/op (? = 0.15 ns/op) [
1.59, 1.91, 1.60]
4 threads, Tavg = 1.59 ns/op (? = 0.01 ns/op) [
1.60, 1.59, 1.59, 1.59]
#
#-------------------------------------------------------------
# END.
##############################################################
##############################################################
# Java: 1.8.0-ea-b82
# VM: Java HotSpot(TM) 64-Bit Server VM 25.0-b23 (mixed mode)
# OS: SunOS 5.10 (sparcv9)
# CPUs: 64 (virtual)
#
#-------------------------------------------------------------
# isLoggableFinest: run duration: 3,000 ms
#
# Warm up:
# 1 threads, Tavg = 45.97 ns/op (? = 0.00 ns/op) [ 45.97]
# 1 threads, Tavg = 42.99 ns/op (? = 0.00 ns/op) [ 42.99]
# Measure:
1 threads, Tavg = 43.10 ns/op (? = 0.00 ns/op) [
43.10]
2 threads, Tavg = 43.06 ns/op (? = 0.03 ns/op) [
43.03, 43.08]
3 threads, Tavg = 43.13 ns/op (? = 0.23 ns/op) [
43.46, 42.99, 42.95]
4 threads, Tavg = 43.19 ns/op (? = 0.14 ns/op) [
42.97, 43.19, 43.36, 43.25]
#
#-------------------------------------------------------------
# java.util.logging enabled
#
#
#-------------------------------------------------------------
# isLoggableFinest: run duration: 3,000 ms
#
# Measure:
1 threads, Tavg = 102.15 ns/op (? = 0.00 ns/op) [
102.15]
2 threads, Tavg = 100.78 ns/op (? = 0.13 ns/op) [
100.65, 100.90]
3 threads, Tavg = 49.12 ns/op (? = 0.11 ns/op) [
48.97, 49.20, 49.18]
4 threads, Tavg = 49.20 ns/op (? = 0.09 ns/op) [
49.09, 49.31, 49.13, 49.27]
1 threads, Tavg = 49.16 ns/op (? = 0.00 ns/op) [
49.16]
2 threads, Tavg = 48.98 ns/op (? = 0.03 ns/op) [
48.95, 49.01]
3 threads, Tavg = 49.04 ns/op (? = 0.09 ns/op) [
48.94, 49.15, 49.04]
4 threads, Tavg = 49.08 ns/op (? = 0.12 ns/op) [
48.93, 49.11, 49.02, 49.26]
1 threads, Tavg = 49.06 ns/op (? = 0.00 ns/op) [
49.06]
2 threads, Tavg = 49.26 ns/op (? = 0.32 ns/op) [
48.94, 49.59]
3 threads, Tavg = 49.01 ns/op (? = 0.06 ns/op) [
49.09, 48.95, 49.00]
4 threads, Tavg = 49.66 ns/op (? = 0.34 ns/op) [
49.90, 49.70, 49.10, 49.96]
#
#-------------------------------------------------------------
# END.
##############################################################
...just a nit! In the test:
private static void checkPlatformLoggerLevelMapping(Level level) {
// map the given level to PlatformLogger.Level of the same name
and value
PlatformLogger.Level platformLevel =
PlatformLogger.Level.valueOf(level.getName());
if (platformLevel == null || platformLevel.intValue() !=
level.intValue()) {
throw new RuntimeException("Mismatched level: " + level
+ " PlatformLogger.Level" + platformLevel);
}
The Level.valueOf(String) is guaranteed to not return null.
Regards, Peter
>
> I have retained the part in webrev.08 that only defines loggerProxy
> and javaLoggerProxy. I don't think the new defaultLoggerProxy
> variable is needed. I prefer to use Class.forName to force load
> JavaLoggerProxy class to make very explicit that we don't want the
> class be initialized. JavaLoggerProxy.<clinit> calls
> LoggingProxy.parseLevel unconditionally that will throw an
> AssertionError if java.util.logging is not available. If
> JavaLoggerProxy class is initialized, j.u.logging should be present
> and I want to catch error if otherwise. Also Class.forName will load
> its superclass LoggerProxy.
>
> As for the PlatformLogger.Level enums, having the members to be
> defined in ascending order is fragile. It'd be more reliable to
> specify the value in the constructor so that it can be used as the
> isLoggable comparsion in the same way as in the Level implementation.
>
> I am running the jdk core regression tests on all platforms and should
> have the result by tomorrow.
>
> On 3/27/2013 9:44 AM, Peter Levart wrote:
>> Hi Mandy, Laurent,
>>
>> It turns out that the API change (change of type for level parameter
>> int -> enum Level) is entirely source-compatible. The tip of JDK8 (tl
>> repo) builds without a problem. So no-one is currently using
>> PlatformLogger.getLevel() method and assigning it to a variable or
>> such...
>>
>
> Great thanks. That is what I expect too.
>
>> Here's the webrev for this change:
>>
>> http://dl.dropbox.com/u/101777488/jdk8-tl/PlatformLogger/webrev.enumapi.01/index.html
>>
>> Besides doing the replacement of type and renaming and removing of
>> the unneeded stuff, I also did some re-arrangements:
>>
>> - introduced a common abstract superclass for both types of
>> LoggerProxys (DefaultLoggerProxy, JavaLoggerProxy), since
>> JavaLoggerProxy does not need the fields of DefaultLoggerProxy and
>> now both concrete subclasses can be declared final (makes JIT even
>> more happy). Also the abstract LoggerProxy could host some common
>> logic (see below about formatting)...
>
> That's a good idea.
>
>> - DefaultLoggerProxy's levelValue/effectiveLevel were given names
>> just the opposite of their meaning. I aligned them with terminology
>> used in j.u.l.Logger and renamed levelValue to plain level.
>
> Swapping these 2 variables makes sense.
>
>> - introduced private method
>> DefaultLoggerProxy.deriveEffectiveLevel(level) that currently just
>> returns defaultLevel (INFO) when given null.
>
> Ok.
>
>> I think with a little more effort, it could be possible to emulate
>> the behaviour of j.u.l.Logger which inherits from 1st parent logger
>> that has non-null level assigned. Of course with all the caching and
>> invalidation...
>
> The only way to change the level to a non-default one is via the
> logging configuration and enable logging. That's why there is no need
> for DefaultLoggerProxy to inherit level from its parent logger. Also
> there is no parent logger hierarchy maintained in DefaultLoggerProxy.
>
>> - instead of static final DefaultLoggerProxy.defaultStream I created
>> a private static method outputStream() that returns System.err. To
>> accomodate for the situation when System.err is changed dynamically.
>
> Ok.
>
>> - fixed the JavaLoggerProxy.isEnabled() method. Original code was:
>>
>> 532 boolean isEnabled() {
>> 533 Object level = LoggingSupport.getLevel(javaLogger);
>> 534 return level == null || level.equals(levelObjects.get(OFF)) == false;
>> 535 }
>>
>> If 'level' is null then it can be that 1st parent that has a non-nul
>> level is "OFF". I think that in such situation all the children that
>> don't override the level should be disabled too. The following does
>> exactly that:
>>
>> 597 boolean isEnabled() {
>> 598 return LoggingSupport.isLoggable(javaLogger, Level.OFF.javaLevel);
>> 599 }
>>
>
> That is right. Good catch.
>
>> That's all for 1st rev. Besides the effective level inheritance, the
>> following method in JavaLoggerProxy also caught my eye:
>>
>> void doLog(Level level, String msg, Object... params) {
>> if (!isLoggable(level)) {
>> return;
>> }
>> // only pass String objects to the j.u.l.Logger which may
>> // be created by untrusted code
>> int len = (params != null) ? params.length : 0;
>> Object[] sparams = new String[len];
>> for (int i = 0; i < len; i++) {
>> sparams [i] = String.valueOf(params[i]);
>> }
>> LoggingSupport.log(javaLogger, level.javaLevel, msg,
>> sparams);
>> }
>>
>> I think this could be improved if the
>> DefaultLoggerProxy.formatMessage() is used instead of turning each
>> parameter into a String. The method could be moved up to abstract
>> LoggerProxy and used in both implementations so that common
>> formatting is applied regardless of back-end used.
>>
>
> Let's do this in a separate clean up as it's better to keep 8010309
> focus on performance improvement (although we have mixed this bag with
> some renaming).
>
>> The benchmarks still show stable performance:
>>
>
> Great. Hope we will wrap up tomorrow.
>
> thanks for the contribution.
> Mandy
>
>>
>>
>> Regards, Peter
>>
>>
>> On 03/26/2013 10:37 PM, Mandy Chung wrote:
>>> Hi Peter,
>>>
>>>> http://dl.dropbox.com/u/101777488/jdk8-tl/PlatformLogger/webrev.08/index.html
>>> I'm glad that you observe similar performance improvement without
>>> the need of method handles. I reviewed this version and realize
>>> that the map from j.u.l.Level object to LevelEnum can be removed
>>> entirely.
>>>
>>> sun.util.logging.PlatformLogger is an internal API that should only
>>> be used by JDK. The static final int fields representing the level
>>> value can be changed to be static final LevelEnum type instead. I
>>> checked the JDK code that uses PlatformLogger and no code will be
>>> impacted by the change of the type of these static fields. So it
>>> removes the need to map from an integer value to LevelEnum. Mapping
>>> from a j.u.l.Level to LevelEnum is trivial - the name of the
>>> LevelEnum is the same as j.u.l.Level (e.g. LevelEnum.FINEST and
>>> Level.FINEST), you can call LoggingSupport.getLevelName(javaLevel)
>>> to find its name and LevelEnum.valueOf(levelName) returns the
>>> LevelEnum instance. However, this would require more changes -
>>> basically the methods taking "int level" as a parameter would be
>>> modified to take LevelEnum and getLevel() would return LevelEnum
>>> too. I think it's worth doing this cleanup to get rid of the
>>> unnecessary conversion from int -> enum -> j.u.l.Level and vice
>>> versa. I also recommend to rename LevelEnum to Level which is an
>>> inner class of PlatformLogger. What do you think of this
>>> alternative to get rid of the map?
>>>
>>> Some other comments of your patch:
>>> - it renames the class JavaLogger to JavaLoggerProxy and the
>>> variable from logger to loggerProxy. I'm fine with that.
>>> - L162: JavaLoggerProxy.init() to force load of the class which
>>> leads to separating the initialization of LevelEnum.javaLevel in a
>>> new JavaLevel class. The JavaLevel utility methods are not needed
>>> if we change the static final fields to LevelEnum.
>>>
>>> Have you tried:
>>> Class.forName("sun.util.logging.PlatformLogger.JavaLoggerProxy",
>>> false, PlatformLogger.getClassLoader());
>>>
>>> would this give you the same performance improvement? If so, you
>>> can keep the static initialization in the JavaLoggerProxy class.
>>>
>>> Thanks for expanding the PlatformLoggerTest to cover additional test
>>> cases. It's good that you compare the value of the PlatformLogger
>>> static final fields with j.u.l.Level.intValue(). You now can use
>>> the API to compare the LevelEnum with Level rather than reflection.
>>> Perhaps you can add the getName() and intValue() methods in
>>> LevelEnum class (just a thought).
>>>
>>> Mandy
>>>
>>>
>>> On 3/25/13 9:31 AM, Peter Levart wrote:
>>>> Well, Laurent, Mandy,
>>>>
>>>> It turns out that the dispatch speed-up (or lack of slow-down to be
>>>> precise) is possible without MethodHandles too. Maybe some VM guru
>>>> could shed some light on this, but the following is currently the
>>>> fastest variant:
>>>>
>>>> http://dl.dropbox.com/u/101777488/jdk8-tl/PlatformLogger/webrev.08/index.html
>>>>
>>>> What I did is a simple "if" deciding between two call-sites, making
>>>> sure that each is only dispatching to single class. This only
>>>> works, if both classes (LoggerProxy and JavaLoggerProxy) are loaded
>>>> in advance, before 1st invocation on any of them is made (might be
>>>> that using MethodHandles forced initialization of both classes
>>>> beforehand and hence the speed-up). If I don't load JavaLoggerProxy
>>>> before warming-up with LoggerProxy, then when j.u.logging is
>>>> enabled, speed drops for a factor of almost 4 and never catches up
>>>> even after very long time.
>>>> This pre-loading also helps for a normal single call site dispatch
>>>> that dispatches to two distinct classes, but the speed 1st drops
>>>> when the class changes, and only catches-up after several billions
>>>> of iterations (30s tight loop on i7).
>>>> Now, because JavaLoggerProxy is initialized early, I had to move
>>>> the initialization of j.u.logging.Level objects and mappings to a
>>>> separate class "JavaLevel".
>>>>
>>>> Here are the benchmark results for this last iteration...
>>>>
>>>
>>
>
More information about the core-libs-dev
mailing list