CODEWITHSUNDEEP
javabenchmarkingjmh
maaartinus
maaartinus

Reputation: 46372

What does JMH when it does nothing?

This is my very first JMH benchmark. I might be doing everything wrong, but....

My benchmark looks like this

@State(Scope.Benchmark) public class JmhBranchingBenchmark {
    private static final int STRING_LENGTH = 100 * 1000;
    private char[][] allQueries = new char[101][];

    @Setup public void up() {
        for (int i=0; i<allQueries.length; ++i) {
            ... fill char[i] with STRING_LENGTH chars
            ... this might take some time, but it's needed only once, or?
        }
    }

   @GenerateMicroBenchmark public void measure5(BlackHole bh) {
       bh.consume(countBreakingWhitespace(allQueries[5]));
   }

   ... some more nearly identical methods as a poor man's replacement for caliper's @Param
}

I started it... and waited and waited and then killed it. I suspected a problem in the @Setup, so I simplified it, but nothing changed. The run starts pretty optimistically...

time -p java -jar target/microbenchmarks.jar ".*JmhBranchingBenchmark.*" -i 5 -f 1
# Run progress: 0.00% complete, ETA 00:02:05
# VM invoker: /usr/lib/jvm/java-7-oracle/jre/bin/java
# VM options: <none>
# Fork: 1 of 1
# Warmup: 20 iterations, 1 s each
# Measurement: 5 iterations, 1 s each
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Throughput, ops/time
# Benchmark: org.openjdk.jmh.samples.JmhBranchingBenchmark.measure10
# Warmup Iteration   1:

and then nothing happens. After a long time, it continues and write 20 lines like

# Warmup Iteration   1: 6.415 ops/ms

and 5 lines like

Iteration   1: 6.506 ops/ms

Then it outputs some results

Result : 6.510 ±(99.9%) 0.030 ops/ms
  Statistics: (min, avg, max) = (6.502, 6.510, 6.521), stdev = 0.008
  Confidence interval (99.9%): [6.480, 6.540]

and corrects its estimated eta:

# Run progress: 20.00% complete, ETA 00:26:52

Does my @Setup get invoked much more often than I though or what else can be the reason for the slowness?

Upvotes: 1

Views: 1053

Answers (1)

Aleksey Shipilev
Aleksey Shipilev

Reputation: 18847

I think you are dealing with very heavy @Setup.

@Setup(Level.Trial) gets lazy-called on first use of @State object. These initializations are counted towards the execution time, and it is another good reason to do warmup. Hence, the first "hiccup" during the first warmup is @Setup execution. Now, JMH forks each @GenerateMicroBenchmark run in the separate VM, so the next test will experience the same.

Upvotes: 4

Related Questions