8010309 : PlatformLogger: isLoggable performance / waste due to HashMap<Integer, Level> leads to Integer allocations (boxing)
Mandy Chung
mandy.chung at oracle.com
Fri Mar 22 16:32:27 UTC 2013
Peter, Laurent,
This is good work. I don't have the cycle to look through this data
this week. I'll get to it next week.
Mandy
On 3/22/2013 9:23 AM, Peter Levart wrote:
> Hi Laurent,
>
> I have run your performance test on my machine (i7 CPU, Linux) and
> with original code on JDK8 64bit (CompressedOOPS enabled by default,
> no TLAB options), i get:
>
> ...
> INFO: testPerf[100000000 iterations]: duration = 1767.6329779999999 ms.
> INFO: testPerf[100000000 iterations]: duration = 1758.7931449999999 ms.
> INFO: testPerf[100000000 iterations]: duration = 1763.386362 ms.
> ...
>
> While with latest patch (webrev.07), the results are:
>
> ...
> INFO: testPerf[100000000 iterations]: duration = 660.940466 ms.
> INFO: testPerf[100000000 iterations]: duration = 662.4854379999999 ms.
> INFO: testPerf[100000000 iterations]: duration = 656.497199 ms.
> ...
>
>
> So it's apparently a 2.5x improvement in speed.
>
> This test is designed to test the PlatformLogger.isLoggable() for
> levels that don't result in log messages being actually written out,
> but there are some caveats:
>
> - the test is using a loop with local variables and counters, which is
> very prone to JIT optimizations such as loop-unrolling. This might or
> might not be happening and even if it is, the impact might be the same
> on unpatched vs. patched PlatformLogger code.
> - the test is testing the performance when the PlatformLogger is
> directed to java.util.logging from the beginning. That means JIT is
> compiling calls to virtual methods of JavaLoggerProxy into monomorphic
> inlined calls. The results are different if the test is 1st warmed-up
> while no java.util.logging is initialized yet (calls directed to
> LoggerProxy) and later java.util.logging is enabled (PlatformLoggers
> are redirected to JavaLoggerProxys) and the same test repeated.
>
> I have created a special test that demonstrates this (all tests run on
> recent JDK8 build, i7 (4 cores) Linux, 64bit, no TLAB option,
> CompressedOOPS enabled by default):
>
> ** Original code
>
> >> JVM START
> #
> # isLoggableFinest: run duration: 5,000 ms, #of logical CPUS: 8
> #
> # Warm up:
> 1 threads, Tavg = 1.78 ns/op (? = 0.00 ns/op) [ 1.78]
> 1 threads, Tavg = 1.67 ns/op (? = 0.00 ns/op) [ 1.67]
> # Measure:
> 1 threads, Tavg = 1.44 ns/op (? = 0.00 ns/op) [ 1.44]
> 2 threads, Tavg = 1.37 ns/op (? = 0.01 ns/op) [
> 1.37, 1.38]
> 3 threads, Tavg = 1.53 ns/op (? = 0.13 ns/op) [
> 1.41, 1.49, 1.71]
> 4 threads, Tavg = 1.43 ns/op (? = 0.10 ns/op) [
> 1.36, 1.62, 1.39, 1.38]
>
> << JVM END
>
> >> JVM START
>
> >> java.util.logging enabled
>
> #
> # isLoggableFinest: run duration: 5,000 ms, #of logical CPUS: 8
> #
> # Warm up:
> 1 threads, Tavg = 4.81 ns/op (? = 0.00 ns/op) [ 4.81]
> 1 threads, Tavg = 4.79 ns/op (? = 0.00 ns/op) [ 4.79]
> # Measure:
> 1 threads, Tavg = 4.67 ns/op (? = 0.00 ns/op) [ 4.67]
> 2 threads, Tavg = 4.67 ns/op (? = 0.00 ns/op) [
> 4.67, 4.67]
> 3 threads, Tavg = 4.87 ns/op (? = 0.31 ns/op) [
> 4.67, 4.68, 5.32]
> 4 threads, Tavg = 4.68 ns/op (? = 0.01 ns/op) [
> 4.68, 4.67, 4.68, 4.69]
>
> << JVM END
>
> >> JVM START
> #
> # isLoggableFinest: run duration: 5,000 ms, #of logical CPUS: 8
> #
> # Warm up:
> 1 threads, Tavg = 1.39 ns/op (? = 0.00 ns/op) [ 1.39]
> 1 threads, Tavg = 1.80 ns/op (? = 0.00 ns/op) [ 1.80]
> # Measure:
> 1 threads, Tavg = 1.38 ns/op (? = 0.00 ns/op) [ 1.38]
> 2 threads, Tavg = 1.38 ns/op (? = 0.00 ns/op) [
> 1.38, 1.38]
> 3 threads, Tavg = 1.38 ns/op (? = 0.01 ns/op) [
> 1.39, 1.38, 1.37]
> 4 threads, Tavg = 1.38 ns/op (? = 0.02 ns/op) [
> 1.42, 1.37, 1.37, 1.37]
>
>
> >> java.util.logging enabled
>
> #
> # isLoggableFinest: run duration: 5,000 ms, #of logical CPUS: 8
> #
> # Warm up:
> 1 threads, Tavg = 11.87 ns/op (? = 0.00 ns/op) [ 11.87]
> 1 threads, Tavg = 9.08 ns/op (? = 0.00 ns/op) [ 9.08]
> # Measure:
> 1 threads, Tavg = 9.12 ns/op (? = 0.00 ns/op) [ 9.12]
> 2 threads, Tavg = 9.02 ns/op (? = 0.02 ns/op) [
> 9.05, 9.00]
> 3 threads, Tavg = 9.20 ns/op (? = 0.04 ns/op) [
> 9.26, 9.19, 9.17]
> 4 threads, Tavg = 9.33 ns/op (? = 0.07 ns/op) [
> 9.44, 9.34, 9.26, 9.28]
>
> << JVM END
>
>
> ** Patched code (webrev.07)
>
> >> JVM START
> #
> # isLoggableFinest: run duration: 5,000 ms, #of logical CPUS: 8
> #
> # Warm up:
> 1 threads, Tavg = 1.38 ns/op (? = 0.00 ns/op) [ 1.38]
> 1 threads, Tavg = 1.68 ns/op (? = 0.00 ns/op) [ 1.68]
> # Measure:
> 1 threads, Tavg = 1.38 ns/op (? = 0.00 ns/op) [ 1.38]
> 2 threads, Tavg = 1.40 ns/op (? = 0.02 ns/op) [
> 1.37, 1.42]
> 3 threads, Tavg = 1.49 ns/op (? = 0.21 ns/op) [
> 1.80, 1.38, 1.36]
> 4 threads, Tavg = 1.50 ns/op (? = 0.13 ns/op) [
> 1.47, 1.73, 1.41, 1.42]
>
> << JVM END
>
> >> JVM START
>
> >> java.util.logging enabled
>
> #
> # isLoggableFinest: run duration: 5,000 ms, #of logical CPUS: 8
> #
> # Warm up:
> 1 threads, Tavg = 1.80 ns/op (? = 0.00 ns/op) [ 1.80]
> 1 threads, Tavg = 1.74 ns/op (? = 0.00 ns/op) [ 1.74]
> # Measure:
> 1 threads, Tavg = 1.78 ns/op (? = 0.00 ns/op) [ 1.78]
> 2 threads, Tavg = 1.80 ns/op (? = 0.00 ns/op) [
> 1.80, 1.80]
> 3 threads, Tavg = 1.84 ns/op (? = 0.03 ns/op) [
> 1.80, 1.88, 1.86]
> 4 threads, Tavg = 1.78 ns/op (? = 0.00 ns/op) [
> 1.78, 1.77, 1.77, 1.78]
>
> << JVM END
>
> >> JVM START
> #
> # isLoggableFinest: run duration: 5,000 ms, #of logical CPUS: 8
> #
> # Warm up:
> 1 threads, Tavg = 1.73 ns/op (? = 0.00 ns/op) [ 1.73]
> 1 threads, Tavg = 1.72 ns/op (? = 0.00 ns/op) [ 1.72]
> # Measure:
> 1 threads, Tavg = 1.38 ns/op (? = 0.00 ns/op) [ 1.38]
> 2 threads, Tavg = 1.37 ns/op (? = 0.00 ns/op) [
> 1.37, 1.37]
> 3 threads, Tavg = 1.52 ns/op (? = 0.19 ns/op) [
> 1.37, 1.45, 1.79]
> 4 threads, Tavg = 1.58 ns/op (? = 0.19 ns/op) [
> 1.42, 1.79, 1.81, 1.41]
>
>
> >> java.util.logging enabled
>
> #
> # isLoggableFinest: run duration: 5,000 ms, #of logical CPUS: 8
> #
> # Warm up:
> 1 threads, Tavg = 5.43 ns/op (? = 0.00 ns/op) [ 5.43]
> 1 threads, Tavg = 5.65 ns/op (? = 0.00 ns/op) [ 5.65]
> # Measure:
> 1 threads, Tavg = 5.66 ns/op (? = 0.00 ns/op) [ 5.66]
> 2 threads, Tavg = 5.67 ns/op (? = 0.01 ns/op) [
> 5.68, 5.66]
> 3 threads, Tavg = 5.65 ns/op (? = 0.00 ns/op) [
> 5.65, 5.65, 5.65]
> 4 threads, Tavg = 5.66 ns/op (? = 0.01 ns/op) [
> 5.65, 5.65, 5.67, 5.67]
>
> << JVM END
>
>
> It appears the speed-up is visible and varies from 1.6x to 2.6x,
> depending on other factors that also play role in the overall speed
> (like JIT optimizations).
>
> I only presented the results for PlatformLogger.isLoggable(FINEST),
> because this is the most sensitive call in tight loops. Other methods
> perform similarly.
>
> This is the test code I used:
>
>
> package test;
>
> import si.pele.microbench.TestRunner;
> import sun.util.logging.PlatformLogger;
>
> import java.util.logging.LogManager;
>
> public class PlatformLoggerBenchmark extends TestRunner {
>
> static final PlatformLogger log =
> PlatformLogger.getLogger(PlatformLoggerBenchmark.class.getName());
>
> static {
> log.setLevel(PlatformLogger.SEVERE); // almost OFF
> }
>
> public static class isLoggableFinest extends Test {
> @Override
> protected void doLoop(Loop loop, DevNull devNull1, DevNull
> devNull2, DevNull devNull3, DevNull devNull4, DevNull devNull5) {
> while (loop.nextIteration()) {
> devNull1.yield(log.isLoggable(PlatformLogger.FINEST));
> }
> }
> }
>
> public static void main(String[] args) throws Exception {
>
> System.out.println(">> JVM START");
>
> doTest(isLoggableFinest.class, 5000L, 1, 4, 1);
>
> // enable java.util.logging
> LogManager.getLogManager().getLogger(log.getName());
> System.out.println("\n>> java.util.logging enabled\n");
>
> doTest(isLoggableFinest.class, 5000L, 1, 4, 1);
>
> System.out.println("<< JVM END");
> }
> }
>
>
> The test uses a simple microbenchmark runner that I coded together
> using some ideas from the sessions with Alexey Shipilev and his
> benchmark suite.
>
> Here's the source to my dirty implementation:
>
> https://github.com/plevart/micro-bench/tree/v2
>
>
> Regards, Peter
>
> On 03/22/2013 02:28 PM, Peter Levart wrote:
>> Ok, Lauret, Mandy,
>>
>> Here are the final touches:
>>
>> https://dl.dropboxusercontent.com/u/101777488/jdk8-tl/PlatformLogger/webrev.07/index.html
>>
>> Changes from webrev.06:
>>
>> - renamed back Level -> LevelEnum
>> - renamed JavaLogger -> JavaLoggerProxy
>> - moved javaLevel(int) static method from LevelEnum to
>> JavaLoggerProxy and made it private (only used there)
>> - consistent use of variable name 'level' to refer to
>> PlatformLogger's int level value
>> - consistent use of variable name 'levelEnum' to refer to LevelEnum
>> member
>> - consistent use of variable name 'javaLevel' to refer to
>> java.util.logging.Level instance
>> - consistent use of variable name 'javaLogger' to refer to
>> java.util.logging.Logger instance
>> - renamed PlatformLogger.newJavaLogger() private method ->
>> PlatformLogger.redirectToJavaLoggerProxy()
>> - renamed PlatformLogger.logger private field ->
>> PlatformLogger.loggerProxy
>> - some additional comments
>>
>> I think that these changes make code more consistent and
>> self-explanatory.
>>
>> What remains is a possible rename from: javaLogger, javaLevel,
>> JavaLoggerProxy -> julLogger, julLevel, JulLoggerProxy if that's the
>> final decision.
>>
>> Regards, Peter
>>
>>
>> On 03/22/2013 01:26 PM, Peter Levart wrote:
>>> On 03/22/2013 11:34 AM, Laurent Bourgès wrote:
>>>> Peter,
>>>>
>>>> You've beaten me! I have been preparing them too ;-) ...
>>>>
>>>>
>>>> Ok I definitely stop working on the code and let you do it.
>>>
>>> Ok. I'll make the final touches, incorporating also comments and
>>> changes from your code...
>>>
>>>>
>>>> I also did some some renames, that I think make the code more
>>>> consistent:
>>>> - LevelEnum -> Level (the code is not dependent on
>>>> java.util.logging.Level, so the name can be reused, its private
>>>> anyway)
>>>> - julLevel -> javaLevel (javaLevel / JavaLogger)
>>>> - LevelEnum.forValue -> Level.valueOf (Mandy)
>>>> - JavaLogger.julLevelToEnum -> JavaLogger.javaLevelToLevel
>>>>
>>>>
>>>> For consistency and clarity, I would prefer having following
>>>> conventions:
>>>> - int levelValue (= PlatformLevel as int) and not int level
>>>> (conflict with Level enum ...)
>>>
>>> I think that PlatformLogger public API should stay as is. Public
>>> method's parameter names are just called 'level' and values of
>>> public constants are expected to be passed to them. There are only
>>> two places where 'level' is the name of a local variable of type
>>> Level (and not int) and at both places there is not conflict, since
>>> there's no 'int level' variable in scope.
>>>
>>> I renamed LevelEnum to Level because the following most frequently
>>> used pattern looks strange:
>>>
>>> LevelEnum.javaLevel(int)
>>>
>>> Neither parameter nor the result has anything to do with LevelEnum
>>> directly.
>>>
>>> But if we move the javaLevel(int) method out of the Level enum into
>>> the JavaLogger, then Level can be renamed back to LevelEnum (or
>>> anything else?).
>>>
>>>
>>>> - julLevel / julLogger: more explicit than javaLevel / javaLogger
>>>> (java means everything ... but jul means java.util.logging and
>>>> javaLogger is in conflict with JavaLogger class)
>>>
>>>
>>> But javaLogger is not in conflict with javaLevel. I suggest renaming
>>> JavaLoger class to JavaLoggerProxy, so we would have:
>>>
>>> Object javaLogger // holding java.util.logging.Logger instance
>>> Object javaLevel // holding java.util.logging.Level instance
>>>
>>> class JavaLoggerProxy // a specialization of LoggerProxy,
>>> delegating to javaLogger
>>>
>>> If 'jul' is a prefered prefix to 'java', I suggest renaming all 3:
>>> julLogger, julLevel, JulLoggerProxy. I don't have a preference for
>>> either, so perhaps Mandy, Laurent or anybody else can express them...
>>>
>>>
>>> Regards, Peter
>>>
>>>>
>>>> Other changes (to webrev.05):
>>>> - removed the occurrence counts in switch comments (as per
>>>> Mandy's suggestion)
>>>> - made LoggerProxy and JavaLogger private
>>>> - fixed double-read of volatile LoggerProxy.levelValue in
>>>> LoggerProxy.isLoggable()
>>>> - added static Level.javaLevel(int value) shortcut (Mandy)
>>>>
>>>> I also updated the test to exercise the correctness of mappings.
>>>>
>>>>
>>>> Well done.
>>>>
>>>> cheers,
>>>> Laurent
>>>>
>>>
>>
>
More information about the core-libs-dev
mailing list