com.hazelcast.jet.job.JobSubmissionSlownessRegressionTest.regressionTestForPR1488

[olukas]

master / 3.2-maintenance (commit 166503c66113d5fe3d7e3158f4aba87cc683a7b9)

Failed on nightly build: http://jenkins.hazelcast.com/job/jet-oss-maintenance-nightly/52/testReport/junit/com.hazelcast.jet.job/JobSubmissionSlownessRegressionTest/regressionTestForPR1488/

It fails intermittently and it is caused by nature of the test since it is not deterministic. Fix will be probably very tricky and will probably need redesign of whole test.

Stacktrace:

java.lang.AssertionError: Job submission rate should not decrease. First rate: 5.197103105280812, second rate: 3.840073037683318
	at org.junit.Assert.fail(Assert.java:88)
	at org.junit.Assert.assertTrue(Assert.java:41)
	at com.hazelcast.jet.job.JobSubmissionSlownessRegressionTest.regressionTestForPR1488(JobSubmissionSlownessRegressionTest.java:120)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
	at com.hazelcast.test.FailOnTimeoutStatement$CallableStatement.call(FailOnTimeoutStatement.java:106)
	at com.hazelcast.test.FailOnTimeoutStatement$CallableStatement.call(FailOnTimeoutStatement.java:98)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.lang.Thread.run(Thread.java:748)

Standard output:

Hiccups measured while running test 'regressionTestForPR1488(com.hazelcast.jet.job.JobSubmissionSlownessRegressionTest):'
19:16:50, accumulated pauses: 984 ms, max pause: 616 ms, pauses over 1000 ms: 0
19:16:55, accumulated pauses: 391 ms, max pause: 101 ms, pauses over 1000 ms: 0
19:17:00, accumulated pauses: 46 ms, max pause: 3 ms, pauses over 1000 ms: 0
19:17:05, accumulated pauses: 1449 ms, max pause: 1122 ms, pauses over 1000 ms: 1
19:17:10, accumulated pauses: 120 ms, max pause: 18 ms, pauses over 1000 ms: 0
19:17:15, accumulated pauses: 83 ms, max pause: 33 ms, pauses over 1000 ms: 0
19:17:20, accumulated pauses: 278 ms, max pause: 87 ms, pauses over 1000 ms: 0
19:17:25, accumulated pauses: 88 ms, max pause: 55 ms, pauses over 1000 ms: 0
19:17:30, accumulated pauses: 367 ms, max pause: 190 ms, pauses over 1000 ms: 0
19:17:35, accumulated pauses: 225 ms, max pause: 116 ms, pauses over 1000 ms: 0
19:17:40, accumulated pauses: 93 ms, max pause: 45 ms, pauses over 1000 ms: 0
19:17:45, accumulated pauses: 36 ms, max pause: 1 ms, pauses over 1000 ms: 0
19:17:50, accumulated pauses: 399 ms, max pause: 121 ms, pauses over 1000 ms: 0
19:17:55, accumulated pauses: 132 ms, max pause: 19 ms, pauses over 1000 ms: 0
19:18:00, accumulated pauses: 424 ms, max pause: 314 ms, pauses over 1000 ms: 0
19:18:05, accumulated pauses: 272 ms, max pause: 67 ms, pauses over 1000 ms: 0
19:18:10, accumulated pauses: 56 ms, max pause: 13 ms, pauses over 1000 ms: 0
19:18:15, accumulated pauses: 236 ms, max pause: 64 ms, pauses over 1000 ms: 0
19:18:20, accumulated pauses: 267 ms, max pause: 93 ms, pauses over 1000 ms: 0
19:18:25, accumulated pauses: 62 ms, max pause: 31 ms, pauses over 1000 ms: 0
19:18:30, accumulated pauses: 709 ms, max pause: 626 ms, pauses over 1000 ms: 0
19:18:35, accumulated pauses: 232 ms, max pause: 45 ms, pauses over 1000 ms: 0
19:18:40, accumulated pauses: 76 ms, max pause: 39 ms, pauses over 1000 ms: 0
19:18:45, accumulated pauses: 184 ms, max pause: 67 ms, pauses over 1000 ms: 0
19:18:50, accumulated pauses: 194 ms, max pause: 68 ms, pauses over 1000 ms: 0
19:18:55, accumulated pauses: 682 ms, max pause: 469 ms, pauses over 1000 ms: 0
19:19:00, accumulated pauses: 103 ms, max pause: 31 ms, pauses over 1000 ms: 0
19:19:05, accumulated pauses: 249 ms, max pause: 56 ms, pauses over 1000 ms: 0
19:19:10, accumulated pauses: 185 ms, max pause: 57 ms, pauses over 1000 ms: 0
19:19:15, accumulated pauses: 85 ms, max pause: 48 ms, pauses over 1000 ms: 0
19:19:20, accumulated pauses: 295 ms, max pause: 73 ms, pauses over 1000 ms: 0
19:19:25, accumulated pauses: 935 ms, max pause: 828 ms, pauses over 1000 ms: 0
19:19:30, accumulated pauses: 244 ms, max pause: 43 ms, pauses over 1000 ms: 0
19:19:35, accumulated pauses: 36 ms, max pause: 2 ms, pauses over 1000 ms: 0
19:19:40, accumulated pauses: 330 ms, max pause: 99 ms, pauses over 1000 ms: 0
19:19:45, accumulated pauses: 104 ms, max pause: 17 ms, pauses over 1000 ms: 0
19:19:50, accumulated pauses: 36 ms, max pause: 0 ms, pauses over 1000 ms: 0
19:19:55, accumulated pauses: 710 ms, max pause: 570 ms, pauses over 1000 ms: 0
19:20:00, accumulated pauses: 381 ms, max pause: 106 ms, pauses over 1000 ms: 0
19:20:05, accumulated pauses: 66 ms, max pause: 12 ms, pauses over 1000 ms: 0
19:20:10, accumulated pauses: 60 ms, max pause: 13 ms, pauses over 1000 ms: 0
19:20:15, accumulated pauses: 688 ms, max pause: 561 ms, pauses over 1000 ms: 0
19:20:20, accumulated pauses: 44 ms, max pause: 2 ms, pauses over 1000 ms: 0
19:20:25, accumulated pauses: 51 ms, max pause: 3 ms, pauses over 1000 ms: 0
19:20:30, accumulated pauses: 40 ms, max pause: 3 ms, pauses over 1000 ms: 0
19:20:35, accumulated pauses: 341 ms, max pause: 122 ms, pauses over 1000 ms: 0
19:20:40, accumulated pauses: 441 ms, max pause: 190 ms, pauses over 1000 ms: 0
19:20:45, accumulated pauses: 37 ms, max pause: 0 ms, pauses over 1000 ms: 0
19:20:50, accumulated pauses: 51 ms, max pause: 11 ms, pauses over 1000 ms: 0
19:20:55, accumulated pauses: 349 ms, max pause: 202 ms, pauses over 1000 ms: 0
19:21:00, accumulated pauses: 270 ms, max pause: 134 ms, pauses over 1000 ms: 0
19:21:05, accumulated pauses: 118 ms, max pause: 60 ms, pauses over 1000 ms: 0
19:21:10, accumulated pauses: 633 ms, max pause: 261 ms, pauses over 1000 ms: 0
19:21:15, accumulated pauses: 116 ms, max pause: 19 ms, pauses over 1000 ms: 0
19:21:20, accumulated pauses: 334 ms, max pause: 260 ms, pauses over 1000 ms: 0
19:21:25, accumulated pauses: 42 ms, max pause: 1 ms, pauses over 1000 ms: 0
19:21:30, accumulated pauses: 457 ms, max pause: 219 ms, pauses over 1000 ms: 0
19:21:35, accumulated pauses: 276 ms, max pause: 43 ms, pauses over 1000 ms: 0
19:21:40, accumulated pauses: 83 ms, max pause: 39 ms, pauses over 1000 ms: 0
19:21:45, accumulated pauses: 34 ms, max pause: 1 ms, pauses over 1000 ms: 0
19:21:50, accumulated pauses: 277 ms, max pause: 117 ms, pauses over 1000 ms: 0
19:21:55, accumulated pauses: 251 ms, max pause: 58 ms, pauses over 1000 ms: 0
19:22:00, accumulated pauses: 64 ms, max pause: 5 ms, pauses over 1000 ms: 0
19:22:05, accumulated pauses: 79 ms, max pause: 22 ms, pauses over 1000 ms: 0
19:22:10, accumulated pauses: 1194 ms, max pause: 833 ms, pauses over 1000 ms: 0
19:22:15, accumulated pauses: 40 ms, max pause: 3 ms, pauses over 1000 ms: 0
19:22:20, accumulated pauses: 71 ms, max pause: 19 ms, pauses over 1000 ms: 0
19:22:25, accumulated pauses: 149 ms, max pause: 70 ms, pauses over 1000 ms: 0
19:22:30, accumulated pauses: 450 ms, max pause: 212 ms, pauses over 1000 ms: 0
19:22:35, accumulated pauses: 116 ms, max pause: 18 ms, pauses over 1000 ms: 0
19:22:40, accumulated pauses: 1004 ms, max pause: 567 ms, pauses over 1000 ms: 0
19:22:45, accumulated pauses: 197 ms, max pause: 17 ms, pauses over 1000 ms: 0
19:22:50, accumulated pauses: 208 ms, max pause: 171 ms, pauses over 1000 ms: 0
19:22:55, accumulated pauses: 385 ms, max pause: 126 ms, pauses over 1000 ms: 0
19:23:00, accumulated pauses: 242 ms, max pause: 141 ms, pauses over 1000 ms: 0
19:23:05, accumulated pauses: 95 ms, max pause: 19 ms, pauses over 1000 ms: 0
19:23:10, accumulated pauses: 821 ms, max pause: 729 ms, pauses over 1000 ms: 0
19:23:15, accumulated pauses: 243 ms, max pause: 100 ms, pauses over 1000 ms: 0
19:23:20, accumulated pauses: 171 ms, max pause: 12 ms, pauses over 1000 ms: 0
19:23:25, accumulated pauses: 177 ms, max pause: 78 ms, pauses over 1000 ms: 0
19:23:30, accumulated pauses: 157 ms, max pause: 35 ms, pauses over 1000 ms: 0
19:23:35, accumulated pauses: 312 ms, max pause: 158 ms, pauses over 1000 ms: 0
19:23:40, accumulated pauses: 287 ms, max pause: 196 ms, pauses over 1000 ms: 0
19:23:45, accumulated pauses: 176 ms, max pause: 100 ms, pauses over 1000 ms: 0
19:23:50, accumulated pauses: 299 ms, max pause: 95 ms, pauses over 1000 ms: 0
19:23:55, accumulated pauses: 598 ms, max pause: 559 ms, pauses over 1000 ms: 0

[olukas]

Unfortunately test fails again -> reopen.

master (commit 620cede895c64c533e874a4061f1ddb59442d710)

It failed twice in nightly build:

• http://jenkins.hazelcast.com/job/jet-oss-master-nightly/163/testReport/com.hazelcast.jet.job/JobSubmissionSlownessRegressionTest/regressionTestForPR1488/
• http://jenkins.hazelcast.com/job/jet-oss-master-nightly/162/testReport/junit/com.hazelcast.jet.job/JobSubmissionSlownessRegressionTest/regressionTestForPR1488/

It seems that hiccups were quite big in both failed run. It can be related to the test failure.

Stacktrace:

java.lang.AssertionError: Job submission rate should not decrease. First rate: 471.6120283730513, second rate: 366.1513343986112
	at org.junit.Assert.fail(Assert.java:88)
	at org.junit.Assert.assertTrue(Assert.java:41)
	at com.hazelcast.jet.job.JobSubmissionSlownessRegressionTest.regressionTestForPR1488(JobSubmissionSlownessRegressionTest.java:116)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
	at com.hazelcast.test.FailOnTimeoutStatement$CallableStatement.call(FailOnTimeoutStatement.java:114)
	at com.hazelcast.test.FailOnTimeoutStatement$CallableStatement.call(FailOnTimeoutStatement.java:106)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.lang.Thread.run(Thread.java:748)

Standard output:

Hiccups measured while running test 'regressionTestForPR1488(com.hazelcast.jet.job.JobSubmissionSlownessRegressionTest):'
07:48:40, accumulated pauses: 221 ms, max pause: 22 ms, pauses over 1000 ms: 0
07:48:45, accumulated pauses: 293 ms, max pause: 81 ms, pauses over 1000 ms: 0
07:48:50, accumulated pauses: 222 ms, max pause: 41 ms, pauses over 1000 ms: 0
07:48:55, accumulated pauses: 343 ms, max pause: 72 ms, pauses over 1000 ms: 0
07:49:00, accumulated pauses: 298 ms, max pause: 66 ms, pauses over 1000 ms: 0
07:49:05, accumulated pauses: 328 ms, max pause: 61 ms, pauses over 1000 ms: 0
07:49:10, accumulated pauses: 292 ms, max pause: 21 ms, pauses over 1000 ms: 0
07:49:15, accumulated pauses: 293 ms, max pause: 15 ms, pauses over 1000 ms: 0
07:49:20, accumulated pauses: 315 ms, max pause: 23 ms, pauses over 1000 ms: 0
07:49:25, accumulated pauses: 400 ms, max pause: 166 ms, pauses over 1000 ms: 0
07:49:30, accumulated pauses: 289 ms, max pause: 38 ms, pauses over 1000 ms: 0
07:49:35, accumulated pauses: 352 ms, max pause: 68 ms, pauses over 1000 ms: 0
07:49:40, accumulated pauses: 243 ms, max pause: 14 ms, pauses over 1000 ms: 0
07:49:45, accumulated pauses: 348 ms, max pause: 84 ms, pauses over 1000 ms: 0
07:49:50, accumulated pauses: 397 ms, max pause: 93 ms, pauses over 1000 ms: 0
07:49:55, accumulated pauses: 444 ms, max pause: 58 ms, pauses over 1000 ms: 0
07:50:00, accumulated pauses: 676 ms, max pause: 220 ms, pauses over 1000 ms: 0
07:50:05, accumulated pauses: 463 ms, max pause: 80 ms, pauses over 1000 ms: 0
07:50:10, accumulated pauses: 405 ms, max pause: 31 ms, pauses over 1000 ms: 0
07:50:15, accumulated pauses: 365 ms, max pause: 26 ms, pauses over 1000 ms: 0
07:50:20, accumulated pauses: 558 ms, max pause: 97 ms, pauses over 1000 ms: 0
07:50:25, accumulated pauses: 544 ms, max pause: 88 ms, pauses over 1000 ms: 0
07:50:30, accumulated pauses: 448 ms, max pause: 28 ms, pauses over 1000 ms: 0
07:50:35, accumulated pauses: 591 ms, max pause: 90 ms, pauses over 1000 ms: 0
07:50:40, accumulated pauses: 557 ms, max pause: 82 ms, pauses over 1000 ms: 0
07:50:45, accumulated pauses: 430 ms, max pause: 413 ms, pauses over 1000 ms: 0

[cangencer]

I don't think there's been any changes in this area - is this still failing intermittently?

[olukas]

It's still failing intermittently - it's based on the fact that test is not deterministic. Maybe we should remove this test due to non-determinism.