WIP output Chrome trace format

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

@@ -8,10 +8,17 @@
 package sbt
 package internal
 
-import sbt.internal.util.RMap
+import java.io.BufferedWriter
+import java.nio.file.{ Files, Paths }
 
+import sbt.internal.util.RMap
 import java.util.concurrent.ConcurrentHashMap
+
 import TaskName._
+import sjsonnew.shaded.scalajson.ast.unsafe.JString
+import sjsonnew.support.scalajson.unsafe.CompactPrinter
+
+import scala.collection.mutable
 
 /**
  * Measure the time elapsed for running tasks.
@@ -25,7 +32,7 @@ import TaskName._
 private[sbt] final class TaskTimings(reportOnShutdown: 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] val timings = new ConcurrentHashMap[Task[_], Timer]
   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")
@@ -60,9 +67,9 @@ private[sbt] final class TaskTimings(reportOnShutdown: Boolean) extends ExecuteP
     }
   }
   override def afterReady(task: Task[_]): Unit = ()
-  override def beforeWork(task: Task[_]): Unit = { timings.put(task, System.nanoTime); () }
+  override def beforeWork(task: Task[_]): Unit = { timings.put(task, new Timer); () }
   override def afterWork[T](task: Task[T], result: Either[Task[T], Result[T]]) = {
-    timings.put(task, System.nanoTime - timings.get(task))
+    timings.get(task).stop()
     result.left.foreach { t =>
       calledBy.put(t, task)
     }
@@ -72,6 +79,17 @@ private[sbt] final class TaskTimings(reportOnShutdown: Boolean) extends ExecuteP
     if (!reportOnShutdown) {
       report()
     }
+  private class Timer() {
+    val startNanos = System.nanoTime()
+    val threadId = Thread.currentThread().getId
+    var endNanos = 0L
+    def stop() = {
+      endNanos = System.nanoTime()
+    }
+    def durationNanos = endNanos - startNanos
+    def startMicros: Long = (startNanos.toDouble / 1000).toLong
+    def durationMicros: Long = (durationNanos.toDouble / 1000).toLong
+  }
 
   override def stop(): Unit = ()
 
@@ -81,7 +99,7 @@ private[sbt] final class TaskTimings(reportOnShutdown: Boolean) extends ExecuteP
     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
+    def sumTimes(in: Seq[(Task[_], Timer)]) = in.map(_._2.durationNanos).sum
     val timingsByName = timings.asScala.toSeq.groupBy { case (t, _) => mappedName(t) } mapValues (sumTimes)
     val times = timingsByName.toSeq
       .sortBy(_._2)
@@ -92,6 +110,7 @@ private[sbt] final class TaskTimings(reportOnShutdown: Boolean) extends ExecuteP
       }
       .filter { _._2 > threshold }
     if (times.size > 0) {
+      toChromeTrace()
       val maxTaskNameLength = times.map { _._1.length }.max
       val maxTime = times.map { _._2 }.max.toString.length
       times.foreach {
@@ -101,6 +120,32 @@ private[sbt] final class TaskTimings(reportOnShutdown: Boolean) extends ExecuteP
       }
     }
   }
+
+  private def toChromeTrace(): Unit = {
+    val path = Files.createTempFile("build-", ".trace")
+    val trace = Files.newBufferedWriter(path)
+    try {
+      trace.append("""{"traceEvents": [""")
+      def durationEvent(name: String, cat: String, t: Timer): String = {
+        val sb = new java.lang.StringBuilder(name.length + 2)
+        CompactPrinter.print(new JString(name), sb)
+        // TODO use proper JSON library for all of this.
+        s"""{"name": ${sb.toString}, "cat": "$cat", "ph": "X", "ts": ${(t.startMicros)}, "dur": ${(t.durationMicros)}, "pid": 0, "tid": ${t.threadId}}"""
+      }
+      val entryIterator = timings.entrySet().iterator()
+      while (entryIterator.hasNext) {
+        val entry = entryIterator.next()
+        trace.append(durationEvent(mappedName(entry.getKey), "task", entry.getValue))
+        if (entryIterator.hasNext) trace.append(",")
+      }
+      trace.append("]}")
+    } finally {
+      trace.close()
+      println(path)
+
+    }
+  }
+
   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))