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