From 4be4017f06d9d68b46a06f0ff23f728737eaf5bf Mon Sep 17 00:00:00 2001 From: Eugene Yokota Date: Thu, 27 Sep 2018 11:48:30 -0400 Subject: [PATCH 1/5] Refactor ExecuteProgress type parameters --- .../src/main/scala/sbt/ExecuteProgress.scala | 28 +++++++++---------- 1 file changed, 14 insertions(+), 14 deletions(-) diff --git a/tasks/src/main/scala/sbt/ExecuteProgress.scala b/tasks/src/main/scala/sbt/ExecuteProgress.scala index 686c6b2de..8e553a590 100644 --- a/tasks/src/main/scala/sbt/ExecuteProgress.scala +++ b/tasks/src/main/scala/sbt/ExecuteProgress.scala @@ -17,7 +17,7 @@ import sbt.internal.util.RMap * * This class is experimental and subject to binary and source incompatible changes at any time. */ -private[sbt] trait ExecuteProgress[A[_]] { +private[sbt] trait ExecuteProgress[F[_]] { type S def initial: S @@ -26,20 +26,20 @@ private[sbt] trait ExecuteProgress[A[_]] { * The dependencies of `task` are `allDeps` and the subset of those dependencies that * have not completed are `pendingDeps`. */ - def registered(state: S, task: A[_], allDeps: Iterable[A[_]], pendingDeps: Iterable[A[_]]): S + def registered(state: S, task: F[_], allDeps: Iterable[F[_]], pendingDeps: Iterable[F[_]]): S /** * Notifies that all of the dependencies of `task` have completed and `task` is therefore * ready to run. The task has not been scheduled on a thread yet. */ - def ready(state: S, task: A[_]): S + def ready(state: S, task: F[_]): S /** * Notifies that the work for `task` is starting after this call returns. * This is called from the thread the task executes on, unlike most other methods in this callback. * It is called immediately before the task's work starts with minimal intervening executor overhead. */ - def workStarting(task: A[_]): Unit + def workStarting(task: F[_]): Unit /** * Notifies that the work for `task` work has finished. The task may have computed the next task to @@ -49,30 +49,30 @@ private[sbt] trait ExecuteProgress[A[_]] { * This is called from the thread the task executes on, unlike most other methods in this callback. * It is immediately called after the task's work is complete with minimal intervening executor overhead. */ - def workFinished[T](task: A[T], result: Either[A[T], Result[T]]): Unit + def workFinished[A](task: F[A], result: Either[F[A], Result[A]]): Unit /** * Notifies that `task` has completed. * The task's work is done with a final `result`. * Any tasks called by `task` have completed. */ - def completed[T](state: S, task: A[T], result: Result[T]): S + def completed[A](state: S, task: F[A], result: Result[A]): S /** All tasks have completed with the final `results` provided. */ - def allCompleted(state: S, results: RMap[A, Result]): S + def allCompleted(state: S, results: RMap[F, Result]): S } /** This module is experimental and subject to binary and source incompatible changes at any time. */ private[sbt] object ExecuteProgress { - def empty[A[_]]: ExecuteProgress[A] = new ExecuteProgress[A] { + def empty[F[_]]: ExecuteProgress[F] = new ExecuteProgress[F] { type S = Unit def initial = () - def registered(state: Unit, task: A[_], allDeps: Iterable[A[_]], pendingDeps: Iterable[A[_]]) = + def registered(state: Unit, task: F[_], allDeps: Iterable[F[_]], pendingDeps: Iterable[F[_]]) = () - def ready(state: Unit, task: A[_]) = () - def workStarting(task: A[_]) = () - def workFinished[T](task: A[T], result: Either[A[T], Result[T]]) = () - def completed[T](state: Unit, task: A[T], result: Result[T]) = () - def allCompleted(state: Unit, results: RMap[A, Result]) = () + def ready(state: Unit, task: F[_]) = () + def workStarting(task: F[_]) = () + def workFinished[A](task: F[A], result: Either[F[A], Result[A]]) = () + def completed[A](state: Unit, task: F[A], result: Result[A]) = () + def allCompleted(state: Unit, results: RMap[F, Result]) = () } } From c316c800936a3bbfd0dd18b9c1d41b3260710ce9 Mon Sep 17 00:00:00 2001 From: Eugene Yokota Date: Mon, 1 Oct 2018 02:29:55 -0400 Subject: [PATCH 2/5] adds task progress Fixes #4362 This implements an instance of ExecuteProgress that is enabled by default to report progress on the shell. Combined with the scroll up logger, this takes over the bottom lines of the terminal screen and display a count up clock of the currently executing task. --- main/src/main/scala/sbt/EvaluateTask.scala | 17 ++- .../main/scala/sbt/internal/Aggregation.scala | 6 +- .../scala/sbt/internal/TaskProgress.scala | 137 ++++++++++++++++++ 3 files changed, 154 insertions(+), 6 deletions(-) create mode 100644 main/src/main/scala/sbt/internal/TaskProgress.scala diff --git a/main/src/main/scala/sbt/EvaluateTask.scala b/main/src/main/scala/sbt/EvaluateTask.scala index e75a8d724..b1e2ff7f5 100644 --- a/main/src/main/scala/sbt/EvaluateTask.scala +++ b/main/src/main/scala/sbt/EvaluateTask.scala @@ -7,7 +7,7 @@ package sbt -import sbt.internal.{ Load, BuildStructure, TaskTimings, TaskName, GCUtil } +import sbt.internal.{ Load, BuildStructure, TaskTimings, TaskName, GCUtil, TaskProgress } import sbt.internal.util.{ Attributed, ConsoleAppender, ErrorHandling, HList, RMap, Signals, Types } import sbt.util.{ Logger, Show } import sbt.librarymanagement.{ Resolver, UpdateReport } @@ -163,13 +163,18 @@ object EvaluateTask { lazy private val sharedProgress = new TaskTimings(shutdown = true) - private[sbt] def defaultProgress: ExecuteProgress[Task] = + // sbt-pgp calls this + private[sbt] def defaultProgress(): ExecuteProgress[Task] = ExecuteProgress.empty[Task] + private[sbt] def defaultProgress(currentRef: ProjectRef): ExecuteProgress[Task] = if (java.lang.Boolean.getBoolean("sbt.task.timings")) { if (java.lang.Boolean.getBoolean("sbt.task.timings.on.shutdown")) sharedProgress else new TaskTimings(shutdown = false) - } else ExecuteProgress.empty[Task] + } else { + if (ConsoleAppender.showProgress) new TaskProgress(currentRef) + else ExecuteProgress.empty[Task] + } val SystemProcessors = Runtime.getRuntime.availableProcessors @@ -229,7 +234,7 @@ object EvaluateTask { import Types.const val maker: State => Keys.TaskProgress = getSetting( Keys.executeProgress, - const(new Keys.TaskProgress(defaultProgress)), + const(new Keys.TaskProgress(defaultProgress(extracted.currentRef))), extracted, structure ) @@ -380,6 +385,10 @@ object EvaluateTask { val currentlyRunningEngine: AtomicReference[(State, RunningTaskEngine)] = new AtomicReference() + /** + * The main method for the task engine. + * See also Aggregation.runTasks. + */ def runTask[T]( root: Task[T], state: State, diff --git a/main/src/main/scala/sbt/internal/Aggregation.scala b/main/src/main/scala/sbt/internal/Aggregation.scala index 83b3ce6c2..833738549 100644 --- a/main/src/main/scala/sbt/internal/Aggregation.scala +++ b/main/src/main/scala/sbt/internal/Aggregation.scala @@ -77,6 +77,8 @@ object Aggregation { if (show.taskValues) printSettings(r, show.print) } if (show.success) printSuccess(start, stop, extracted, success, log) + // wait for async logger to catch up + Thread.sleep(100) } def timedRun[T]( @@ -129,9 +131,9 @@ object Aggregation { if (get(showSuccess)) { if (get(showTiming)) { val msg = timingString(start, stop, structure.data, currentRef) - if (success) log.success(msg) else log.error(msg) + if (success) log.success(msg + "\n") else log.error(msg + "\n") } else if (success) - log.success("") + log.success("" + "\n") } } diff --git a/main/src/main/scala/sbt/internal/TaskProgress.scala b/main/src/main/scala/sbt/internal/TaskProgress.scala new file mode 100644 index 000000000..c1f928dab --- /dev/null +++ b/main/src/main/scala/sbt/internal/TaskProgress.scala @@ -0,0 +1,137 @@ +/* + * sbt + * Copyright 2011 - 2018, Lightbend, Inc. + * Copyright 2008 - 2010, Mark Harrah + * Licensed under Apache License 2.0 (see LICENSE) + */ + +package sbt +package internal + +import sbt.internal.util.{ RMap, ConsoleOut } +import java.util.concurrent.ConcurrentHashMap +import scala.concurrent.{ blocking, Future, ExecutionContext } +import java.util.concurrent.atomic.AtomicBoolean +import scala.collection.JavaConverters._ +import scala.collection.concurrent.TrieMap +import TaskProgress._ + +/** + * implements task progress display on the shell. + */ +private[sbt] final class TaskProgress(currentRef: ProjectRef) extends ExecuteProgress[Task] { + type S = Unit + + private[this] val showScopedKey = Def.showRelativeKey2(currentRef) + // private[this] var start = 0L + private[this] val activeTasks = new ConcurrentHashMap[Task[_], Long] + private[this] val timings = new ConcurrentHashMap[Task[_], Long] + private[this] val calledBy = new ConcurrentHashMap[Task[_], Task[_]] + private[this] val anonOwners = new ConcurrentHashMap[Task[_], Task[_]] + private[this] val isReady = new AtomicBoolean(false) + private[this] val isAllCompleted = new AtomicBoolean(false) + + override def initial: Unit = () + override def registered( + state: Unit, + task: Task[_], + allDeps: Iterable[Task[_]], + pendingDeps: Iterable[Task[_]] + ): Unit = { + // we need this to infer anonymous task names + pendingDeps foreach { t => + if (TaskName.transformNode(t).isEmpty) { + anonOwners.put(t, task) + } + } + } + override def ready(state: Unit, task: Task[_]): Unit = { + isReady.set(true) + } + + override def workStarting(task: Task[_]): Unit = { + activeTasks.put(task, System.nanoTime) + () + } + + override def workFinished[A](task: Task[A], result: Either[Task[A], Result[A]]): Unit = { + activeTasks.remove(task) + timings.put(task, System.nanoTime - activeTasks.get(task)) + // we need this to infer anonymous task names + result.left.foreach { t => + calledBy.put(t, task) + } + } + + override def completed[A](state: Unit, task: Task[A], result: Result[A]): Unit = () + override def allCompleted(state: Unit, results: RMap[Task, Result]): Unit = { + isAllCompleted.set(true) + } + + import ExecutionContext.Implicits._ + Future { + while (!isReady.get) { + blocking { + Thread.sleep(500) + } + } + readyLog() + while (!isAllCompleted.get) { + blocking { + report() + Thread.sleep(500) + } + } + } + + private[this] val console = ConsoleOut.systemOut + private[this] def readyLog(): Unit = { + console.println("") + console.println("") + console.println("") + console.println("") + console.println("") + console.println("") + console.print(CursorUp5) + } + + private[this] val stopReportTask = + Set("run", "bgRun", "fgRun", "scala", "console", "consoleProject") + private[this] def report(): Unit = console.lockObject.synchronized { + val currentTasks = activeTasks.asScala.toList + def report0: Unit = { + console.print(s"$CursorDown1") + currentTasks foreach { + case (task, start) => + val elapsed = (System.nanoTime - start) / 1000000000L + console.println(s"$DeleteLine1 | => ${taskName(task)} ${elapsed}s") + } + console.print(cursorUp(currentTasks.size + 1)) + } + val isStop = currentTasks + .map({ case (t, _) => taskName(t) }) + .exists(n => stopReportTask.exists(m => n.endsWith("/ " + m))) + if (isStop) () + else report0 + } + + private[this] val taskNameCache = TrieMap.empty[Task[_], String] + private[this] def taskName(t: Task[_]): String = + taskNameCache.getOrElseUpdate(t, taskName0(t)) + private[this] def taskName0(t: Task[_]): String = { + def definedName(node: Task[_]): Option[String] = + node.info.name orElse TaskName.transformNode(node).map(showScopedKey.show) + def inferredName(t: Task[_]): Option[String] = nameDelegate(t) map taskName + def nameDelegate(t: Task[_]): Option[Task[_]] = + Option(anonOwners.get(t)) orElse Option(calledBy.get(t)) + definedName(t) orElse inferredName(t) getOrElse TaskName.anonymousName(t) + } +} + +private[sbt] object TaskProgress { + final val DeleteLine1 = "\u001B[2K" + final val CursorUp5 = cursorUp(5) + def cursorUp(n: Int): String = s"\u001B[${n}A" + def cursorDown(n: Int): String = s"\u001B[${n}B" + final val CursorDown1 = cursorDown(1) +} From 1465604f8cb8930c8275b11414a65ceb4eb95d0b Mon Sep 17 00:00:00 2001 From: Eugene Yokota Date: Mon, 1 Oct 2018 02:47:15 -0400 Subject: [PATCH 3/5] Demote "Done updating." log to debug level --- main-actions/src/main/scala/sbt/Package.scala | 4 ++-- main/src/main/scala/sbt/internal/LibraryManagement.scala | 4 ++-- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/main-actions/src/main/scala/sbt/Package.scala b/main-actions/src/main/scala/sbt/Package.scala index d91bf524b..7dcea5dac 100644 --- a/main-actions/src/main/scala/sbt/Package.scala +++ b/main-actions/src/main/scala/sbt/Package.scala @@ -154,7 +154,7 @@ object Package { } def makeJar(sources: Seq[(File, String)], jar: File, manifest: Manifest, log: Logger): Unit = { val path = jar.getAbsolutePath - log.info("Packaging " + path + " ...") + log.debug("Packaging " + path + " ...") if (jar.exists) if (jar.isFile) IO.delete(jar) @@ -162,7 +162,7 @@ object Package { sys.error(path + " exists, but is not a regular file") log.debug(sourcesDebugString(sources)) IO.jar(sources, jar, manifest) - log.info("Done packaging.") + log.debug("Done packaging.") } def sourcesDebugString(sources: Seq[(File, String)]): String = "Input file mappings:\n\t" + (sources map { case (f, s) => s + "\n\t " + f } mkString ("\n\t")) diff --git a/main/src/main/scala/sbt/internal/LibraryManagement.scala b/main/src/main/scala/sbt/internal/LibraryManagement.scala index 1adae3fb7..fc45b83c0 100644 --- a/main/src/main/scala/sbt/internal/LibraryManagement.scala +++ b/main/src/main/scala/sbt/internal/LibraryManagement.scala @@ -40,7 +40,7 @@ private[sbt] object LibraryManagement { def resolve: UpdateReport = { import sbt.util.ShowLines._ - log.info(s"Updating $label...") + log.debug(s"Updating $label...") val reportOrUnresolved: Either[UnresolvedWarning, UpdateReport] = lm.update(module, updateConfig, uwConfig, log) val report = reportOrUnresolved match { @@ -49,7 +49,7 @@ private[sbt] object LibraryManagement { unresolvedWarning.lines.foreach(log.warn(_)) throw unresolvedWarning.resolveException } - log.info("Done updating.") + log.debug(s"Done updating $label") val finalReport = transform(report) // Warn of any eviction and compatibility warnings From 6dc27a3f6ec2537a766ef01f39a1aef64ad3524c Mon Sep 17 00:00:00 2001 From: Eugene Yokota Date: Mon, 1 Oct 2018 06:03:07 -0400 Subject: [PATCH 4/5] change to DeleteLine --- main/src/main/scala/sbt/internal/TaskProgress.scala | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/main/src/main/scala/sbt/internal/TaskProgress.scala b/main/src/main/scala/sbt/internal/TaskProgress.scala index c1f928dab..641f3a932 100644 --- a/main/src/main/scala/sbt/internal/TaskProgress.scala +++ b/main/src/main/scala/sbt/internal/TaskProgress.scala @@ -104,7 +104,7 @@ private[sbt] final class TaskProgress(currentRef: ProjectRef) extends ExecutePro currentTasks foreach { case (task, start) => val elapsed = (System.nanoTime - start) / 1000000000L - console.println(s"$DeleteLine1 | => ${taskName(task)} ${elapsed}s") + console.println(s"$DeleteLine | => ${taskName(task)} ${elapsed}s") } console.print(cursorUp(currentTasks.size + 1)) } @@ -129,7 +129,7 @@ private[sbt] final class TaskProgress(currentRef: ProjectRef) extends ExecutePro } private[sbt] object TaskProgress { - final val DeleteLine1 = "\u001B[2K" + final val DeleteLine = "\u001B[2K" final val CursorUp5 = cursorUp(5) def cursorUp(n: Int): String = s"\u001B[${n}A" def cursorDown(n: Int): String = s"\u001B[${n}B" From 6224b1dda1dff29003da546c74b1bb8f5906e77a Mon Sep 17 00:00:00 2001 From: Eugene Yokota Date: Tue, 2 Oct 2018 09:49:37 -0400 Subject: [PATCH 5/5] Util 1.3.0-M2 --- project/Dependencies.scala | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/project/Dependencies.scala b/project/Dependencies.scala index 99179eab1..039c447af 100644 --- a/project/Dependencies.scala +++ b/project/Dependencies.scala @@ -9,7 +9,7 @@ object Dependencies { // sbt modules private val ioVersion = "1.2.1" - private val utilVersion = "1.2.2" + private val utilVersion = "1.3.0-M2" private val lmVersion = "1.2.1" private val zincVersion = "1.2.2"