Closed pieter-bos closed 2 weeks ago
lefou
commented
4 months ago Thanks for reporting this. Yeah, a reproducer would be nice, even if it's not small.
My suspicion is that, although the task graph is ordered, there is no guarantee that in two different task graphs all elements are ordered the same.
lefou
commented
4 months ago Besides the BSP client sending requests in parallel, do you also have parallel task processing enabled? I suspect not. It could be that the locked tasks not really depend on each other and that enabling --jobs n with n > 1 works around the locking.
To understand the issue, we should concentrate on the ordering of the task execution plan. I think the ordering of tasks is not total, which means the ordering of task that do not depend on each other is not defined. The deadlock might be obvious, if we could look at the execution plans.
pieter-bos
commented
4 months ago Still posting the stuff below in case I'm wrong, but I just now realized: isn't this stack trace from creating the actual task objects, rather than evaluating any tasks? I can reliably make a deadlock with this example:
import mill._
import scalalib._
object left extends Module {
def task = T { right.otherTask() }
def otherTask = T { 0 }
}
object right extends Module {
def task = T { left.otherTask() }
def otherTask = T { 0 }
}
object bspDummy1 extends JavaModule {
def sources = T {
left.task()
Seq.empty[PathRef]
}
}
object bspDummy2 extends JavaModule {
def resources = T {
right.task()
Seq.empty[PathRef]
}
}if I manually send buildTarget/sources for bspDummy1 and buildTarget/resosurces for bspDummy2 to a modified mill, that deliberately delays the construction of TargetImpl a bit for the appropriate tasks:
diff --git a/main/define/src/mill/define/Task.scala b/main/define/src/mill/define/Task.scala
index c8c41d746e..338d5b54ce 100644
--- a/main/define/src/mill/define/Task.scala
+++ b/main/define/src/mill/define/Task.scala
@@ -356,16 +356,39 @@ object Target extends Applicative.Applyer[Task, Task, Result, mill.api.Ctx] {
val lhs = Applicative.impl0[Task, T, mill.api.Ctx](c)(reify(Result.create(t.splice)).tree)
- mill.moduledefs.Cacher.impl0[Target[T]](c)(
- reify(
- new TargetImpl[T](
- lhs.splice,
- ctx.splice,
- rw.splice,
- taskIsPrivate.splice
+ val taskName = c.enclosingDef.symbol.fullName
+ val slowTaskConstructions = Set(
+ "millbuild.build.right.otherTask",
+ "millbuild.build.left.task",
+ "millbuild.build.left.otherTask",
+ "millbuild.build.right.task",
+ )
+
+ if(slowTaskConstructions.contains(taskName)) {
+ mill.moduledefs.Cacher.impl0[Target[T]](c)(
+ reify({
+ Thread.sleep(500)
+ new TargetImpl[T](
+ lhs.splice,
+ ctx.splice,
+ rw.splice,
+ taskIsPrivate.splice
+ )
+ })
+ )
+ } else {
+ mill.moduledefs.Cacher.impl0[Target[T]](c)(
+ reify(
+ new TargetImpl[T](
+ lhs.splice,
+ ctx.splice,
+ rw.splice,
+ taskIsPrivate.splice
+ )
)
)
- )
+ }
}
def targetResultImpl[T: c.WeakTypeTag](c: Context)(t: c.Expr[Result[T]])(This sequences the construction of task objects such that left.task and right.task wait for each other to start and lock left and right respectively, then try to call right.otherTask, left.otherTask who need to lock right, left respectively. In IntelliJ it gets more complicated because it sends all commands for all targets at once, so you need to consider that bspDummy{1,2} are locked as well, making this scheme less reliable. In any case I think this sufficiently sketches that task construction is not thread safe and/or the module lock (in Cacher.cachedTarget) is too coarse for task construction.
Just my reduced build.sc reply follows here, in case I was incorrect thinking this is about task construction:
I've reduced our build and it still reproduces about 1 in 5 times now, but it no longer needs sources / has long source generation tasks and whatnot, so I'd call it a net win :). This is with .mill-version 0.11.7 but I also tried with 0.11.6 for a bit, so it doesn't seem to matter that much. Just to avoid confusion: I just place this build.sc in a directory, have IntelliJ import it, and click the refresh button until some of the tasks in the IntelliJ dialog seem to run indefinitely. I haven't had to retry more than ~10 times. I've also tried to stabilize the deadlock with some tactical sleep calls but I had no luck.
One example of two task dependency chains (obtained from stack traces) that cause a deadlock in this example now is:
buildTargetSources - vercors.main.buildInfo.generatedSources - vercors.main.buildInfo.buildInfoSources - vercors.main.buildInfo.buildInfoMembers - vercors.main.scalaVersionbuildTargetScalacOptions - vercors.main.bspCompileClassesPath - vercors.main.compile - vercors.main.upstreamCompileOutput - vercors.main.buildInfo.compileThe former locks vercors.main.buildInfo early, then needs vercors.main later, the latter locks vercors.main early, then needs vercors.main.buildInfo later.
Besides the BSP client sending requests in parallel, do you also have parallel task processing enabled? I suspect not. It could be that the locked tasks not really depend on each other and that enabling --jobs n with n > 1 works around the locking.
No, just the default --jobs 1. How do you convince IntelliJ to use that? It seems anytime I install mill-bsp.json with --jobs 0 it does appear, but IntelliJ immediately clobbers that change when I re-import before restarting mill.
lihaoyi
commented
3 months ago Just hit this as well using IntelliJ import, on Mill's own codebase
lihaoyi
commented
3 months ago I think the issue is that concurrent lazy initialization of the module tree can cause deadlocks in a scenario like
object Foo{
val bar = Baz
}
object Baz{
val qux = Foo
}In this case, A thread accessingFoo.bar and another thread accessing Baz.qux can deadlock as follows:
FooBazFoo.bar and tries to lock BazBaz.qux and tries to lock FooNot totally sure, but that's what it seems the stack trace is describing. In the case of Mill, the objects are the Modules, and the references between the objects are the edges in the target graph, with some subtlety around laziness in the target graph that makes it not trigger every time
lihaoyi
commented
3 months ago From the stack trace, it seems the issue is that IntelliJ is asking Mill to compute both buildTargetJavacOptions and buildTargetScalacOptions concurrently in two separate requests to the same JVM. It's nothing to do with the --jobs flag which enables parallelism within a single request, and it takes place during module-initialization time before any evaluation (single-threaded or parallel) takes place. It also doesn't require any cycles in the target graph, only cycles at the module level where two modules refer to each others targets
Maybe we can put a big coarse-grained lock around BSP, so that Mill only serves one ongoing BSP request at a time? In general I don't think Mill's codebase is designed to handle concurrency at the moment, and running the requests sequentially should be fast enough due to caching that BSP-request-level parallelism isn't necessary. While we could put in the work to make the entire codebase threadsafe, it feels like just forcing a coarse-grained lock is good enough. That's what Bazel does, to an even greater extent (they disallow multiple processes running at the same time as well)
lefou
commented
3 months ago Maybe, we can lock the module-initialization phase and after that revert to the current behavior?
lihaoyi
commented
3 months ago That works too. I guess it depends on how much we really want to support concurrent evaluation. My feeling is that the long tail of concurrency issues we're going to be dealing with would outweigh the marginal benefits of occasionally being able to run the evaluator in parallel in a single JVM, which basically only happens during BSP and nowhere else (since the CLI runs concurrent Mill commands in separate JVMs anyway)
lihaoyi
commented
3 months ago One thing to consider is that because we only run parallel Mill evaluations within the same JVM in BSP, that means we should expect it to continually surface bugs that do not get caught otherwise in interactive use. If we ran Mill parallel within the same JVM in normal usage, at least both BSP and CLI would go through the same code paths, and bugs found and fixed in one would stay fixed in the other. But if we continue to have BSP go thread-parallel while CLI go process-parallel, the bugs in each case would be independent, and we would find it impossible to reproduce BSP concurrency issues via the CLI
Given that, it seems pretty clear to me that putting a coarse-grained lock around the BSP code path is the right thing to do. Better one standardized well-tested code path than having two totally different concurrency model, especially given how tricky concurrency issues are to surface, reproduce, and fix. I think if people had to make a choice between slightly-slower-BSP-import v.s. nondeterministic deadlocks and race conditions, they would pick the slightly-slower-BSP-imports every time
Importing our project via BSP seems to get stuck. Various tasks like "sources", "dependency sources" etc. sometimes stay running forever, then gets killed by IntelliJ after 10 minutes. I'd say this happens about 60% of the time, varying by machine / the weather.
Inspecting the mill process with VisualVM reports there is a deadlock:
(Full Thread Dump)
``` 2024-03-22 16:57:55 Full thread dump OpenJDK 64-Bit Server VM (18.0.2-ea+9-Ubuntu-2 mixed mode, sharing): Threads class SMR info: _java_thread_list=0x00007f8680011b80, length=30, elements={ 0x00007f870c014ec0, 0x00007f870c120aa0, 0x00007f870c121f40, 0x00007f870c129010, 0x00007f870c12a3b0, 0x00007f870c12b7b0, 0x00007f870c12d1d0, 0x00007f870c12e6f0, 0x00007f870c12fb50, 0x00007f870c147060, 0x00007f870c14ada0, 0x00007f870c14bd30, 0x00007f870c14fdf0, 0x00007f870c62ed10, 0x00007f870c6316a0, 0x00007f870c9df190, 0x00007f8628003ee0, 0x00007f865c084c60, 0x00007f865c085d80, 0x00007f865c0873f0, 0x00007f86bc000fe0, 0x00007f86603d0cb0, 0x00007f8660155830, 0x00007f866028b030, 0x00007f8624081460, 0x00007f860000dd00, 0x00007f860001d600, 0x00007f86a8026a20, 0x00007f8624081c30, 0x00007f8680011150 } "main" #1 prio=5 os_prio=0 cpu=3574,17ms elapsed=194,62s tid=0x00007f870c014ec0 nid=107718 waiting on condition [0x00007f8714bfa000] java.lang.Thread.State: WAITING (parking) at jdk.internal.misc.Unsafe.park(java.base@18.0.2-ea/Native Method) - parking to wait for <0x0000000084c00000> (a scala.concurrent.impl.CompletionLatch) at java.util.concurrent.locks.LockSupport.park(java.base@18.0.2-ea/LockSupport.java:211) at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(java.base@18.0.2-ea/AbstractQueuedSynchronizer.java:715) at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(java.base@18.0.2-ea/AbstractQueuedSynchronizer.java:1047) at scala.concurrent.impl.Promise$DefaultPromise.tryAwait0(Promise.scala:243) at scala.concurrent.impl.Promise$DefaultPromise.result(Promise.scala:261) at scala.concurrent.Await$.$anonfun$result$1(package.scala:201) at scala.concurrent.Await$$$Lambda$947/0x0000000800f3c2c0.apply(Unknown Source) at scala.concurrent.BlockContext$DefaultBlockContext$.blockOn(BlockContext.scala:62) at scala.concurrent.Await$.result(package.scala:124) at mill.bsp.worker.BspWorkerImpl$$anon$2.runSession(BspWorkerImpl.scala:71) at mill.bsp.BSP$.$anonfun$startSession$2(BSP.scala:55) at mill.bsp.BSP$$$Lambda$1578/0x0000000801037590.apply(Unknown Source) at mill.api.Result$.create(Result.scala:20) at mill.bsp.BSP$.$anonfun$startSession$1(BSP.scala:53) at mill.bsp.BSP$$$Lambda$1576/0x00000008010357c8.apply(Unknown Source) at mill.define.Task$TraverseCtx.evaluate(Task.scala:71) at mill.eval.GroupEvaluator.$anonfun$evaluateGroup$11(GroupEvaluator.scala:356) at mill.eval.GroupEvaluator$$Lambda$828/0x0000000800ee7790.apply(Unknown Source) at scala.util.DynamicVariable.withValue(DynamicVariable.scala:59) at scala.Console$.withErr(Console.scala:193) at mill.api.SystemStreams$.$anonfun$withStreams$2(SystemStreams.scala:62) at mill.api.SystemStreams$$$Lambda$28/0x0000000800cec4f0.apply(Unknown Source) at scala.util.DynamicVariable.withValue(DynamicVariable.scala:59) at scala.Console$.withOut(Console.scala:164) at mill.api.SystemStreams$.$anonfun$withStreams$1(SystemStreams.scala:61) at mill.api.SystemStreams$$$Lambda$27/0x0000000800cec248.apply(Unknown Source) at scala.util.DynamicVariable.withValue(DynamicVariable.scala:59) at scala.Console$.withIn(Console.scala:227) at mill.api.SystemStreams$.withStreams(SystemStreams.scala:60) at mill.eval.GroupEvaluator.$anonfun$evaluateGroup$8(GroupEvaluator.scala:356) at mill.eval.GroupEvaluator.$anonfun$evaluateGroup$8$adapted(GroupEvaluator.scala:325) at mill.eval.GroupEvaluator$$Lambda$826/0x0000000800ee6038.apply(Unknown Source) at scala.collection.immutable.Vector.foreach(Vector.scala:2124) at mill.eval.GroupEvaluator.computeAll$1(GroupEvaluator.scala:325) at mill.eval.GroupEvaluator.evaluateGroup(GroupEvaluator.scala:380) at mill.eval.GroupEvaluator.$anonfun$evaluateGroupCached$22(GroupEvaluator.scala:247) at mill.eval.GroupEvaluator$$Lambda$817/0x0000000800edeae8.apply(Unknown Source) at scala.util.DynamicVariable.withValue(DynamicVariable.scala:59) at mill.eval.GroupEvaluator.$anonfun$evaluateGroupCached$2(GroupEvaluator.scala:238) at mill.eval.GroupEvaluator$$Lambda$776/0x0000000800ecdf60.apply(Unknown Source) at mill.eval.GroupEvaluator$synchronizedEval$.$anonfun$apply$1(GroupEvaluator.scala:65) at mill.eval.GroupEvaluator$synchronizedEval$$$Lambda$778/0x0000000800ece8d8.apply(Unknown Source) at scala.util.Using$.resource(Using.scala:262) at mill.eval.GroupEvaluator$synchronizedEval$.apply(GroupEvaluator.scala:64) at mill.eval.GroupEvaluator.evaluateGroupCached(GroupEvaluator.scala:83) at mill.eval.GroupEvaluator.evaluateGroupCached$(GroupEvaluator.scala:71) at mill.eval.EvaluatorImpl.evaluateGroupCached(EvaluatorImpl.scala:15) at mill.eval.EvaluatorCore.$anonfun$evaluate0$2(EvaluatorCore.scala:116) at mill.eval.EvaluatorCore$$Lambda$772/0x0000000800ecc790.apply(Unknown Source) at scala.concurrent.impl.Promise$Transformation.run(Promise.scala:467) at mill.eval.ExecutionContexts$RunNow$.execute(ExecutionContexts.scala:14) at scala.concurrent.impl.Promise$Transformation.submitWithValue(Promise.scala:429) at scala.concurrent.impl.Promise$DefaultPromise.submitWithValue(Promise.scala:338) at scala.concurrent.impl.Promise$DefaultPromise.dispatchOrAddCallbacks(Promise.scala:312) at scala.concurrent.impl.Promise$DefaultPromise.map(Promise.scala:182) at mill.eval.EvaluatorCore.$anonfun$evaluate0$1(EvaluatorCore.scala:92) at mill.eval.EvaluatorCore.$anonfun$evaluate0$1$adapted(EvaluatorCore.scala:90) at mill.eval.EvaluatorCore$$Lambda$763/0x0000000800ec4c58.apply(Unknown Source) at scala.collection.immutable.Vector.foreach(Vector.scala:2124) at mill.eval.EvaluatorCore.evaluate0(EvaluatorCore.scala:90) at mill.eval.EvaluatorCore.$anonfun$evaluate$1(EvaluatorCore.scala:43) at mill.eval.EvaluatorCore$$Lambda$737/0x0000000800eb33e0.apply(Unknown Source) at scala.util.DynamicVariable.withValue(DynamicVariable.scala:59) at mill.eval.EvaluatorCore.evaluate(EvaluatorCore.scala:34) at mill.eval.EvaluatorCore.evaluate$(EvaluatorCore.scala:26) at mill.eval.EvaluatorImpl.evaluate(EvaluatorImpl.scala:15) at mill.main.RunScript$.evaluateNamed(RunScript.scala:38) at mill.main.RunScript$.$anonfun$evaluateTasksNamed$2(RunScript.scala:26) at mill.main.RunScript$$$Lambda$734/0x0000000800eb0ec8.apply(Unknown Source) at scala.util.Either.map(Either.scala:382) at mill.main.RunScript$.evaluateTasksNamed(RunScript.scala:26) at mill.runner.MillBuildBootstrap$.evaluateWithWatches(MillBuildBootstrap.scala:399) at mill.runner.MillBuildBootstrap.$anonfun$processFinalTargets$3(MillBuildBootstrap.scala:308) at mill.runner.MillBuildBootstrap$$Lambda$1553/0x0000000800f935c8.apply(Unknown Source) at scala.util.DynamicVariable.withValue(DynamicVariable.scala:59) at mill.runner.MillBuildBootstrap.processFinalTargets(MillBuildBootstrap.scala:308) at mill.runner.MillBuildBootstrap.evaluateRec(MillBuildBootstrap.scala:196) at mill.runner.MillBuildBootstrap.$anonfun$evaluate$1(MillBuildBootstrap.scala:49) at mill.runner.MillBuildBootstrap$$Lambda$191/0x0000000800dcb430.apply(Unknown Source) at scala.util.DynamicVariable.withValue(DynamicVariable.scala:59) at mill.runner.MillBuildBootstrap.evaluate(MillBuildBootstrap.scala:48) at mill.runner.MillMain$.$anonfun$main0$6(MillMain.scala:234) at mill.runner.MillMain$$$Lambda$163/0x0000000800d85b28.apply(Unknown Source) at mill.runner.Watching$.watchLoop(Watching.scala:27) at mill.runner.MillMain$.$anonfun$main0$1(MillMain.scala:219) at mill.runner.MillMain$$$Lambda$26/0x0000000800ce75a8.apply(Unknown Source) at scala.util.DynamicVariable.withValue(DynamicVariable.scala:59) at scala.Console$.withErr(Console.scala:193) at mill.api.SystemStreams$.$anonfun$withStreams$2(SystemStreams.scala:62) at mill.api.SystemStreams$$$Lambda$28/0x0000000800cec4f0.apply(Unknown Source) at scala.util.DynamicVariable.withValue(DynamicVariable.scala:59) at scala.Console$.withOut(Console.scala:164) at mill.api.SystemStreams$.$anonfun$withStreams$1(SystemStreams.scala:61) at mill.api.SystemStreams$$$Lambda$27/0x0000000800cec248.apply(Unknown Source) at scala.util.DynamicVariable.withValue(DynamicVariable.scala:59) at scala.Console$.withIn(Console.scala:227) at mill.api.SystemStreams$.withStreams(SystemStreams.scala:60) at mill.runner.MillMain$.main0(MillMain.scala:101) at mill.runner.MillMain$.liftedTree1$1(MillMain.scala:78) at mill.runner.MillMain$.main(MillMain.scala:69) at mill.runner.MillMain.main(MillMain.scala) at java.lang.invoke.LambdaForm$DMH/0x0000000800c08000.invokeStatic(java.base@18.0.2-ea/LambdaForm$DMH) at java.lang.invoke.LambdaForm$MH/0x0000000800c09400.invoke(java.base@18.0.2-ea/LambdaForm$MH) at java.lang.invoke.Invokers$Holder.invokeExact_MT(java.base@18.0.2-ea/Invokers$Holder) at jdk.internal.reflect.DirectMethodHandleAccessor.invokeImpl(java.base@18.0.2-ea/DirectMethodHandleAccessor.java:155) at jdk.internal.reflect.DirectMethodHandleAccessor.invoke(java.base@18.0.2-ea/DirectMethodHandleAccessor.java:104) at java.lang.reflect.Method.invoke(java.base@18.0.2-ea/Method.java:577) at mill.main.client.IsolatedMillMainLoader.runMain(IsolatedMillMainLoader.java:58) at mill.main.client.MillClientMain.main(MillClientMain.java:78) Locked ownable synchronizers: - None "Reference Handler" #2 daemon prio=10 os_prio=0 cpu=1,92ms elapsed=194,62s tid=0x00007f870c120aa0 nid=107725 waiting on condition [0x00007f86e1ffe000] java.lang.Thread.State: RUNNABLE at java.lang.ref.Reference.waitForReferencePendingList(java.base@18.0.2-ea/Native Method) at java.lang.ref.Reference.processPendingReferences(java.base@18.0.2-ea/Reference.java:253) at java.lang.ref.Reference$ReferenceHandler.run(java.base@18.0.2-ea/Reference.java:215) Locked ownable synchronizers: - None "Finalizer" #3 daemon prio=8 os_prio=0 cpu=0,21ms elapsed=194,62s tid=0x00007f870c121f40 nid=107726 in Object.wait() [0x00007f86cfffe000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(java.base@18.0.2-ea/Native Method) - waiting on <0x0000000080300af8> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(java.base@18.0.2-ea/ReferenceQueue.java:155) - locked <0x0000000080300af8> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(java.base@18.0.2-ea/ReferenceQueue.java:176) at java.lang.ref.Finalizer$FinalizerThread.run(java.base@18.0.2-ea/Finalizer.java:183) Locked ownable synchronizers: - None "Signal Dispatcher" #4 daemon prio=9 os_prio=0 cpu=0,37ms elapsed=194,61s tid=0x00007f870c129010 nid=107727 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE Locked ownable synchronizers: - None "Service Thread" #5 daemon prio=9 os_prio=0 cpu=1,80ms elapsed=194,61s tid=0x00007f870c12a3b0 nid=107728 runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE Locked ownable synchronizers: - None "Monitor Deflation Thread" #6 daemon prio=9 os_prio=0 cpu=4,46ms elapsed=194,61s tid=0x00007f870c12b7b0 nid=107729 runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE Locked ownable synchronizers: - None "C2 CompilerThread0" #7 daemon prio=9 os_prio=0 cpu=2765,60ms elapsed=194,61s tid=0x00007f870c12d1d0 nid=107730 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE No compile task Locked ownable synchronizers: - None "C1 CompilerThread0" #15 daemon prio=9 os_prio=0 cpu=1142,85ms elapsed=194,61s tid=0x00007f870c12e6f0 nid=107731 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE No compile task Locked ownable synchronizers: - None "Sweeper thread" #19 daemon prio=9 os_prio=0 cpu=47,90ms elapsed=194,61s tid=0x00007f870c12fb50 nid=107732 runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE Locked ownable synchronizers: - None "JDWP Transport Listener: dt_socket" #20 daemon prio=10 os_prio=0 cpu=0,13ms elapsed=194,60s tid=0x00007f870c147060 nid=107733 runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE Locked ownable synchronizers: - None "JDWP Event Helper Thread" #21 daemon prio=10 os_prio=0 cpu=0,06ms elapsed=194,60s tid=0x00007f870c14ada0 nid=107734 runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE Locked ownable synchronizers: - None "Notification Thread" #22 daemon prio=9 os_prio=0 cpu=0,03ms elapsed=194,60s tid=0x00007f870c14bd30 nid=107735 runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE Locked ownable synchronizers: - None "Common-Cleaner" #23 daemon prio=8 os_prio=0 cpu=1,77ms elapsed=194,60s tid=0x00007f870c14fdf0 nid=107737 in Object.wait() [0x00007f868fffe000] java.lang.Thread.State: TIMED_WAITING (on object monitor) at java.lang.Object.wait(java.base@18.0.2-ea/Native Method) - waiting on <0x0000000080301480> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(java.base@18.0.2-ea/ReferenceQueue.java:155) - locked <0x0000000080301480> (a java.lang.ref.ReferenceQueue$Lock) at jdk.internal.ref.CleanerImpl.run(java.base@18.0.2-ea/CleanerImpl.java:140) at java.lang.Thread.run(java.base@18.0.2-ea/Thread.java:833) at jdk.internal.misc.InnocuousThread.run(java.base@18.0.2-ea/InnocuousThread.java:162) Locked ownable synchronizers: - None "pool-1-thread-1" #25 prio=5 os_prio=0 cpu=153,29ms elapsed=193,76s tid=0x00007f870c62ed10 nid=107748 runnable [0x00007f8667ffe000] java.lang.Thread.State: RUNNABLE at java.io.FileInputStream.readBytes(java.base@18.0.2-ea/Native Method) at java.io.FileInputStream.read(java.base@18.0.2-ea/Unknown Source) at java.io.BufferedInputStream.fill(java.base@18.0.2-ea/BufferedInputStream.java:244) at java.io.BufferedInputStream.read(java.base@18.0.2-ea/BufferedInputStream.java:263) - locked <0x0000000080301cd8> (a java.io.BufferedInputStream) at org.eclipse.lsp4j.jsonrpc.json.StreamMessageProducer.listen(StreamMessageProducer.java:79) at org.eclipse.lsp4j.jsonrpc.json.ConcurrentMessageProcessor.run(ConcurrentMessageProcessor.java:113) at java.util.concurrent.Executors$RunnableAdapter.call(java.base@18.0.2-ea/Executors.java:539) at java.util.concurrent.FutureTask.run(java.base@18.0.2-ea/FutureTask.java:264) at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@18.0.2-ea/ThreadPoolExecutor.java:1136) at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@18.0.2-ea/ThreadPoolExecutor.java:635) at java.lang.Thread.run(java.base@18.0.2-ea/Thread.java:833) Locked ownable synchronizers: - <0x0000000080612a80> (a java.util.concurrent.ThreadPoolExecutor$Worker) "Thread-0" #26 prio=5 os_prio=0 cpu=0,46ms elapsed=193,76s tid=0x00007f870c6316a0 nid=107749 waiting on condition [0x00007f8665ffe000] java.lang.Thread.State: WAITING (parking) at jdk.internal.misc.Unsafe.park(java.base@18.0.2-ea/Native Method) - parking to wait for <0x0000000080600170> (a java.util.concurrent.FutureTask) at java.util.concurrent.locks.LockSupport.park(java.base@18.0.2-ea/LockSupport.java:211) at java.util.concurrent.FutureTask.awaitDone(java.base@18.0.2-ea/FutureTask.java:447) at java.util.concurrent.FutureTask.get(java.base@18.0.2-ea/FutureTask.java:190) at org.eclipse.lsp4j.jsonrpc.json.ConcurrentMessageProcessor$1.get(ConcurrentMessageProcessor.java:54) at org.eclipse.lsp4j.jsonrpc.json.ConcurrentMessageProcessor$1.get(ConcurrentMessageProcessor.java:50) at mill.bsp.worker.BspWorkerImpl.$anonfun$startBspServer$2(BspWorkerImpl.scala:86) at mill.bsp.worker.BspWorkerImpl$$Lambda$160/0x0000000800d9f518.run(Unknown Source) at java.lang.Thread.run(java.base@18.0.2-ea/Thread.java:833) Locked ownable synchronizers: - None "scala-execution-context-global-27" #27 daemon prio=5 os_prio=0 cpu=21,22ms elapsed=192,28s tid=0x00007f870c9df190 nid=107767 waiting for monitor entry [0x00007f8633ffc000] java.lang.Thread.State: BLOCKED (on object monitor) at mill.moduledefs.Cacher.cachedTarget(Cacher.scala:9) - parking to wait for <0x00000000806c37b0> (a scala.concurrent.impl.ExecutionContextImpl$$anon$3) - waiting to lock <0x0000000084c9e350> (a millbuild.build$viper$silicon$buildInfo$) at mill.moduledefs.Cacher.cachedTarget$(Cacher.scala:9) at mill.define.Module$BaseClass.cachedTarget(Module.scala:58) at mill.scalalib.JavaModule.transitiveIvyDeps(JavaModule.scala:259) at mill.scalalib.JavaModule.transitiveIvyDeps$(JavaModule.scala:259) at millbuild.build$viper$silicon$buildInfo$.transitiveIvyDeps(build.sc:104) at mill.scalalib.JavaModule.$anonfun$transitiveIvyDeps$2(JavaModule.scala:261) at mill.scalalib.JavaModule$$Lambda$621/0x0000000800e8f288.apply(Unknown Source) at scala.collection.immutable.List.map(List.scala:250) at scala.collection.immutable.List.map(List.scala:79) at mill.define.Target$.traverse(Task.scala:330) at mill.scalalib.JavaModule.$anonfun$transitiveIvyDeps$1(JavaModule.scala:261) at mill.scalalib.JavaModule$$Lambda$602/0x0000000800e8a2f8.apply(Unknown Source) at scala.collection.mutable.HashMap.getOrElseUpdate(HashMap.scala:469) at mill.moduledefs.Cacher.cachedTarget(Cacher.scala:10) - locked <0x0000000084c9cdc8> (a millbuild.build$viper$silicon$) at mill.moduledefs.Cacher.cachedTarget$(Cacher.scala:9) at mill.define.Module$BaseClass.cachedTarget(Module.scala:58) at mill.scalalib.JavaModule.transitiveIvyDeps(JavaModule.scala:259) at mill.scalalib.JavaModule.transitiveIvyDeps$(JavaModule.scala:259) at millbuild.build$viper$silicon$.transitiveIvyDeps(build.sc:103) at mill.scalalib.JavaModule.$anonfun$transitiveIvyDeps$2(JavaModule.scala:261) at mill.scalalib.JavaModule$$Lambda$621/0x0000000800e8f288.apply(Unknown Source) at scala.collection.immutable.List.map(List.scala:250) at scala.collection.immutable.List.map(List.scala:79) at mill.define.Target$.traverse(Task.scala:330) at mill.scalalib.JavaModule.$anonfun$transitiveIvyDeps$1(JavaModule.scala:261) at mill.scalalib.JavaModule$$Lambda$602/0x0000000800e8a2f8.apply(Unknown Source) at scala.collection.mutable.HashMap.getOrElseUpdate(HashMap.scala:469) at mill.moduledefs.Cacher.cachedTarget(Cacher.scala:10) - locked <0x0000000084c99ed0> (a millbuild.build$viper$) at mill.moduledefs.Cacher.cachedTarget$(Cacher.scala:9) at mill.define.Module$BaseClass.cachedTarget(Module.scala:58) at mill.scalalib.JavaModule.transitiveIvyDeps(JavaModule.scala:259) at mill.scalalib.JavaModule.transitiveIvyDeps$(JavaModule.scala:259) at millbuild.build$viper$.transitiveIvyDeps(build.sc:59) at mill.scalalib.JavaModule.$anonfun$transitiveIvyDeps$2(JavaModule.scala:261) at mill.scalalib.JavaModule$$Lambda$621/0x0000000800e8f288.apply(Unknown Source) at scala.collection.immutable.List.map(List.scala:250) at scala.collection.immutable.List.map(List.scala:79) at mill.define.Target$.traverse(Task.scala:330) at mill.scalalib.JavaModule.$anonfun$transitiveIvyDeps$1(JavaModule.scala:261) at mill.scalalib.JavaModule$$Lambda$602/0x0000000800e8a2f8.apply(Unknown Source) at scala.collection.mutable.HashMap.getOrElseUpdate(HashMap.scala:469) at mill.moduledefs.Cacher.cachedTarget(Cacher.scala:10) - locked <0x0000000084ca7848> (a millbuild.build$vercors$viperApi$) at mill.moduledefs.Cacher.cachedTarget$(Cacher.scala:9) at mill.define.Module$BaseClass.cachedTarget(Module.scala:58) at mill.scalalib.JavaModule.transitiveIvyDeps(JavaModule.scala:259) at mill.scalalib.JavaModule.transitiveIvyDeps$(JavaModule.scala:259) at millbuild.build$vercors$viperApi$.transitiveIvyDeps(build.sc:524) at mill.bsp.worker.MillBuildServer.$anonfun$buildTargetDependencySources$2(MillBuildServer.scala:346) at mill.bsp.worker.MillBuildServer$$Lambda$1648/0x00000008010559e8.apply(Unknown Source) at mill.bsp.worker.MillBuildServer.$anonfun$completableTasks$2(MillBuildServer.scala:657) at mill.bsp.worker.MillBuildServer$$Lambda$1606/0x0000000801048950.apply(Unknown Source) at scala.collection.immutable.List.map(List.scala:250) at scala.collection.immutable.List.map(List.scala:79) at mill.bsp.worker.MillBuildServer.$anonfun$completableTasks$1(MillBuildServer.scala:655) at mill.bsp.worker.MillBuildServer$$Lambda$210/0x0000000800de6ff0.apply(Unknown Source) at mill.bsp.worker.MillBuildServer.$anonfun$completable$1(MillBuildServer.scala:699) at mill.bsp.worker.MillBuildServer.$anonfun$completable$1$adapted(MillBuildServer.scala:696) at mill.bsp.worker.MillBuildServer$$Lambda$212/0x0000000800de73a8.apply(Unknown Source) at scala.concurrent.impl.Promise$Transformation.run(Promise.scala:484) at java.util.concurrent.ForkJoinTask$RunnableExecuteAction.exec(java.base@18.0.2-ea/ForkJoinTask.java:1395) at java.util.concurrent.ForkJoinTask.doExec(java.base@18.0.2-ea/ForkJoinTask.java:373) at java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(java.base@18.0.2-ea/ForkJoinPool.java:1182) at java.util.concurrent.ForkJoinPool.scan(java.base@18.0.2-ea/ForkJoinPool.java:1655) at java.util.concurrent.ForkJoinPool.runWorker(java.base@18.0.2-ea/ForkJoinPool.java:1622) at java.util.concurrent.ForkJoinWorkerThread.run(java.base@18.0.2-ea/ForkJoinWorkerThread.java:165) Locked ownable synchronizers: - None "scala-execution-context-global-28" #28 daemon prio=5 os_prio=0 cpu=1131,66ms elapsed=192,27s tid=0x00007f8628003ee0 nid=107768 waiting for monitor entry [0x00007f8631ffd000] java.lang.Thread.State: BLOCKED (on object monitor) at mill.moduledefs.Cacher.cachedTarget(Cacher.scala:9) - parking to wait for <0x00000000806c37b0> (a scala.concurrent.impl.ExecutionContextImpl$$anon$3) - waiting to lock <0x0000000084c99ed0> (a millbuild.build$viper$) at mill.moduledefs.Cacher.cachedTarget$(Cacher.scala:9) at mill.define.Module$BaseClass.cachedTarget(Module.scala:58) at mill.scalalib.JavaModule.sources(JavaModule.scala:343) at mill.scalalib.JavaModule.sources$(JavaModule.scala:343) at millbuild.build$viper$.sources(build.sc:59) at mill.bsp.worker.MillBuildServer.$anonfun$buildTargetSources$2(MillBuildServer.scala:297) at mill.bsp.worker.MillBuildServer$$Lambda$1642/0x0000000801054ed0.apply(Unknown Source) at mill.bsp.worker.MillBuildServer.$anonfun$completableTasks$2(MillBuildServer.scala:657) at mill.bsp.worker.MillBuildServer$$Lambda$1606/0x0000000801048950.apply(Unknown Source) at scala.collection.immutable.List.map(List.scala:250) at scala.collection.immutable.List.map(List.scala:79) at mill.bsp.worker.MillBuildServer.$anonfun$completableTasks$1(MillBuildServer.scala:655) at mill.bsp.worker.MillBuildServer$$Lambda$210/0x0000000800de6ff0.apply(Unknown Source) at mill.bsp.worker.MillBuildServer.$anonfun$completable$1(MillBuildServer.scala:699) at mill.bsp.worker.MillBuildServer.$anonfun$completable$1$adapted(MillBuildServer.scala:696) at mill.bsp.worker.MillBuildServer$$Lambda$212/0x0000000800de73a8.apply(Unknown Source) at scala.concurrent.impl.Promise$Transformation.run(Promise.scala:484) at java.util.concurrent.ForkJoinTask$RunnableExecuteAction.exec(java.base@18.0.2-ea/ForkJoinTask.java:1395) at java.util.concurrent.ForkJoinTask.doExec(java.base@18.0.2-ea/ForkJoinTask.java:373) at java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(java.base@18.0.2-ea/ForkJoinPool.java:1182) at java.util.concurrent.ForkJoinPool.scan(java.base@18.0.2-ea/ForkJoinPool.java:1655) at java.util.concurrent.ForkJoinPool.runWorker(java.base@18.0.2-ea/ForkJoinPool.java:1622) at java.util.concurrent.ForkJoinWorkerThread.run(java.base@18.0.2-ea/ForkJoinWorkerThread.java:165) Locked ownable synchronizers: - None "scala-execution-context-global-29" #29 daemon prio=5 os_prio=0 cpu=29,28ms elapsed=189,39s tid=0x00007f865c084c60 nid=107789 waiting for monitor entry [0x00007f860fffc000] java.lang.Thread.State: BLOCKED (on object monitor) at mill.moduledefs.Cacher.cachedTarget(Cacher.scala:9) - waiting to lock <0x0000000084c9cdc8> (a millbuild.build$viper$silicon$) at mill.moduledefs.Cacher.cachedTarget$(Cacher.scala:9) at mill.define.Module$BaseClass.cachedTarget(Module.scala:58) at millbuild.build$viper$silicon$.scalaVersion(build.sc:104) at millbuild.build$viper$silicon$buildInfo$.$anonfun$buildInfoMembers$1(build.sc:89) at millbuild.build$viper$silicon$buildInfo$$$Lambda$1871/0x000000080109a3c8.apply(Unknown Source) at scala.collection.mutable.HashMap.getOrElseUpdate(HashMap.scala:469) at mill.moduledefs.Cacher.cachedTarget(Cacher.scala:10) - locked <0x0000000084c9e350> (a millbuild.build$viper$silicon$buildInfo$) at mill.moduledefs.Cacher.cachedTarget$(Cacher.scala:9) at mill.define.Module$BaseClass.cachedTarget(Module.scala:58) at millbuild.build$viper$silicon$buildInfo$.buildInfoMembers(build.sc:85) at mill.contrib.buildinfo.BuildInfo.$anonfun$buildInfoResources$1(BuildInfo.scala:44) at mill.contrib.buildinfo.BuildInfo$$Lambda$1803/0x0000000801087838.apply(Unknown Source) at scala.collection.mutable.HashMap.getOrElseUpdate(HashMap.scala:469) at mill.moduledefs.Cacher.cachedTarget(Cacher.scala:10) - locked <0x0000000084c9e350> (a millbuild.build$viper$silicon$buildInfo$) at mill.moduledefs.Cacher.cachedTarget$(Cacher.scala:9) at mill.define.Module$BaseClass.cachedTarget(Module.scala:58) at mill.contrib.buildinfo.BuildInfo.buildInfoResources(BuildInfo.scala:42) at mill.contrib.buildinfo.BuildInfo.buildInfoResources$(BuildInfo.scala:42) at millbuild.build$viper$silicon$buildInfo$.buildInfoResources(build.sc:104) at mill.contrib.buildinfo.BuildInfo.$anonfun$resources$1(BuildInfo.scala:40) at mill.contrib.buildinfo.BuildInfo$$Lambda$1800/0x0000000801086d58.apply(Unknown Source) at scala.collection.mutable.HashMap.getOrElseUpdate(HashMap.scala:469) at mill.moduledefs.Cacher.cachedTarget(Cacher.scala:10) - locked <0x0000000084c9e350> (a millbuild.build$viper$silicon$buildInfo$) at mill.moduledefs.Cacher.cachedTarget$(Cacher.scala:9) at mill.define.Module$BaseClass.cachedTarget(Module.scala:58) at mill.contrib.buildinfo.BuildInfo.resources(BuildInfo.scala:40) at mill.contrib.buildinfo.BuildInfo.resources$(BuildInfo.scala:38) at millbuild.build$viper$silicon$buildInfo$.resources(build.sc:104) at mill.bsp.worker.MillBuildServer.$anonfun$buildTargetResources$2(MillBuildServer.scala:404) at mill.bsp.worker.MillBuildServer$$Lambda$1661/0x0000000801056730.apply(Unknown Source) at mill.bsp.worker.MillBuildServer.$anonfun$completableTasks$2(MillBuildServer.scala:657) at mill.bsp.worker.MillBuildServer$$Lambda$1606/0x0000000801048950.apply(Unknown Source) at scala.collection.immutable.List.map(List.scala:250) at scala.collection.immutable.List.map(List.scala:79) at mill.bsp.worker.MillBuildServer.$anonfun$completableTasks$1(MillBuildServer.scala:655) at mill.bsp.worker.MillBuildServer$$Lambda$210/0x0000000800de6ff0.apply(Unknown Source) at mill.bsp.worker.MillBuildServer.$anonfun$completable$1(MillBuildServer.scala:699) at mill.bsp.worker.MillBuildServer.$anonfun$completable$1$adapted(MillBuildServer.scala:696) at mill.bsp.worker.MillBuildServer$$Lambda$212/0x0000000800de73a8.apply(Unknown Source) at scala.concurrent.impl.Promise$Transformation.run(Promise.scala:484) at java.util.concurrent.ForkJoinTask$RunnableExecuteAction.exec(java.base@18.0.2-ea/ForkJoinTask.java:1395) at java.util.concurrent.ForkJoinTask.doExec(java.base@18.0.2-ea/ForkJoinTask.java:373) at java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(java.base@18.0.2-ea/ForkJoinPool.java:1182) at java.util.concurrent.ForkJoinPool.scan(java.base@18.0.2-ea/ForkJoinPool.java:1655) at java.util.concurrent.ForkJoinPool.runWorker(java.base@18.0.2-ea/ForkJoinPool.java:1622) at java.util.concurrent.ForkJoinWorkerThread.run(java.base@18.0.2-ea/ForkJoinWorkerThread.java:165) Locked ownable synchronizers: - None "scala-execution-context-global-30" #30 daemon prio=5 os_prio=0 cpu=8,48ms elapsed=189,39s tid=0x00007f865c085d80 nid=107790 waiting on condition [0x00007f860dffe000] java.lang.Thread.State: WAITING (parking) at jdk.internal.misc.Unsafe.park(java.base@18.0.2-ea/Native Method) - parking to wait for <0x00000000806c37b0> (a scala.concurrent.impl.ExecutionContextImpl$$anon$3) at java.util.concurrent.locks.LockSupport.park(java.base@18.0.2-ea/LockSupport.java:341) at java.util.concurrent.ForkJoinPool.awaitWork(java.base@18.0.2-ea/ForkJoinPool.java:1724) at java.util.concurrent.ForkJoinPool.runWorker(java.base@18.0.2-ea/ForkJoinPool.java:1623) at java.util.concurrent.ForkJoinWorkerThread.run(java.base@18.0.2-ea/ForkJoinWorkerThread.java:165) Locked ownable synchronizers: - None "scala-execution-context-global-31" #31 daemon prio=5 os_prio=0 cpu=20,97ms elapsed=189,38s tid=0x00007f865c0873f0 nid=107791 waiting for monitor entry [0x00007f860bffd000] java.lang.Thread.State: BLOCKED (on object monitor) at mill.moduledefs.Cacher.cachedTarget(Cacher.scala:9) - waiting to lock <0x0000000084ca7848> (a millbuild.build$vercors$viperApi$) at mill.moduledefs.Cacher.cachedTarget$(Cacher.scala:9) at mill.define.Module$BaseClass.cachedTarget(Module.scala:58) at mill.scalalib.ScalaModule.compile(ScalaModule.scala:280) at mill.scalalib.ScalaModule.compile$(ScalaModule.scala:280) at millbuild.build$vercors$viperApi$.compile(build.sc:524) at mill.scalalib.ScalaModule.bspCompileClassesPath(ScalaModule.scala:308) at mill.scalalib.ScalaModule.bspCompileClassesPath$(ScalaModule.scala:307) at millbuild.build$vercors$viperApi$.bspCompileClassesPath(build.sc:524) at mill.bsp.worker.MillScalaBuildServer.$anonfun$buildTargetScalacOptions$2(MillScalaBuildServer.scala:39) at mill.bsp.worker.MillScalaBuildServer$$Lambda$1685/0x00000008010649e0.apply(Unknown Source) at mill.bsp.worker.MillBuildServer.$anonfun$completableTasks$2(MillBuildServer.scala:657) at mill.bsp.worker.MillBuildServer$$Lambda$1606/0x0000000801048950.apply(Unknown Source) at scala.collection.immutable.List.map(List.scala:250) at scala.collection.immutable.List.map(List.scala:79) at mill.bsp.worker.MillBuildServer.$anonfun$completableTasks$1(MillBuildServer.scala:655) at mill.bsp.worker.MillBuildServer$$Lambda$210/0x0000000800de6ff0.apply(Unknown Source) at mill.bsp.worker.MillBuildServer.$anonfun$completable$1(MillBuildServer.scala:699) at mill.bsp.worker.MillBuildServer.$anonfun$completable$1$adapted(MillBuildServer.scala:696) at mill.bsp.worker.MillBuildServer$$Lambda$212/0x0000000800de73a8.apply(Unknown Source) at scala.concurrent.impl.Promise$Transformation.run(Promise.scala:484) at java.util.concurrent.ForkJoinTask$RunnableExecuteAction.exec(java.base@18.0.2-ea/ForkJoinTask.java:1395) at java.util.concurrent.ForkJoinTask.doExec(java.base@18.0.2-ea/ForkJoinTask.java:373) at java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(java.base@18.0.2-ea/ForkJoinPool.java:1182) at java.util.concurrent.ForkJoinPool.scan(java.base@18.0.2-ea/ForkJoinPool.java:1655) at java.util.concurrent.ForkJoinPool.runWorker(java.base@18.0.2-ea/ForkJoinPool.java:1622) at java.util.concurrent.ForkJoinWorkerThread.run(java.base@18.0.2-ea/ForkJoinWorkerThread.java:165) Locked ownable synchronizers: - None "Attach Listener" #32 daemon prio=9 os_prio=0 cpu=224,96ms elapsed=18,70s tid=0x00007f86bc000fe0 nid=108441 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE Locked ownable synchronizers: - None "JFR Recorder Thread" #33 daemon prio=5 os_prio=0 cpu=0,15ms elapsed=18,59s tid=0x00007f86603d0cb0 nid=108442 runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE Locked ownable synchronizers: - None "JFR Periodic Tasks" #34 daemon prio=9 os_prio=0 cpu=69,99ms elapsed=18,42s tid=0x00007f8660155830 nid=108449 in Object.wait() [0x00007f8605ffe000] java.lang.Thread.State: TIMED_WAITING (on object monitor) at java.lang.Object.wait(java.base@18.0.2-ea/Native Method) - waiting onIt reports:
These threads are rooted in:
mill.bsp.worker.MillBuildServer$anonfun$buildTargetDependencySources$2(MillBuildServer.scala:346)mill.bsp.worker.MillBuildServer.$anonfun$buildTargetResources$2(MillBuildServer.scala:404)respectively, so indeed two different bsp requests. Here are some lines from the
dependencySourcesstack trace from the full report above:The other stack trace has a similar sequence of cache misses, and it so happens that the other one locks the
viper.silicon.buildInfomodule earlier in the stack, and then tries to lockviper.silicon(already locked here). I don't even really understand how it's possible that tasks have cache misses like this after they are ordered, but maybe my mental model is off.I should say I'm happy to provide
build.scetc. but it's quite large, and I'm having trouble reproducing this outside IntelliJ, or with smaller examples. Maybe you already have some thoughts on the cause, or I can try a bit harder to reducebuild.sc, feel free to let me know. Thanks!