From b9c3a56454669a58bd1eaab78a6356ea0702cea2 Mon Sep 17 00:00:00 2001 From: David Perez Date: Tue, 1 Sep 2015 14:36:33 +0200 Subject: [PATCH 1/5] Changed logging from error to debug, because it is quite annoying the error message when autocompleting --- main/src/main/scala/sbt/Main.scala | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) 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 From 70fa960f564c91fad09199a9cdf38108a0ac0a2c Mon Sep 17 00:00:00 2001 From: David Perez Date: Wed, 16 Sep 2015 16:31:12 +0200 Subject: [PATCH 2/5] Improved time logging capabilities --- main/src/main/scala/sbt/EvaluateTask.scala | 9 ++- .../main/scala/sbt/internal/TaskTimings.scala | 56 +++++++++++++++---- 2 files changed, 54 insertions(+), 11 deletions(-) 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 } } From 4f5c5c92a200335031b3ced91f7fdc401f6d928b Mon Sep 17 00:00:00 2001 From: David Perez Date: Wed, 16 Sep 2015 17:07:19 +0200 Subject: [PATCH 3/5] Alignment of reported time measuring data --- .../main/scala/sbt/internal/TaskTimings.scala | 16 +++++++++++----- 1 file changed, 11 insertions(+), 5 deletions(-) diff --git a/main/src/main/scala/sbt/internal/TaskTimings.scala b/main/src/main/scala/sbt/internal/TaskTimings.scala index 977e21f33..1f23d82b0 100644 --- a/main/src/main/scala/sbt/internal/TaskTimings.scala +++ b/main/src/main/scala/sbt/internal/TaskTimings.scala @@ -64,11 +64,17 @@ private[sbt] final class TaskTimings(shutdown: Boolean) extends ExecuteProgress[ 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") + val times = timingsByName.toSeq.sortBy(_._2).reverse + .map { case (name, time) => (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)) From 6ab0bc403abd130de1e70823208c85e6068e3826 Mon Sep 17 00:00:00 2001 From: David Perez Date: Thu, 17 Sep 2015 08:44:37 +0200 Subject: [PATCH 4/5] Renamed: sbt.task.timings.shutdown -> sbt.task.timings.on.shutdown sbt.task.timings.divider -> sbt.task.timings.unit --- main/src/main/scala/sbt/EvaluateTask.scala | 2 +- .../main/scala/sbt/internal/TaskTimings.scala | 19 ++++++++++--------- 2 files changed, 11 insertions(+), 10 deletions(-) diff --git a/main/src/main/scala/sbt/EvaluateTask.scala b/main/src/main/scala/sbt/EvaluateTask.scala index b1d4facf6..08d2571ea 100644 --- a/main/src/main/scala/sbt/EvaluateTask.scala +++ b/main/src/main/scala/sbt/EvaluateTask.scala @@ -154,7 +154,7 @@ object EvaluateTask { private[sbt] def defaultProgress: ExecuteProgress[Task] = if (java.lang.Boolean.getBoolean("sbt.task.timings")) { - if (java.lang.Boolean.getBoolean("sbt.task.timings.shutdown")) + if (java.lang.Boolean.getBoolean("sbt.task.timings.on.shutdown")) sharedProgress else new TaskTimings(shutdown = false) diff --git a/main/src/main/scala/sbt/internal/TaskTimings.scala b/main/src/main/scala/sbt/internal/TaskTimings.scala index 1f23d82b0..4767c1544 100644 --- a/main/src/main/scala/sbt/internal/TaskTimings.scala +++ b/main/src/main/scala/sbt/internal/TaskTimings.scala @@ -10,8 +10,8 @@ import TaskName._ * 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.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)? */ @@ -20,14 +20,15 @@ private[sbt] final class TaskTimings(shutdown: Boolean) extends ExecuteProgress[ 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 _ => "" + 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 From 618487eb582882a0824ea2d78deec7512bdd625f Mon Sep 17 00:00:00 2001 From: David Perez Date: Wed, 30 Sep 2015 08:52:59 +0200 Subject: [PATCH 5/5] New option sbt.task.timings.omit.paths, to produce even cleaner reports. --- main/src/main/scala/sbt/internal/TaskTimings.scala | 9 +++++++-- 1 file changed, 7 insertions(+), 2 deletions(-) diff --git a/main/src/main/scala/sbt/internal/TaskTimings.scala b/main/src/main/scala/sbt/internal/TaskTimings.scala index 4767c1544..d6acbeaaa 100644 --- a/main/src/main/scala/sbt/internal/TaskTimings.scala +++ b/main/src/main/scala/sbt/internal/TaskTimings.scala @@ -21,6 +21,7 @@ private[sbt] final class TaskTimings(shutdown: Boolean) extends ExecuteProgress[ 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) @@ -59,6 +60,8 @@ private[sbt] final class TaskTimings(shutdown: Boolean) extends ExecuteProgress[ report() } + private val reFilePath = raw"\{[^}]+\}".r + private[this] def report() = { val total = divide(System.nanoTime - start) println(s"Total time: $total $unit") @@ -66,8 +69,10 @@ private[sbt] final class TaskTimings(shutdown: Boolean) extends ExecuteProgress[ 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) => (name, divide(time)) } - .filter { _._2 > threshold } + .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