[FIR] Isolate benchmark thread, add jit log format events for passes

Add special output for pass events to match with LogCompilation
2020-09-09 14:59:18 +03:00
parent 618de5fa32
commit b6fb3c9799
5 changed files with 174 additions and 27 deletions
@@ -1,3 +1,5 @@
+import org.jetbrains.kotlin.cli.common.toBooleanLenient
+
 /*
 * Copyright 2000-2018 JetBrains s.r.o. Use of this source code is governed by the Apache 2.0 license
 * that can be found in the license/LICENSE.txt file.
@@ -8,13 +10,17 @@ plugins {
    id("jps-compatible")
 }

+repositories {
+    mavenLocal()
+}
+
 dependencies {
    Platform[193].orLower {
        testCompileOnly(intellijDep()) { includeJars("openapi", rootProject = rootProject) }
    }

    testCompileOnly(intellijDep()) {
-        includeJars("extensions", "idea_rt", "util", "asm-all", "platform-util-ex", rootProject = rootProject)
+        includeJars("extensions", "idea_rt", "util", "asm-all", "platform-util-ex", "jna", rootProject = rootProject)
    }

    testCompileOnly(intellijPluginDep("java")) { includeJars("java-api") }
@@ -9,6 +9,8 @@ import com.intellij.openapi.util.Disposer
 import com.intellij.psi.PsiElementFinder
 import com.intellij.psi.search.GlobalSearchScope
 import com.intellij.psi.search.ProjectScope
+import com.sun.jna.Library
+import com.sun.jna.Native
 import com.sun.management.HotSpotDiagnosticMXBean
 import org.jetbrains.kotlin.asJava.finder.JavaElementFinder
 import org.jetbrains.kotlin.cli.common.profiling.AsyncProfilerHelper
@@ -26,10 +28,12 @@ import org.jetbrains.kotlin.fir.resolve.firProvider
 import org.jetbrains.kotlin.fir.resolve.providers.impl.FirProviderImpl
 import org.jetbrains.kotlin.fir.resolve.transformers.createAllCompilerResolveProcessors
 import org.jetbrains.kotlin.fir.scopes.ProcessorAction
+import sun.management.ManagementFactoryHelper
 import java.io.File
 import java.io.FileOutputStream
 import java.io.PrintStream
 import java.lang.management.ManagementFactory
+import java.text.DecimalFormat


 private const val FAIL_FAST = true
@@ -52,6 +56,61 @@ private val ASYNC_PROFILER_START_CMD = System.getProperty("fir.bench.use.async.p
 private val ASYNC_PROFILER_STOP_CMD = System.getProperty("fir.bench.use.async.profiler.cmd.stop")
 private val PROFILER_SNAPSHOT_DIR = System.getProperty("fir.bench.snapshot.dir") ?: "tmp/snapshots"

+private val REPORT_PASS_EVENTS = System.getProperty("fir.bench.report.pass.events", "false").toBooleanLenient()!!
+
+private interface CLibrary : Library {
+    fun getpid(): Int
+    fun gettid(): Int
+
+    companion object {
+        val INSTANCE = Native.load("c", CLibrary::class.java) as CLibrary
+    }
+}
+
+internal fun isolate() {
+    val isolatedList = System.getenv("DOCKER_ISOLATED_CPUSET")
+    val othersList = System.getenv("DOCKER_CPUSET")
+    println("Trying to set affinity, other: '$othersList', isolated: '$isolatedList'")
+    if (othersList != null) {
+        println("Will move others affinity to '$othersList'")
+        ProcessBuilder().command("bash", "-c", "ps -ae -o pid= | xargs -n 1 taskset -cap $othersList ").inheritIO().start().waitFor()
+    }
+    if (isolatedList != null) {
+        val selfPid = CLibrary.INSTANCE.getpid()
+        val selfTid = CLibrary.INSTANCE.gettid()
+        println("Will pin self affinity, my pid: $selfPid, my tid: $selfTid")
+        ProcessBuilder().command("taskset", "-cp", isolatedList, "$selfTid").inheritIO().start().waitFor()
+    }
+    if (othersList == null && isolatedList == null) {
+        println("No affinity specified")
+    }
+}
+
+class PassEventReporter(private val stream: PrintStream) : AutoCloseable {
+
+    private val decimalFormat = DecimalFormat().apply {
+        this.maximumFractionDigits = 3
+    }
+
+    private fun formatStamp(): String {
+        val uptime = ManagementFactoryHelper.getRuntimeMXBean().uptime
+        return decimalFormat.format(uptime.toDouble() / 1000)
+    }
+
+    fun reportPassStart(num: Int) {
+        stream.println("<pass_start num='$num' stamp='${formatStamp()}'/>")
+    }
+
+    fun reportPassEnd(num: Int) {
+        stream.println("<pass_end num='$num' stamp='${formatStamp()}'/>")
+        stream.flush()
+    }
+
+    override fun close() {
+        stream.close()
+    }
+}
+
 class FirResolveModularizedTotalKotlinTest : AbstractModularizedTest() {

    private lateinit var dump: MultiModuleHtmlFirDump
@@ -59,6 +118,8 @@ class FirResolveModularizedTotalKotlinTest : AbstractModularizedTest() {
    private var bestStatistics: FirResolveBench.TotalStatistics? = null
    private var bestPass: Int = 0

+    private var passEventReporter: PassEventReporter? = null
+
    private val asyncProfiler = if (ASYNC_PROFILER_LIB != null) {
        try {
            AsyncProfilerHelper.getInstance(ASYNC_PROFILER_LIB)
@@ -92,7 +153,6 @@ class FirResolveModularizedTotalKotlinTest : AbstractModularizedTest() {
        val project = environment.project
        val ktFiles = environment.getSourceFiles()

-
        val scope = GlobalSearchScope.filesScope(project, ktFiles.map { it.virtualFile })
            .uniteWith(TopDownAnalyzerFacadeForJVM.AllJavaSourcesInProjectScope(project))
        val librariesScope = ProjectScope.getLibrariesScope(project)
@@ -107,6 +167,7 @@ class FirResolveModularizedTotalKotlinTest : AbstractModularizedTest() {
        }

        val firProvider = session.firProvider as FirProviderImpl
+
        val firFiles = if (USE_LIGHT_TREE) {
            val lightTree2Fir = LightTree2Fir(session, firProvider.kotlinScopeProvider, stubMode = false)

@@ -125,9 +186,9 @@ class FirResolveModularizedTotalKotlinTest : AbstractModularizedTest() {
            bench.buildFiles(builder, ktFiles)
        }

-        //println("Raw FIR up, files: ${firFiles.size}")

        bench.processFiles(firFiles, processors)
+
        createMemoryDump(moduleData)

        val disambiguatedName = moduleData.disambiguatedName()
@@ -182,6 +243,7 @@ class FirResolveModularizedTotalKotlinTest : AbstractModularizedTest() {
    override fun beforePass(pass: Int) {
        if (DUMP_FIR) dump = MultiModuleHtmlFirDump(File(FIR_HTML_DUMP_PATH))
        System.gc()
+        passEventReporter?.reportPassStart(pass)
        executeAsyncProfilerCommand(ASYNC_PROFILER_START_CMD, pass)
    }

@@ -202,6 +264,8 @@ class FirResolveModularizedTotalKotlinTest : AbstractModularizedTest() {
        }

        executeAsyncProfilerCommand(ASYNC_PROFILER_STOP_CMD, pass)
+
+        passEventReporter?.reportPassEnd(pass)
    }

    override fun afterAllPasses() {
@@ -237,10 +301,21 @@ class FirResolveModularizedTotalKotlinTest : AbstractModularizedTest() {
        }
    }

+    private fun beforeAllPasses() {
+        isolate()
+
+        if (REPORT_PASS_EVENTS) {
+            passEventReporter =
+                PassEventReporter(PrintStream(FileOutputStream(reportDir().resolve("pass-events-$reportDateStr.log"), true)))
+        }
+    }
+
    fun testTotalKotlin() {
+
+        beforeAllPasses()
+
        for (i in 0 until PASSES) {
            println("Pass $i")
-
            bench = FirResolveBench(withProgress = false)
            runTestOnce(i)
        }
@@ -6,6 +6,7 @@
 package org.jetbrains.kotlin.fir

 import com.intellij.openapi.util.Disposer
+import com.intellij.openapi.util.text.StringUtil
 import org.jetbrains.kotlin.cli.common.CLIConfigurationKeys.MESSAGE_COLLECTOR_KEY
 import org.jetbrains.kotlin.cli.common.messages.CompilerMessageSeverity
 import org.jetbrains.kotlin.cli.common.messages.CompilerMessageSourceLocation
@@ -24,10 +25,13 @@ private val USE_NI = System.getProperty("fir.bench.oldfe.ni", "true") == "true"
 class NonFirResolveModularizedTotalKotlinTest : AbstractModularizedTest() {
    private var totalTime = 0L
    private var files = 0
+    private var lines = 0
+    private var measure = FirResolveBench.Measure()

    private val times = mutableListOf<Long>()

    private fun runAnalysis(environment: KotlinCoreEnvironment) {
+        val vmBefore = vmStateSnapshot()
        val time = measureNanoTime {
            try {
                KotlinToJVMBytecodeCompiler.analyze(environment)
@@ -40,9 +44,14 @@ class NonFirResolveModularizedTotalKotlinTest : AbstractModularizedTest() {
                throw e
            }
        }
+        val vmAfter = vmStateSnapshot()

        files += environment.getSourceFiles().size
+        lines += environment.getSourceFiles().sumBy { StringUtil.countNewLines(it.text) }
        totalTime += time
+        measure.time += time
+        measure.vmCounters += vmAfter - vmBefore
+
        println("Time is ${time * 1e-6} ms")
    }

@@ -102,11 +111,19 @@ class NonFirResolveModularizedTotalKotlinTest : AbstractModularizedTest() {
        return ProcessorAction.NEXT
    }

-
    override fun afterPass(pass: Int) {}
-    override fun beforePass(pass: Int) {}
+
+    override fun beforePass(pass: Int) {
+        measure = FirResolveBench.Measure()
+        files = 0
+        lines = 0
+        totalTime = 0
+    }

    fun testTotalKotlin() {
+
+        isolate()
+
        writeMessageToLog("use_ni: $USE_NI")

        for (i in 0 until PASSES) {
@@ -44,7 +44,12 @@ fun checkFirProvidersConsistency(firFiles: List<FirFile>) {
 private data class FailureInfo(val transformer: KClass<*>, val throwable: Throwable, val file: String)
 data class ErrorTypeReport(val report: String, var count: Int = 0)

-class FirResolveBench(val withProgress: Boolean) {
+abstract class BenchListener {
+    abstract fun before()
+    abstract fun after(stageClass: KClass<*>)
+}
+
+class FirResolveBench(val withProgress: Boolean, val listener: BenchListener? = null) {
    data class TotalStatistics(
        val unresolvedTypes: Int,
        val resolvedTypes: Int,
@@ -81,7 +86,8 @@ class FirResolveBench(val withProgress: Boolean) {
        var cpu: Long = 0,
        var gcTime: Long = 0,
        var gcCollections: Int = 0,
-        var files: Int = 0
+        var files: Int = 0,
+        var vmCounters: VMCounters = VMCounters()
    )

    val timePerTransformer = mutableMapOf<KClass<*>, Measure>()
@@ -105,6 +111,7 @@ class FirResolveBench(val withProgress: Boolean) {
        builder: RawFirBuilder,
        ktFiles: List<KtFile>
    ): List<FirFile> {
+        listener?.before()
        return ktFiles.map { file ->
            val before = vmStateSnapshot()
            val firFile: FirFile
@@ -118,6 +125,7 @@ class FirResolveBench(val withProgress: Boolean) {
            totalLines += StringUtil.countNewLines(file.text)
            firFile
        }.also {
+            listener?.after(builder::class)
            totalTime = timePerTransformer.values.sumByLong { it.time }
        }
    }
@@ -126,6 +134,7 @@ class FirResolveBench(val withProgress: Boolean) {
        builder: LightTree2Fir,
        files: List<File>
    ): List<FirFile> {
+        listener?.before()
        return files.map { file ->
            val before = vmStateSnapshot()
            val firFile: FirFile
@@ -141,6 +150,7 @@ class FirResolveBench(val withProgress: Boolean) {
            totalLines += StringUtil.countNewLines(code)
            firFile
        }.also {
+            listener?.after(builder::class)
            totalTime = timePerTransformer.values.sumByLong { it.time }
        }
    }
@@ -165,6 +175,7 @@ class FirResolveBench(val withProgress: Boolean) {

    private fun runStage(processor: FirTransformerBasedResolveProcessor, firFileSequence: Sequence<FirFile>) {
        val transformer = processor.transformer
+        listener?.before()
        for (firFile in firFileSequence) {
            processWithTimeMeasure(
                transformer::class,
@@ -180,6 +191,7 @@ class FirResolveBench(val withProgress: Boolean) {
                }
            }
        }
+        listener?.after(transformer::class)
    }

    private fun runStage(processor: FirGlobalResolveProcessor, firFiles: List<FirFile>) {
@@ -403,6 +415,24 @@ fun FirResolveBench.TotalStatistics.reportErrors(stream: PrintStream) {
    }
 }

+fun FirResolveBench.TotalStatistics.reportTimings(stream: PrintStream) {
+    printTable(stream) {
+        row {
+            cell("Stage", LEFT)
+            cells("Time", "Time per file", "Files: OK/E/T", "CPU", "User", "GC", "GC count", "L/S")
+        }
+        separator()
+        timePerTransformer.forEach { (transformer, measure) ->
+            printMeasureAsTable(measure, this@reportTimings, transformer)
+        }
+
+        if (timePerTransformer.keys.isNotEmpty()) {
+            separator()
+            printMeasureAsTable(totalMeasure, this@reportTimings, "Total time")
+        }
+    }
+}
+
 fun FirResolveBench.TotalStatistics.report(stream: PrintStream, header: String) {
    with(stream) {
        infix fun Int.percentOf(other: Int): String {
@@ -419,21 +449,7 @@ fun FirResolveBench.TotalStatistics.report(stream: PrintStream, header: String)
        println("Erroneously resolved implicit types: $implicitTypes (${implicitTypes percentOf resolvedTypes} of resolved)")
        println("Unique error types: $uniqueErrorTypes")

-        printTable(stream) {
-            row {
-                cell("Stage", LEFT)
-                cells("Time", "Time per file", "Files: OK/E/T", "CPU", "User", "GC", "GC count", "L/S")
-            }
-            separator()
-            timePerTransformer.forEach { (transformer, measure) ->
-                printMeasureAsTable(measure, this@report, transformer)
-            }
-
-            if (timePerTransformer.keys.isNotEmpty()) {
-                separator()
-                printMeasureAsTable(totalMeasure, this@report, "Total time")
-            }
-        }
+        this@report.reportTimings(stream)
    }
 }

@@ -17,19 +17,48 @@ data class GCInfo(val name: String, val gcTime: Long, val collections: Long) {
            collections = collections - other.collections
        )
    }
+
+    operator fun plus(other: GCInfo): GCInfo {
+        return this.copy(
+            gcTime = gcTime + other.gcTime,
+            collections = collections + other.collections
+        )
+    }
 }

-data class VMCounters(val userTime: Long, val cpuTime: Long, val gcInfo: Map<String, GCInfo>) {
+data class VMCounters(
+    val userTime: Long = 0,
+    val cpuTime: Long = 0,
+    val gcInfo: Map<String, GCInfo> = emptyMap(),
+
+    val safePointTotalTime: Long = 0,
+    val safePointSyncTime: Long = 0,
+    val safePointCount: Long = 0,
+) {


    operator fun minus(other: VMCounters): VMCounters {
        return VMCounters(
            userTime - other.userTime,
            cpuTime - other.cpuTime,
-            merge(gcInfo, other.gcInfo) { a, b -> a - b }
+            merge(gcInfo, other.gcInfo) { a, b -> a - b },
+            safePointTotalTime - other.safePointTotalTime,
+            safePointSyncTime - other.safePointSyncTime,
+            safePointCount - other.safePointCount
        )
    }

+
+    operator fun plus(other: VMCounters): VMCounters {
+        return VMCounters(
+            userTime + other.userTime,
+            cpuTime + other.cpuTime,
+            merge(gcInfo, other.gcInfo) { a, b -> a + b },
+            safePointTotalTime + other.safePointTotalTime,
+            safePointSyncTime + other.safePointSyncTime,
+            safePointCount + other.safePointCount
+        )
+    }
 }


@@ -50,9 +79,13 @@ object Init {
 fun vmStateSnapshot(): VMCounters {
    Init
    val threadMXBean = ManagementFactoryHelper.getThreadMXBean()
+    val hotspotRuntimeMBean = ManagementFactoryHelper.getHotspotRuntimeMBean()

    return VMCounters(
        threadMXBean.threadUserTime(), threadMXBean.threadCpuTime(),
-        ManagementFactoryHelper.getGarbageCollectorMXBeans().associate { it.name to GCInfo(it.name, it.collectionTime, it.collectionCount) }
+        ManagementFactoryHelper.getGarbageCollectorMXBeans().associate { it.name to GCInfo(it.name, it.collectionTime, it.collectionCount) },
+        hotspotRuntimeMBean.totalSafepointTime,
+        hotspotRuntimeMBean.safepointSyncTime,
+        hotspotRuntimeMBean.safepointCount
    )
-}
+}