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/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/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 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..641f3a932 --- /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"$DeleteLine | => ${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 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" + final val CursorDown1 = cursorDown(1) +} diff --git a/project/Dependencies.scala b/project/Dependencies.scala index 24d204f29..940c35405 100644 --- a/project/Dependencies.scala +++ b/project/Dependencies.scala @@ -10,7 +10,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" 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]) = () } }