Put the completion back on the same slice as the main thread, more concise output

Author: retronym

src/compiler/scala/tools/nsc/profile/Profiler.scala

@@ -113,52 +113,52 @@ private [profile] object RealProfiler {
   val threadMx = ExtendedThreadMxBean.proxy
   if (threadMx.isThreadCpuTimeSupported) threadMx.setThreadCpuTimeEnabled(true)
   private val idGen = new AtomicInteger()
+  private val baselineSnap = snapThread(0)
+
   lazy val allPlugins = ServiceLoader.load(classOf[ProfilerPlugin]).iterator().asScala.toList
+
+  private[profile] def snapThread( idleTimeNanos:Long): ProfileSnap = {
+    val current = Thread.currentThread()
+    val allocatedBytes = threadMx.getThreadAllocatedBytes(Thread.currentThread().getId)
+    ProfileSnap(
+      threadId = current.getId,
+      threadName = current.getName,
+      snapTimeNanos = System.nanoTime(),
+      idleTimeNanos = idleTimeNanos,
+      cpuTimeNanos = threadMx.getCurrentThreadCpuTime,
+      userTimeNanos = threadMx.getCurrentThreadUserTime,
+      allocatedBytes = allocatedBytes,
+      heapBytes = readHeapUsage(),
+      totalClassesLoaded = classLoaderMx.getTotalLoadedClassCount,
+      totalJITCompilationTime = compileMx.getTotalCompilationTime
+    )
+  }
+  private def readHeapUsage() = RealProfiler.memoryMx.getHeapMemoryUsage.getUsed
 }
 
 private [profile] class RealProfiler(reporter : ProfileReporter, val settings: Settings) extends Profiler with NotificationListener {
   private val mainThread = Thread.currentThread()
+  val id = RealProfiler.idGen.incrementAndGet()
   val tracePath = {
     if (settings.YprofileDestination.isSetByUser) new File(new java.io.File(settings.YprofileDestination.value)).changeExtension("trace").jfile.toPath
     else Files.createTempFile("scalac-", ".trace")
   }
   private val chromeTrace = new ChromeTrace(tracePath)
-  chromeTrace.traceAsyncEventStart("scalac-" + mainThread.getId, mainThread.getId, "0")
+  chromeTrace.traceAsyncEventStart("scalac-" + id, id, "0")
 
   def completeBackground(threadRange: ProfileRange): Unit = {
     reporter.reportBackground(this, threadRange)
   }
 
   def outDir = settings.outputDirs.getSingleOutput.getOrElse(settings.outputDirs.outputs.head._2.file).toString
 
-  val id = RealProfiler.idGen.incrementAndGet()
   RealProfiler.gcMx foreach {
     case emitter: NotificationEmitter => emitter.addNotificationListener(this, null, null)
     case gc => println(s"Cant connect gcListener to ${gc.getClass}")
   }
 
   val active = RealProfiler.allPlugins map (_.generate(this, settings))
 
-
-  private[profile] def snapThread( idleTimeNanos:Long): ProfileSnap = {
-    import RealProfiler._
-    val current = Thread.currentThread()
-    val allocatedBytes = threadMx.getThreadAllocatedBytes(Thread.currentThread().getId)
-    ProfileSnap(
-      threadId = current.getId,
-      threadName = current.getName,
-      snapTimeNanos = System.nanoTime(),
-      idleTimeNanos = idleTimeNanos,
-      cpuTimeNanos = threadMx.getCurrentThreadCpuTime,
-      userTimeNanos = threadMx.getCurrentThreadUserTime,
-      allocatedBytes = allocatedBytes,
-      heapBytes = readHeapUsage(),
-      totalClassesLoaded = classLoaderMx.getTotalLoadedClassCount,
-      totalJITCompilationTime = compileMx.getTotalCompilationTime
-    )
-  }
-  private def readHeapUsage() = RealProfiler.memoryMx.getHeapMemoryUsage.getUsed
-
   private def doGC: Unit = {
     System.gc()
     System.runFinalization()
@@ -179,7 +179,7 @@ private [profile] class RealProfiler(reporter : ProfileReporter, val settings: S
       val startNanos = gcEvent.endNanos - durationNanos
       chromeTrace.traceDurationEvent(gcEvent.name, startNanos, durationNanos, GcThreadId)
     }
-    chromeTrace.traceAsyncEventEnd("scalac-" + mainThread.getId, 0, "0")
+    chromeTrace.traceAsyncEventEnd("scalac-" + id, id, "0")
 
     println("Trace file: " + tracePath)
     chromeTrace.close()
@@ -215,97 +215,84 @@ private [profile] class RealProfiler(reporter : ProfileReporter, val settings: S
 
   override def beforePhase(phase: Phase): ProfileSnap = {
     assert(mainThread eq Thread.currentThread())
-    chromeTrace.traceAsyncEventStart(phase.name, mainThread.getId, "0")
+    chromeTrace.traceAsyncEventStart(phase.name, id, "0")
     if (settings.YprofileRunGcBetweenPhases.containsPhase(phase))
       doGC
     if (settings.YprofileExternalTool.containsPhase(phase)) {
       println("Profile hook start")
       ExternalToolHook.before()
     }
     active foreach {_.beforePhase(phase)}
-    val snap = snapThread(0)
-    if (phase.prev eq null) baseline = snap
-    snap
+    RealProfiler.snapThread(0)
   }
 
   override def afterPhase(phase: Phase, snapBefore: ProfileSnap): Unit = {
     assert(mainThread eq Thread.currentThread())
-    val initialSnap = snapThread(0)
+    val initialSnap = RealProfiler.snapThread(0)
     active foreach {_.afterPhase(phase)}
     if (settings.YprofileExternalTool.containsPhase(phase)) {
       println("Profile hook stop")
       ExternalToolHook.after()
     }
     val finalSnap = if (settings.YprofileRunGcBetweenPhases.containsPhase(phase)) {
       doGC
-      initialSnap.updateHeap(readHeapUsage())
+      initialSnap.updateHeap(RealProfiler.readHeapUsage())
     } else initialSnap
-    chromeTrace.traceAsyncEventEnd(phase.name, mainThread.getId, "0")
+    chromeTrace.traceAsyncEventEnd(phase.name, id, "-GC")
 
     reporter.reportForeground(this, ProfileRange(snapBefore, finalSnap, phase, "", 0, Thread.currentThread))
   }
 
   override def beforeUnit(phase: Phase, file: AbstractFile): ProfileSnap = {
     assert(mainThread eq Thread.currentThread())
-    chromeTrace.traceAsyncEventStart(file.name, mainThread.getId, "0")
-    snapThread(0)
+    chromeTrace.traceAsyncEventStart(file.name, id, "0")
+    RealProfiler.snapThread(0)
   }
 
   override def afterUnit(phase: Phase, file: AbstractFile, snapBefore: ProfileSnap): Unit = {
     assert(mainThread eq Thread.currentThread())
-    val initialSnap = snapThread(0)
-    chromeTrace.traceAsyncEventEnd(file.name, mainThread.getId, "0")
-    chromeTrace.traceCounterEvent("allocBytes", "allocBytes", initialSnap.allocatedBytes - this.baseline.allocatedBytes)
-    chromeTrace.traceCounterEvent("heapBytes", "heapBytes", initialSnap.heapBytes - this.baseline.heapBytes)
-    chromeTrace.traceCounterEvent("classesLoaded", "classesLoaded", initialSnap.totalClassesLoaded - this.baseline.totalClassesLoaded)
-    chromeTrace.traceCounterEvent("jitCompilationTime", "jitCompilationTime", initialSnap.totalJITCompilationTime - this.baseline.totalJITCompilationTime)
-    chromeTrace.traceCounterEvent("userTime", "userTime", initialSnap.userTimeNanos - this.baseline.userTimeNanos)
-    chromeTrace.traceCounterEvent("cpuTime", "cpuTime", initialSnap.cpuTimeNanos - this.baseline.cpuTimeNanos)
-    chromeTrace.traceCounterEvent("idleTime", "idleTime", initialSnap.idleTimeNanos - this.baseline.idleTimeNanos)
+    val initialSnap = RealProfiler.snapThread(0)
+    chromeTrace.traceAsyncEventEnd(file.name, id, "0")
+    chromeTrace.traceCounterEvent("allocBytes", "allocBytes", initialSnap.allocatedBytes - RealProfiler.baselineSnap.allocatedBytes)
+    chromeTrace.traceCounterEvent("heapBytes", "heapBytes", initialSnap.heapBytes - RealProfiler.baselineSnap.heapBytes)
+    chromeTrace.traceCounterEvent("classesLoaded", "classesLoaded", initialSnap.totalClassesLoaded - RealProfiler.baselineSnap.totalClassesLoaded)
+    chromeTrace.traceCounterEvent("jitCompilationTime", "jitCompilationTime", initialSnap.totalJITCompilationTime - RealProfiler.baselineSnap.totalJITCompilationTime)
+    chromeTrace.traceCounterEvent("userTime", "userTime", initialSnap.userTimeNanos - RealProfiler.baselineSnap.userTimeNanos)
+    chromeTrace.traceCounterEvent("cpuTime", "cpuTime", initialSnap.cpuTimeNanos - RealProfiler.baselineSnap.cpuTimeNanos)
+    chromeTrace.traceCounterEvent("idleTime", "idleTime", initialSnap.idleTimeNanos - RealProfiler.baselineSnap.idleTimeNanos)
   }
 
-  private var baseline: ProfileSnap = _
-
-  private val completingStack = new mutable.ArrayStack[Global#Symbol]
-  private val stringsOf = (0 to 128).map(_.toString).toArray
-  def intToString(i: Int) = if (i < 128) stringsOf(i) else i.toString
-
-  private def traceId = if (completingStack.isEmpty) mainThread.getId else mainThread.getId << 32 | (completingStack.top.id.toLong & 0xffffffffL)
   override def beforeTypedImplDef(sym: Global#Symbol): Unit = {
-    chromeTrace.traceAsyncEventStart(sym.rawname.toString, traceId, intToString(completingStack.length))
+    chromeTrace.traceAsyncEventStart(sym.rawname.toString, id, "")
   }
   override def afterTypedImplDef(sym: Global#Symbol): Unit = {
-    chromeTrace.traceAsyncEventEnd(sym.rawname.toString, traceId, intToString(completingStack.length))
+    chromeTrace.traceAsyncEventEnd(sym.rawname.toString, id, "")
   }
 
   override def beforeImplicitSearch(pt: Global#Symbol): Unit = {
-    chromeTrace.traceAsyncEventStart("<implicit> " + pt.rawname, traceId, intToString(completingStack.length), colour = "yellow")
+    chromeTrace.traceAsyncEventStart("?[" + pt.rawname + "]", id, "", colour = "yellow")
   }
 
   override def afterImplicitSearch(pt: Global#Symbol): Unit = {
-    chromeTrace.traceAsyncEventEnd("<implicit> " + pt.rawname, traceId, intToString(completingStack.length), colour = "yellow")
+    chromeTrace.traceAsyncEventEnd("?[" + pt.rawname + "]", id, "", colour = "yellow")
   }
 
   override def beforeMacroExpansion(macroSym: Global#Symbol): Unit = {
-    chromeTrace.traceAsyncEventStart("<macro> " + macroSym.rawname, traceId, intToString(completingStack.length), colour = "olive")
+    chromeTrace.traceAsyncEventStart("«" + macroSym.rawname + "»", id, "", colour = "olive")
   }
 
   override def afterMacroExpansion(macroSym: Global#Symbol): Unit = {
-    chromeTrace.traceAsyncEventEnd("<macro> " + macroSym.rawname, traceId, intToString(completingStack.length), colour = "olive")
+    chromeTrace.traceAsyncEventEnd("«" + macroSym.rawname + "»", id, "", colour = "olive")
   }
 
   override def beforeCompletion(root: Global#Symbol): Unit = {
-    chromeTrace.traceAsyncEventStart("<wait>", traceId, intToString(completingStack.length), colour = "thread_state_sleeping")
-    completingStack.push(root)
-    chromeTrace.traceAsyncEventStart("<completion>", traceId, intToString(completingStack.length))
-    chromeTrace.traceAsyncEventStart(root.rawname.toString, traceId, intToString(completingStack.length))
+    chromeTrace.traceAsyncEventStart("↯", id, "", colour = "thread_state_sleeping")
+    chromeTrace.traceAsyncEventStart(root.rawname.toString, id, "")
   }
 
   override def afterCompletion(root: Global#Symbol): Unit = {
-    chromeTrace.traceAsyncEventEnd(root.rawname.toString, traceId, intToString(completingStack.length))
-    chromeTrace.traceAsyncEventEnd("<completion>", traceId, intToString(completingStack.length))
-    completingStack.pop()
-    chromeTrace.traceAsyncEventEnd("<wait>", traceId, intToString(completingStack.length))
+    chromeTrace.traceAsyncEventEnd(root.rawname.toString, id, "")
+    chromeTrace.traceAsyncEventEnd("↯", id, "", colour = "thread_state_sleeping")
   }
 }
 

src/compiler/scala/tools/nsc/profile/ThreadPoolFactory.scala

@@ -86,9 +86,9 @@ object ThreadPoolFactory {
       val data = new ThreadProfileData
       localData.set(data)
 
-      val profileStart = profiler.snapThread(0)
+      val profileStart = RealProfiler.snapThread(0)
       try worker.run finally {
-        val snap = profiler.snapThread(data.idleNs)
+        val snap = RealProfiler.snapThread(data.idleNs)
         val threadRange = ProfileRange(profileStart, snap, phase, shortId, data.taskCount, Thread.currentThread())
         profiler.completeBackground(threadRange)
       }

src/reflect/scala/reflect/internal/util/ChromeTrace.scala

@@ -27,9 +27,10 @@ final class ChromeTrace(f: Path) extends Closeable {
   import ChromeTrace.EventType
   private val traceWriter = Files.newBufferedWriter(f)
   traceWriter.write("""{"traceEvents": [""")
+  traceWriter.write("\n")
 
   override def close(): Unit = {
-    traceWriter.append("]}")
+    traceWriter.append("\n]}")
     traceWriter.close()
   }