Transient failure of DruidAvaticaHandlerTest.testConcurrentQueries

[leventov]

Tests run: 18, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 73.942 sec <<< FAILURE! - in io.druid.sql.avatica.DruidAvaticaHandlerTest
testConcurrentQueries(io.druid.sql.avatica.DruidAvaticaHandlerTest)  Time elapsed: 30.822 sec  <<< ERROR!
java.lang.Exception: test timed out after 30000 milliseconds
	at sun.misc.Unsafe.park(Native Method)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:997)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1304)
	at com.google.common.util.concurrent.AbstractFuture$Sync.get(AbstractFuture.java:285)
	at com.google.common.util.concurrent.AbstractFuture.get(AbstractFuture.java:116)
	at io.druid.sql.avatica.DruidAvaticaHandlerTest.testConcurrentQueries(DruidAvaticaHandlerTest.java:398)
	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:483)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
	at org.junit.internal.runners.statements.FailOnTimeout$StatementThread.run(FailOnTimeout.java:74)

FYI @gianm

[gianm]

Might be fixed by #4415.

[jon-wei]

I think this is a separate issue from #4403, when I run DruidAvaticaHandlerTest.testConcurrentQueries, I see all of the individual query results being returned in a single JDBC frame (all the DruidStatement.nextFrame() calls have fetchOffset=0).

[gianm]

Do you also see the yielder being created in the same thread? I think that depends on whether execute or prepareAndExecute is being used. If it's execute, then even if all results are returned in one frame, the yielder could still have been created in a different thread (on an earlier call to prepare).

[jon-wei]

For that unit test, the yielders are being created and closed in the same thread (the test also uses prepareAndExecute only).

[gianm]

Okay, yeah, probably not related then.

[gianm]

I looked at a few successful travis jobs, and found that even in those successful jobs, the test often takes 15-20 seconds. So it's believable that when travis is being extra-slow, it could take 30 seconds and timeout. So this might just be a timeout issue.

I raised #4416 to increase the timeout.

[gianm]

The test only takes 8s on my machine, but I guess travis uses slower machines. It seems to take extra-long for the concurrency tests, not just in this file but also in others.