diff --git a/main/src/main/scala/sbt/EvaluateTask.scala b/main/src/main/scala/sbt/EvaluateTask.scala index b99fe54b8..b1d4facf6 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.shutdown")) + sharedProgress + else + new TaskTimings(shutdown = false) + } else ExecuteProgress.empty[Task] val SystemProcessors = Runtime.getRuntime.availableProcessors diff --git a/main/src/main/scala/sbt/internal/TaskTimings.scala b/main/src/main/scala/sbt/internal/TaskTimings.scala index 5a9d8e46d..977e21f33 100644 --- a/main/src/main/scala/sbt/internal/TaskTimings.scala +++ b/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 } }