From 367461e586524cd4d07d8f00f79e9e72c853491b Mon Sep 17 00:00:00 2001 From: Ethan Atkins Date: Sat, 5 Oct 2019 13:10:01 -0700 Subject: [PATCH 1/3] Use logger rather than ConsoleOut for TaskTimings When running sbt -Dtask.timings=true, the task timings get printed to the console which can overwrite the shell prompt. When we use a logger, the timing lines are correctly separated from the prompt lines. --- main/src/main/scala/sbt/EvaluateTask.scala | 4 +++- .../main/scala/sbt/internal/TaskTimings.scala | 18 +++++++++++++----- 2 files changed, 16 insertions(+), 6 deletions(-) diff --git a/main/src/main/scala/sbt/EvaluateTask.scala b/main/src/main/scala/sbt/EvaluateTask.scala index b23ab9105..fae25d2fe 100644 --- a/main/src/main/scala/sbt/EvaluateTask.scala +++ b/main/src/main/scala/sbt/EvaluateTask.scala @@ -245,7 +245,9 @@ object EvaluateTask { case _ => None } val reporters = maker.map(_.progress) ++ progressReporter ++ - (if (SysProp.taskTimings) new TaskTimings(reportOnShutdown = false) :: Nil else Nil) + (if (SysProp.taskTimings) + new TaskTimings(reportOnShutdown = false, state.globalLogging.full) :: Nil + else Nil) reporters match { case xs if xs.isEmpty => ExecuteProgress.empty[Task] case xs if xs.size == 1 => xs.head diff --git a/main/src/main/scala/sbt/internal/TaskTimings.scala b/main/src/main/scala/sbt/internal/TaskTimings.scala index 08170e813..ed7516249 100644 --- a/main/src/main/scala/sbt/internal/TaskTimings.scala +++ b/main/src/main/scala/sbt/internal/TaskTimings.scala @@ -8,7 +8,8 @@ package sbt package internal -import sbt.internal.util.{ RMap, ConsoleOut } +import sbt.internal.util.{ ConsoleOut, RMap } +import sbt.util.{ Level, Logger } /** * Measure the time elapsed for running tasks. @@ -19,9 +20,17 @@ import sbt.internal.util.{ RMap, ConsoleOut } * - -Dsbt.task.timings.threshold=number * @param reportOnShutdown Should the report be given when exiting the JVM (true) or immediately (false)? */ -private[sbt] final class TaskTimings(reportOnShutdown: Boolean) +private[sbt] final class TaskTimings(reportOnShutdown: Boolean, logger: Logger) extends AbstractTaskExecuteProgress with ExecuteProgress[Task] { + @deprecated("Use the constructor that takes an sbt.util.Logger parameter.", "1.3.3") + def this(reportOnShutdown: Boolean) = + this(reportOnShutdown, new Logger { + override def trace(t: => Throwable): Unit = {} + override def success(message: => String): Unit = {} + override def log(level: Level.Value, message: => String): Unit = + ConsoleOut.systemOut.println(message) + }) import AbstractTaskExecuteProgress.Timer private[this] var start = 0L private[this] val threshold = SysProp.taskTimingsThreshold @@ -48,11 +57,10 @@ private[sbt] final class TaskTimings(reportOnShutdown: Boolean) override def stop(): Unit = () private[this] val reFilePath = raw"\{[^}]+\}".r - private[this] val console = ConsoleOut.systemOut private[this] def report() = { val total = divide(System.nanoTime - start) - console.println(s"Total time: $total $unit") + logger.info(s"Total time: $total $unit") import collection.JavaConverters._ def sumTimes(in: Seq[(Task[_], Timer)]) = in.map(_._2.durationNanos).sum val timingsByName = timings.asScala.toSeq.groupBy { case (t, _) => taskName(t) } mapValues (sumTimes) @@ -69,7 +77,7 @@ private[sbt] final class TaskTimings(reportOnShutdown: Boolean) val maxTime = times.map { _._2 }.max.toString.length times.foreach { case (taskName, time) => - console.println(s" ${taskName.padTo(maxTaskNameLength, ' ')}: ${"" + logger.info(s" ${taskName.padTo(maxTaskNameLength, ' ')}: ${"" .padTo(maxTime - time.toString.length, ' ')}$time $unit") } } From 6559c3a06da7d3e30a3a357014f84ce4148bd754 Mon Sep 17 00:00:00 2001 From: Ethan Atkins Date: Sat, 5 Oct 2019 14:35:09 -0700 Subject: [PATCH 2/3] Use only one progress thread during task evaluation In some circumstances, sbt would generate a number of task progress threads that could run concurrently. The issue was that the TaskProgress could be shared by multiple EvaluateTaskConfigs if a dynamic task was used. This was problematic because when a dynamic task completed, it might call afterAllCompleted which would stop the progress thread. There also was a race condition because multiple threads calling initial could theoretically have created a new progress thread which would cause a resource leak. To fix this, we modify the shared task progress so that the `stop()` method is a no-op. This should prevent dynamic tasks from stopping the progress thread. We also defer the creation of the task thread until there is at least one active task. This prevents a thread from being created in the shell. The motivation for this change was that I found that sometimes there was a leaked progress thread that would make the shell not really work for me because the progress thread would overwrite the shell prompt. This change fixes that behavior and I was able to validate with jstack that there was consistently either one or zero task progress threads at a time (zero in the shell, one when tasks were actually running). --- main/src/main/scala/sbt/EvaluateTask.scala | 79 ++++++++++++------- .../scala/sbt/internal/TaskProgress.scala | 23 +++--- tasks/src/main/scala/sbt/Execute.scala | 1 + 3 files changed, 66 insertions(+), 37 deletions(-) diff --git a/main/src/main/scala/sbt/EvaluateTask.scala b/main/src/main/scala/sbt/EvaluateTask.scala index fae25d2fe..2e1105a50 100644 --- a/main/src/main/scala/sbt/EvaluateTask.scala +++ b/main/src/main/scala/sbt/EvaluateTask.scala @@ -224,36 +224,59 @@ object EvaluateTask { structure: BuildStructure, state: State ): ExecuteProgress[Task] = { - state.get(currentTaskProgress).map(_.progress).getOrElse { - val maker: Seq[Keys.TaskProgress] = getSetting( - Keys.progressReports, - Seq(), - extracted, - structure - ) - val progressReporter = extracted.getOpt(progressState in ThisBuild).flatMap { - case Some(ps) => - ps.reset() - ConsoleAppender.setShowProgress(true) - val appender = MainAppender.defaultScreen(StandardMain.console) - appender match { - case c: ConsoleAppender => c.setProgressState(ps) - case _ => - } - val log = LogManager.progressLogger(appender) - Some(new TaskProgress(log)) - case _ => None + state + .get(currentTaskProgress) + .map { tp => + new ExecuteProgress[Task] { + val progress = tp.progress + override def initial(): Unit = progress.initial() + override def afterRegistered( + task: Task[_], + allDeps: Iterable[Task[_]], + pendingDeps: Iterable[Task[_]] + ): Unit = + progress.afterRegistered(task, allDeps, pendingDeps) + override def afterReady(task: Task[_]): Unit = progress.afterReady(task) + override def beforeWork(task: Task[_]): Unit = progress.beforeWork(task) + override def afterWork[A](task: Task[A], result: Either[Task[A], Result[A]]): Unit = + progress.afterWork(task, result) + override def afterCompleted[A](task: Task[A], result: Result[A]): Unit = + progress.afterCompleted(task, result) + override def afterAllCompleted(results: RMap[Task, Result]): Unit = + progress.afterAllCompleted(results) + override def stop(): Unit = {} + } } - val reporters = maker.map(_.progress) ++ progressReporter ++ - (if (SysProp.taskTimings) - new TaskTimings(reportOnShutdown = false, state.globalLogging.full) :: Nil - else Nil) - reporters match { - case xs if xs.isEmpty => ExecuteProgress.empty[Task] - case xs if xs.size == 1 => xs.head - case xs => ExecuteProgress.aggregate[Task](xs) + .getOrElse { + val maker: Seq[Keys.TaskProgress] = getSetting( + Keys.progressReports, + Seq(), + extracted, + structure + ) + val progressReporter = extracted.getOpt(progressState in ThisBuild).flatMap { + case Some(ps) => + ps.reset() + ConsoleAppender.setShowProgress(true) + val appender = MainAppender.defaultScreen(StandardMain.console) + appender match { + case c: ConsoleAppender => c.setProgressState(ps) + case _ => + } + val log = LogManager.progressLogger(appender) + Some(new TaskProgress(log)) + case _ => None + } + val reporters = maker.map(_.progress) ++ progressReporter ++ + (if (SysProp.taskTimings) + new TaskTimings(reportOnShutdown = false, state.globalLogging.full) :: Nil + else Nil) + reporters match { + case xs if xs.isEmpty => ExecuteProgress.empty[Task] + case xs if xs.size == 1 => xs.head + case xs => ExecuteProgress.aggregate[Task](xs) + } } - } } // TODO - Should this pull from Global or from the project itself? private[sbt] def forcegc(extracted: Extracted, structure: BuildStructure): Boolean = diff --git a/main/src/main/scala/sbt/internal/TaskProgress.scala b/main/src/main/scala/sbt/internal/TaskProgress.scala index fbf81a786..ad7cf226e 100644 --- a/main/src/main/scala/sbt/internal/TaskProgress.scala +++ b/main/src/main/scala/sbt/internal/TaskProgress.scala @@ -48,14 +48,7 @@ private[sbt] final class TaskProgress(log: ManagedLogger) } } - override def initial(): Unit = { - currentProgressThread.get() match { - case None => - currentProgressThread.set(Some(new ProgressThread)) - case _ => - } - ConsoleAppender.setTerminalWidth(JLine.terminal.getWidth) - } + override def initial(): Unit = ConsoleAppender.setTerminalWidth(JLine.terminal.getWidth) override def beforeWork(task: Task[_]): Unit = { super.beforeWork(task) @@ -72,15 +65,27 @@ private[sbt] final class TaskProgress(log: ManagedLogger) val event = ProgressEvent("Info", Vector(), Some(lastTaskCount.get), None, None) import sbt.internal.util.codec.JsonProtocol._ log.logEvent(Level.Info, event) - stop() } private[this] val skipReportTasks = Set("run", "bgRun", "fgRun", "scala", "console", "consoleProject", "consoleQuick", "state") + private[this] def maybeStartThread(): Unit = { + currentProgressThread.get() match { + case None => + currentProgressThread.synchronized { + currentProgressThread.get() match { + case None => currentProgressThread.set(Some(new ProgressThread)) + case _ => + } + } + case _ => + } + } private[this] def report(): Unit = { val currentTasks = activeTasks.toVector.filterNot(Def.isDummy) val ltc = lastTaskCount.get val currentTasksCount = currentTasks.size def report0(tasks: Vector[Task[_]]): Unit = { + if (tasks.nonEmpty) maybeStartThread() val event = ProgressEvent( "Info", tasks diff --git a/tasks/src/main/scala/sbt/Execute.scala b/tasks/src/main/scala/sbt/Execute.scala index 556410c17..627aa16cd 100644 --- a/tasks/src/main/scala/sbt/Execute.scala +++ b/tasks/src/main/scala/sbt/Execute.scala @@ -95,6 +95,7 @@ private[sbt] final class Execute[F[_] <: AnyRef]( assert(results contains root, "No result for root node.") val finalResults = triggers.onComplete(results) progress.afterAllCompleted(finalResults) + progress.stop() finalResults } From d12bb2d71e09ce95cab02a615401ddeeaeb4d435 Mon Sep 17 00:00:00 2001 From: Ethan Atkins Date: Sun, 6 Oct 2019 16:21:59 -0700 Subject: [PATCH 3/3] Shutdown progress thread when there are no tasks It is still possible for progress threads to leak so shut them down if there are no active tasks. The report0 method will start up a new thread if a task is added. --- main/src/main/scala/sbt/internal/TaskProgress.scala | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/main/src/main/scala/sbt/internal/TaskProgress.scala b/main/src/main/scala/sbt/internal/TaskProgress.scala index ad7cf226e..4a91a0f01 100644 --- a/main/src/main/scala/sbt/internal/TaskProgress.scala +++ b/main/src/main/scala/sbt/internal/TaskProgress.scala @@ -35,6 +35,7 @@ private[sbt] final class TaskProgress(log: ManagedLogger) try { report() Thread.sleep(sleepDuration) + if (active.isEmpty) TaskProgress.this.stop() } catch { case _: InterruptedException => } @@ -58,7 +59,9 @@ private[sbt] final class TaskProgress(log: ManagedLogger) override def afterCompleted[A](task: Task[A], result: Result[A]): Unit = () - override def stop(): Unit = currentProgressThread.getAndSet(None).foreach(_.close()) + override def stop(): Unit = currentProgressThread.synchronized { + currentProgressThread.getAndSet(None).foreach(_.close()) + } override def afterAllCompleted(results: RMap[Task, Result]): Unit = { // send an empty progress report to clear out the previous report @@ -80,8 +83,9 @@ private[sbt] final class TaskProgress(log: ManagedLogger) case _ => } } + private[this] def active: Vector[Task[_]] = activeTasks.toVector.filterNot(Def.isDummy) private[this] def report(): Unit = { - val currentTasks = activeTasks.toVector.filterNot(Def.isDummy) + val currentTasks = active val ltc = lastTaskCount.get val currentTasksCount = currentTasks.size def report0(tasks: Vector[Task[_]]): Unit = {