Profile more events, make the profiler more Scala3 idiomatic

Author: WojciechMazur

compiler/src/dotty/tools/dotc/config/ScalaSettings.scala

@@ -429,7 +429,7 @@ private sealed trait YSettings:
       //.withPostSetHook( _ => YprofileEnabled.value = true )
   val YprofileRunGcBetweenPhases: Setting[List[String]] = PhasesSetting(ForkSetting, "Yprofile-run-gc", "Run a GC between phases - this allows heap size to be accurate at the expense of more time. Specify a list of phases, or *", "_")
       //.withPostSetHook( _ => YprofileEnabled.value = true )
-  val YprofileTrace: Setting[String]  = StringSetting("-Yprofile-trace", "file", "Capture trace of compilation in Chrome Trace format", "profile.trace")
+  val YprofileTrace: Setting[String]  = StringSetting(ForkSetting, "Yprofile-trace", "file", "Capture trace of compilation in Chrome Trace format", "profile.trace")
       //.withPostSetHook( _ => YprofileEnabled.value = true )
 
   val YbestEffort: Setting[Boolean] = BooleanSetting(ForkSetting, "Ybest-effort", "Enable best-effort compilation attempting to produce betasty to the META-INF/best-effort directory, regardless of errors, as part of the pickler phase.")

compiler/src/dotty/tools/dotc/core/SymbolLoaders.scala

@@ -8,7 +8,7 @@ import java.nio.channels.ClosedByInterruptException
 import scala.util.control.NonFatal
 
 import dotty.tools.dotc.classpath.FileUtils.{hasTastyExtension, hasBetastyExtension}
-import dotty.tools.io.{ ClassPath, ClassRepresentation, AbstractFile }
+import dotty.tools.io.{ ClassPath, ClassRepresentation, AbstractFile, NoAbstractFile }
 import dotty.tools.backend.jvm.DottyBackendInterface.symExtensions
 
 import Contexts.*, Symbols.*, Flags.*, SymDenotations.*, Types.*, Scopes.*, Names.*
@@ -333,7 +333,18 @@ abstract class SymbolLoader extends LazyType { self =>
     def description(using Context): String = s"proxy to ${self.description}"
   }
 
-  override def complete(root: SymDenotation)(using Context): Unit = {
+  private inline def tryProfileCompletion[T](root: SymDenotation)(inline body: T)(using Context): T = {
+    if ctx.profiler eq null
+    then body
+    else
+      val sym = root.symbol
+      val associatedFile = root.symbol.associatedFile match
+        case file: AbstractFile => file
+        case _ => NoAbstractFile
+      ctx.profiler.onCompletion(sym, associatedFile)(body)
+  }
+
+  override def complete(root: SymDenotation)(using Context): Unit = tryProfileCompletion(root) {
     def signalError(ex: Exception): Unit = {
       if (ctx.debug) ex.printStackTrace()
       val msg = ex.getMessage()
@@ -408,7 +419,6 @@ class ClassfileLoader(val classfile: AbstractFile) extends SymbolLoader {
 
   def compilationUnitInfo: CompilationUnitInfo | Null = CompilationUnitInfo(classfile)
 
-
   def description(using Context): String = "class file " + classfile.toString
 
   override def doComplete(root: SymDenotation)(using Context): Unit =

compiler/src/dotty/tools/dotc/profile/ChromeTrace.scala

@@ -63,7 +63,7 @@ final class ChromeTrace(f: Path) extends Closeable {
     traceWriter.close()
   }
 
-  def traceDurationEvent(name: String, startNanos: Long, durationNanos: Long, tid: String = this.tid(), pidSuffix: String = ""): Unit = {
+  def traceDurationEvent(name: String, startNanos: Long, durationNanos: Long, tid: String = this.tid(), pidSuffix: String = ""): Unit = synchronized {
     val durationMicros = nanosToMicros(durationNanos)
     val startMicros = nanosToMicros(startNanos)
     objStart()
@@ -85,7 +85,7 @@ final class ChromeTrace(f: Path) extends Closeable {
       str2("pid", pid, "-", pidSuffix)
   }
 
-  def traceCounterEvent(name: String, counterName: String, count: Long, processWide: Boolean): Unit = {
+  def traceCounterEvent(name: String, counterName: String, count: Long, processWide: Boolean): Unit = synchronized {
     objStart()
     str("cat", "scalac")
     str("name", name)
@@ -104,7 +104,7 @@ final class ChromeTrace(f: Path) extends Closeable {
   def traceDurationEventStart(cat: String, name: String, colour: String = "", pidSuffix: String = tid()): Unit = traceDurationEventStartEnd(EventType.Start, cat, name, colour, pidSuffix)
   def traceDurationEventEnd(cat: String, name: String, colour: String = "", pidSuffix: String = tid()): Unit = traceDurationEventStartEnd(EventType.End, cat, name, colour, pidSuffix)
 
-  private def traceDurationEventStartEnd(eventType: String, cat: String, name: String, colour: String, pidSuffix: String = ""): Unit = {
+  private def traceDurationEventStartEnd(eventType: String, cat: String, name: String, colour: String, pidSuffix: String = ""): Unit = synchronized {
     objStart()
     str("cat", cat)
     str("name", name)

compiler/src/dotty/tools/dotc/profile/Profiler.scala

@@ -16,8 +16,11 @@ import dotty.tools.dotc.core.Contexts.*
 import dotty.tools.dotc.CompilationUnit
 import dotty.tools.dotc.core.Types.Type
 import dotty.tools.dotc.core.Symbols.Symbol
+import dotty.tools.dotc.core.Flags
+import dotty.tools.backend.jvm.DottyBackendInterface.symExtensions
 import dotty.tools.io.AbstractFile
 import annotation.internal.sharable
+import dotty.tools.dotc.core.Symbols.NoSymbol
 
 object Profiler {
   def apply()(using Context): Profiler =
@@ -78,15 +81,39 @@ sealed trait Profiler {
 
   def afterPhase(phase: Phase, profileBefore: ProfileSnap): Unit
 
+  inline def onUnit[T](phase: Phase, unit: CompilationUnit)(inline body: T): T =
+    beforeUnit(phase, unit)
+    try body
+    finally afterUnit(phase, unit)
   def beforeUnit(phase: Phase, unit: CompilationUnit): Unit = ()
   def afterUnit(phase: Phase,  unit: CompilationUnit): Unit = ()
 
+  inline def onTypedImplDef[T](sym: Symbol)(inline body: T): T =
+    beforeTypedImplDef(sym)
+    try body
+    finally afterTypedImplDef(sym)
   def beforeTypedImplDef(sym: Symbol): Unit = ()
   def afterTypedImplDef(sym: Symbol): Unit = ()
 
+
+  inline def onImplicitSearch[T](pt: Type)(inline body: T): T =
+    beforeImplicitSearch(pt)
+    try body
+    finally afterImplicitSearch(pt)
   def beforeImplicitSearch(pt: Type): Unit  = ()
   def afterImplicitSearch(pt: Type): Unit = ()
 
+  inline def onMacroExpansion[T](macroSym: Symbol)(inline body: T): T =
+    beforeMacroExpansion(macroSym)
+    try body
+    finally afterMacroExpansion(macroSym)
+  def beforeMacroExpansion(macroSym: Symbol): Unit = ()
+  def afterMacroExpansion(macroSym: Symbol): Unit = ()
+
+  inline def onCompletion[T](root: Symbol, associatedFile: AbstractFile)(inline body: T): T =
+    beforeCompletion(root, associatedFile)
+    try body
+    finally afterCompletion(root, associatedFile)
   def beforeCompletion(root: Symbol, associatedFile: AbstractFile): Unit = ()
   def afterCompletion(root: Symbol, associatedFile: AbstractFile): Unit = ()
 }
@@ -280,13 +307,42 @@ private [profile] class RealProfiler(reporter : ProfileReporter)(using Context)
 
   override def beforeImplicitSearch(pt: Type): Unit =
     if chromeTrace != null
-    then chromeTrace.traceDurationEventStart(Category.Implicit, "?[" + pt.typeSymbol.fullName + "]", colour = "yellow")
-
+    then chromeTrace.traceDurationEventStart(Category.Implicit, s"?[${symbolName(pt.typeSymbol)}]", colour = "yellow")
 
   override def afterImplicitSearch(pt: Type): Unit =
     if chromeTrace != null
-    then chromeTrace.traceDurationEventEnd(Category.Implicit, "?[" + pt.typeSymbol.fullName + "]", colour = "yellow")
+    then chromeTrace.traceDurationEventEnd(Category.Implicit, s"?[${symbolName(pt.typeSymbol)}]", colour = "yellow")
+
+  override def beforeMacroExpansion(macroSym: Symbol): Unit =
+    if chromeTrace != null
+    then chromeTrace.traceDurationEventStart(Category.Macro, s"«${symbolName(macroSym)}»", colour = "olive")
+
+  override def afterMacroExpansion(macroSym: Symbol): Unit =
+    if chromeTrace != null
+    then chromeTrace.traceDurationEventEnd(Category.Macro, s"«${symbolName(macroSym)}»", colour = "olive")
+
+  override def beforeCompletion(root: Symbol, associatedFile: AbstractFile): Unit =
+    if chromeTrace != null
+    then
+      chromeTrace.traceDurationEventStart(Category.Completion, "↯", colour = "thread_state_sleeping")
+      chromeTrace.traceDurationEventStart(Category.File, associatedFile.name)
+      chromeTrace.traceDurationEventStart(Category.Completion, completionName(root, associatedFile))
 
+  override def afterCompletion(root: Symbol, associatedFile: AbstractFile): Unit =
+    if chromeTrace != null
+    then
+      chromeTrace.traceDurationEventEnd(Category.Completion, completionName(root, associatedFile))
+      chromeTrace.traceDurationEventEnd(Category.File, associatedFile.name)
+      chromeTrace.traceDurationEventEnd(Category.Completion, "↯", colour = "thread_state_sleeping")
+
+  private def symbolName(sym: Symbol): String = sym.name.toString
+  private def completionName(root: Symbol, associatedFile: AbstractFile): String =
+    def isTopLevel = root.owner != NoSymbol && root.owner.is(Flags.Package)
+    if root.is(Flags.Package) || isTopLevel
+    then root.javaBinaryName
+    else
+      val enclosing = root.enclosingClass
+      s"${enclosing.javaBinaryName}::${root.name}"
 }
 
 case class EventType(name: String)

compiler/src/dotty/tools/dotc/quoted/Interpreter.scala

@@ -171,7 +171,9 @@ class Interpreter(pos: SrcPos, classLoader0: ClassLoader)(using Context):
     val clazz = inst.getClass
     val name = fn.name.asTermName
     val method = getMethod(clazz, name, paramsSig(fn))
-    stopIfRuntimeException(method.invoke(inst, args*), method)
+    ctx.profiler.onMacroExpansion(fn){
+      stopIfRuntimeException(method.invoke(inst, args*), method)
+    }
   }
 
   private def interpretedStaticFieldAccess(sym: Symbol): Object = {

compiler/src/dotty/tools/dotc/typer/Implicits.scala

@@ -1063,9 +1063,8 @@ trait Implicits:
    *                         it should be applied, EmptyTree otherwise.
    *  @param span            The position where errors should be reported.
    */
-  def inferImplicit(pt: Type, argument: Tree, span: Span)(using Context): SearchResult =
-    ctx.profiler.beforeImplicitSearch(pt)
-    try trace(s"search implicit ${pt.show}, arg = ${argument.show}: ${argument.tpe.show}", implicits, show = true) {
+  def inferImplicit(pt: Type, argument: Tree, span: Span)(using Context): SearchResult = ctx.profiler.onImplicitSearch(pt) {
+    trace(s"search implicit ${pt.show}, arg = ${argument.show}: ${argument.tpe.show}", implicits, show = true) {
       record("inferImplicit")
       assert(ctx.phase.allowsImplicitSearch,
         if (argument.isEmpty) i"missing implicit parameter of type $pt after typer at phase ${ctx.phase.phaseName}"
@@ -1132,7 +1131,8 @@ trait Implicits:
         }
       // If we are at the outermost implicit search then emit the implicit dictionary, if any.
       ctx.searchHistory.emitDictionary(span, result)
-    } finally ctx.profiler.afterImplicitSearch(pt)
+    }
+  }
 
   /** Try to typecheck an implicit reference */
   def typedImplicit(cand: Candidate, pt: Type, argument: Tree, span: Span)(using Context): SearchResult =  trace(i"typed implicit ${cand.ref}, pt = $pt, implicitsEnabled == ${ctx.mode is ImplicitsEnabled}", implicits, show = true) {

compiler/src/dotty/tools/dotc/typer/Typer.scala

@@ -2632,9 +2632,7 @@ class Typer(@constructorOnly nestingLevel: Int = 0) extends Namer
     if filters == List(MessageFilter.None) then sup.markUsed()
     ctx.run.nn.suppressions.addSuppression(sup)
 
-  def typedValDef(vdef: untpd.ValDef, sym: Symbol)(using Context): Tree =
-    ctx.profiler.beforeTypedImplDef(sym)
-    try {
+  def typedValDef(vdef: untpd.ValDef, sym: Symbol)(using Context): Tree = ctx.profiler.onTypedImplDef(sym) {
     val ValDef(name, tpt, _) = vdef
     checkNonRootName(vdef.name, vdef.nameSpan)
     completeAnnotations(vdef, sym)
@@ -2648,7 +2646,7 @@ class Typer(@constructorOnly nestingLevel: Int = 0) extends Namer
     val vdef1 = assignType(cpy.ValDef(vdef)(name, tpt1, rhs1), sym)
     postProcessInfo(vdef1, sym)
     vdef1.setDefTree
-  } finally ctx.profiler.afterTypedImplDef(sym)
+  }
 
   private def retractDefDef(sym: Symbol)(using Context): Tree =
     // it's a discarded method (synthetic case class method or synthetic java record constructor or overridden member), drop it
@@ -2660,7 +2658,7 @@ class Typer(@constructorOnly nestingLevel: Int = 0) extends Namer
     sym.owner.info.decls.openForMutations.unlink(sym)
     EmptyTree
 
-  def typedDefDef(ddef: untpd.DefDef, sym: Symbol)(using Context): Tree = if !sym.info.exists then retractDefDef(sym) else {
+  def typedDefDef(ddef: untpd.DefDef, sym: Symbol)(using Context): Tree = if !sym.info.exists then retractDefDef(sym) else ctx.profiler.onTypedImplDef {
 
     // TODO: - Remove this when `scala.language.experimental.erasedDefinitions` is no longer experimental.
     //       - Modify signature to `erased def erasedValue[T]: T`
@@ -2759,7 +2757,7 @@ class Typer(@constructorOnly nestingLevel: Int = 0) extends Namer
     postProcessInfo(ddef2, sym)
     ddef2.setDefTree
       //todo: make sure dependent method types do not depend on implicits or by-name params
-  } finally ctx.profiler.afterTypedImplDef(sym)
+  }
 
   /** (1) Check that the signature of the class member does not return a repeated parameter type
    *  (2) If info is an erased class, set erased flag of member
@@ -2771,9 +2769,7 @@ class Typer(@constructorOnly nestingLevel: Int = 0) extends Namer
     if !sym.is(Module) && !sym.isConstructor && sym.info.finalResultType.isErasedClass then
       sym.setFlag(Erased)
 
-  def typedTypeDef(tdef: untpd.TypeDef, sym: Symbol)(using Context): Tree = {
-    ctx.profiler.beforeTypedImplDef(sym)
-    try {
+  def typedTypeDef(tdef: untpd.TypeDef, sym: Symbol)(using Context): Tree = ctx.profiler.onTypedImplDef(sym) {
     val TypeDef(name, rhs) = tdef
     completeAnnotations(tdef, sym)
     val rhs1 = tdef.rhs match
@@ -2784,12 +2780,9 @@ class Typer(@constructorOnly nestingLevel: Int = 0) extends Namer
     checkFullyAppliedType(rhs1)
     if sym.isOpaqueAlias then checkNoContextFunctionType(rhs1)
     assignType(cpy.TypeDef(tdef)(name, rhs1), sym)
-    } finally  ctx.profiler.afterTypedImplDef(sym)
   }
 
-  def typedClassDef(cdef: untpd.TypeDef, cls: ClassSymbol)(using Context): Tree =
-    ctx.profiler.beforeTypedImplDef(cls)
-    try {
+  def typedClassDef(cdef: untpd.TypeDef, cls: ClassSymbol)(using Context): Tree = ctx.profiler.onTypedImplDef(cls) {
     if (!cls.info.isInstanceOf[ClassInfo]) return EmptyTree.assertingErrorsReported
 
     val TypeDef(name, impl @ Template(constr, _, self, _)) = cdef: @unchecked
@@ -2941,7 +2934,7 @@ class Typer(@constructorOnly nestingLevel: Int = 0) extends Namer
 
       cdef1
     }
-  } finally ctx.profiler.afterTypedImplDef(cls)
+  }
 
       // todo later: check that
       //  1. If class is non-abstract, it is instantiatable: