diff --git a/main/src/main/scala/sbt/EvaluateTask.scala b/main/src/main/scala/sbt/EvaluateTask.scala index a2d795819..3992c738a 100644 --- a/main/src/main/scala/sbt/EvaluateTask.scala +++ b/main/src/main/scala/sbt/EvaluateTask.scala @@ -12,6 +12,7 @@ package sbt import Types.const import scala.Console.RED import std.Transform.{DummyTaskMap,TaskAndValue} + import TaskName._ final case class EvaluateConfig(cancelable: Boolean, restrictions: Seq[Tags.Rule], checkCycles: Boolean = false) final case class PluginData(dependencyClasspath: Seq[Attributed[File]], definitionClasspath: Seq[Attributed[File]], resolvers: Option[Seq[Resolver]], report: Option[UpdateReport]) @@ -162,7 +163,8 @@ object EvaluateTask case _ => true } def run() = { - val x = Execute[Task]( Execute.config(config.checkCycles, overwriteNode), triggers)(taskToNode) + val progress = if(java.lang.Boolean.getBoolean("sbt.task.timings")) new TaskTimings else ExecuteProgress.empty[Task] + val x = new Execute[Task]( Execute.config(config.checkCycles, overwriteNode), triggers, progress)(taskToNode) val (newState, result) = try applyResults(x.runKeep(root)(service), state, root) catch { case inc: Incomplete => (state, Inc(inc)) } @@ -211,8 +213,7 @@ object EvaluateTask c.toString + (if(caller eq target) "(task: " + name(caller) + ")" else "(caller: " + name(caller) + ", target: " + name(target) + ")" ) case _ => c.toString } - def name(node: Task[_]): String = - node.info.name orElse transformNode(node).map(displayFull) getOrElse ("") + def liftAnonymous: Incomplete => Incomplete = { case i @ Incomplete(node, tpe, None, causes, None) => causes.find( inc => !inc.node.isDefined && (inc.message.isDefined || inc.directCause.isDefined)) match { @@ -221,8 +222,6 @@ object EvaluateTask } case i => i } - def transformNode(node: Task[_]): Option[ScopedKey[_]] = - node.info.attributes get taskDefinitionKey def processResult[T](result: Result[T], log: Logger, show: Boolean = false): T = onResult(result, log) { v => if(show) println("Result: " + v); v } diff --git a/main/src/main/scala/sbt/TaskName.scala b/main/src/main/scala/sbt/TaskName.scala new file mode 100644 index 000000000..c48e569e2 --- /dev/null +++ b/main/src/main/scala/sbt/TaskName.scala @@ -0,0 +1,12 @@ +package sbt + + import Def.{displayFull, ScopedKey} + import Keys.taskDefinitionKey + +private[sbt] object TaskName +{ + def name(node: Task[_]): String = definedName(node) getOrElse anonymousName(node) + def definedName(node: Task[_]): Option[String] = node.info.name orElse transformNode(node).map(displayFull) + def anonymousName(node: Task[_]): String = "" + def transformNode(node: Task[_]): Option[ScopedKey[_]] = node.info.attributes get taskDefinitionKey +} \ No newline at end of file diff --git a/main/src/main/scala/sbt/TaskTimings.scala b/main/src/main/scala/sbt/TaskTimings.scala new file mode 100644 index 000000000..40775588a --- /dev/null +++ b/main/src/main/scala/sbt/TaskTimings.scala @@ -0,0 +1,39 @@ +package sbt + + import java.util.concurrent.ConcurrentHashMap + import TaskName._ + +private[sbt] final class TaskTimings 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 + + type S = Unit + + def initial = { 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) } + } + def ready(state: Unit, task: Task[_]) = () + def workStarting(task: Task[_]) = timings.put(task, System.nanoTime) + def workFinished[T](task: Task[T], result: Either[Task[T], Result[T]]) = { + timings.put(task, System.nanoTime - timings.get(task)) + result.left.foreach { t => calledBy.put(t, 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.JavaConversions._ + def sumTimes(in: Seq[(Task[_], Long)]) = in.map(_._2).sum + val timingsByName = timings.toSeq.groupBy { case (t, time) => mappedName(t) } mapValues(sumTimes) + for( (taskName, time) <- timingsByName.toSeq.sortBy(_._2).reverse) + println(" " + taskName + ": " + (time*1e-6) + " ms") + } + 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) +} diff --git a/tasks/src/main/scala/sbt/Execute.scala b/tasks/src/main/scala/sbt/Execute.scala index b47309358..02a30ff28 100644 --- a/tasks/src/main/scala/sbt/Execute.scala +++ b/tasks/src/main/scala/sbt/Execute.scala @@ -11,7 +11,7 @@ import scala.annotation.tailrec import scala.collection.{mutable, JavaConversions} import mutable.Map -object Execute +private[sbt] object Execute { def idMap[A,B]: Map[A, B] = JavaConversions.mapAsScalaMap(new java.util.IdentityHashMap[A,B]) def pMap[A[_], B[_]]: PMap[A,B] = new DelegatingPMap[A, B](idMap) @@ -20,27 +20,21 @@ object Execute } def noTriggers[A[_]] = new Triggers[A](Map.empty, Map.empty, idFun) - def apply[A[_] <: AnyRef](config: Config, triggers: Triggers[A])(implicit view: NodeView[A]): Execute[A] = - new Execute(config, triggers)(view) - def config(checkCycles: Boolean, overwriteNode: Incomplete => Boolean = const(false)): Config = new Config(checkCycles, overwriteNode) final class Config private[sbt](val checkCycles: Boolean, val overwriteNode: Incomplete => Boolean) } sealed trait Completed { def process(): Unit } -trait NodeView[A[_]] +private[sbt] trait NodeView[A[_]] { def apply[T](a: A[T]): Node[A, T] def inline[T](a: A[T]): Option[() => T] } final class Triggers[A[_]](val runBefore: collection.Map[A[_], Seq[A[_]]], val injectFor: collection.Map[A[_], Seq[A[_]]], val onComplete: RMap[A,Result] => RMap[A,Result]) -final class Execute[A[_] <: AnyRef] private(config: Config, triggers: Triggers[A])(implicit view: NodeView[A]) +private[sbt] final class Execute[A[_] <: AnyRef](config: Config, triggers: Triggers[A], progress: ExecuteProgress[A])(implicit view: NodeView[A]) { - @deprecated("Use Execute.apply", "0.13.0") - def this(checkCycles: Boolean, triggers: Triggers[A])(implicit view: NodeView[A]) = this(Execute.config(checkCycles), triggers)(view) - type Strategy = CompletionService[A[_], Completed] private[this] val forward = idMap[A[_], IDSet[A[_]] ] @@ -56,6 +50,7 @@ final class Execute[A[_] <: AnyRef] private(config: Config, triggers: Triggers[A case None => results(a) } } + private[this] var progressState: progress.S = progress.initial private[this] type State = State.Value private[this] object State extends Enumeration { @@ -73,7 +68,9 @@ final class Execute[A[_] <: AnyRef] private(config: Config, triggers: Triggers[A addNew(root) processAll() assert( results contains root, "No result for root node." ) - triggers.onComplete(results) + val finalResults = triggers.onComplete(results) + progressState = progress.allCompleted(progressState, finalResults) + finalResults } def processAll()(implicit strategy: Strategy) @@ -136,6 +133,7 @@ final class Execute[A[_] <: AnyRef] private(config: Config, triggers: Triggers[A results(node) = result state(node) = Done + progressState = progress.completed(progressState, node, result) remove( reverse, node ) foreach { dep => notifyDone(node, dep) } callers.remove( node ).toList.flatten.foreach { c => retire(c, callerResult(c, result)) } triggeredBy( node ) foreach { t => addChecked(t) } @@ -174,9 +172,9 @@ final class Execute[A[_] <: AnyRef] private(config: Config, triggers: Triggers[A post { addedInv( node ) } } /** Adds a node that has not yet been registered with the system. - * If all of the node's dependencies have finished, the node's computation scheduled to run. + * If all of the node's dependencies have finished, the node's computation is scheduled to run. * The node's dependencies will be added (transitively) if they are not already registered. - * */ + */ def addNew[T](node: A[T])(implicit strategy: Strategy) { pre { newPre(node) } @@ -184,6 +182,7 @@ final class Execute[A[_] <: AnyRef] private(config: Config, triggers: Triggers[A val v = register( node ) val deps = dependencies(v) ++ runBefore(node) val active = IDSet[A[_]](deps filter notDone ) + progressState = progress.registered(progressState, node, deps, active.toList /** active is mutable, so take a snapshot */) if( active.isEmpty) ready( node ) @@ -214,6 +213,7 @@ final class Execute[A[_] <: AnyRef] private(config: Config, triggers: Triggers[A } state(node) = Running + progressState = progress.ready(progressState, node) submit(node) post { @@ -240,18 +240,26 @@ final class Execute[A[_] <: AnyRef] private(config: Config, triggers: Triggers[A * This returns a Completed instance, which contains the post-processing to perform after the result is retrieved from the Strategy.*/ def work[T](node: A[T], f: => Either[A[T], T])(implicit strategy: Strategy): Completed = { - val result = wideConvert(f).left.map { + progress.workStarting(node) + val rawResult = wideConvert(f).left.map { case i: Incomplete => if(config.overwriteNode(i)) i.copy(node = Some(node)) else i case e => Incomplete(Some(node), Incomplete.Error, directCause = Some(e)) } + val result = rewrap(rawResult) + progress.workFinished(node, result) completed { result match { - case Left(i) => retire(node, Inc(i)) - case Right(Right(v)) => retire(node, Value(v)) - case Right(Left(target)) => call(node, target) + case Right(v) => retire(node, v) + case Left(target) => call(node, target) } } } + private[this] def rewrap[T](rawResult: Either[Incomplete, Either[A[T], T]]): Either[A[T], Result[T]] = + rawResult match { + case Left(i) => Right(Inc(i)) + case Right(Right(v)) => Right(Value(v)) + case Right(Left(target)) => Left(target) + } def remove[K, V](map: Map[K, V], k: K): V = map.remove(k).getOrElse(sys.error("Key '" + k + "' not in map :\n" + map)) diff --git a/tasks/src/main/scala/sbt/ExecuteProgress.scala b/tasks/src/main/scala/sbt/ExecuteProgress.scala new file mode 100644 index 000000000..98f665c32 --- /dev/null +++ b/tasks/src/main/scala/sbt/ExecuteProgress.scala @@ -0,0 +1,58 @@ +package sbt + +/** Processes progress events during task execution. +* All methods are called from the same thread except `started` and `finished`, +* which is called from the executing task's thread. +* All methods should return quickly to avoid task execution overhead. +* +* This class is experimental and subject to binary and source incompatible changes at any time. */ +private[sbt] trait ExecuteProgress[A[_]] +{ + type S + def initial: S + + /** Notifies that a `task` has been registered in the system for execution. + * The dependencies of `task` are `allDeps` and the subset of those dependencies that + * have not completed are `pendingDeps`.*/ + def registered(state: S, task: A[_], allDeps: Iterable[A[_]], pendingDeps: Iterable[A[_]]): S + + /** Notifies that all of the dependencies of `task` have completed and `task` is therefore + * ready to run. The task has not been scheduled on a thread yet. */ + def ready(state: S, task: A[_]): S + + /** Notifies that the work for `task` is starting after this call returns. + * This is called from the thread the task executes on, unlike most other methods in this callback. + * It is called immediately before the task's work starts with minimal intervening executor overhead. */ + def workStarting(task: A[_]): Unit + + /** Notifies that the work for `task` work has finished. The task may have computed the next task to + * run, in which case `result` contains that next task wrapped in Left. If the task produced a value + * or terminated abnormally, `result` provides that outcome wrapped in Right. The ultimate result of + * a task is provided to the `completed` method. + * This is called from the thread the task executes on, unlike most other methods in this callback. + * It is immediately called after the task's work is complete with minimal intervening executor overhead. */ + def workFinished[T](task: A[T], result: Either[A[T], Result[T]]): Unit + + /** Notifies that `task` has completed. + * The task's work is done with a final `result`. + * Any tasks called by `task` have completed. */ + def completed[T](state: S, task: A[T], result: Result[T]): S + + /** All tasks have completed with the final `results` provided. */ + def allCompleted(state: S, results: RMap[A,Result]): S +} + +/** This module is experimental and subject to binary and source incompatible changes at any time. */ +private[sbt] object ExecuteProgress +{ + def empty[A[_]]: ExecuteProgress[A] = new ExecuteProgress[A] { + type S = Unit + def initial = () + def registered(state: Unit, task: A[_], allDeps: Iterable[A[_]], pendingDeps: Iterable[A[_]]) = () + def ready(state: Unit, task: A[_]) = () + def workStarting(task: A[_]) = () + def workFinished[T](task: A[T], result: Either[A[T], Result[T]]) = () + def completed[T](state: Unit, task: A[T], result: Result[T]) = () + def allCompleted(state: Unit, results: RMap[A,Result]) = () + } +} \ No newline at end of file diff --git a/util/collection/src/main/scala/sbt/IDSet.scala b/util/collection/src/main/scala/sbt/IDSet.scala index 447082d8b..43a0d6f16 100644 --- a/util/collection/src/main/scala/sbt/IDSet.scala +++ b/util/collection/src/main/scala/sbt/IDSet.scala @@ -12,6 +12,7 @@ trait IDSet[T] def ++=(t: Iterable[T]): Unit def -= (t: T): Boolean def all: collection.Iterable[T] + def toList: List[T] def isEmpty: Boolean def foreach(f: T => Unit): Unit def process[S](t: T)(ifSeen: S)(ifNew: => S): S @@ -38,6 +39,7 @@ object IDSet def ++=(t: Iterable[T]) = t foreach += def -= (t:T) = if(backing.remove(t) eq null) false else true def all = collection.JavaConversions.collectionAsScalaIterable(backing.keySet) + def toList = all.toList def isEmpty = backing.isEmpty def process[S](t: T)(ifSeen: S)(ifNew: => S) = if(contains(t)) ifSeen else { this += t ; ifNew } override def toString = backing.toString