54

UPDATE: Seeing as each method might be suffering from a different performance issue I decided to split this question into two:

  1. Empty methods noticeably slower in Java 11 than Java 8
  2. Consuming stack traces noticeably slower in Java 11 than Java 8

The original discussion can be found below...

I was comparing my library's performance under Java 8 and 11 when I ran across some surprising numbers. Here is the benchmark code:

import org.openjdk.jmh.annotations.Benchmark;
import org.openjdk.jmh.annotations.BenchmarkMode;
import org.openjdk.jmh.annotations.Mode;
import org.openjdk.jmh.annotations.OutputTimeUnit;
import org.openjdk.jmh.infra.Blackhole;

import java.io.PrintWriter;
import java.io.StringWriter;
import java.util.concurrent.TimeUnit;

@BenchmarkMode(Mode.AverageTime)
@OutputTimeUnit(TimeUnit.NANOSECONDS)
public class MyBenchmark
{
    @Benchmark
    public void emptyMethod()
    {
    }

    @Benchmark
    public void throwAndConsumeStacktrace(Blackhole bh)
    {
        try
        {
            throw new IllegalArgumentException("I love benchmarks");
        }
        catch (IllegalArgumentException e)
        {
            StringWriter sw = new StringWriter();
            e.printStackTrace(new PrintWriter(sw));
            bh.consume(sw.toString());
        }
    }
}

Running with jmh 1.21, OracleJDK 1.8.0_192 returns:

MyBenchmark.emptyMethod                avgt   25      0.363 ±   0.001  ns/op
MyBenchmark.throwAndConsumeStacktrace  avgt   25  21408.072 ± 127.393  ns/op

OracleJDK 11.0.1 returns:

Benchmark                              Mode  Cnt      Score      Error  Units
MyBenchmark.emptyMethod                avgt   25      0.759 ±    0.034  ns/op
MyBenchmark.throwAndConsumeStacktrace  avgt   25  47143.168 ± 1346.898  ns/op

OpenJDK 11.0.1 returns:

Benchmark                              Mode  Cnt      Score     Error  Units
MyBenchmark.emptyMethod                avgt   25      0.725 ±   0.001  ns/op
MyBenchmark.throwAndConsumeStacktrace  avgt   25  47389.051 ± 994.345  ns/op

Granted, the absolute difference for emptyMethod() is tiny but the trend seems to follow for more expensive operations like throwAndConsumeStacktrace(). As an aside, other operations (such as throwing exceptions and never consuming their stacktrace) are only moderately slower in Java 11 so the performance drop does not apply across all operations.

I understand that microbenchmarks do not indicate the performance behavior of real-life applications. Still, I'm curious where this difference is coming from. Any ideas?

Here is the full version info for the JDKs I used:

OracleJDK 8:

java version "1.8.0_192"
Java(TM) SE Runtime Environment (build 1.8.0_192-b12)
Java HotSpot(TM) 64-Bit Server VM (build 25.192-b12, mixed mode)

OracleJDK 11.0.1:

java version "11.0.1" 2018-10-16 LTS
Java(TM) SE Runtime Environment 18.9 (build 11.0.1+13-LTS)
Java HotSpot(TM) 64-Bit Server VM 18.9 (build 11.0.1+13-LTS, mixed mode)

OpenJDK 11.0.1:

openjdk version "11.0.1" 2018-10-16
OpenJDK Runtime Environment 18.9 (build 11.0.1+13)
OpenJDK 64-Bit Server VM 18.9 (build 11.0.1+13, mixed mode)
Brian Goetz
  • 90,105
  • 23
  • 150
  • 161
Gili
  • 86,244
  • 97
  • 390
  • 689
  • 4
    Though I am not good at JMH. Yet, trying out few things, what further puzzles me now is that when I separated out the `writer`s to a different method and *ignored* the exception. Java-11 stats came up better than Java-8. Maybe just running the benchmark with `bh.consume(e.toString());` could clear out the picture here. Would give it a try in sometime to confirm. – Naman Dec 29 '18 at 07:34
  • 6
    You might want to try catching IAE with an empty catch block to see if throwing the exception has really regressed. It may be that printStackTrace is more expensive in JDK 9 and newer as the output is a bit more complicated. – Alan Bateman Dec 29 '18 at 07:35
  • 4
    @AlanBateman I could confirm running the benchmark for ignoring the exception. The results were quite similar for both the JDK version at least for me. I would though insist Gili to give it a try by himself and come back with the exact results. – Naman Dec 29 '18 at 07:37
  • 3
    Thanks for checking, can you now add a benchmark for Throwable::toString to see whether e.printStackTrace is the real difference in the original benchmark. – Alan Bateman Dec 29 '18 at 07:44
  • @nullpointer I already tried ignoring the exception. Notice I wrote `other operations (such as throwing exceptions and never consuming their stacktrace) are only moderately slower in Java 11`. That's not what this question is about. This question is about why two specific cases (empty methods and consuming stacktraces) are so much slower. PS: You can't just ignore thrown exceptions. See https://stackoverflow.com/a/45417818/14731. You must consume the exception to avoid the compiler from optimizing-away the throw statement. – Gili Dec 30 '18 at 21:32
  • @AlanBateman As I explained to nullpointer (above) I already tried throwing IAE with an empty catch block. It is about 30% slower than JDK 8 on my machine, but that's not what this question is about. Could you please elaborate on how `the output is a bit more complicated` in JDK 11 than JDK 8? Also, what about the empty method case? – Gili Dec 30 '18 at 21:37
  • 1
    Stack traces in JDK 11 can contain information about the module, but it's not printed if it is an unnamed module. The check to see if is unnamed module will still probably eat some CPU cycles. My 2 cents. – Kire Haglin Dec 31 '18 at 09:38
  • @KireHaglin That is a reasonable hypothesis, but I'm hoping that someone will come back with something more concrete (comparing the low-level JVM behavior in each case) to be sure. No one has yet figured out why empty methods are showing a performance degradation. What's worse, the degradation ratios are conspicuously similar to one another. – Gili Dec 31 '18 at 20:13
  • 1
    I would suggest splitting this question into 2; one about the empty method call and the other about the throwing and catching. Reasons for these regressions might be different, and splitting will let people answer one but not the other (if they only know the cause of one of them). – Jorn Vernee Jan 01 '19 at 18:47
  • 1
    FWIW, running with Graal on java 11 the numbers are better, but still slower than JDK 8. Running with java 10 the numbers for `emptyMethod` are about the same as in java 11, but for `throwAndConsumeStacktrace` they are much closer to java 8. So, I don't think the slowdown has the same cause in both cases, or at least there's more than 1 thing causing it. – Jorn Vernee Jan 01 '19 at 19:16
  • @JornVernee Good catch! I've split the question as you suggested and provided even more data. – Gili Jan 02 '19 at 15:21
  • 1
    One more related ticket regarding G1 - https://stackoverflow.com/questions/46582523/why-there-is-performance-degradation-after-6-hours-of-java-9-g1-work-without-th – Dmitriy Dumanskiy Jan 03 '19 at 10:44
  • is there a chance it's not the code but the gc that causes the difference, didn't the default collectors change between 8 and 11? – default_avatar Mar 21 '19 at 17:09

0 Answers0