IllegalStateException: More threads than expected

[Aleksey Shipilev]

Hi Chris,

On 02/10/2015 05:09 PM, Chris Vest wrote:
> ~% java -XX:+UnlockCommercialFeatures -XX:+FlightRecorder -XX:+UnlockDiagnosticVMOptions -XX:+DebugNonSafepoints -jar benchmark.jar Mixed -tg 2,1,3 -t 12
> 
> (...)
> 
> Iteration 1110: n = 99, mean = 77 ms/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 543, 546, 1101, 1101, 1101, 1101 ms/op
>                   createUser:       n = 4, mean = 821 ms/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 543, 819, 1101, 1101, 1101, 1101, 1101, 1101 ms/op
>                   friendsOfFriends: n = 88, mean = 12 ms/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 0, 1, 540, 540, 540, 540 ms/op
>                   linkUser:         n = 7, mean = 469 ms/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 7, 546, 546, 546, 546, 546, 546, 546 ms/op
> 
> Iteration 1111: n = 12, mean = 729 ms/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 1087, 1097, 1097, 1097, 1097, 1097, 1097 ms/op
>                   createUser:       n = 4, mean = 1088 ms/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 1080, 1089, 1095, 1095, 1095, 1095, 1095, 1095 ms/op
>                   friendsOfFriends: n = 2, mean = 1 ms/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 1, 1, 1, 1, 1, 1, 1 ms/op
>                   linkUser:         n = 6, mean = 733 ms/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 10, 1093, 1097, 1097, 1097, 1097, 1097, 1097 ms/op
> 
> Iteration 1112: n = 104, mean = 93 ms/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 532, 546, 1623, 1623, 1623, 1623 ms/op
>                   createUser:       n = 4, mean = 1083 ms/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 548, 1081, 1623, 1623, 1623, 1623, 1623, 1623 ms/op
>                   friendsOfFriends: n = 93, mean = 12 ms/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 0, 0, 531, 531, 531, 531 ms/op
>                   linkUser:         n = 7, mean = 616 ms/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 7, 538, 1623, 1623, 1623, 1623, 1623, 1623 ms/op
> 
> Iteration 1113: n = 111, mean = 138 ms/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 531, 1367, 3384, 3548, 3548, 3548 ms/op
>                   createUser:       n = 4, mean = 2122 ms/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 842, 2049, 3548, 3548, 3548, 3548, 3548, 3548 ms/op
>                   friendsOfFriends: n = 100, mean = 11 ms/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 0, 1, 531, 531, 531, 531 ms/op
>                   linkUser:         n = 7, mean = 817 ms/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 6, 538, 1367, 1367, 1367, 1367, 1367, 1367 ms/op
> 
> Iteration 1114: <failure>
> 
> java.lang.IllegalStateException: More threads than expected
> 	at org.openjdk.jmh.runner.InfraControlL2.announceWarmdownReady(InfraControl.java:191)
> 	at org.openjdk.jmh.runner.InfraControl.announceWarmdownReady(InfraControl.java:39)
> 	at org.neo4j.benchmark.generated.MixedWorkloadBenchmark_g.g_SampleTime(MixedWorkloadBenchmark_g.java:440)
> 	at sun.reflect.GeneratedMethodAccessor32.invoke(Unknown Source)
> 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> 	at java.lang.reflect.Method.invoke(Method.java:483)
> 	at org.openjdk.jmh.runner.LoopBenchmarkHandler$BenchmarkTask.call(LoopBenchmarkHandler.java:189)
> 	at org.openjdk.jmh.runner.LoopBenchmarkHandler$BenchmarkTask.call(LoopBenchmarkHandler.java:171)
> 	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
> 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> 	at java.lang.Thread.run(Thread.java:745)

All right, what you've stepped on is the defensive check in our
synchronize iterations epilog. Only benchmark threads are expected here.
This puzzles me, because I don't see how could it happen in current
code. I could understand some benchmark threads *not* coming to the
epilog, but here, *more* thread have come.


However, when I try to run a relevant test:

@State(Scope.Group)
public class MyBenchmark {

    @Group
    @Benchmark
    public void test1() {
        // do nothing
    }

    @Group
    @Benchmark
    public void test2() {
        // do nothing
    }

    @Group
    @Benchmark
    public void test3() {
        // do nothing
    }

}

...with:

$ java  -XX:+UnlockDiagnosticVMOptions -XX:+DebugNonSafepoints -jar
target/benchmarks.jar -tg 2,1,3 -t 12 -wi 0 -i 10000 -f 1 -bm sample -r 10ms

...it OOMs. When I supply -Xmx1g -Xms1g it OOMEs way before 500
iterations. The heap pollution is caused by SampleBuffers consuming a
lot of space even for a modest number of events, fixed with:
 https://bugs.openjdk.java.net/browse/CODETOOLS-7901301
 https://bugs.openjdk.java.net/browse/CODETOOLS-7901299

After that, the test is passing tens of thousands of iterations without
a glitch

> 
> # Run complete. Total time: 00:08:46
> 
> Benchmark  Mode  Cnt  Score   Error  Units
> ~%                                                                                                                                                       
> 
> Lucene is involved, so I know it creates “merge threads” all the
> time, but from a quick reading of the JMH source code, they don’t
> appear to be the ones that are counted here. I guess it could also
> have to do with my asking for iteration times that a significantly
> less than the max latency, but I don’t know.

Lucene is known to put VM in strange situations, maybe this is the key.
Anyhow, I would like you to try the next release version where the OOME
is being evaded. If the failure still reproduces, we would need a
minimized test case...


Thanks,
-Aleksey.