[CI] QueueResizingEsThreadPoolExecutorTests.testAutoQueueSizingWithMax + thread leakage

[vladimirdolzhenko]

Log:

https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.2+periodic/704/console

REPRODUCE WITH: ./gradlew :server:test -Dtests.seed=FA63CC5EE34DF6A8 -Dtests.class=org.elasticsearch.common.util.concurrent.QueueResizingEsThreadPoolExecutorTests -Dtests.method="testAutoQueueSizingWithMax" -Dtests.security.manager=true -Dtests.locale=ru-RU -Dtests.timezone=SystemV/EST5

1> [2018-05-18T15:02:47,981][INFO ][o.e.c.u.c.QueueResizingEsThreadPoolExecutorTests] --> executor: QueueResizingEsThreadPoolExecutor[name = test-threadpool, queue capacity = 5000, min queue capacity = 10, max queue capacity = 5024, frame size = 23, targeted response rate = 1ms, task execution EWMA = 0s, adjustment amount = 50, org.elasticsearch.common.util.concurrent.QueueResizingEsThreadPoolExecutor@af1c9b0[Running, pool size = 3, active threads = 0, queued tasks = 0, completed tasks = 0]]
  1> [2018-05-18T15:02:47,982][INFO ][o.e.c.u.c.QueueResizingEsThreadPoolExecutorTests] --> executing a task [69] times
  1> [2018-05-18T15:02:57,986][INFO ][o.e.c.u.c.QueueResizingEsThreadPoolExecutorTests] [testAutoQueueSizingWithMax]: after test
FAILURE 10.0s J1 | QueueResizingEsThreadPoolExecutorTests.testAutoQueueSizingWithMax <<< FAILURES!
   > Throwable #1: java.lang.AssertionError: 
   > Expected: <5024>
   >      but: was <4974>
   > 	at __randomizedtesting.SeedInfo.seed([FA63CC5EE34DF6A8:66709390C577231B]:0)
   > 	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
   > 	at org.elasticsearch.common.util.concurrent.QueueResizingEsThreadPoolExecutorTests.lambda$testAutoQueueSizingWithMax$7(QueueResizingEsThreadPoolExecutorTests.java:180)
   > 	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:731)
   > 	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:705)
   > 	at org.elasticsearch.common.util.concurrent.QueueResizingEsThreadPoolExecutorTests.testAutoQueueSizingWithMax(QueueResizingEsThreadPoolExecutorTests.java:179)
   > 	at java.lang.Thread.run(Thread.java:748)

+ thred leakage there

2> SEVERE: 3 threads leaked from SUITE scope at org.elasticsearch.common.util.concurrent.QueueResizingEsThreadPoolExecutorTests: 
  2>    1) Thread[id=1873, name=queuetest[T#2], state=WAITING, group=TGRP-QueueResizingEsThreadPoolExecutorTests]
  2>         at sun.misc.Unsafe.park(Native Method)
  2>         at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
  2>         at java.util.concurrent.LinkedTransferQueue.awaitMatch(LinkedTransferQueue.java:737)
  2>         at java.util.concurrent.LinkedTransferQueue.xfer(LinkedTransferQueue.java:647)
  2>         at java.util.concurrent.LinkedTransferQueue.take(LinkedTransferQueue.java:1269)
  2>         at org.elasticsearch.common.util.concurrent.SizeBlockingQueue.take(SizeBlockingQueue.java:165)
  2>         at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
  2>         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
  2>         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
  2>         at java.lang.Thread.run(Thread.java:748)
  2>    2) Thread[id=1872, name=queuetest[T#1], state=WAITING, group=TGRP-QueueResizingEsThreadPoolExecutorTests]
  2>         at sun.misc.Unsafe.park(Native Method)
  2>         at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
  2>         at java.util.concurrent.LinkedTransferQueue.awaitMatch(LinkedTransferQueue.java:737)
  2>         at java.util.concurrent.LinkedTransferQueue.xfer(LinkedTransferQueue.java:647)
  2>         at java.util.concurrent.LinkedTransferQueue.take(LinkedTransferQueue.java:1269)
  2>         at org.elasticsearch.common.util.concurrent.SizeBlockingQueue.take(SizeBlockingQueue.java:165)
  2>         at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
  2>         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
  2>         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
  2>         at java.lang.Thread.run(Thread.java:748)
ERROR   0.00s J1 | QueueResizingEsThreadPoolExecutorTests (suite) <<< FAILURES!
  2>    3) Thread[id=1874, name=queuetest[T#3], state=WAITING, group=TGRP-QueueResizingEsThreadPoolExecutorTests]
   > Throwable #1: com.carrotsearch.randomizedtesting.ThreadLeakError: 3 threads leaked from SUITE scope at org.elasticsearch.common.util.concurrent.QueueResizingEsThreadPoolExecutorTests: 
  2>         at sun.misc.Unsafe.park(Native Method)

[elasticmachine]

Pinging @elastic/es-core-infra

[jasontedor]

@dakrone Would you take a look?

[dakrone]

Yep I'll take a look

[dakrone]

I pushed a commit to enable debug logging for this test, unfortunately I wasn't able to reproduce it and there's not much info from the failure currently. Hopefully if it fails again we'll have more information.

[bizybot]

Hi @dakrone, I see this failure on 6.x build.
https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.x+matrix-java-periodic/ES_BUILD_JAVA=java10,ES_RUNTIME_JAVA=java8fips,nodes=virtual&&linux/7/consoleText
I think this will have your debug logs, could you please take a look? Thank you.

[alpar-t]

Another reproduction https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.x+matrix-java-periodic/ES_BUILD_JAVA=java10,ES_RUNTIME_JAVA=java8fips,nodes=virtual&&linux/7/console

[danielmitterdorfer]

@dakrone unfortunately the commit to enable debug logging was missing on 6.x so I took the liberty of cherry-picking it for you in a204f93.

@bizybot, @atorok As a suggestion: I think it would make sense in such cases to paste the relevant log snippet here on the ticket and not just refer to the CI links because the logs are wiped after some time (IIRC the retention period is two weeks). While it is possible to get them after that period as well it can be a bit of a hassle.

For completeness, here is the snippet containing the relevant output from recent test failure referred to by Alpar above (which is actually the same link as the one from Yogesh):

  1> [2018-09-17T19:17:26,986][INFO ][o.e.c.u.c.QueueResizingEsThreadPoolExecutorTests] [testAutoQueueSizingWithMax] before test
  1> [2018-09-17T19:17:26,986][INFO ][o.e.c.u.c.QueueResizingEsThreadPoolExecutorTests] [testAutoQueueSizingWithMax] --> auto-queue with a measurement window of 29 tasks
  1> [2018-09-17T19:17:26,987][INFO ][o.e.c.u.c.QueueResizingEsThreadPoolExecutorTests] [testAutoQueueSizingWithMax] --> executor: QueueResizingEsThreadPoolExecutor[name = test-threadpool, queue capacity = 5000, min queue capacity = 10, max queue capacity = 5021, frame size = 29, targeted response rate = 1ms, task execution EWMA = 0s, adjustment amount = 50, org.elasticsearch.common.util.concurrent.QueueResizingEsThreadPoolExecutor@13a240ca[Running, pool size = 5, active threads = 1, queued tasks = 0, completed tasks = 0]]
  1> [2018-09-17T19:17:26,988][INFO ][o.e.c.u.c.QueueResizingEsThreadPoolExecutorTests] [testAutoQueueSizingWithMax] --> executing a task [87] times
  1> [2018-09-17T19:17:36,995][INFO ][o.e.c.u.c.QueueResizingEsThreadPoolExecutorTests] [testAutoQueueSizingWithMax] after test

As you see the output only contains INFO messages but no DEBUG logs.

[jakelandis]

Looks like 6.x missed the @TestLogging import, so I added it : 6c44fbb