Merge pull request #2938 from eed3si9n/wip/2210

[sbt 1.0] Rebased: Improve time measuring 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.on.shutdown"))
+        sharedProgress
+      else
+        new TaskTimings(shutdown = false)
+    } else ExecuteProgress.empty[Task]
 
   val SystemProcessors = Runtime.getRuntime.availableProcessors
 

main/src/main/scala/sbt/Main.scala

@@ -221,7 +221,7 @@ object BuiltinCommands {
           Some(index.keyMap(key))
         catch {
           case NonFatal(ex) =>
-            s.log error ex.getMessage
+            s.log debug ex.getMessage
             None
         }
       }.collect { case Some(s) => s }.distinct

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

@@ -6,15 +6,45 @@ 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.on.shutdown=true|false
+ * - -Dsbt.task.timings.unit=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 threshold = java.lang.Long.getLong("sbt.task.timings.threshold", 0L)
+  private[this] val omitPaths = java.lang.Boolean.getBoolean("sbt.task.timings.omit.paths")
+  private[this] val (unit, divider) = System.getProperty("sbt.task.timings.unit", "ms") match {
+    case "ns" => ("ns", 0)
+    case "us" => ("µs", 3)
+    case "ms" => ("ms", 6)
+    case "s"  => ("sec", 9)
+    case x =>
+      System.err.println(s"Unknown sbt.task.timings.unit: $x.\nUsing milliseconds.")
+      ("ms", 6)
+  }
 
   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 +56,34 @@ 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 val reFilePath = raw"\{[^}]+\}".r
+
+  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)
+    val times = timingsByName.toSeq.sortBy(_._2).reverse
+      .map {
+        case (name, time) =>
+          (if (omitPaths) reFilePath.replaceFirstIn(name, "") else name, divide(time))
+      }.filter { _._2 > threshold }
+    if (times.size > 0) {
+      val maxTaskNameLength = times.map { _._1.length }.max
+      val maxTime = times.map { _._2 }.max.toString.length
+      times.foreach {
+        case (taskName, time) =>
+          println(s"  ${taskName.padTo(maxTaskNameLength, ' ')}: ${"".padTo(maxTime - time.toString.length, ' ')}$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 }
 }