Capture contextual typer timings suitable for flamegraphs

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

```scala
package p1

import scala.reflect.macros.blackbox._
import language.experimental._

object Macro {
  def impl(c: Context): c.Tree = {
    import c.universe._
    println(rootMirror.staticClass("p1.Base").knownDirectSubclasses)
    q"()"
  }
  def p1_Base_knownDirectSubclasses: Unit = macro impl
}
```

```scala
class Test1 {
  Sleep.sleep(100)
  def twoHundred() {
    Sleep.sleep(200)
  }
  def fast() {
    "".isEmpty
  }
  def stillFast() {
    new Test3
  }
  val slowVal = Sleep.sleep(140)
  def slowDefSlowVal = {
    Sleep.sleep(140)
    val slowValNested = Sleep.sleep(140)
  }
  def fooCall(t: Test3) = t.foo
}

class Test3 extends Test2(Sleep.sleep(100)) {
  def foo = Sleep.sleep(300)
}
class Test2[T](a: T)
```

Gives:

```
⚡ cat /tmp/output.csv
<root>;java;lang;invoke 6784973
<root>;scala;Boolean 1008832
<root>;<empty>;Test3;<init> 3968070
<root>;scala;AnyVal 545566
<root>;<empty>;Test1 41991858
<root>;scala;reflect;macros 3394111
<root>;<empty>;Test1;stillFast 44014771
<root>;<empty> 3888809
<root>;<empty>;Test1;slowDefSlowVal;slowValNested;<macro>;Sleep.sleep 145958765
<root>;scala;DeprecatedPredef 1905347
<root>;scala;reflect;macros;internal 1038672
<root>;<empty>;Test1;twoHundred 2229225
<root>;<empty>;Test2;a 140655
<root>;<empty>;Test1;slowVal ;<macro>;Sleep.sleep 142835436
<root>;<empty>;<local <empty>>;<macro>;Sleep.sleep 103792019
<root>;<empty>;Test1;slowVal 488540
<root>;<empty>;Test1;twoHundred;<macro>;Sleep.sleep 204254878
<root>;<empty>;Test2;<init>;a 138838
<root>;<empty>;Sleep 5413257
<root>;java;util;stream 3461340
<root>;<empty>;Test1;fooCall;t 434245
<root>;<empty>;Test1;slowVal  517689
<root>;<empty>;Test3;<init>;<macro>;Sleep.sleep 103095814
<root>;<empty>;Test3 6626318
<root>;java;lang;CharSequence 1181685
<root>;<empty>;Test2 4495052
<root>;<empty>;Test3;foo 141093
<root>;scala;collection;immutable 6981213
<root>;<empty>;Test3;foo;<macro>;Sleep.sleep 307391221
<root>;<empty>;Test2;<init> 1416591
<root>;scala;Unit 849716
<root>;scala;reflect;macros;package 1492276
<root>;<empty>;Test1;<local Test1>;<macro>;Sleep.sleep 207086274
<root>;scala;Int 3794993
<root>;<empty>;Test1;slowDefSlowVal;<macro>;Sleep.sleep 145070640
<root>;scala;Predef 13958827
<root>;<empty>;Test1;slowDefSlowVal;slowValNested 186048
<root>;<empty>;<local <empty>>;<macro>;Sleep.sleep 106121967
<root>;<empty>;Test1;<init> 19296574
<root>;scala;LowPriorityImplicits 2508560
<root>;<empty>;Test1;fooCall 1268531
<root>;<empty>;Test1;fast 2643270
<root>;<empty>;Test1;slowDefSlowVal 156368
```

Which renders to:

https://cdn.rawgit.com/retronym/672ca835fb5513003499ce6c68831219/raw/975adfa0a4d9bda45264002bf0e0206a03e2cbd4/output.svg
https://cdn.rawgit.com/retronym/01b6640a1ef5584add72f432735d540e/raw/89de5e8e32ad9a2dddf1dc3473c27546e770f8f8/output-reverse.svg

Author: retronym

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

@@ -10,12 +10,13 @@ package nsc
 import java.io.{File, FileNotFoundException, IOException}
 import java.net.URL
 import java.nio.charset.{Charset, CharsetDecoder, IllegalCharsetNameException, UnsupportedCharsetException}
+
 import scala.collection.{immutable, mutable}
 import io.{AbstractFile, Path, SourceReader}
 import reporters.Reporter
 import util.{ClassPath, returning}
 import scala.reflect.ClassTag
-import scala.reflect.internal.util.{BatchSourceFile, NoSourceFile, ScalaClassLoader, ScriptSourceFile, SourceFile, StatisticsStatics}
+import scala.reflect.internal.util.{BatchSourceFile, NoSourceFile, ScalaClassLoader, ScriptSourceFile, SourceFile, Statistics, StatisticsStatics}
 import scala.reflect.internal.pickling.PickleBuffer
 import symtab.{Flags, SymbolTable, SymbolTrackers}
 import symtab.classfile.Pickler
@@ -26,9 +27,11 @@ import typechecker._
 import transform.patmat.PatternMatching
 import transform._
 import backend.{JavaPlatform, ScalaPrimitives}
-import backend.jvm.{GenBCode, BackendStats}
+import backend.jvm.{BackendStats, GenBCode}
+import scala.collection.mutable.ArrayBuffer
 import scala.concurrent.Future
 import scala.language.postfixOps
+import scala.reflect.io.Path
 import scala.tools.nsc.ast.{TreeGen => AstTreeGen}
 import scala.tools.nsc.classpath._
 import scala.tools.nsc.profile.Profiler
@@ -1477,8 +1480,41 @@ class Global(var currentSettings: Settings, reporter0: Reporter)
           runCheckers()
 
         // output collected statistics
-        if (settings.YstatisticsEnabled && settings.Ystatistics.contains(phase.name))
+        if (settings.YstatisticsEnabled && settings.Ystatistics.contains(phase.name)) {
           printStatisticsFor(phase)
+          if (phase == typerPhase) {
+            import java.nio.file._
+            val writer = Files.newBufferedWriter(java.nio.file.Paths.get("/tmp/output.csv"))
+            try {
+              for ((key @ statistics.StatsKey(sym, macroo, implicitPt), stats) <- statistics.statsMap if sym != NoSymbol) {
+                val ownerChain = sym.ownerChain.toArray
+                var i = ownerChain.length - 1
+                while (i >= 0) {
+                  writer.write(ownerChain(i).name.toString)
+                  if (i != 0) writer.write(";")
+                  i -= 1
+                }
+                if (macroo != NoSymbol) {
+                  writer.write(";")
+                  writer.write("<macro>;")
+                  writer.write(macroo.fullName)
+                }
+                if (implicitPt != NoSymbol) {
+                  writer.write(";")
+                  writer.write("<implicit>;")
+                  writer.write(implicitPt.fullName)
+                }
+                writer.write(" ")
+                writer.write(String.valueOf(stats.duration))
+                writer.write("\n")
+              }
+            } finally {
+              writer.close()
+            }
+          }
+        }
+
+
 
         advancePhase()
       }
@@ -1580,9 +1616,8 @@ class Global(var currentSettings: Settings, reporter0: Reporter)
     private val hotCounters =
       List(statistics.retainedCount, statistics.retainedByType, statistics.nodeByType)
     private val parserStats = {
-      import statistics.treeNodeCount
-      if (settings.YhotStatisticsEnabled) treeNodeCount :: hotCounters
-      else List(treeNodeCount)
+      if (settings.YhotStatisticsEnabled) statistics.treeNodeCount :: hotCounters
+      else List(statistics.treeNodeCount)
     }
 
     final def printStatisticsFor(phase: Phase) = {
@@ -1599,7 +1634,7 @@ class Global(var currentSettings: Settings, reporter0: Reporter)
         }
       }
 
-      val quants: Iterable[statistics.Quantity] =
+      val quants: Iterable[Statistics#Quantity] =
         if (phase.name == "parser") parserStats
         else if (settings.YhotStatisticsEnabled) statistics.allQuantities
         else statistics.allQuantities.filterNot(q => hotCounters.contains(q))

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

@@ -213,7 +213,12 @@ abstract class SymbolLoaders {
       })
     }
 
-    override def complete(root: Symbol) {
+    override def complete(root: Symbol): Unit = {
+      statistics.withContext(true, root, NoSymbol, NoSymbol) {
+        completeInternal(root)
+      }
+    }
+    private def completeInternal(root: Symbol) {
       try {
         val start = java.util.concurrent.TimeUnit.NANOSECONDS.toMillis(System.nanoTime())
         val currentphase = phase
@@ -225,7 +230,7 @@ abstract class SymbolLoaders {
         setSource(root.companionSymbol) // module -> class, class -> module
       }
       catch {
-        case ex @ (_: IOException | _: MissingRequirementError) =>
+        case ex@(_: IOException | _: MissingRequirementError) =>
           ok = false
           signalError(root, ex)
       }

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

@@ -80,6 +80,11 @@ trait Implicits {
    *  @return                        A search result
    */
   def inferImplicit(tree: Tree, pt: Type, reportAmbiguous: Boolean, isView: Boolean, context: Context, saveAmbiguousDivergent: Boolean, pos: Position): SearchResult = {
+    statistics.withContext(hasLength(context.openImplicits, 0) && hasLength(openMacros, 0), context.owner, NoSymbol, pt.typeSymbol) {
+      inferImplicit1(tree, pt, reportAmbiguous, isView, context, saveAmbiguousDivergent, pos)
+    }
+  }
+  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,12 @@ 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 addContext = hasLength(openMacros, 0) && hasLength(typer.context.openImplicits, 0)
+    statistics.withContext(addContext, typer.context.owner, expandee.symbol, NoSymbol){
+      pluginsMacroExpand(typer, expandee, mode, pt)
+    }
+  }
 
   /** Default implementation of `macroExpand`.
    *  Can be overridden by analyzer plugins (see AnalyzerPlugins.pluginsMacroExpand for more details)

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

@@ -1820,7 +1820,7 @@ trait Typers extends Adaptations with Tags with TypersTracking with PatternTyper
       }
     }
 
-    def typedClassDef(cdef: ClassDef): Tree = {
+    def typedClassDef(cdef: ClassDef): Tree = statistics.withContext(true, cdef.symbol, NoSymbol, NoSymbol) {
       val clazz = cdef.symbol
       val typedMods = typedModifiers(cdef.mods)
       assert(clazz != NoSymbol, cdef)
@@ -1856,7 +1856,7 @@ trait Typers extends Adaptations with Tags with TypersTracking with PatternTyper
         .setType(NoType)
     }
 
-    def typedModuleDef(mdef: ModuleDef): Tree = {
+    def typedModuleDef(mdef: ModuleDef): Tree = statistics.withContext(true, mdef.symbol, NoSymbol, NoSymbol) {
       // initialize all constructors of the linked class: the type completer (Namer.methodSig)
       // might add default getters to this object. example: "object T; class T(x: Int = 1)"
       val linkedClass = companionSymbolOf(mdef.symbol, context)
@@ -2032,7 +2032,7 @@ trait Typers extends Adaptations with Tags with TypersTracking with PatternTyper
     def typedModifiers(mods: Modifiers): Modifiers =
       mods.copy(annotations = Nil) setPositions mods.positions
 
-    def typedValDef(vdef: ValDef): ValDef = {
+    def typedValDef(vdef: ValDef): ValDef = statistics.withContext(true, vdef.symbol, NoSymbol, NoSymbol) {
       val sym = vdef.symbol
       val valDefTyper = {
         val maybeConstrCtx =
@@ -2258,9 +2258,7 @@ trait Typers extends Adaptations with Tags with TypersTracking with PatternTyper
         failStruct(ddef.tpt.pos, "a user-defined value class", where = "Result type")
     }
 
-    def typedDefDef(ddef: DefDef): DefDef = {
-      // an accessor's type completer may mutate a type inside `ddef` (`== context.unit.synthetics(ddef.symbol)`)
-      // concretely: it sets the setter's parameter type or the getter's return type (when derived from a valdef with empty tpt)
+    def typedDefDef(ddef: DefDef): DefDef = statistics.withContext(true, ddef.symbol, NoSymbol, NoSymbol) {
       val meth = ddef.symbol.initialize
 
       reenterTypeParams(ddef.tparams)
@@ -2293,9 +2291,9 @@ trait Typers extends Adaptations with Tags with TypersTracking with PatternTyper
       var rhs1 =
         if (ddef.name == nme.CONSTRUCTOR && !ddef.symbol.hasStaticFlag) { // need this to make it possible to generate static ctors
           if (!meth.isPrimaryConstructor &&
-              (!meth.owner.isClass ||
-               meth.owner.isModuleClass ||
-               meth.owner.isAnonOrRefinementClass))
+            (!meth.owner.isClass ||
+              meth.owner.isModuleClass ||
+              meth.owner.isAnonOrRefinementClass))
             InvalidConstructorDefError(ddef)
           typed(ddef.rhs)
         } else if (meth.isMacro) {
@@ -2320,7 +2318,7 @@ trait Typers extends Adaptations with Tags with TypersTracking with PatternTyper
         rhs1 = checkDead(rhs1)
 
       if (!isPastTyper && meth.owner.isClass &&
-          meth.paramss.exists(ps => ps.exists(_.hasDefault) && isRepeatedParamType(ps.last.tpe)))
+        meth.paramss.exists(ps => ps.exists(_.hasDefault) && isRepeatedParamType(ps.last.tpe)))
         StarWithDefaultError(meth)
 
       if (!isPastTyper) {

src/library/scala/collection/immutable/StringOps.scala

@@ -27,7 +27,6 @@ import mutable.StringBuilder
  *  @define coll string
  */
 final class StringOps(override val repr: String) extends AnyVal with StringLike[String] {
-
   override protected[this] def thisCollection: WrappedString = new WrappedString(repr)
   override protected[this] def toCollection(repr: String): WrappedString = new WrappedString(repr)
 

src/reflect/scala/reflect/internal/Symbols.scala

@@ -1236,6 +1236,13 @@ trait Symbols extends api.Symbols { self: SymbolTable =>
       def next = { val r = current; current = current.owner; r }
     }
 
+    @tailrec final def hasTermOwner: Boolean = this != NoSymbol && {
+      val owner = this.owner
+      if (owner.hasPackageFlag) false
+      else if (owner.isTerm) true
+      else owner.hasTermOwner
+    }
+
     /** Same as `ownerChain contains sym` but more efficient, and
      *  with a twist for refinement classes (see RefinementClassSymbol.)
      */

src/reflect/scala/reflect/internal/Types.scala

@@ -4839,4 +4839,6 @@ trait TypesStats {
   val typerefBaseTypeSeqCount = newSubCounter("  of which for typerefs", baseTypeSeqCount)
   val singletonBaseTypeSeqCount = newSubCounter("  of which for singletons", baseTypeSeqCount)
   val typeOpsStack = newTimerStack()
+  val completionStack = newTimerStack()
+  class PerSymbolStats(stats: List[Quantity])
 }

src/reflect/scala/reflect/internal/util/Statistics.scala

@@ -9,14 +9,56 @@ import java.util.concurrent.atomic.{AtomicInteger, AtomicLong}
 import scala.runtime.LongRef
 
 abstract class Statistics(val symbolTable: SymbolTable, settings: MutableSettings) {
-
   initFromSettings(settings)
 
   def initFromSettings(currentSettings: MutableSettings): Unit = {
     enabled = currentSettings.YstatisticsEnabled
     hotEnabled = currentSettings.YhotStatisticsEnabled
   }
 
+  type Sym = SymbolTable#Symbol
+  case class StatsKey(owner: Sym, macroo: Sym, implicitPt: Sym)
+
+  final class StackedStats {
+    private var startNanos = System.nanoTime()
+    var duration: Long = 0
+    var running = true
+    def stop(): Unit = {
+      assert(running)
+      duration += System.nanoTime() - startNanos
+      running = false
+    }
+    def start(): Unit = {
+      startNanos = System.nanoTime()
+      running = true
+    }
+  }
+
+  private val TopKey = StatsKey(symbolTable.NoSymbol, symbolTable.NoSymbol, symbolTable.NoSymbol)
+  private var statsStack = mutable.ArrayStack[(StatsKey, StackedStats)]((TopKey, new StackedStats))
+  val statsMap = mutable.AnyRefMap[StatsKey, StackedStats](statsStack.head)
+  private def currentStats: StackedStats = statsStack.top._2
+
+  def start(owner: Sym, macroo: Sym, implicitPt: Sym): Unit = {
+    currentStats.stop()
+    val key = StatsKey(owner, macroo, implicitPt)
+    val stats = statsMap.getOrNull(key) match {
+      case null => val x = new StackedStats; statsMap(key) = x; x
+      case existing => existing.start(); existing
+    }
+    statsStack.push((key, stats))
+  }
+  def end(): Unit = {
+    statsStack.pop()._2.stop()
+    currentStats.start()
+  }
+  @inline final def withContext[T](condition: Boolean, owner: Sym, macroo: Sym, implicitPt: Sym)(f: => T): T = {
+    def implicitOrMacroOnStack = statsStack.exists(x => x._1.implicitPt != symbolTable.NoSymbol || x._1.macroo != symbolTable.NoSymbol)
+    val shouldStart = StatisticsStatics.areSomeColdStatsEnabled() && enabled && condition && !implicitOrMacroOnStack
+    if (shouldStart) start(owner, macroo, implicitPt)
+    try { f } finally {if (shouldStart) end()}
+  }
+
   type TimerSnapshot = (Long, Long)
 
   /** If enabled, increment counter by one */