Merge pull request #4396 from eed3si9n/wip/progress

"super shell" for sbt

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"))

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,

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")
     }
   }
 

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

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)
+}

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"
 

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 ready(state: Unit, task: F[_]) = ()
-    def workStarting(task: A[_]) = ()
+    def workStarting(task: F[_]) = ()
-    def workFinished[T](task: A[T], result: Either[A[T], Result[T]]) = ()
+    def workFinished[A](task: F[A], result: Either[F[A], Result[A]]) = ()
-    def completed[T](state: Unit, task: A[T], result: Result[T]) = ()
+    def completed[A](state: Unit, task: F[A], result: Result[A]) = ()
-    def allCompleted(state: Unit, results: RMap[A, Result]) = ()
+    def allCompleted(state: Unit, results: RMap[F, Result]) = ()
   }
 }