IllegalStateException: More threads than expected

[Chris Vest]

I have a benchmark, of sorts, that attempts to run 7200 sample-time iterations of 250 milliseconds each. The benchmark has a thread-group with 3 different participants, that each run a different query against an embedded database (@State(Scope.Benchmark)). The purpose if the exercise is actually to create conditions where the database will experience periods of fluctuating performance, such that I can probe into this problem further. JMH just happened to look like a quick way to set this up.

Anyway, a period of fluctuating performance comes along, and after a little while, the benchmark terminates like so:

~% 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)



# 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.

Is there a way to mitigate this?

Cheers,
Chris