search

scala / scala-jenkins-infra

A Chef cookbook that manages Scala's CI infrastructure.
https://scala-ci.typesafe.com
Apache License 2.0
14 stars 17 forks source link

validate jobs hanging / very slow #249

Closed adriaanm closed 6 years ago

adriaanm commented 6 years ago

Here's an example of a job that seems deadlocked: https://scala-ci.typesafe.com/job/scala-2.13.x-validate-main/254/console. I've also noticed jobs running for >5 hrs (but terminating eventually).

I'll post the stack dump for the deadlocked job in a comment.

adriaanm commented 6 years ago 
jenkins@ip-172-31-2-4:~$ jps -v | grep sbt-launch
31586 sbt-launch.jar -Dsbt.global.base=/home/jenkins/workspace/scala-2.12.x-integrate-community-build/./target-0.9.11/sbt-base-dir/extractor -Dsbt.version=0.13.17 -Dsbt.override.build.repos=true -Dsbt.log.noformat=true -Ddbuild.sbt-runner.last-msg=/tmp/sbtrunner2395923364262074659lastExceptionMessage -Dsbt.repository.config=/home/jenkins/workspace/scala-2.12.x-integrate-community-build/target-0.9.11/extraction/0eab0edc0a190b697649d81667ed105d383e5a93/projects/dffc452610d7137800ed7be870ff123447e5da49/.dbuild/repositories -XX:+CMSClassUnloadingEnabled -XX:+DoEscapeAnalysis -Xms1536m -Xmx1536m -Xss2m -XX:MaxPermSize=640m -XX:ReservedCodeCacheSize=192m -Xms1g -Xmx4g -Xss2m -XX:MaxMetaspaceSize=256m

10999 sbt-launch.jar -Xms512m -Xmx1536m -Xss2m -Dsbt.override.build.repos=true -Dsbt.repository.config=/home/jenkins/workspace/scala-2.13.x-validate-main@2/scripts/sbt-repositories-config -Dstarr.version=2.13.0-pre-570f11d-SNAPSHOT

jenkins@ip-172-31-2-4:~$ jstack 10999 
2018-03-04 20:15:15
Full thread dump OpenJDK 64-Bit Server VM (25.151-b12 mixed mode):

"Attach Listener" #102 daemon prio=9 os_prio=0 tid=0x00007f93bc002000 nid=0x6f83 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"pool-8-thread-25" #101 prio=5 os_prio=0 tid=0x00007f93980ef800 nid=0x34d0 runnable [0x00007f9397ffd000]
   java.lang.Thread.State: RUNNABLE
    at scala.collection.mutable.HashTable$class.elemEquals(HashTable.scala:347)
    at scala.collection.mutable.HashMap.elemEquals(HashMap.scala:39)
    at scala.collection.mutable.HashTable$class.removeEntry(HashTable.scala:185)
    at scala.collection.mutable.HashMap.removeEntry(HashMap.scala:39)
    at scala.collection.mutable.HashMap.remove(HashMap.scala:83)
    at sbt.TestStatusReporter.startGroup(TestStatusReporter.scala:15)
    at sbt.TestRunner$$anonfun$run$2.apply(TestFramework.scala:83)
    at sbt.TestRunner$$anonfun$run$2.apply(TestFramework.scala:83)
    at sbt.TestFramework$$anonfun$safeForeach$1.apply(TestFramework.scala:107)
    at sbt.TestFramework$$anonfun$safeForeach$1.apply(TestFramework.scala:107)
    at scala.collection.immutable.List.foreach(List.scala:318)
    at sbt.TestFramework$.safeForeach(TestFramework.scala:107)
    at sbt.TestRunner.safeListenersCall(TestFramework.scala:96)
    at sbt.TestRunner.run(TestFramework.scala:83)
    at sbt.TestFramework$$anon$2$$anonfun$$init$$1$$anonfun$apply$8.apply(TestFramework.scala:202)
    at sbt.TestFramework$$anon$2$$anonfun$$init$$1$$anonfun$apply$8.apply(TestFramework.scala:202)
    at sbt.TestFramework$.sbt$TestFramework$$withContextLoader(TestFramework.scala:185)
    at sbt.TestFramework$$anon$2$$anonfun$$init$$1.apply(TestFramework.scala:202)
    at sbt.TestFramework$$anon$2$$anonfun$$init$$1.apply(TestFramework.scala:202)
    at sbt.TestFunction.apply(TestFramework.scala:207)
    at sbt.Tests$$anonfun$9.apply(Tests.scala:216)
    at sbt.Tests$$anonfun$9.apply(Tests.scala:216)
    at sbt.std.Transform$$anon$3$$anonfun$apply$2.apply(System.scala:44)
    at sbt.std.Transform$$anon$3$$anonfun$apply$2.apply(System.scala:44)
    at sbt.std.Transform$$anon$4.work(System.scala:63)
    at sbt.Execute$$anonfun$submit$1$$anonfun$apply$1.apply(Execute.scala:228)
    at sbt.Execute$$anonfun$submit$1$$anonfun$apply$1.apply(Execute.scala:228)
    at sbt.ErrorHandling$.wideConvert(ErrorHandling.scala:17)
    at sbt.Execute.work(Execute.scala:237)
    at sbt.Execute$$anonfun$submit$1.apply(Execute.scala:228)
    at sbt.Execute$$anonfun$submit$1.apply(Execute.scala:228)
    at sbt.ConcurrentRestrictions$$anon$4$$anonfun$1.apply(ConcurrentRestrictions.scala:159)
    at sbt.CompletionService$$anon$2.call(CompletionService.scala:28)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"pool-8-thread-24" #100 prio=5 os_prio=0 tid=0x00007f93980ef000 nid=0x34cf runnable [0x00007f93973f8000]
   java.lang.Thread.State: RUNNABLE
    at scala.collection.mutable.HashTable$class.elemEquals(HashTable.scala:347)
    at scala.collection.mutable.HashMap.elemEquals(HashMap.scala:39)
    at scala.collection.mutable.HashTable$class.removeEntry(HashTable.scala:185)
    at scala.collection.mutable.HashMap.removeEntry(HashMap.scala:39)
    at scala.collection.mutable.HashMap.remove(HashMap.scala:83)
    at sbt.TestStatusReporter.startGroup(TestStatusReporter.scala:15)
    at sbt.TestRunner$$anonfun$run$2.apply(TestFramework.scala:83)
    at sbt.TestRunner$$anonfun$run$2.apply(TestFramework.scala:83)
    at sbt.TestFramework$$anonfun$safeForeach$1.apply(TestFramework.scala:107)
    at sbt.TestFramework$$anonfun$safeForeach$1.apply(TestFramework.scala:107)
    at scala.collection.immutable.List.foreach(List.scala:318)
    at sbt.TestFramework$.safeForeach(TestFramework.scala:107)
    at sbt.TestRunner.safeListenersCall(TestFramework.scala:96)
    at sbt.TestRunner.run(TestFramework.scala:83)
    at sbt.TestFramework$$anon$2$$anonfun$$init$$1$$anonfun$apply$8.apply(TestFramework.scala:202)
    at sbt.TestFramework$$anon$2$$anonfun$$init$$1$$anonfun$apply$8.apply(TestFramework.scala:202)
    at sbt.TestFramework$.sbt$TestFramework$$withContextLoader(TestFramework.scala:185)
    at sbt.TestFramework$$anon$2$$anonfun$$init$$1.apply(TestFramework.scala:202)
    at sbt.TestFramework$$anon$2$$anonfun$$init$$1.apply(TestFramework.scala:202)
    at sbt.TestFunction.apply(TestFramework.scala:207)
    at sbt.Tests$$anonfun$9.apply(Tests.scala:216)
    at sbt.Tests$$anonfun$9.apply(Tests.scala:216)
    at sbt.std.Transform$$anon$3$$anonfun$apply$2.apply(System.scala:44)
    at sbt.std.Transform$$anon$3$$anonfun$apply$2.apply(System.scala:44)
    at sbt.std.Transform$$anon$4.work(System.scala:63)
    at sbt.Execute$$anonfun$submit$1$$anonfun$apply$1.apply(Execute.scala:228)
    at sbt.Execute$$anonfun$submit$1$$anonfun$apply$1.apply(Execute.scala:228)
    at sbt.ErrorHandling$.wideConvert(ErrorHandling.scala:17)
    at sbt.Execute.work(Execute.scala:237)
    at sbt.Execute$$anonfun$submit$1.apply(Execute.scala:228)
    at sbt.Execute$$anonfun$submit$1.apply(Execute.scala:228)
    at sbt.ConcurrentRestrictions$$anon$4$$anonfun$1.apply(ConcurrentRestrictions.scala:159)
    at sbt.CompletionService$$anon$2.call(CompletionService.scala:28)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"pool-8-thread-23" #99 prio=5 os_prio=0 tid=0x00007f940a489000 nid=0x34ce runnable [0x00007f9397bfb000]
   java.lang.Thread.State: RUNNABLE
    at scala.collection.mutable.HashTable$class.elemEquals(HashTable.scala:347)
    at scala.collection.mutable.HashMap.elemEquals(HashMap.scala:39)
    at scala.collection.mutable.HashTable$class.removeEntry(HashTable.scala:185)
    at scala.collection.mutable.HashMap.removeEntry(HashMap.scala:39)
    at scala.collection.mutable.HashMap.remove(HashMap.scala:83)
    at sbt.TestStatusReporter.startGroup(TestStatusReporter.scala:15)
    at sbt.TestRunner$$anonfun$run$2.apply(TestFramework.scala:83)
    at sbt.TestRunner$$anonfun$run$2.apply(TestFramework.scala:83)
    at sbt.TestFramework$$anonfun$safeForeach$1.apply(TestFramework.scala:107)
    at sbt.TestFramework$$anonfun$safeForeach$1.apply(TestFramework.scala:107)
    at scala.collection.immutable.List.foreach(List.scala:318)
    at sbt.TestFramework$.safeForeach(TestFramework.scala:107)
    at sbt.TestRunner.safeListenersCall(TestFramework.scala:96)
    at sbt.TestRunner.run(TestFramework.scala:83)
    at sbt.TestFramework$$anon$2$$anonfun$$init$$1$$anonfun$apply$8.apply(TestFramework.scala:202)
    at sbt.TestFramework$$anon$2$$anonfun$$init$$1$$anonfun$apply$8.apply(TestFramework.scala:202)
    at sbt.TestFramework$.sbt$TestFramework$$withContextLoader(TestFramework.scala:185)
    at sbt.TestFramework$$anon$2$$anonfun$$init$$1.apply(TestFramework.scala:202)
    at sbt.TestFramework$$anon$2$$anonfun$$init$$1.apply(TestFramework.scala:202)
    at sbt.TestFunction.apply(TestFramework.scala:207)
    at sbt.Tests$$anonfun$9.apply(Tests.scala:216)
    at sbt.Tests$$anonfun$9.apply(Tests.scala:216)
    at sbt.std.Transform$$anon$3$$anonfun$apply$2.apply(System.scala:44)
    at sbt.std.Transform$$anon$3$$anonfun$apply$2.apply(System.scala:44)
    at sbt.std.Transform$$anon$4.work(System.scala:63)
    at sbt.Execute$$anonfun$submit$1$$anonfun$apply$1.apply(Execute.scala:228)
    at sbt.Execute$$anonfun$submit$1$$anonfun$apply$1.apply(Execute.scala:228)
    at sbt.ErrorHandling$.wideConvert(ErrorHandling.scala:17)
    at sbt.Execute.work(Execute.scala:237)
    at sbt.Execute$$anonfun$submit$1.apply(Execute.scala:228)
    at sbt.Execute$$anonfun$submit$1.apply(Execute.scala:228)
    at sbt.ConcurrentRestrictions$$anon$4$$anonfun$1.apply(ConcurrentRestrictions.scala:159)
    at sbt.CompletionService$$anon$2.call(CompletionService.scala:28)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"pool-8-thread-22" #98 prio=5 os_prio=0 tid=0x00007f940a488000 nid=0x34cd runnable [0x00007f93a83fa000]
   java.lang.Thread.State: RUNNABLE
    at scala.collection.mutable.HashTable$class.removeEntry(HashTable.scala:185)
    at scala.collection.mutable.HashMap.removeEntry(HashMap.scala:39)
    at scala.collection.mutable.HashMap.remove(HashMap.scala:83)
    at sbt.TestStatusReporter.startGroup(TestStatusReporter.scala:15)
    at sbt.TestRunner$$anonfun$run$2.apply(TestFramework.scala:83)
    at sbt.TestRunner$$anonfun$run$2.apply(TestFramework.scala:83)
    at sbt.TestFramework$$anonfun$safeForeach$1.apply(TestFramework.scala:107)
    at sbt.TestFramework$$anonfun$safeForeach$1.apply(TestFramework.scala:107)
    at scala.collection.immutable.List.foreach(List.scala:318)
    at sbt.TestFramework$.safeForeach(TestFramework.scala:107)
    at sbt.TestRunner.safeListenersCall(TestFramework.scala:96)
    at sbt.TestRunner.run(TestFramework.scala:83)
    at sbt.TestFramework$$anon$2$$anonfun$$init$$1$$anonfun$apply$8.apply(TestFramework.scala:202)
    at sbt.TestFramework$$anon$2$$anonfun$$init$$1$$anonfun$apply$8.apply(TestFramework.scala:202)
    at sbt.TestFramework$.sbt$TestFramework$$withContextLoader(TestFramework.scala:185)
    at sbt.TestFramework$$anon$2$$anonfun$$init$$1.apply(TestFramework.scala:202)
    at sbt.TestFramework$$anon$2$$anonfun$$init$$1.apply(TestFramework.scala:202)
    at sbt.TestFunction.apply(TestFramework.scala:207)
    at sbt.Tests$$anonfun$9.apply(Tests.scala:216)
    at sbt.Tests$$anonfun$9.apply(Tests.scala:216)
    at sbt.std.Transform$$anon$3$$anonfun$apply$2.apply(System.scala:44)
    at sbt.std.Transform$$anon$3$$anonfun$apply$2.apply(System.scala:44)
    at sbt.std.Transform$$anon$4.work(System.scala:63)
    at sbt.Execute$$anonfun$submit$1$$anonfun$apply$1.apply(Execute.scala:228)
    at sbt.Execute$$anonfun$submit$1$$anonfun$apply$1.apply(Execute.scala:228)
    at sbt.ErrorHandling$.wideConvert(ErrorHandling.scala:17)
    at sbt.Execute.work(Execute.scala:237)
    at sbt.Execute$$anonfun$submit$1.apply(Execute.scala:228)
    at sbt.Execute$$anonfun$submit$1.apply(Execute.scala:228)
    at sbt.ConcurrentRestrictions$$anon$4$$anonfun$1.apply(ConcurrentRestrictions.scala:159)
    at sbt.CompletionService$$anon$2.call(CompletionService.scala:28)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"pool-8-thread-21" #97 prio=5 os_prio=0 tid=0x00007f94094f9800 nid=0x34cc runnable [0x00007f93955f7000]
   java.lang.Thread.State: RUNNABLE
    at scala.collection.mutable.HashTable$class.removeEntry(HashTable.scala:187)
    at scala.collection.mutable.HashMap.removeEntry(HashMap.scala:39)
    at scala.collection.mutable.HashMap.remove(HashMap.scala:83)
    at sbt.TestStatusReporter.startGroup(TestStatusReporter.scala:15)
    at sbt.TestRunner$$anonfun$run$2.apply(TestFramework.scala:83)
    at sbt.TestRunner$$anonfun$run$2.apply(TestFramework.scala:83)
    at sbt.TestFramework$$anonfun$safeForeach$1.apply(TestFramework.scala:107)
    at sbt.TestFramework$$anonfun$safeForeach$1.apply(TestFramework.scala:107)
    at scala.collection.immutable.List.foreach(List.scala:318)
    at sbt.TestFramework$.safeForeach(TestFramework.scala:107)
    at sbt.TestRunner.safeListenersCall(TestFramework.scala:96)
    at sbt.TestRunner.run(TestFramework.scala:83)
    at sbt.TestFramework$$anon$2$$anonfun$$init$$1$$anonfun$apply$8.apply(TestFramework.scala:202)
    at sbt.TestFramework$$anon$2$$anonfun$$init$$1$$anonfun$apply$8.apply(TestFramework.scala:202)
    at sbt.TestFramework$.sbt$TestFramework$$withContextLoader(TestFramework.scala:185)
    at sbt.TestFramework$$anon$2$$anonfun$$init$$1.apply(TestFramework.scala:202)
    at sbt.TestFramework$$anon$2$$anonfun$$init$$1.apply(TestFramework.scala:202)
    at sbt.TestFunction.apply(TestFramework.scala:207)
    at sbt.Tests$$anonfun$9.apply(Tests.scala:216)
    at sbt.Tests$$anonfun$9.apply(Tests.scala:216)
    at sbt.std.Transform$$anon$3$$anonfun$apply$2.apply(System.scala:44)
    at sbt.std.Transform$$anon$3$$anonfun$apply$2.apply(System.scala:44)
    at sbt.std.Transform$$anon$4.work(System.scala:63)
    at sbt.Execute$$anonfun$submit$1$$anonfun$apply$1.apply(Execute.scala:228)
    at sbt.Execute$$anonfun$submit$1$$anonfun$apply$1.apply(Execute.scala:228)
    at sbt.ErrorHandling$.wideConvert(ErrorHandling.scala:17)
    at sbt.Execute.work(Execute.scala:237)
    at sbt.Execute$$anonfun$submit$1.apply(Execute.scala:228)
    at sbt.Execute$$anonfun$submit$1.apply(Execute.scala:228)
    at sbt.ConcurrentRestrictions$$anon$4$$anonfun$1.apply(ConcurrentRestrictions.scala:159)
    at sbt.CompletionService$$anon$2.call(CompletionService.scala:28)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"pool-8-thread-19" #95 prio=5 os_prio=0 tid=0x00007f9409287800 nid=0x34ca runnable [0x00007f9397dfc000]
   java.lang.Thread.State: RUNNABLE
    at scala.runtime.ScalaRunTime$.hash(ScalaRunTime.scala:210)
    at scala.collection.mutable.HashTable$HashUtils$class.elemHashCode(HashTable.scala:398)
    at scala.collection.mutable.HashMap.elemHashCode(HashMap.scala:39)
    at scala.collection.mutable.HashTable$class.resize(HashTable.scala:253)
    at scala.collection.mutable.HashTable$class.scala$collection$mutable$HashTable$$addEntry0(HashTable.scala:151)
    at scala.collection.mutable.HashTable$class.findOrAddEntry(HashTable.scala:163)
    at scala.collection.mutable.HashMap.findOrAddEntry(HashMap.scala:39)
    at scala.collection.mutable.HashMap.put(HashMap.scala:75)
    at scala.collection.mutable.HashMap.update(HashMap.scala:80)
    at sbt.TestStatusReporter.endGroup(TestStatusReporter.scala:20)
    at sbt.TestRunner$$anonfun$run$3.apply(TestFramework.scala:86)
    at sbt.TestRunner$$anonfun$run$3.apply(TestFramework.scala:86)
    at sbt.TestFramework$$anonfun$safeForeach$1.apply(TestFramework.scala:107)
    at sbt.TestFramework$$anonfun$safeForeach$1.apply(TestFramework.scala:107)
    at scala.collection.immutable.List.foreach(List.scala:318)
    at sbt.TestFramework$.safeForeach(TestFramework.scala:107)
    at sbt.TestRunner.safeListenersCall(TestFramework.scala:96)
    at sbt.TestRunner.run(TestFramework.scala:86)
    at sbt.TestFramework$$anon$2$$anonfun$$init$$1$$anonfun$apply$8.apply(TestFramework.scala:202)
    at sbt.TestFramework$$anon$2$$anonfun$$init$$1$$anonfun$apply$8.apply(TestFramework.scala:202)
    at sbt.TestFramework$.sbt$TestFramework$$withContextLoader(TestFramework.scala:185)
    at sbt.TestFramework$$anon$2$$anonfun$$init$$1.apply(TestFramework.scala:202)
    at sbt.TestFramework$$anon$2$$anonfun$$init$$1.apply(TestFramework.scala:202)
    at sbt.TestFunction.apply(TestFramework.scala:207)
    at sbt.Tests$$anonfun$9.apply(Tests.scala:216)
    at sbt.Tests$$anonfun$9.apply(Tests.scala:216)
    at sbt.std.Transform$$anon$3$$anonfun$apply$2.apply(System.scala:44)
    at sbt.std.Transform$$anon$3$$anonfun$apply$2.apply(System.scala:44)
    at sbt.std.Transform$$anon$4.work(System.scala:63)
    at sbt.Execute$$anonfun$submit$1$$anonfun$apply$1.apply(Execute.scala:228)
    at sbt.Execute$$anonfun$submit$1$$anonfun$apply$1.apply(Execute.scala:228)
    at sbt.ErrorHandling$.wideConvert(ErrorHandling.scala:17)
    at sbt.Execute.work(Execute.scala:237)
    at sbt.Execute$$anonfun$submit$1.apply(Execute.scala:228)
    at sbt.Execute$$anonfun$submit$1.apply(Execute.scala:228)
    at sbt.ConcurrentRestrictions$$anon$4$$anonfun$1.apply(ConcurrentRestrictions.scala:159)
    at sbt.CompletionService$$anon$2.call(CompletionService.scala:28)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"pool-8-thread-17" #93 prio=5 os_prio=0 tid=0x00007f940a143800 nid=0x34c8 runnable [0x00007f93977f9000]
   java.lang.Thread.State: RUNNABLE
    at scala.collection.mutable.HashTable$class.removeEntry(HashTable.scala:187)
    at scala.collection.mutable.HashMap.removeEntry(HashMap.scala:39)
    at scala.collection.mutable.HashMap.remove(HashMap.scala:83)
    at sbt.TestStatusReporter.startGroup(TestStatusReporter.scala:15)
    at sbt.TestRunner$$anonfun$run$2.apply(TestFramework.scala:83)
    at sbt.TestRunner$$anonfun$run$2.apply(TestFramework.scala:83)
    at sbt.TestFramework$$anonfun$safeForeach$1.apply(TestFramework.scala:107)
    at sbt.TestFramework$$anonfun$safeForeach$1.apply(TestFramework.scala:107)
    at scala.collection.immutable.List.foreach(List.scala:318)
    at sbt.TestFramework$.safeForeach(TestFramework.scala:107)
    at sbt.TestRunner.safeListenersCall(TestFramework.scala:96)
    at sbt.TestRunner.run(TestFramework.scala:83)
    at sbt.TestFramework$$anon$2$$anonfun$$init$$1$$anonfun$apply$8.apply(TestFramework.scala:202)
    at sbt.TestFramework$$anon$2$$anonfun$$init$$1$$anonfun$apply$8.apply(TestFramework.scala:202)
    at sbt.TestFramework$.sbt$TestFramework$$withContextLoader(TestFramework.scala:185)
    at sbt.TestFramework$$anon$2$$anonfun$$init$$1.apply(TestFramework.scala:202)
    at sbt.TestFramework$$anon$2$$anonfun$$init$$1.apply(TestFramework.scala:202)
    at sbt.TestFunction.apply(TestFramework.scala:207)
    at sbt.Tests$$anonfun$9.apply(Tests.scala:216)
    at sbt.Tests$$anonfun$9.apply(Tests.scala:216)
    at sbt.std.Transform$$anon$3$$anonfun$apply$2.apply(System.scala:44)
    at sbt.std.Transform$$anon$3$$anonfun$apply$2.apply(System.scala:44)
    at sbt.std.Transform$$anon$4.work(System.scala:63)
    at sbt.Execute$$anonfun$submit$1$$anonfun$apply$1.apply(Execute.scala:228)
    at sbt.Execute$$anonfun$submit$1$$anonfun$apply$1.apply(Execute.scala:228)
    at sbt.ErrorHandling$.wideConvert(ErrorHandling.scala:17)
    at sbt.Execute.work(Execute.scala:237)
    at sbt.Execute$$anonfun$submit$1.apply(Execute.scala:228)
    at sbt.Execute$$anonfun$submit$1.apply(Execute.scala:228)
    at sbt.ConcurrentRestrictions$$anon$4$$anonfun$1.apply(ConcurrentRestrictions.scala:159)
    at sbt.CompletionService$$anon$2.call(CompletionService.scala:28)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"pool-8-thread-14" #85 prio=5 os_prio=0 tid=0x00007f9408efd800 nid=0x2f5a runnable [0x00007f93953f6000]
   java.lang.Thread.State: RUNNABLE
    at scala.collection.mutable.HashTable$class.elemEquals(HashTable.scala:347)
    at scala.collection.mutable.HashMap.elemEquals(HashMap.scala:39)
    at scala.collection.mutable.HashTable$class.removeEntry(HashTable.scala:185)
    at scala.collection.mutable.HashMap.removeEntry(HashMap.scala:39)
    at scala.collection.mutable.HashMap.remove(HashMap.scala:83)
    at sbt.TestStatusReporter.startGroup(TestStatusReporter.scala:15)
    at sbt.TestRunner$$anonfun$run$2.apply(TestFramework.scala:83)
    at sbt.TestRunner$$anonfun$run$2.apply(TestFramework.scala:83)
    at sbt.TestFramework$$anonfun$safeForeach$1.apply(TestFramework.scala:107)
    at sbt.TestFramework$$anonfun$safeForeach$1.apply(TestFramework.scala:107)
    at scala.collection.immutable.List.foreach(List.scala:318)
    at sbt.TestFramework$.safeForeach(TestFramework.scala:107)
    at sbt.TestRunner.safeListenersCall(TestFramework.scala:96)
    at sbt.TestRunner.run(TestFramework.scala:83)
    at sbt.TestFramework$$anon$2$$anonfun$$init$$1$$anonfun$apply$8.apply(TestFramework.scala:202)
    at sbt.TestFramework$$anon$2$$anonfun$$init$$1$$anonfun$apply$8.apply(TestFramework.scala:202)
    at sbt.TestFramework$.sbt$TestFramework$$withContextLoader(TestFramework.scala:185)
    at sbt.TestFramework$$anon$2$$anonfun$$init$$1.apply(TestFramework.scala:202)
    at sbt.TestFramework$$anon$2$$anonfun$$init$$1.apply(TestFramework.scala:202)
    at sbt.TestFunction.apply(TestFramework.scala:207)
    at sbt.Tests$$anonfun$9.apply(Tests.scala:216)
    at sbt.Tests$$anonfun$9.apply(Tests.scala:216)
    at sbt.std.Transform$$anon$3$$anonfun$apply$2.apply(System.scala:44)
    at sbt.std.Transform$$anon$3$$anonfun$apply$2.apply(System.scala:44)
    at sbt.std.Transform$$anon$4.work(System.scala:63)
    at sbt.Execute$$anonfun$submit$1$$anonfun$apply$1.apply(Execute.scala:228)
    at sbt.Execute$$anonfun$submit$1$$anonfun$apply$1.apply(Execute.scala:228)
    at sbt.ErrorHandling$.wideConvert(ErrorHandling.scala:17)
    at sbt.Execute.work(Execute.scala:237)
    at sbt.Execute$$anonfun$submit$1.apply(Execute.scala:228)
    at sbt.Execute$$anonfun$submit$1.apply(Execute.scala:228)
    at sbt.ConcurrentRestrictions$$anon$4$$anonfun$1.apply(ConcurrentRestrictions.scala:159)
    at sbt.CompletionService$$anon$2.call(CompletionService.scala:28)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"Service Thread" #9 daemon prio=9 os_prio=0 tid=0x00007f9408212800 nid=0x2b09 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C1 CompilerThread3" #8 daemon prio=9 os_prio=0 tid=0x00007f9408205800 nid=0x2b08 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread2" #7 daemon prio=9 os_prio=0 tid=0x00007f9408201000 nid=0x2b07 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" #6 daemon prio=9 os_prio=0 tid=0x00007f94081ff000 nid=0x2b06 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #5 daemon prio=9 os_prio=0 tid=0x00007f94081fc000 nid=0x2b05 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" #4 daemon prio=9 os_prio=0 tid=0x00007f94081fa000 nid=0x2b04 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007f94081d3000 nid=0x2b03 in Object.wait() [0x00007f93d29e9000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000000a00126d0> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
    - locked <0x00000000a00126d0> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)
    at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)

"Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007f94081ce800 nid=0x2b02 in Object.wait() [0x00007f93d2bea000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000000a001a528> (a java.lang.ref.Reference$Lock)
    at java.lang.Object.wait(Object.java:502)
    at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
    - locked <0x00000000a001a528> (a java.lang.ref.Reference$Lock)
    at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)

"main" #1 prio=5 os_prio=0 tid=0x00007f940800a000 nid=0x2af8 waiting on condition [0x00007f940d8d6000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000a3cb4150> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ExecutorCompletionService.take(ExecutorCompletionService.java:193)
    at sbt.ConcurrentRestrictions$$anon$4.take(ConcurrentRestrictions.scala:188)
    at sbt.Execute.next$1(Execute.scala:85)
    at sbt.Execute.processAll(Execute.scala:88)
    at sbt.Execute.runKeep(Execute.scala:68)
    at sbt.EvaluateTask$.liftedTree1$1(EvaluateTask.scala:359)
    at sbt.EvaluateTask$.run$1(EvaluateTask.scala:358)
    at sbt.EvaluateTask$.runTask(EvaluateTask.scala:378)
    at sbt.Aggregation$$anonfun$3.apply(Aggregation.scala:69)
    at sbt.Aggregation$$anonfun$3.apply(Aggregation.scala:67)
    at sbt.EvaluateTask$.withStreams(EvaluateTask.scala:314)
    at sbt.Aggregation$.timedRun(Aggregation.scala:67)
    at sbt.Aggregation$.runTasks(Aggregation.scala:76)
    at sbt.Aggregation$$anonfun$applyTasks$1.apply(Aggregation.scala:37)
    at sbt.Aggregation$$anonfun$applyTasks$1.apply(Aggregation.scala:36)
    at sbt.Command$$anonfun$applyEffect$2$$anonfun$apply$3.apply(Command.scala:61)
    at sbt.Command$$anonfun$applyEffect$2$$anonfun$apply$3.apply(Command.scala:61)
    at sbt.Aggregation$$anonfun$evaluatingParser$4$$anonfun$apply$5.apply(Aggregation.scala:158)
    at sbt.Aggregation$$anonfun$evaluatingParser$4$$anonfun$apply$5.apply(Aggregation.scala:157)
    at sbt.Act$$anonfun$sbt$Act$$actParser0$1$$anonfun$sbt$Act$$anonfun$$evaluate$1$1$$anonfun$apply$10.apply(Act.scala:253)
    at sbt.Act$$anonfun$sbt$Act$$actParser0$1$$anonfun$sbt$Act$$anonfun$$evaluate$1$1$$anonfun$apply$10.apply(Act.scala:250)
    at sbt.Command$.process(Command.scala:93)
    at sbt.MainLoop$$anonfun$1$$anonfun$apply$1.apply(MainLoop.scala:96)
    at sbt.MainLoop$$anonfun$1$$anonfun$apply$1.apply(MainLoop.scala:96)
    at sbt.State$$anon$1.runCmd$1(State.scala:183)
    at sbt.State$$anon$1.process(State.scala:187)
    at sbt.MainLoop$$anonfun$1.apply(MainLoop.scala:96)
    at sbt.MainLoop$$anonfun$1.apply(MainLoop.scala:96)
    at sbt.ErrorHandling$.wideConvert(ErrorHandling.scala:17)
    at sbt.MainLoop$.next(MainLoop.scala:96)
    at sbt.MainLoop$.run(MainLoop.scala:89)
    at sbt.MainLoop$$anonfun$runWithNewLog$1.apply(MainLoop.scala:68)
    at sbt.MainLoop$$anonfun$runWithNewLog$1.apply(MainLoop.scala:63)
    at sbt.Using.apply(Using.scala:24)
    at sbt.MainLoop$.runWithNewLog(MainLoop.scala:63)
    at sbt.MainLoop$.runAndClearLast(MainLoop.scala:46)
    at sbt.MainLoop$.runLoggedLoop(MainLoop.scala:30)
    at sbt.MainLoop$.runLogged(MainLoop.scala:22)
    at sbt.StandardMain$.runManaged(Main.scala:61)
    at sbt.xMain.run(Main.scala:35)
    at xsbt.boot.Launch$$anonfun$run$1.apply(Launch.scala:109)
    at xsbt.boot.Launch$.withContextLoader(Launch.scala:128)
    at xsbt.boot.Launch$.run(Launch.scala:109)
    at xsbt.boot.Launch$$anonfun$apply$1.apply(Launch.scala:35)
    at xsbt.boot.Launch$.launch(Launch.scala:117)
    at xsbt.boot.Launch$.apply(Launch.scala:18)
    at xsbt.boot.Boot$.runImpl(Boot.scala:41)
    at xsbt.boot.Boot$.main(Boot.scala:17)
    at xsbt.boot.Boot.main(Boot.scala)

"VM Thread" os_prio=0 tid=0x00007f94081c7000 nid=0x2b01 runnable 

"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007f940801f000 nid=0x2af9 runnable 

"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00007f9408021000 nid=0x2afa runnable 

"GC task thread#2 (ParallelGC)" os_prio=0 tid=0x00007f9408022800 nid=0x2afb runnable 

"GC task thread#3 (ParallelGC)" os_prio=0 tid=0x00007f9408024800 nid=0x2afc runnable 

"GC task thread#4 (ParallelGC)" os_prio=0 tid=0x00007f9408026000 nid=0x2afd runnable 

"GC task thread#5 (ParallelGC)" os_prio=0 tid=0x00007f9408028000 nid=0x2afe runnable 

"GC task thread#6 (ParallelGC)" os_prio=0 tid=0x00007f9408029800 nid=0x2aff runnable 

"GC task thread#7 (ParallelGC)" os_prio=0 tid=0x00007f940802b800 nid=0x2b00 runnable 

"VM Periodic Task Thread" os_prio=0 tid=0x00007f9408215000 nid=0x2b0a waiting on condition 

JNI global references: 8443

jenkins@ip-172-31-2-4:~$
retronym commented 6 years ago

This looks like either a latent thread safety bug in SBT's test infrastructure, or a usage bug in our build where we end up with an intentionally non-threadsafe TestStatusListener shared between concurrent test tasks.

retronym commented 6 years ago

Inspection of the stack trace suggests that we're looking at the scalacheck:test task, which does not fork a JVM for its tests like partest and junit:test.

I attached a debugger with a logging break point set at startGroup, which suspends the current thread. The log output shows that other threads pile up at that point on the same instance.

image

image

So this appears to be an sbt bug. I've proposed a fix in

I'll propose a workaround for our build. I was going to say, let's just fork them, but then checked the history and found:

https://github.com/scala/scala/commit/71f9b43c9eb9a3bb8ee16619c432da35609f23bc

Avoid forking Scalacheck tests when run by SBT to avoid a bug in Scalacheck itself that doensn't report failures. We've been exposed to this since the refactoring that stopped using partest to manage scalacheck test execution.

We can turn off intra-test-suite parallelism in the scalacheck suite instead.

NthPortal commented 6 years ago

Another job hanging in ScalaCheck https://scala-ci.typesafe.com/job/scala-2.13.x-validate-main/385/

retronym commented 6 years ago

I forgot to include a timeout in the reworked validate-main jobs, I need to do this as a backstop for this an future build hangs. I think it needs to be configured within the pipeline script now.

SethTisue commented 6 years ago

I aborted several stuck jobs just now.

SethTisue commented 6 years ago

hasn't been happening lately.