Merge pull request #5156 from eatkins/task-timing-logger

Improve task timing output and supershell thread management

main/src/main/scala/sbt/EvaluateTask.scala

@@ -224,34 +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) :: 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 =

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 =>
         }
@@ -48,14 +49,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)
@@ -65,22 +59,37 @@ 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
     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 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 = {
+      if (tasks.nonEmpty) maybeStartThread()
       val event = ProgressEvent(
         "Info",
         tasks

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

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
   }