scalacenter/bloop

Bloop CLI hangs after several runs

brunofarache opened this issue · 4 comments

We noticed Bloop's CLI starts hanging after several project compilations at this line: Compiled ${project.name} (${durationMs}ms).

The only to fix it is to restart the server.

Took some thread dumps:
threaddump-1667905915033.tgz

Apparently there are many threads hanging on cleanUpNonStableCliDirectories:

def cleanUpNonStableCliDirectories(
client: CliClientInfo,
out: PrintStream
): Task[Unit] = {
if (client.useStableCliDirs) Task.unit
else {
val deleteTasks = client.getCreatedCliDirectories.map { freshDir =>
if (!freshDir.exists) Task.unit
else {
out.println(s"Preparing to delete dir ${freshDir}")
Task.eval(Paths.delete(freshDir)).asyncBoundary
}
}
val groups = deleteTasks
.grouped(4)
.map(group => Task.gatherUnordered(group).map(_ => ()))
.toList
Task
.sequence(groups)
.map(_ => ())
.executeOn(ExecutionContext.ioScheduler)
}
}
.

"scala-execution-context-global-1657" #1657 daemon prio=5 os_prio=31 cpu=5.70ms elapsed=3929.90s tid=0x00007fc1d8013800 nid=0x8b17 waiting for monitor entry  [0x0000700014968000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at java.io.PrintStream.println(java.base@11.0.11/PrintStream.java:881)
	- waiting to lock <0x000000060001b920> (a java.io.PrintStream)
	at bloop.Cli$.$anonfun$cleanUpNonStableCliDirectories$1(Cli.scala:441)
	at bloop.Cli$.$anonfun$cleanUpNonStableCliDirectories$1$adapted(Cli.scala:438)
	at bloop.Cli$$$Lambda$5185/0x0000000801358840.apply(Unknown Source)
	at scala.collection.immutable.List.map(List.scala:293)
	at bloop.Cli$.cleanUpNonStableCliDirectories(Cli.scala:438)
	at bloop.Cli$.$anonfun$runWithState$3(Cli.scala:374)
	at bloop.Cli$$$Lambda$271/0x0000000800282040.apply(Unknown Source)
	at monix.eval.internal.TaskRunLoop$.monix$eval$internal$TaskRunLoop$$loop$1(TaskRunLoop.scala:220)
	at monix.eval.internal.TaskRunLoop$RestartCallback$1.onSuccess(TaskRunLoop.scala:119)
	at monix.eval.Callback$Extensions$.monix$eval$Callback$Extensions$$$anonfun$asyncOnSuccess$1(Callback.scala:100)
	at monix.eval.Callback$Extensions$$anonfun$asyncOnSuccess$extension$1.run(Callback.scala:100)
	at monix.execution.schedulers.TrampolineExecutionContext.monix$execution$schedulers$TrampolineExecutionContext$$localRunLoop(TrampolineExecutionContext.scala:109)
	at monix.execution.schedulers.TrampolineExecutionContext.startLoopOptimal(TrampolineExecutionContext.scala:93)
	at monix.execution.schedulers.TrampolineExecutionContext.execute(TrampolineExecutionContext.scala:78)
	at monix.execution.schedulers.BatchingScheduler.execute(BatchingScheduler.scala:50)
	at monix.execution.schedulers.BatchingScheduler.execute$(BatchingScheduler.scala:47)
	at monix.execution.schedulers.AsyncScheduler.execute(AsyncScheduler.scala:29)
	at monix.execution.schedulers.ExecuteExtensions.executeTrampolined(ExecuteExtensions.scala:86)
	at monix.execution.schedulers.ExecuteExtensions.executeTrampolined$(ExecuteExtensions.scala:85)
	at monix.execution.Scheduler$Extensions.executeTrampolined(Scheduler.scala:187)
	at monix.eval.Callback$Extensions$.asyncOnSuccess$extension(Callback.scala:100)
	at monix.eval.internal.TaskDoOnCancel$$anon$1.onSuccess(TaskDoOnCancel.scala:38)
	at monix.eval.internal.TaskRunLoop$.monix$eval$internal$TaskRunLoop$$loop$1(TaskRunLoop.scala:174)
	at monix.eval.internal.TaskRunLoop$RestartCallback$1.onSuccess(TaskRunLoop.scala:119)
	at monix.eval.Task$.$anonfun$forkedUnit$2(Task.scala:1463)
	at monix.eval.Task$$$Lambda$291/0x00000008002a8440.run(Unknown Source)
	at java.util.concurrent.ForkJoinTask$RunnableExecuteAction.exec(java.base@11.0.11/ForkJoinTask.java:1426)
	at java.util.concurrent.ForkJoinTask.doExec(java.base@11.0.11/ForkJoinTask.java:290)
	at java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(java.base@11.0.11/ForkJoinPool.java:1020)
	at java.util.concurrent.ForkJoinPool.scan(java.base@11.0.11/ForkJoinPool.java:1656)
	at java.util.concurrent.ForkJoinPool.runWorker(java.base@11.0.11/ForkJoinPool.java:1594)
	at java.util.concurrent.ForkJoinWorkerThread.run(java.base@11.0.11/ForkJoinWorkerThread.java:183)

   Locked ownable synchronizers:
	- None

"scala-execution-context-global-1658" #1658 daemon prio=5 os_prio=31 cpu=509.99ms elapsed=3929.90s tid=0x00007fc188380800 nid=0x7d6b runnable  [0x0000700015571000]
   java.lang.Thread.State: RUNNABLE
	at java.io.FileOutputStream.writeBytes(java.base@11.0.11/Native Method)
	at java.io.FileOutputStream.write(java.base@11.0.11/FileOutputStream.java:354)
	at java.io.BufferedOutputStream.write(java.base@11.0.11/BufferedOutputStream.java:123)
	- locked <0x000000060001b948> (a java.io.BufferedOutputStream)
	at java.io.PrintStream.write(java.base@11.0.11/PrintStream.java:559)
	- locked <0x000000060001b920> (a java.io.PrintStream)
	at sun.nio.cs.StreamEncoder.writeBytes(java.base@11.0.11/StreamEncoder.java:233)
	at sun.nio.cs.StreamEncoder.implFlushBuffer(java.base@11.0.11/StreamEncoder.java:312)
	at sun.nio.cs.StreamEncoder.flushBuffer(java.base@11.0.11/StreamEncoder.java:104)
	- locked <0x000000060001baa0> (a java.io.OutputStreamWriter)
	at java.io.OutputStreamWriter.flushBuffer(java.base@11.0.11/OutputStreamWriter.java:181)
	at java.io.PrintStream.write(java.base@11.0.11/PrintStream.java:606)
	- locked <0x000000060001b920> (a java.io.PrintStream)
	at java.io.PrintStream.print(java.base@11.0.11/PrintStream.java:745)
	at java.io.PrintStream.println(java.base@11.0.11/PrintStream.java:882)
	- locked <0x000000060001b920> (a java.io.PrintStream)
	at bloop.Cli$.$anonfun$cleanUpNonStableCliDirectories$1(Cli.scala:441)
	at bloop.Cli$.$anonfun$cleanUpNonStableCliDirectories$1$adapted(Cli.scala:438)
	at bloop.Cli$$$Lambda$5185/0x0000000801358840.apply(Unknown Source)
	at scala.collection.immutable.List.map(List.scala:297)
	at bloop.Cli$.cleanUpNonStableCliDirectories(Cli.scala:438)
	at bloop.Cli$.$anonfun$runWithState$3(Cli.scala:374)
	at bloop.Cli$$$Lambda$271/0x0000000800282040.apply(Unknown Source)
	at monix.eval.internal.TaskRunLoop$.monix$eval$internal$TaskRunLoop$$loop$1(TaskRunLoop.scala:220)
	at monix.eval.internal.TaskRunLoop$RestartCallback$1.onSuccess(TaskRunLoop.scala:119)
	at monix.eval.Callback$Extensions$.monix$eval$Callback$Extensions$$$anonfun$asyncOnSuccess$1(Callback.scala:100)
	at monix.eval.Callback$Extensions$$anonfun$asyncOnSuccess$extension$1.run(Callback.scala:100)
	at monix.execution.schedulers.TrampolineExecutionContext.monix$execution$schedulers$TrampolineExecutionContext$$localRunLoop(TrampolineExecutionContext.scala:109)
	at monix.execution.schedulers.TrampolineExecutionContext.startLoopOptimal(TrampolineExecutionContext.scala:93)
	at monix.execution.schedulers.TrampolineExecutionContext.execute(TrampolineExecutionContext.scala:78)
	at monix.execution.schedulers.BatchingScheduler.execute(BatchingScheduler.scala:50)
	at monix.execution.schedulers.BatchingScheduler.execute$(BatchingScheduler.scala:47)
	at monix.execution.schedulers.AsyncScheduler.execute(AsyncScheduler.scala:29)
	at monix.execution.schedulers.ExecuteExtensions.executeTrampolined(ExecuteExtensions.scala:86)
	at monix.execution.schedulers.ExecuteExtensions.executeTrampolined$(ExecuteExtensions.scala:85)
	at monix.execution.Scheduler$Extensions.executeTrampolined(Scheduler.scala:187)
	at monix.eval.Callback$Extensions$.asyncOnSuccess$extension(Callback.scala:100)
	at monix.eval.internal.TaskDoOnCancel$$anon$1.onSuccess(TaskDoOnCancel.scala:38)
	at monix.eval.internal.TaskRunLoop$.monix$eval$internal$TaskRunLoop$$loop$1(TaskRunLoop.scala:174)
	at monix.eval.internal.TaskRunLoop$RestartCallback$1.onSuccess(TaskRunLoop.scala:119)
	at monix.eval.Task$.$anonfun$forkedUnit$2(Task.scala:1463)
	at monix.eval.Task$$$Lambda$291/0x00000008002a8440.run(Unknown Source)
	at java.util.concurrent.ForkJoinTask$RunnableExecuteAction.exec(java.base@11.0.11/ForkJoinTask.java:1426)
	at java.util.concurrent.ForkJoinTask.doExec(java.base@11.0.11/ForkJoinTask.java:290)
	at java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(java.base@11.0.11/ForkJoinPool.java:1020)
	at java.util.concurrent.ForkJoinPool.scan(java.base@11.0.11/ForkJoinPool.java:1656)
	at java.util.concurrent.ForkJoinPool.runWorker(java.base@11.0.11/ForkJoinPool.java:1594)
	at java.util.concurrent.ForkJoinWorkerThread.run(java.base@11.0.11/ForkJoinWorkerThread.java:183)

   Locked ownable synchronizers:
	- None

Environment info:

macOS Monterey
Version 12.6.1

bloop v1.5.2
Using Scala v2.12.15 and Zinc v1.6.0
Running on Java JDK v11.0.11

@brunofarache could you recheck on the newest versions if the recent PR helped at all? And maybe see how the jstack changed?

@tgodzik thanks for trying to fix it. I just upgraded to 1.5.6. I will leave the server running for some time and keep an eye if it hangs again, will let you know.

Thanks!

@tgodzik ran it several times this week without restarting the server and it's not hanging, thanks!