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...
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)...
- 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.
- introduced private method
DefaultLoggerProxy.deriveEffectiveLevel(level) that currently just
returns defaultLevel (INFO) when given null. 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...
- 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.
- 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'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.
The benchmarks still show stable performance:
##############################################################
# Java: 1.8.0-internal-peter_2013_03_04_10_48-b00
# VM: OpenJDK 64-Bit Server VM 25.0-b19 (mixed mode)
# OS: Linux 3.7.9-104.fc17.x86_64 (amd64)
# CPUs: 8 (virtual) - Intel i7-2600K
#
#-------------------------------------------------------------
# isLoggableFinest: run duration: 3,000 ms
#
# Warm up:
# 1 threads, Tavg = 1.71 ns/op (? = 0.00 ns/op) [ 1.71]
# 1 threads, Tavg = 1.45 ns/op (? = 0.00 ns/op) [ 1.45]
# Measure:
1 threads, Tavg = 1.69 ns/op (? = 0.00 ns/op) [
1.69]
2 threads, Tavg = 1.69 ns/op (? = 0.00 ns/op) [
1.69, 1.69]
3 threads, Tavg = 1.67 ns/op (? = 0.04 ns/op) [
1.70, 1.70, 1.62]
4 threads, Tavg = 1.66 ns/op (? = 0.11 ns/op) [
1.49, 1.70, 1.79, 1.69]
#
#-------------------------------------------------------------
# java.util.logging enabled
#
#
#-------------------------------------------------------------
# isLoggableFinest: run duration: 3,000 ms
#
# Measure:
1 threads, Tavg = 1.75 ns/op (? = 0.00 ns/op) [
1.75]
2 threads, Tavg = 1.78 ns/op (? = 0.01 ns/op) [
1.79, 1.77]
3 threads, Tavg = 1.68 ns/op (? = 0.02 ns/op) [
1.68, 1.66, 1.69]
4 threads, Tavg = 1.66 ns/op (? = 0.00 ns/op) [
1.65, 1.65, 1.66, 1.66]
1 threads, Tavg = 1.68 ns/op (? = 0.00 ns/op) [
1.68]
2 threads, Tavg = 1.68 ns/op (? = 0.02 ns/op) [
1.70, 1.66]
3 threads, Tavg = 1.67 ns/op (? = 0.02 ns/op) [
1.69, 1.65, 1.66]
4 threads, Tavg = 1.68 ns/op (? = 0.03 ns/op) [
1.65, 1.65, 1.66, 1.73]
1 threads, Tavg = 1.65 ns/op (? = 0.00 ns/op) [
1.65]
2 threads, Tavg = 1.68 ns/op (? = 0.03 ns/op) [
1.71, 1.65]
3 threads, Tavg = 1.66 ns/op (? = 0.00 ns/op) [
1.66, 1.65, 1.66]
4 threads, Tavg = 1.74 ns/op (? = 0.12 ns/op) [
1.95, 1.70, 1.69, 1.65]
#
#-------------------------------------------------------------
# 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) - UltraSPARC-T2
#
#-------------------------------------------------------------
# isLoggableFinest: run duration: 3,000 ms
#
# Warm up:
# 1 threads, Tavg = 40.63 ns/op (? = 0.00 ns/op) [ 40.63]
# 1 threads, Tavg = 38.69 ns/op (? = 0.00 ns/op) [ 38.69]
# Measure:
1 threads, Tavg = 38.64 ns/op (? = 0.00 ns/op) [
38.64]
2 threads, Tavg = 38.70 ns/op (? = 0.04 ns/op) [
38.74, 38.66]
3 threads, Tavg = 38.89 ns/op (? = 0.06 ns/op) [
38.97, 38.85, 38.84]
4 threads, Tavg = 38.94 ns/op (? = 0.18 ns/op) [
39.18, 38.76, 38.78, 39.04]
#
#-------------------------------------------------------------
# java.util.logging enabled
#
#
#-------------------------------------------------------------
# isLoggableFinest: run duration: 3,000 ms
#
# Measure:
1 threads, Tavg = 101.37 ns/op (? = 0.00 ns/op) [
101.37]
2 threads, Tavg = 99.67 ns/op (? = 0.01 ns/op) [
99.67, 99.68]
3 threads, Tavg = 48.27 ns/op (? = 0.06 ns/op) [
48.31, 48.31, 48.19]
4 threads, Tavg = 48.28 ns/op (? = 0.14 ns/op) [
48.11, 48.24, 48.28, 48.50]
1 threads, Tavg = 48.14 ns/op (? = 0.00 ns/op) [
48.14]
2 threads, Tavg = 48.21 ns/op (? = 0.01 ns/op) [
48.21, 48.22]
3 threads, Tavg = 48.26 ns/op (? = 0.18 ns/op) [
48.52, 48.11, 48.16]
4 threads, Tavg = 48.30 ns/op (? = 0.10 ns/op) [
48.33, 48.44, 48.15, 48.27]
1 threads, Tavg = 48.21 ns/op (? = 0.00 ns/op) [
48.21]
2 threads, Tavg = 48.18 ns/op (? = 0.09 ns/op) [
48.27, 48.09]
3 threads, Tavg = 48.44 ns/op (? = 0.09 ns/op) [
48.54, 48.44, 48.33]
4 threads, Tavg = 49.29 ns/op (? = 0.16 ns/op) [
49.36, 49.02, 49.33, 49.46]
#
#-------------------------------------------------------------
# END.
##############################################################
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...
