diff --git a/main/src/main/scala/sbt/EvaluateTask.scala b/main/src/main/scala/sbt/EvaluateTask.scala index b99fe54b8..08d2571ea 100644 --- a/main/src/main/scala/sbt/EvaluateTask.scala +++ b/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 diff --git a/main/src/main/scala/sbt/Main.scala b/main/src/main/scala/sbt/Main.scala index 1aaa9333d..3499c9e28 100644 --- a/main/src/main/scala/sbt/Main.scala +++ b/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 diff --git a/main/src/main/scala/sbt/internal/TaskTimings.scala b/main/src/main/scala/sbt/internal/TaskTimings.scala index 5a9d8e46d..d6acbeaaa 100644 --- a/main/src/main/scala/sbt/internal/TaskTimings.scala +++ b/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 } }