Fix #2909: Port per-phase profiling from scalac

AUTHORS.md

@@ -34,6 +34,11 @@ The majority of the dotty codebase is new code, with the exception of the compon
 > The lexical and syntactic analysis components were adapted from the current Scala compiler. They were originally authored by Martin Odersky,
 > Burak Emir, Paul Phillips, Lex Spoon, Sean McDirmid and others.
 
+`dotty.tools.dotc.profile`
+
+> The per-phase profiling support is taken mostly as is from [scala/scala](https://github.com/scala/scala).
+> The original author was Mike Skells.
+
 `dotty.tools.dotc.reporting`
 
 > Adapted from  [scala/scala](https://github.com/scala/scala) with some heavy modifications. They were originally authored by Matthias Zenger, Martin Odersky, and others.

compiler/src/dotty/tools/dotc/Run.scala

@@ -8,22 +8,26 @@ import Symbols._
 import Phases._
 import Types._
 import Scopes._
-import typer.{FrontEnd, Typer, ImportInfo, RefChecks}
+import typer.{FrontEnd, ImportInfo, RefChecks, Typer}
 import Decorators._
 import io.{AbstractFile, PlainFile}
+
 import scala.io.Codec
 import util.{Set => _, _}
 import reporting.Reporter
 import transform.TreeChecker
 import rewrite.Rewrites
 import java.io.{BufferedWriter, OutputStreamWriter}
+
+import dotty.tools.dotc.profile.Profiler
 import printing.XprintMode
 import parsing.Parsers.Parser
 import typer.ImplicitRunInfo
 import collection.mutable
 
 import scala.annotation.tailrec
 import dotty.tools.io.VirtualFile
+
 import scala.util.control.NonFatal
 
 /** A compiler run. Exports various methods to compile source files */
@@ -156,11 +160,15 @@ class Run(comp: Compiler, ictx: Context) extends ImplicitRunInfo with Constraint
 
     def runPhases(implicit ctx: Context) = {
       var lastPrintedTree: PrintedTree = NoPrintedTree
+      val profiler = ctx.profiler
+
       for (phase <- ctx.allPhases)
         if (phase.isRunnable)
           Stats.trackTime(s"$phase ms ") {
             val start = System.currentTimeMillis
+            val profileBefore = profiler.beforePhase(phase)
             units = phase.runOn(units)
+            profiler.afterPhase(phase, profileBefore)
             if (ctx.settings.Xprint.value.containsPhase(phase)) {
               for (unit <- units) {
                 lastPrintedTree =
@@ -172,9 +180,12 @@ class Run(comp: Compiler, ictx: Context) extends ImplicitRunInfo with Constraint
             for (unit <- units)
               Stats.record(s"retained typed trees at end of $phase", unit.tpdTree.treeSize)
           }
+
+      profiler.finished()
     }
 
     val runCtx = ctx.fresh
+    runCtx.setProfiler(Profiler())
     ctx.phases.foreach(_.initContext(runCtx))
     runPhases(runCtx)
     if (!ctx.reporter.hasErrors) Rewrites.writeBack()

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

@@ -113,6 +113,14 @@ class ScalaSettings extends Settings.SettingGroup {
   val YretainTrees = BooleanSetting("-Yretain-trees", "Retain trees for top-level classes, accessible from ClassSymbol#tree")
   val YshowTreeIds = BooleanSetting("-Yshow-tree-ids", "Uniquely tag all tree nodes in debugging output.")
 
+  val YprofileEnabled = BooleanSetting("-Yprofile-enabled", "Enable profiling.")
+  val YprofileDestination = StringSetting("-Yprofile-destination", "file", "where to send profiling output - specify a file, default is to the console.", "")
+      //.withPostSetHook( _ => YprofileEnabled.value = true )
+  val YprofileExternalTool = PhasesSetting("-Yprofile-external-tool", "Enable profiling for a phase using an external tool hook. Generally only useful for a single phase", "typer")
+      //.withPostSetHook( _ => YprofileEnabled.value = true )
+  val YprofileRunGcBetweenPhases = PhasesSetting("-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 )
+
   /** Area-specific debug output */
   val YexplainLowlevel = BooleanSetting("-Yexplain-lowlevel", "When explaining type errors, show types at a lower level.")
   val YnoDoubleBindings = BooleanSetting("-Yno-double-bindings", "Assert no namedtype is bound twice (should be enabled only if program is error-free).")

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

@@ -17,7 +17,7 @@ import Comments._
 import util.Positions._
 import ast.Trees._
 import ast.untpd
-import util.{FreshNameCreator, SimpleIdentityMap, SourceFile, NoSource}
+import util.{FreshNameCreator, NoSource, SimpleIdentityMap, SourceFile}
 import typer.{Implicits, ImportInfo, Inliner, NamerContextOps, SearchHistory, TypeAssigner, Typer}
 import Implicits.ContextualImplicits
 import config.Settings._
@@ -27,9 +27,11 @@ import reporting.diagnostic.Message
 import collection.mutable
 import collection.immutable.BitSet
 import printing._
-import config.{Settings, ScalaSettings, Platform, JavaPlatform}
+import config.{JavaPlatform, Platform, ScalaSettings, Settings}
+
 import language.implicitConversions
 import DenotTransformers.DenotTransformer
+import dotty.tools.dotc.profile.Profiler
 import util.Property.Key
 import util.Store
 import xsbti.AnalysisCallback
@@ -43,7 +45,8 @@ object Contexts {
   private val (freshNamesLoc,       store5) = store4.newLocation[FreshNameCreator](new FreshNameCreator.Default)
   private val (compilationUnitLoc,  store6) = store5.newLocation[CompilationUnit]()
   private val (runLoc,              store7) = store6.newLocation[Run]()
-  private val initialStore = store7
+  private val (profilerLoc,         store8) = store7.newLocation[Profiler]()
+  private val initialStore = store8
 
   /** A context is passed basically everywhere in dotc.
    *  This is convenient but carries the risk of captured contexts in
@@ -196,6 +199,9 @@ object Contexts {
     /** The current compiler-run */
     def run: Run = store(runLoc)
 
+    /**  The current compiler-run profiler */
+    def profiler: Profiler = store(profilerLoc)
+
     /** The new implicit references that are introduced by this scope */
     protected var implicitsCache: ContextualImplicits = null
     def implicits: ContextualImplicits = {
@@ -460,6 +466,7 @@ object Contexts {
     def setSettings(settingsState: SettingsState): this.type = updateStore(settingsStateLoc, settingsState)
     def setCompilationUnit(compilationUnit: CompilationUnit): this.type = updateStore(compilationUnitLoc, compilationUnit)
     def setRun(run: Run): this.type = updateStore(runLoc, run)
+    def setProfiler(profiler: Profiler): this.type = updateStore(profilerLoc, profiler)
     def setFreshNames(freshNames: FreshNameCreator): this.type = updateStore(freshNamesLoc, freshNames)
 
     def setProperty[T](key: Key[T], value: T): this.type =

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

@@ -0,0 +1,139 @@
+package dotty.tools.dotc.profile
+
+import java.util.concurrent.ThreadPoolExecutor.AbortPolicy
+import java.util.concurrent._
+import java.util.concurrent.atomic.AtomicInteger
+
+import dotty.tools.dotc.core.Phases.Phase
+import dotty.tools.dotc.core.Contexts.Context
+
+sealed trait AsyncHelper {
+
+  def newUnboundedQueueFixedThreadPool
+  (nThreads: Int,
+   shortId: String, priority : Int = Thread.NORM_PRIORITY) : ThreadPoolExecutor
+  def newBoundedQueueFixedThreadPool
+  (nThreads: Int, maxQueueSize: Int, rejectHandler: RejectedExecutionHandler,
+   shortId: String, priority : Int = Thread.NORM_PRIORITY) : ThreadPoolExecutor
+
+}
+
+object AsyncHelper {
+  def apply(phase: Phase)(implicit ctx: Context): AsyncHelper = ctx.profiler match {
+    case NoOpProfiler => new BasicAsyncHelper(phase)
+    case r: RealProfiler => new ProfilingAsyncHelper(phase, r)
+  }
+
+  private abstract class BaseAsyncHelper(phase: Phase)(implicit ctx: Context) extends AsyncHelper {
+    val baseGroup = new ThreadGroup(s"dotc-${phase.phaseName}")
+    private def childGroup(name: String) = new ThreadGroup(baseGroup, name)
+
+    protected def wrapRunnable(r: Runnable, shortId:String): Runnable
+
+    protected class CommonThreadFactory(shortId: String,
+                                        daemon: Boolean = true,
+                                        priority: Int) extends ThreadFactory {
+      private val group: ThreadGroup = childGroup(shortId)
+      private val threadNumber: AtomicInteger = new AtomicInteger(1)
+      private val namePrefix = s"${baseGroup.getName}-$shortId-"
+
+      override def newThread(r: Runnable): Thread = {
+        val wrapped = wrapRunnable(r, shortId)
+        val t: Thread = new Thread(group, wrapped, namePrefix + threadNumber.getAndIncrement, 0)
+        if (t.isDaemon != daemon) t.setDaemon(daemon)
+        if (t.getPriority != priority) t.setPriority(priority)
+        t
+      }
+    }
+  }
+
+  private final class BasicAsyncHelper(phase: Phase)(implicit ctx: Context) extends BaseAsyncHelper(phase) {
+
+    override def newUnboundedQueueFixedThreadPool(nThreads: Int, shortId: String, priority: Int): ThreadPoolExecutor = {
+      val threadFactory = new CommonThreadFactory(shortId, priority = priority)
+      //like Executors.newFixedThreadPool
+      new ThreadPoolExecutor(nThreads, nThreads, 0L, TimeUnit.MILLISECONDS, new LinkedBlockingQueue[Runnable], threadFactory)
+    }
+
+    override def newBoundedQueueFixedThreadPool(nThreads: Int, maxQueueSize: Int, rejectHandler: RejectedExecutionHandler, shortId: String, priority: Int): ThreadPoolExecutor = {
+      val threadFactory = new CommonThreadFactory(shortId, priority = priority)
+      //like Executors.newFixedThreadPool
+      new ThreadPoolExecutor(nThreads, nThreads, 0L, TimeUnit.MILLISECONDS, new ArrayBlockingQueue[Runnable](maxQueueSize), threadFactory, rejectHandler)
+    }
+
+    override protected def wrapRunnable(r: Runnable, shortId:String): Runnable = r
+  }
+
+  private class ProfilingAsyncHelper(phase: Phase, private val profiler: RealProfiler)(implicit ctx: Context) extends BaseAsyncHelper(phase) {
+
+    override def newUnboundedQueueFixedThreadPool(nThreads: Int, shortId: String, priority: Int): ThreadPoolExecutor = {
+      val threadFactory = new CommonThreadFactory(shortId, priority = priority)
+      //like Executors.newFixedThreadPool
+      new SinglePhaseInstrumentedThreadPoolExecutor(nThreads, nThreads, 0L, TimeUnit.MILLISECONDS, new LinkedBlockingQueue[Runnable], threadFactory, new AbortPolicy)
+    }
+
+    override def newBoundedQueueFixedThreadPool(nThreads: Int, maxQueueSize: Int, rejectHandler: RejectedExecutionHandler, shortId: String, priority: Int): ThreadPoolExecutor = {
+      val threadFactory = new CommonThreadFactory(shortId, priority = priority)
+      //like Executors.newFixedThreadPool
+      new SinglePhaseInstrumentedThreadPoolExecutor(nThreads, nThreads, 0L, TimeUnit.MILLISECONDS, new ArrayBlockingQueue[Runnable](maxQueueSize), threadFactory, rejectHandler)
+    }
+
+    override protected def wrapRunnable(r: Runnable, shortId:String): Runnable = () => {
+      val data = new ThreadProfileData
+      localData.set(data)
+
+      val profileStart = profiler.snapThread(0)
+      try r.run finally {
+        val snap = profiler.snapThread(data.idleNs)
+        val threadRange = ProfileRange(profileStart, snap, phase, shortId, data.taskCount, Thread.currentThread())
+        profiler.completeBackground(threadRange)
+      }
+    }
+
+    /**
+     * data for thread run. Not threadsafe, only written from a single thread
+     */
+    final class ThreadProfileData {
+      var firstStartNs = 0L
+      var taskCount = 0
+
+      var idleNs = 0L
+      var runningNs = 0L
+
+      var lastStartNs = 0L
+      var lastEndNs = 0L
+    }
+
+    val localData = new ThreadLocal[ThreadProfileData]
+
+    private class SinglePhaseInstrumentedThreadPoolExecutor
+    (   corePoolSize: Int, maximumPoolSize: Int, keepAliveTime: Long, unit: TimeUnit,
+        workQueue: BlockingQueue[Runnable], threadFactory: ThreadFactory, handler: RejectedExecutionHandler
+    ) extends ThreadPoolExecutor(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue, threadFactory, handler) {
+
+      override def beforeExecute(t: Thread, r: Runnable): Unit = {
+        val data = localData.get
+        data.taskCount += 1
+        val now = System.nanoTime()
+
+        if (data.firstStartNs == 0) data.firstStartNs = now
+        else data.idleNs += now - data.lastEndNs
+
+        data.lastStartNs = now
+
+        super.beforeExecute(t, r)
+      }
+
+      override def afterExecute(r: Runnable, t: Throwable): Unit = {
+        val now = System.nanoTime()
+        val data = localData.get
+
+        data.lastEndNs = now
+        data.runningNs += now - data.lastStartNs
+
+        super.afterExecute(r, t)
+      }
+
+    }
+  }
+}