Emit detailed compiler trace under -Yprofile

Suitable for viewing directly in chrome://tracing, or manipulation
with the underlying tooling at:

https://github.com/catapult-project/catapult/tree/master/tracing

  - Time spent completing lazy types is excluded from the callsite,
    and instead attributed to the symbol being completed itself.
  - The top-most implicit search is tracked.
  - macro expansions are tracked the trace

Author: retronym

src/compiler/scala/tools/nsc/Global.scala

@@ -438,8 +438,10 @@ class Global(var currentSettings: Settings, reporter0: Reporter)
         currentRun.informUnitStarting(this, unit)
         val unit0 = currentUnit
         currentRun.currentUnit = unit
+        val beforeSnap = currentRun.profiler.beforeUnit(phase, unit.source.file)
         try apply(unit)
         finally {
+          currentRun.profiler.afterUnit(phase, unit.source.file, beforeSnap)
           currentRun.currentUnit = unit0
           currentRun.advanceUnit()
         }
@@ -1100,6 +1102,9 @@ class Global(var currentSettings: Settings, reporter0: Reporter)
 
   def newJavaUnitParser(unit: CompilationUnit): JavaUnitParser = new JavaUnitParser(unit)
 
+  override protected[scala] def currentRunProfilerBeforeCompletion(root: Symbol): Unit = currentRun.profiler.beforeCompletion(root)
+  override protected[scala] def currentRunProfilerAfterCompletion(root: Symbol): Unit = currentRun.profiler.afterCompletion(root)
+
   /** A Run is a single execution of the compiler on a set of units.
    */
   class Run extends RunContextApi with RunReporting with RunParsing {
@@ -1448,7 +1453,7 @@ class Global(var currentSettings: Settings, reporter0: Reporter)
     private final val GlobalPhaseName = "global (synthetic)"
     protected final val totalCompileTime = statistics.newTimer("#total compile time", GlobalPhaseName)
 
-    def compileUnits(units: List[CompilationUnit], fromPhase: Phase): Unit =  compileUnitsInternal(units,fromPhase)
+    def compileUnits(units: List[CompilationUnit], fromPhase: Phase): Unit = compileUnitsInternal(units,fromPhase)
     private def compileUnitsInternal(units: List[CompilationUnit], fromPhase: Phase) {
       units foreach addUnit
       reporter.reset()

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

@@ -2,13 +2,19 @@ package scala.tools.nsc.profile
 
 import java.io.{FileWriter, PrintWriter}
 import java.lang.management.ManagementFactory
+import java.nio.file.Files
 import java.util.ServiceLoader
 import java.util.concurrent.TimeUnit
 import java.util.concurrent.atomic.AtomicInteger
+
 import javax.management.openmbean.CompositeData
 import javax.management.{Notification, NotificationEmitter, NotificationListener}
 
-import scala.tools.nsc.{Phase, Settings}
+import scala.collection.mutable
+import scala.collection.mutable.ArrayBuffer
+import scala.reflect.internal.util.ChromeTrace
+import scala.reflect.io.{AbstractFile, File}
+import scala.tools.nsc.{Global, Phase, Settings}
 
 object Profiler {
   def apply(settings: Settings):Profiler =
@@ -20,13 +26,15 @@ object Profiler {
       new RealProfiler(reporter, settings)
     }
 
-  private[profile] val emptySnap = ProfileSnap(0, "", 0, 0, 0, 0, 0, 0)
+  private[profile] val emptySnap = ProfileSnap(0, "", 0, 0, 0, 0, 0, 0, 0, 0)
+}
+case class GcEventData(pool:String, reportTimeNs: Long, gcStartMillis:Long, gcEndMillis:Long, durationMillis: Long, name:String, action:String, cause:String, threads:Long) {
+  val endNanos = System.nanoTime()
 }
-case class GcEventData(pool:String, reportTimeNs: Long, gcStartMillis:Long, gcEndMillis:Long, name:String, action:String, cause:String, threads:Long)
 
 case class ProfileSnap(threadId: Long, threadName: String, snapTimeNanos : Long,
-                         idleTimeNanos:Long, cpuTimeNanos: Long, userTimeNanos: Long,
-                         allocatedBytes:Long, heapBytes:Long) {
+                       idleTimeNanos:Long, cpuTimeNanos: Long, userTimeNanos: Long,
+                       allocatedBytes:Long, heapBytes:Long, totalClassesLoaded: Long, totalJITCompilationTime: Long) {
   def updateHeap(heapBytes:Long) = {
     copy(heapBytes = heapBytes)
   }
@@ -61,20 +69,38 @@ case class ProfileRange(start: ProfileSnap, end:ProfileSnap, phase:Phase, purpos
   def retainedHeapMB = toMegaBytes(end.heapBytes - start.heapBytes)
 }
 
-sealed trait Profiler {
+sealed abstract class Profiler {
 
   def finished(): Unit
 
   def beforePhase(phase: Phase): ProfileSnap
 
   def afterPhase(phase: Phase, profileBefore: ProfileSnap): Unit
+
+  def beforeUnit(phase: Phase, file: AbstractFile): ProfileSnap
+
+  def afterUnit(phase: Phase, file: AbstractFile, profileBefore: ProfileSnap): Unit
+
+  def beforeTypedImplDef(sym: Global#Symbol): Unit = ()
+  def afterTypedImplDef(sym: Global#Symbol): Unit = ()
+
+  def beforeImplicitSearch(pt: Global#Symbol): Unit = ()
+  def afterImplicitSearch(pt: Global#Symbol): Unit = ()
+
+  def beforeMacroExpansion(macroSym: Global#Symbol): Unit = ()
+  def afterMacroExpansion(macroSym: Global#Symbol): Unit = ()
+
+  def beforeCompletion(root: Global#Symbol): Unit = ()
+  def afterCompletion(root: Global#Symbol): Unit = ()
 }
 private [profile] object NoOpProfiler extends Profiler {
 
   override def beforePhase(phase: Phase): ProfileSnap = Profiler.emptySnap
 
   override def afterPhase(phase: Phase, profileBefore: ProfileSnap): Unit = ()
 
+  override def beforeUnit(phase: Phase, file: AbstractFile): ProfileSnap = Profiler.emptySnap
+  override def afterUnit(phase: Phase, file: AbstractFile, profileBefore: ProfileSnap): Unit = ()
   override def finished(): Unit = ()
 }
 private [profile] object RealProfiler {
@@ -91,6 +117,14 @@ private [profile] object RealProfiler {
 }
 
 private [profile] class RealProfiler(reporter : ProfileReporter, val settings: Settings) extends Profiler with NotificationListener {
+
+  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", 0, "0")
+
   def completeBackground(threadRange: ProfileRange): Unit = {
     reporter.reportBackground(this, threadRange)
   }
@@ -110,16 +144,18 @@ private [profile] class RealProfiler(reporter : ProfileReporter, val settings: S
   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 = threadMx.getThreadAllocatedBytes(Thread.currentThread().getId),
-      heapBytes = readHeapUsage()
+      allocatedBytes = allocatedBytes,
+      heapBytes = readHeapUsage(),
+      totalClassesLoaded = classLoaderMx.getTotalLoadedClassCount,
+      totalJITCompilationTime = compileMx.getTotalCompilationTime
     )
   }
   private def readHeapUsage() = RealProfiler.memoryMx.getHeapMemoryUsage.getUsed
@@ -139,8 +175,19 @@ private [profile] class RealProfiler(reporter : ProfileReporter, val settings: S
       case gc =>
     }
     reporter.close(this)
+    for (gcEvent <- gcEvents) {
+      val durationNanos = TimeUnit.MILLISECONDS.toNanos(gcEvent.durationMillis)
+      val startNanos = gcEvent.endNanos - durationNanos
+      chromeTrace.traceDurationEvent(gcEvent.name, startNanos, durationNanos, GcThreadId)
+    }
+    chromeTrace.traceAsyncEventEnd("scalac", 0, "0")
+
+    println("Trace file: " + tracePath)
+    chromeTrace.close()
   }
 
+  private val gcEvents = ArrayBuffer[GcEventData]()
+  private val GcThreadId = 0
 
   override def handleNotification(notification: Notification, handback: scala.Any): Unit = {
     import java.lang.{Long => jLong}
@@ -161,7 +208,9 @@ private [profile] class RealProfiler(reporter : ProfileReporter, val settings: S
         val startTime = info.get("startTime").asInstanceOf[jLong].longValue()
         val endTime = info.get("endTime").asInstanceOf[jLong].longValue()
         val threads = info.get("GcThreadCount").asInstanceOf[jInt].longValue()
-        reporter.reportGc(GcEventData("", reportNs, startTime, endTime, name, action, cause, threads))
+        val gcEvent = GcEventData("", reportNs, startTime, endTime, duration, name, action, cause, threads)
+        gcEvents += gcEvent
+        reporter.reportGc(gcEvent)
     }
   }
 
@@ -177,22 +226,89 @@ private [profile] class RealProfiler(reporter : ProfileReporter, val settings: S
       doGC
       initialSnap.updateHeap(readHeapUsage())
     } else initialSnap
+    chromeTrace.traceAsyncEventEnd(phase.name, 0, "0")
 
     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, 0, "0")
+    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, 0, "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)
+  }
+
+  private var baseline: ProfileSnap = _
+
   override def beforePhase(phase: Phase): ProfileSnap = {
     assert(mainThread eq Thread.currentThread())
+    chromeTrace.traceAsyncEventStart(phase.name, 0, "0")
     if (settings.YprofileRunGcBetweenPhases.containsPhase(phase))
       doGC
     if (settings.YprofileExternalTool.containsPhase(phase)) {
       println("Profile hook start")
       ExternalToolHook.before()
     }
     active foreach {_.beforePhase(phase)}
-    snapThread(0)
+    val snap = snapThread(0)
+    if (phase.prev eq null) baseline = snap
+    snap
+  }
+
+  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
+
+  import scala.reflect.internal.util.ChromeTrace
+  private def traceId = if (completingStack.isEmpty) 0 else completingStack.top.id
+  override def beforeTypedImplDef(sym: Global#Symbol): Unit = {
+    chromeTrace.traceAsyncEventStart(sym.rawname.toString, traceId, intToString(completingStack.length))
+  }
+  override def afterTypedImplDef(sym: Global#Symbol): Unit = {
+    chromeTrace.traceAsyncEventEnd(sym.rawname.toString, traceId, intToString(completingStack.length))
+  }
+
+  override def beforeImplicitSearch(pt: Global#Symbol): Unit = {
+    chromeTrace.traceAsyncEventStart("<implicit> " + pt.rawname, traceId, intToString(completingStack.length))
   }
 
+  override def afterImplicitSearch(pt: Global#Symbol): Unit = {
+    chromeTrace.traceAsyncEventEnd("<implicit> " + pt.rawname, traceId, intToString(completingStack.length))
+  }
+
+  override def beforeMacroExpansion(macroSym: Global#Symbol): Unit = {
+    chromeTrace.traceAsyncEventStart("<macro> " + macroSym.rawname, traceId, intToString(completingStack.length))
+  }
+
+  override def afterMacroExpansion(macroSym: Global#Symbol): Unit = {
+    chromeTrace.traceAsyncEventEnd("<macro> " + macroSym.rawname, traceId, intToString(completingStack.length))
+  }
+
+  override def beforeCompletion(root: Global#Symbol): Unit = {
+    chromeTrace.traceAsyncEventStart("<wait>", traceId, intToString(completingStack.length))
+    completingStack.push(root)
+    chromeTrace.traceAsyncEventStart("<completion>", traceId, intToString(completingStack.length))
+    chromeTrace.traceAsyncEventStart(root.rawname.toString, traceId, intToString(completingStack.length))
+  }
+
+  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))
+  }
 }
 
 object EventType extends Enumeration {

src/compiler/scala/tools/nsc/symtab/SymbolLoaders.scala

@@ -214,6 +214,7 @@ abstract class SymbolLoaders {
     }
 
     override def complete(root: Symbol) {
+      currentRunProfilerBeforeCompletion(root)
       try {
         val start = java.util.concurrent.TimeUnit.NANOSECONDS.toMillis(System.nanoTime())
         val currentphase = phase
@@ -228,6 +229,8 @@ abstract class SymbolLoaders {
         case ex @ (_: IOException | _: MissingRequirementError) =>
           ok = false
           signalError(root, ex)
+      } finally {
+        currentRunProfilerAfterCompletion(root)
       }
       initRoot(root)
       if (!root.isPackageClass) initRoot(root.companionSymbol)

src/compiler/scala/tools/nsc/typechecker/Implicits.scala

@@ -80,6 +80,16 @@ trait Implicits {
    *  @return                        A search result
    */
   def inferImplicit(tree: Tree, pt: Type, reportAmbiguous: Boolean, isView: Boolean, context: Context, saveAmbiguousDivergent: Boolean, pos: Position): SearchResult = {
+    val ptSym = pt.typeSymbol
+    currentRun.profiler.beforeImplicitSearch(ptSym)
+    try {
+      inferImplicit1(tree, pt, reportAmbiguous, isView, context, saveAmbiguousDivergent, pos)
+    } finally {
+      currentRun.profiler.afterImplicitSearch(ptSym)
+    }
+  }
+
+  private def inferImplicit1(tree: Tree, pt: Type, reportAmbiguous: Boolean, isView: Boolean, context: Context, saveAmbiguousDivergent: Boolean, pos: Position): SearchResult = {
     // Note that the isInvalidConversionTarget seems to make a lot more sense right here, before all the
     // work is performed, than at the point where it presently exists.
     val shouldPrint     = printTypings && !context.undetparams.isEmpty

src/compiler/scala/tools/nsc/typechecker/Macros.scala

@@ -754,7 +754,15 @@ trait Macros extends MacroRuntimes with Traces with Helpers {
   /** Expands a term macro used in apply role as `M(2)(3)` in `val x = M(2)(3)`.
    *  @see DefMacroExpander
    */
-  def macroExpand(typer: Typer, expandee: Tree, mode: Mode, pt: Type): Tree = pluginsMacroExpand(typer, expandee, mode, pt)
+  def macroExpand(typer: Typer, expandee: Tree, mode: Mode, pt: Type): Tree = {
+    val macroSym = expandee.symbol
+    currentRun.profiler.beforeMacroExpansion(macroSym)
+    try {
+      pluginsMacroExpand(typer, expandee, mode, pt)
+    } finally {
+      currentRun.profiler.afterMacroExpansion(macroSym)
+    }
+  }
 
   /** Default implementation of `macroExpand`.
    *  Can be overridden by analyzer plugins (see AnalyzerPlugins.pluginsMacroExpand for more details)