Improved time logging capabilities

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

@@ -150,8 +150,15 @@ object EvaluateTask {
   import std.Transform
   import Keys.state
 
+  lazy private val sharedProgress = new TaskTimings(shutdown = true)
+
   private[sbt] def defaultProgress: ExecuteProgress[Task] =
-    if (java.lang.Boolean.getBoolean("sbt.task.timings")) new TaskTimings else ExecuteProgress.empty[Task]
+    if (java.lang.Boolean.getBoolean("sbt.task.timings")) {
+      if (java.lang.Boolean.getBoolean("sbt.task.timings.shutdown"))
+        sharedProgress
+      else
+        new TaskTimings(shutdown = false)
+    } else ExecuteProgress.empty[Task]
 
   val SystemProcessors = Runtime.getRuntime.availableProcessors
 

main/src/main/scala/sbt/internal/TaskTimings.scala

@@ -6,15 +6,43 @@ import sbt.internal.util.RMap
 import java.util.concurrent.ConcurrentHashMap
 import TaskName._
 
-private[sbt] final class TaskTimings extends ExecuteProgress[Task] {
+/**
+ * Measure the time elapsed for running tasks.
+ * This class is activated by adding -Dsbt.task.timing=true to the JVM options.
+ * Formatting options:
+ * - -Dsbt.task.timings.shutdown=true|false
+ * - -Dsbt.task.timings.decimals=number
+ * - -Dsbt.task.timings.threshold=number
+ * @param shutdown    Should the report be given when exiting the JVM (true) or immediatelly (false)?
+ */
+private[sbt] final class TaskTimings(shutdown: Boolean) extends ExecuteProgress[Task] {
   private[this] val calledBy = new ConcurrentHashMap[Task[_], Task[_]]
   private[this] val anonOwners = new ConcurrentHashMap[Task[_], Task[_]]
   private[this] val timings = new ConcurrentHashMap[Task[_], Long]
   private[this] var start = 0L
+  private[this] val divider = java.lang.Integer.getInteger("sbt.task.timings.divider", 6).toInt
+  private[this] val threshold = java.lang.Long.getLong("sbt.task.timings.threshold", 0L)
+  private[this] val unit = divider match {
+    case 0 => "ns"
+    case 3 => "µs"
+    case 6 => "ms"
+    case 9 => "sec"
+    case _ => ""
+  }
 
   type S = Unit
 
-  def initial = { start = System.nanoTime }
+  if (shutdown) {
+    start = System.nanoTime
+    Runtime.getRuntime.addShutdownHook(new Thread {
+      override def run() = report()
+    })
+  }
+
+  def initial = {
+    if (!shutdown)
+      start = System.nanoTime
+  }
   def registered(state: Unit, task: Task[_], allDeps: Iterable[Task[_]], pendingDeps: Iterable[Task[_]]) = {
     pendingDeps foreach { t => if (transformNode(t).isEmpty) anonOwners.put(t, task) }
   }
@@ -26,16 +54,24 @@ private[sbt] final class TaskTimings extends ExecuteProgress[Task] {
   }
   def completed[T](state: Unit, task: Task[T], result: Result[T]) = ()
   def allCompleted(state: Unit, results: RMap[Task, Result]) =
-    {
-      val total = System.nanoTime - start
-      println("Total time: " + (total * 1e-6) + " ms")
-      import collection.JavaConverters._
-      def sumTimes(in: Seq[(Task[_], Long)]) = in.map(_._2).sum
-      val timingsByName = timings.asScala.toSeq.groupBy { case (t, time) => mappedName(t) } mapValues (sumTimes)
-      for ((taskName, time) <- timingsByName.toSeq.sortBy(_._2).reverse)
-        println("  " + taskName + ": " + (time * 1e-6) + " ms")
+    if (!shutdown) {
+      report()
     }
+
+  private[this] def report() = {
+    val total = divide(System.nanoTime - start)
+    println(s"Total time: $total $unit")
+    import collection.JavaConverters._
+    def sumTimes(in: Seq[(Task[_], Long)]) = in.map(_._2).sum
+    val timingsByName = timings.asScala.toSeq.groupBy { case (t, time) => mappedName(t) } mapValues (sumTimes)
+    for (
+      (taskName, time) <- timingsByName.toSeq.sortBy(_._2).reverse
+        .map { case (name, time) => (name, divide(time)) }
+        .filter { _._2 > threshold }
+    ) println(s"  $taskName: $time $unit")
+  }
   private[this] def inferredName(t: Task[_]): Option[String] = nameDelegate(t) map mappedName
   private[this] def nameDelegate(t: Task[_]): Option[Task[_]] = Option(anonOwners.get(t)) orElse Option(calledBy.get(t))
   private[this] def mappedName(t: Task[_]): String = definedName(t) orElse inferredName(t) getOrElse anonymousName(t)
+  private[this] def divide(time: Long) = (1L to divider.toLong).fold(time) { (a, b) => a / 10L }
 }