Skip to content

Update scalac profiler - capture more info on background threads #6264

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 1 commit into from
Jan 16, 2018
Merged

Update scalac profiler - capture more info on background threads #6264

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
14 changes: 7 additions & 7 deletions src/compiler/scala/tools/nsc/profile/AsyncHelper.scala
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -28,7 +28,7 @@ object AsyncHelper {
val baseGroup = new ThreadGroup(s"scalac-${phase.name}")
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,
Expand All @@ -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)
Expand All @@ -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(global: Global, phase: Phase, private val profiler: RealProfiler) extends BaseAsyncHelper(global, phase) {
Expand All @@ -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)
}
}
Expand Down
20 changes: 10 additions & 10 deletions src/compiler/scala/tools/nsc/profile/Profiler.scala
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -30,7 +30,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
Expand Down Expand Up @@ -103,15 +103,15 @@ private [profile] class RealProfiler(reporter : ProfileReporter, val settings: S

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),
Expand Down Expand Up @@ -156,13 +156,13 @@ 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(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 (settings.YprofileExternalTool.containsPhase(phase)) {
println("Profile hook stop")
ExternalToolHook.after()
Expand All @@ -172,7 +172,7 @@ private [profile] class RealProfiler(reporter : ProfileReporter, val settings: S
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 = {
Expand All @@ -183,7 +183,7 @@ private [profile] class RealProfiler(reporter : ProfileReporter, val settings: S
println("Profile hook start")
ExternalToolHook.before()
}
snapThread()
snapThread(0)
}

}
Expand Down Expand Up @@ -231,8 +231,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")
}

Expand All @@ -243,7 +243,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.name},${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.name},${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 = {
Expand Down