Setup time is counted against iteration time in Mode.SingleShotTime (JMH-1.0)

Dmitry Vyazelenko vyazelenko at yahoo.com
Mon Sep 1 14:48:35 UTC 2014


Hi,

I've discovered that when Mode.SingleShotTime is used the time in @Setup
is counted against iteration time. This results in benchmark being interrupted
if @Setup takes long time. 
What is also interesting is that iteration time for Mode.SingleShotTime is set 
to 10 minutes. I would expect that in this mode JMH will wait forever for iteration
to complete. Or at least such behavior should be documented somewhere. :)

Here is the benchmark to reproduce:
@Fork(1) 
@Warmup(iterations=10) 
@Measurement(iterations=10) 
@OutputTimeUnit(TimeUnit.NANOSECONDS) 
@State(Scope.Benchmark) 
@BenchmarkMode(Mode.SingleShotTime) 
public class SetupTimeCountedAgainstIterationTime_SingleShotTime { 
 @Setup(Level.Trial) 
    public void setUp() throws Exception { 
     System.out.println("Starting setup..."); 
        Thread.sleep(TimeUnit.MINUTES.toMillis(15)); 
     System.out.println("Setup finished!"); 
    } 
    @Benchmark 
    public void baseline() { 
    } 
}

When executed it fails with InterruptedException:
java -jar target\benchmarks.jar -foe true 
# VM invoker: C:\Program Files\Java\jre7\bin\java.exe 
# VM options: <none> 
# Warmup: 10 iterations, single-shot each 
# Measurement: 10 iterations, single-shot each 
# Threads: 1 thread 
# Benchmark mode: Single shot invocation time 
# Benchmark: org.sample.SetupTimeCountedAgainstIterationTime_SingleShotTime.baseline 
# Run progress: 0.00% complete, ETA 00:00:00 
# Fork: 1 of 1 
# Warmup Iteration   1: Starting setup... 
(*interrupt*) <failure> 
java.lang.InterruptedException: sleep interrupted 
        at java.lang.Thread.sleep(Native Method) 
        at org.sample.SetupTimeCountedAgainstIterationTime_SingleShotTime.setUp(SetupTimeCountedAgainstIterationTime_SingleShotTime.java:16) 
        at org.sample.generated.SetupTimeCountedAgainstIterationTime_SingleShotTime_baseline._jmh_tryInit_f_setuptimecountedagainstiterationtime_singleshottime0_G(SetupTimeCountedAgainstIterationTime_SingleShotTime_baseline.java:340) 
        at org.sample.generated.SetupTimeCountedAgainstIterationTime_SingleShotTime_baseline.baseline_SingleShotTime(SetupTimeCountedAgainstIterationTime_SingleShotTime_baseline.java:281) 
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) 
        at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) 
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) 
        at java.lang.reflect.Method.invoke(Unknown Source) 
        at org.openjdk.jmh.runner.LoopBenchmarkHandler$BenchmarkTask.call(LoopBenchmarkHandler.java:210) 
        at org.openjdk.jmh.runner.LoopBenchmarkHandler$BenchmarkTask.call(LoopBenchmarkHandler.java:192) 
        at java.util.concurrent.FutureTask.run(Unknown Source) 
        at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) 
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) 
        at java.lang.Thread.run(Unknown Source) 

Expected: @Setup completes after 15 minutes and benchmark executes without exception.
 

Best regards,
Dmitry Vyazelenko


More information about the jmh-dev mailing list