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...
