Port: Update scalac profiler - capture more info on background threads

scala/scala#6264

Author: nicolasstucki

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

@@ -28,7 +28,7 @@ object AsyncHelper {
     val baseGroup = new ThreadGroup(s"scalac-${phase.phaseName}")
     private def childGroup(name: String) = new ThreadGroup(baseGroup, name)
 
-    protected def wrapRunnable(r: Runnable): Runnable
+    protected def wrapRunnable(r: Runnable, shortId:String): Runnable
 
     protected class CommonThreadFactory(shortId: String,
                                         daemon: Boolean = true,
@@ -38,7 +38,7 @@ object AsyncHelper {
       private val namePrefix = s"${baseGroup.getName}-$shortId-"
 
       override def newThread(r: Runnable): Thread = {
-        val wrapped = wrapRunnable(r)
+        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)
@@ -61,7 +61,7 @@ object AsyncHelper {
       new ThreadPoolExecutor(nThreads, nThreads, 0L, TimeUnit.MILLISECONDS, new ArrayBlockingQueue[Runnable](maxQueueSize), threadFactory, rejectHandler)
     }
 
-    override protected def wrapRunnable(r: Runnable): Runnable = r
+    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) {
@@ -78,14 +78,14 @@ object AsyncHelper {
       new SinglePhaseInstrumentedThreadPoolExecutor(nThreads, nThreads, 0L, TimeUnit.MILLISECONDS, new ArrayBlockingQueue[Runnable](maxQueueSize), threadFactory, rejectHandler)
     }
 
-    override protected def wrapRunnable(r: Runnable): Runnable = () => {
+    override protected def wrapRunnable(r: Runnable, shortId:String): Runnable = () => {
       val data = new ThreadProfileData
       localData.set(data)
 
-      val profileStart = Profiler.emptySnap
+      val profileStart = profiler.snapThread(0)
       try r.run finally {
-        val snap = profiler.snapThread()
-        val threadRange = ProfileRange(profileStart, snap, phase, 0, "", Thread.currentThread())
+        val snap = profiler.snapThread(data.idleNs)
+        val threadRange = ProfileRange(profileStart, snap, phase, shortId, data.taskCount, Thread.currentThread())
         profiler.completeBackground(threadRange)
       }
     }

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

@@ -32,7 +32,7 @@ case class ProfileSnap(threadId: Long, threadName: String, snapTimeNanos : Long,
     copy(heapBytes = heapBytes)
   }
 }
-case class ProfileRange(start: ProfileSnap, end:ProfileSnap, phase:Phase, id:Int, purpose:String, thread:Thread) {
+case class ProfileRange(start: ProfileSnap, end:ProfileSnap, phase:Phase, purpose:String, taskCount:Int, thread:Thread) {
   def allocatedBytes = end.allocatedBytes - start.allocatedBytes
 
   def userNs = end.userTimeNanos - start.userTimeNanos
@@ -105,15 +105,15 @@ private [profile] class RealProfiler(reporter : ProfileReporter)(implicit ctx: C
 
   private val mainThread = Thread.currentThread()
 
-  private[profile] def snapThread(): ProfileSnap = {
+  private[profile] def snapThread(idleTimeNanos: Long): ProfileSnap = {
     import RealProfiler._
     val current = Thread.currentThread()
 
     ProfileSnap(
       threadId = current.getId,
       threadName = current.getName,
       snapTimeNanos = System.nanoTime(),
-      idleTimeNanos = 0,
+      idleTimeNanos = idleTimeNanos,
       cpuTimeNanos = threadMx.getCurrentThreadCpuTime,
       userTimeNanos = threadMx.getCurrentThreadUserTime,
       allocatedBytes = threadMx.getThreadAllocatedBytes(Thread.currentThread().getId),
@@ -158,13 +158,13 @@ private [profile] class RealProfiler(reporter : ProfileReporter)(implicit ctx: C
         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(new GcEventData("", reportNs, startTime, endTime, name, action, cause, threads))
+        reporter.reportGc(GcEventData("", reportNs, startTime, endTime, name, action, cause, threads))
     }
   }
 
   override def afterPhase(phase: Phase, snapBefore: ProfileSnap): Unit = {
     assert(mainThread eq Thread.currentThread())
-    val initialSnap = snapThread()
+    val initialSnap = snapThread(0)
     if (ctx.settings.YprofileExternalTool.value.contains(phase.toString)) {
       println("Profile hook stop")
       ExternalToolHook.after()
@@ -174,7 +174,7 @@ private [profile] class RealProfiler(reporter : ProfileReporter)(implicit ctx: C
       initialSnap.updateHeap(readHeapUsage())
     } else initialSnap
 
-    reporter.reportForeground(this, new ProfileRange(snapBefore, finalSnap, phase, id, "", Thread.currentThread))
+    reporter.reportForeground(this, ProfileRange(snapBefore, finalSnap, phase, "", 0, Thread.currentThread))
   }
 
   override def beforePhase(phase: Phase): ProfileSnap = {
@@ -185,7 +185,7 @@ private [profile] class RealProfiler(reporter : ProfileReporter)(implicit ctx: C
       println("Profile hook start")
       ExternalToolHook.before()
     }
-    snapThread()
+    snapThread(0)
   }
 
 }
@@ -233,8 +233,8 @@ object ConsoleProfileReporter extends ProfileReporter {
 
 class StreamProfileReporter(out:PrintWriter) extends ProfileReporter {
   override def header(profiler: RealProfiler): Unit = {
-    out.println(s"info, ${profiler.id}, ${profiler.outDir}")
-    out.println(s"header(main/background),startNs,endNs,runId,phaseId,phaseName,purpose,threadId,threadName,runNs,idleNs,cpuTimeNs,userTimeNs,allocatedByte,heapSize")
+    out.println(s"info, ${profiler.id}, version, 2, output, ${profiler.outDir}")
+    out.println(s"header(main/background),startNs,endNs,runId,phaseId,phaseName,purpose,task-count,threadId,threadName,runNs,idleNs,cpuTimeNs,userTimeNs,allocatedByte,heapSize")
     out.println(s"header(GC),startNs,endNs,startMs,endMs,name,action,cause,threads")
   }
 
@@ -245,7 +245,7 @@ class StreamProfileReporter(out:PrintWriter) extends ProfileReporter {
     reportCommon(EventType.MAIN, profiler, threadRange)
   }
   private def reportCommon(tpe:EventType.value, profiler: RealProfiler, threadRange: ProfileRange): Unit = {
-    out.println(s"$tpe,${threadRange.start.snapTimeNanos},${threadRange.end.snapTimeNanos},${profiler.id},${threadRange.phase.id},${threadRange.phase.phaseName.replace(',', ' ')},${threadRange.purpose},${threadRange.thread.getId},${threadRange.thread.getName},${threadRange.runNs},${threadRange.idleNs},${threadRange.cpuNs},${threadRange.userNs},${threadRange.allocatedBytes},${if(tpe == EventType.MAIN) threadRange.end.heapBytes else ""}")
+    out.println(s"$tpe,${threadRange.start.snapTimeNanos},${threadRange.end.snapTimeNanos},${profiler.id},${threadRange.phase.id},${threadRange.phase.phaseName.replace(',', ' ')},${threadRange.purpose},${threadRange.taskCount},${threadRange.thread.getId},${threadRange.thread.getName},${threadRange.runNs},${threadRange.idleNs},${threadRange.cpuNs},${threadRange.userNs},${threadRange.allocatedBytes},${threadRange.end.heapBytes} ")
   }
 
   override def reportGc(data: GcEventData): Unit = {