Add async profiler to perfTests

2019-09-16 19:44:22 -07:00
parent 0f4176a88e
commit 3d79e77df3
5 changed files with 272 additions and 37 deletions
@@ -73,7 +73,9 @@ abstract class AbstractPerformanceHighlightingTest : KotlinLightCodeInsightFixtu
    private fun innerPerfTest(name: String, setUpBody: (TestData<Unit, MutableList<HighlightInfo>>) -> Unit) {
        stats.perfTest<Unit, MutableList<HighlightInfo>>(
            testName = name,
-            setUp = { setUpBody(it) },
+            setUp = {
+                setUpBody(it)
+            },
            test = { it.value = perfTestCore() },
            tearDown = {
                assertNotNull("no reasons to validate output as it is a performance test", it.value)
@@ -48,6 +48,7 @@ import com.intellij.util.io.exists
 import org.jetbrains.kotlin.idea.configuration.getModulesWithKotlinFiles
 import org.jetbrains.kotlin.idea.core.script.ScriptConfigurationManager
 import org.jetbrains.kotlin.idea.framework.KotlinSdkType
+import org.jetbrains.kotlin.idea.perf.Stats.Companion.WARM_UP
 import org.jetbrains.kotlin.idea.perf.Stats.Companion.runAndMeasure
 import org.jetbrains.kotlin.idea.project.getAndCacheLanguageLevelByDependencies
 import org.jetbrains.kotlin.idea.test.ConfigLibraryUtil
@@ -95,9 +96,9 @@ abstract class AbstractPerformanceProjectsTest : UsefulTestCase() {
    }

    protected fun warmUpProject(stats: Stats) {
-        val project = perfOpenHelloWorld(stats, "warm-up")
+        val project = perfOpenHelloWorld(stats, WARM_UP)
        try {
-            val perfHighlightFile = perfHighlightFile(project, "src/HelloMain.kt", stats, "warm-up")
+            val perfHighlightFile = perfHighlightFile(project, "src/HelloMain.kt", stats, WARM_UP)
            assertTrue("kotlin project has been not imported properly", perfHighlightFile.isNotEmpty())
        } finally {
            closeProject(project)
@@ -254,7 +255,7 @@ abstract class AbstractPerformanceProjectsTest : UsefulTestCase() {
            Fixture.enableAnnotatorsAndLoadDefinitions(project)
        }

-        return lastProject!!
+        return lastProject ?: error("unable to open project $name at $path")
    }

    private fun refreshGradleProjectIfNeeded(projectPath: String, project: Project) {
@@ -476,7 +477,7 @@ abstract class AbstractPerformanceProjectsTest : UsefulTestCase() {
        note: String = ""
    ): List<HighlightInfo> {
        return highlightFile {
-            val isWarmUp = note == "warm-up"
+            val isWarmUp = note == WARM_UP
            var highlightInfos: List<HighlightInfo> = emptyList()
            stats.perfTest<EditorFile, List<HighlightInfo>>(
                warmUpIterations = if (isWarmUp) 1 else 3,
@@ -6,15 +6,13 @@
 package org.jetbrains.kotlin.idea.perf

 import org.jetbrains.kotlin.idea.perf.WholeProjectPerformanceTest.Companion.nsToMs
+import org.jetbrains.kotlin.idea.perf.profilers.async.ProfilerHandler
 import org.jetbrains.kotlin.idea.testFramework.logMessage
 import org.jetbrains.kotlin.util.PerformanceCounter
 import java.io.*
-import kotlin.math.pow
-import kotlin.math.sqrt
 import kotlin.system.measureNanoTime
 import java.lang.ref.WeakReference
-import kotlin.math.exp
-import kotlin.math.ln
+import kotlin.math.*
 import kotlin.system.measureTimeMillis
 import kotlin.test.assertEquals

@@ -24,10 +22,12 @@ class Stats(val name: String = "", val header: Array<String> = arrayOf("Name", "

    private val perfTestRawDataMs = mutableListOf<Long>()

-    private val statsFile: File = File("build/stats${statFilePrefix()}.csv").absoluteFile
+    private val statsFile: File = File(pathToResource("stats${statFilePrefix()}.csv")).absoluteFile

    private val statsOutput: BufferedWriter

+    private val profilerHandler = ProfilerHandler.getInstance()
+
    init {
        statsOutput = statsFile.bufferedWriter()

@@ -36,10 +36,14 @@ class Stats(val name: String = "", val header: Array<String> = arrayOf("Name", "
        PerformanceCounter.setTimeCounterEnabled(true)
    }

-    private fun statFilePrefix() = if (name.isNotEmpty()) "-${name.toLowerCase().replace(' ', '-').replace('/', '_')}" else ""
+    private fun statFilePrefix() = if (name.isNotEmpty()) "-${plainname()}" else ""
+
+    private fun plainname() = name.toLowerCase().replace(' ', '-').replace('/', '_')
+
+    private fun pathToResource(resource: String) = "build/$resource"

    private fun append(id: String, statInfosArray: Array<StatInfos>) {
-        val timingsMs = statInfosArray.map { info -> info?.let { it[TEST_KEY] as Long }?.nsToMs ?: 0L }.toLongArray()
+        val timingsMs = toTimingsMs(statInfosArray)

        val calcMean = calcMean(timingsMs)

@@ -77,6 +81,11 @@ class Stats(val name: String = "", val header: Array<String> = arrayOf("Name", "
        append(arrayOf(id, calcMean.mean, calcMean.stdDev))
    }

+    private fun toTimingsMs(statInfosArray: Array<StatInfos>) =
+        statInfosArray.map { info -> info?.let { it[TEST_KEY] as? Long }?.nsToMs ?: 0L }.toLongArray()
+
+    private fun calcMean(statInfosArray: Array<StatInfos>): Mean = calcMean(toTimingsMs(statInfosArray))
+
    private fun calcMean(values: LongArray): Mean {
        val mean = values.average()

@@ -106,13 +115,13 @@ class Stats(val name: String = "", val header: Array<String> = arrayOf("Name", "
        append(arrayOf(file, id, ms))
    }

-    fun <K, T> perfTest(
+    fun <SV, TV> perfTest(
        testName: String,
-        warmUpIterations: Int = 3,
-        iterations: Int = 10,
-        setUp: (TestData<K, T>) -> Unit = { },
-        test: (TestData<K, T>) -> Unit,
-        tearDown: (TestData<K, T>) -> Unit = { }
+        warmUpIterations: Int = 5,
+        iterations: Int = 20,
+        setUp: (TestData<SV, TV>) -> Unit = { },
+        test: (TestData<SV, TV>) -> Unit,
+        tearDown: (TestData<SV, TV>) -> Unit = { }
    ) {

        tcSuite(testName) {
@@ -124,7 +133,7 @@ class Stats(val name: String = "", val header: Array<String> = arrayOf("Name", "
        }
    }

-    private fun _printTimings(
+    private fun printTimings(
        prefix: String,
        statInfoArray: Array<StatInfos>,
        attemptFn: (Int) -> String = { attempt -> "#$attempt" }
@@ -149,55 +158,62 @@ class Stats(val name: String = "", val header: Array<String> = arrayOf("Name", "
    fun printWarmUpTimings(
        prefix: String,
        warmUpStatInfosArray: Array<StatInfos>
-    ) {
-        _printTimings(prefix, warmUpStatInfosArray) { attempt -> "warm-up #$attempt" }
-    }
+    ) = printTimings(prefix, warmUpStatInfosArray) { attempt -> "warm-up #$attempt" }

    fun appendTimings(
        prefix: String,
        statInfosArray: Array<StatInfos>
    ) {
-        _printTimings(prefix, statInfosArray)
-        val namePrefix = "$name: $prefix"
-        append(namePrefix, statInfosArray)
+        printTimings(prefix, statInfosArray)
+        append("$name: $prefix", statInfosArray)
    }

    private fun <K, T> mainPhase(
        iterations: Int,
-        namePrefix: String,
+        testName: String,
        setUp: (TestData<K, T>) -> Unit,
        test: (TestData<K, T>) -> Unit,
        tearDown: (TestData<K, T>) -> Unit
    ): Array<StatInfos> {
-        val statInfosArray = Array<StatInfos>(iterations) { null }
-        _phase(iterations, setUp, statInfosArray, test, namePrefix, tearDown)
+        val statInfosArray = phase(testName, "", iterations, setUp, test, tearDown)
+
+        // do not estimate stability for warm-up
+        if (!testName.contains(WARM_UP)) {
+            val calcMean = calcMean(statInfosArray)
+            val stabilityPercentage = round(calcMean.stdDev * 100.0 / calcMean.mean).toInt()
+            logMessage { "$testName stability is $stabilityPercentage %" }
+            check(stabilityPercentage <= 10) { "$testName is not stable: stability above $stabilityPercentage %" }
+        }
+
        return statInfosArray
    }

    private fun <K, T> warmUpPhase(
        warmUpIterations: Int,
-        namePrefix: String,
+        testName: String,
        setUp: (TestData<K, T>) -> Unit,
        test: (TestData<K, T>) -> Unit,
        tearDown: (TestData<K, T>) -> Unit
    ) {
-        val warmUpStatInfosArray = Array<StatInfos>(warmUpIterations) { null }
-        _phase(warmUpIterations, setUp, warmUpStatInfosArray, test, namePrefix, tearDown)
+        val warmUpStatInfosArray = phase(testName, "warm-up", warmUpIterations, setUp, test, tearDown)

-        printWarmUpTimings(namePrefix, warmUpStatInfosArray)
+        printWarmUpTimings(testName, warmUpStatInfosArray)

        warmUpStatInfosArray.filterNotNull().map { it[ERROR_KEY] as? Exception }.firstOrNull()?.let { throw it }
    }

-    private fun <K, T> _phase(
+    private fun <K, T> phase(
+        namePrefix: String,
+        phaseName: String,
        iterations: Int,
        setUp: (TestData<K, T>) -> Unit,
-        statInfosArray: Array<StatInfos>,
        test: (TestData<K, T>) -> Unit,
-        namePrefix: String,
        tearDown: (TestData<K, T>) -> Unit
-    ) {
+    ): Array<StatInfos> {
+        val statInfosArray = Array<StatInfos>(iterations) { null }
        val testData = TestData<K, T>(null, null)
+        val profilerPath = pathToResource("profile/${plainname()}/")
+        check(with(File(profilerPath)) { exists() || mkdirs() }) { "unable to mkdirs $profilerPath for $namePrefix" }
        try {
            for (attempt in 0 until iterations) {
                testData.reset()
@@ -210,9 +226,12 @@ class Stats(val name: String = "", val header: Array<String> = arrayOf("Name", "
                val valueMap = HashMap<String, Any>(2 * PerformanceCounter.numberOfCounters + 1)
                statInfosArray[attempt] = valueMap
                try {
+                    val activityName = "$namePrefix-${if (phaseName.isEmpty()) "" else "$phaseName-"}$attempt"
+                    profilerHandler.startProfiling(activityName)
                    valueMap[TEST_KEY] = measureNanoTime {
                        test(testData)
                    }
+                    profilerHandler.stopProfiling(profilerPath, activityName)
                    PerformanceCounter.report { name, counter, nanos ->
                        valueMap["counter \"$name\": count"] = counter.toLong()
                        valueMap["counter \"$name\": time"] = nanos.nsToMs
@@ -237,6 +256,7 @@ class Stats(val name: String = "", val header: Array<String> = arrayOf("Name", "
            println("error at $namePrefix:")
            tcPrintErrors(namePrefix, listOf(t))
        }
+        return statInfosArray
    }

    private fun triggerGC(attempt: Int) {
@@ -265,6 +285,8 @@ class Stats(val name: String = "", val header: Array<String> = arrayOf("Name", "
        const val TEST_KEY = "test"
        const val ERROR_KEY = "error"

+        const val WARM_UP = "warm-up"
+
        inline fun runAndMeasure(note: String, block: () -> Unit) {
            val openProjectMillis = measureTimeMillis {
                block()
@@ -334,7 +356,7 @@ class Stats(val name: String = "", val header: Array<String> = arrayOf("Name", "
    }
 }

-data class TestData<SV, V>(var setUpValue: SV?, var value: V?) {
+data class TestData<SV, TV>(var setUpValue: SV?, var value: TV?) {
    fun reset() {
        setUpValue = null
        value = null
@@ -0,0 +1,165 @@
+/*
+ * Copyright 2010-2019 JetBrains s.r.o. and Kotlin Programming Language contributors.
+ * Use of this source code is governed by the Apache 2.0 license that can be found in the license/LICENSE.txt file.
+ */
+
+package org.jetbrains.kotlin.idea.perf.profilers.async
+
+import com.intellij.openapi.util.SystemInfo
+import com.intellij.openapi.util.io.FileUtil
+import com.intellij.util.containers.ContainerUtil
+import org.jetbrains.kotlin.idea.testFramework.logMessage
+//import one.profiler.AsyncProfiler
+import java.io.File
+import java.nio.file.Files
+import java.nio.file.StandardCopyOption
+import java.util.*
+
+internal class AsyncProfilerHandler : ProfilerHandler {
+
+    private val asyncProfiler: Any
+
+    private var profilingStarted = false
+    private var profilingOptions: List<String>? = null
+
+    init {
+        val asyncLibPath = asyncLib().absolutePath
+        val getInstanceMethod = asyncLibClass.getMethod("getInstance", String::class.java)
+
+        // use reflection to exclude compile time dependency on async profiler that has not been published to maven yet
+        asyncProfiler = getInstanceMethod.invoke(null, asyncLibPath) as Any
+
+        logMessage { "asyncProfiler successfully loaded" }
+    }
+
+    private fun execute(command: String) {
+        executeMethod.invoke(asyncProfiler, command)
+    }
+
+    override fun startProfiling(activityName: String, options: List<String>) {
+        try {
+            profilingOptions = options
+            execute(AsyncProfilerCommandBuilder.buildStartCommand(options))
+            profilingStarted = true
+        } catch (e: Exception) {
+            throw RuntimeException(e)
+        }
+    }
+
+    override fun stopProfiling(snapshotsPath: String, activityName: String, options: List<String>) {
+        val combinedOptions = ArrayList(options)
+        val commandBuilder = AsyncProfilerCommandBuilder(snapshotsPath)
+        val stopAndDumpCommands = commandBuilder.buildStopAndDumpCommands(activityName, combinedOptions)
+        for (stopCommand in stopAndDumpCommands) {
+            execute(stopCommand)
+        }
+        profilingStarted = false
+    }
+
+    companion object {
+        const val AGENT_FILE_NAME = "libasyncProfiler.so"
+        private val asyncLibClass: Class<*> = Class.forName("one.profiler.AsyncProfiler")!!
+        private val executeMethod = asyncLibClass.getMethod("execute", String::class.java)
+        private var extractedFile: File? = null
+
+        private fun asyncLib(): File {
+            if (extractedFile == null) {
+                extractedFile = File("${System.getenv("ASYNC_PROFILER_HOME")}/build/$AGENT_FILE_NAME")
+            }
+            if (extractedFile == null || !extractedFile!!.exists()) {
+                val extracted = FileUtil.createTempFile("extracted_$AGENT_FILE_NAME", null, true)
+                val osName = if (SystemInfo.isLinux) "linux" else "macos"
+                val inputStream = asyncLibClass.getResourceAsStream("/binaries/$osName/$AGENT_FILE_NAME")
+                Files.copy(inputStream, extracted.toPath(), StandardCopyOption.REPLACE_EXISTING)
+                extractedFile = extracted
+            }
+            return extractedFile!!
+        }
+
+    }
+
+}
+
+class AsyncProfilerCommandBuilder(private val snapshotsPath: String) {
+    fun buildStopAndDumpCommands(activityName: String, options: List<String>): List<String> {
+        if (options.isEmpty()) {
+            val dumpFileName = getDumpFileName(activityName, "svg")
+            return listOf(buildCommand("stop", listOf("svg", "file=$dumpFileName")))
+        } else {
+            val dumpOptions = ArrayList<String>()
+            val profilingOptions = ArrayList<String>()
+            for (option in options) {
+                val myDumpOptions = listOf("summary", "traces", "flat", "jfr", "collapsed", "svg", "tree")
+                val trimmedOption = option.split("=".toRegex()).dropLastWhile { it.isEmpty() }.toTypedArray()[0].trim { it <= ' ' }
+                if (myDumpOptions.contains(trimmedOption)) {
+                    dumpOptions.add(option + ",file=" + getDumpFileName(activityName, trimmedOption))
+                } else {
+                    profilingOptions.add(option)
+                }
+            }
+            val stopCommands = ArrayList<String>()
+            for (option in dumpOptions) {
+                stopCommands.add(
+                    buildCommand(
+                        "stop",
+                        mergeParameters(
+                            profilingOptions,
+                            listOf(*option.split(",".toRegex()).dropLastWhile { it.isEmpty() }.toTypedArray())
+                        )
+                    )
+                )
+            }
+            return stopCommands
+        }
+    }
+
+    private fun getDumpFileName(activityName: String, profilingType: String): String {
+        return "$snapshotsPath${File.separator}$activityName" + when (profilingType) {
+            "jfr" -> ".jfr"
+            "svg" -> ".svg"
+            "tree" -> ".html"
+            else -> ".txt"
+        }
+    }
+
+    companion object {
+
+        private val DEFAULT_PROFILING_OPTIONS: List<String> = listOf("event=cpu", "framebuf=10000000", "interval=1000000")
+
+        fun buildStartCommand(options: List<String>): String {
+            return if (options.isEmpty()) {
+                buildCommand("start", DEFAULT_PROFILING_OPTIONS)
+            } else {
+                buildCommand("start", mergeParameters(options, DEFAULT_PROFILING_OPTIONS))
+            }
+        }
+
+        private fun buildCommand(initialCommand: String, options: List<String>): String {
+            val builder = StringBuilder(initialCommand)
+            for (option in options) {
+                builder.append(",").append(option)
+            }
+            return builder.toString()
+        }
+
+        private fun parseParametersList(options: List<String>): Map<String, String> {
+            return options.map { option ->
+                option.split("=".toRegex()).dropLastWhile { it.isEmpty() }
+                    .toTypedArray()
+            }.flatMap { it.toList() }.map { it to it }.toMap()
+        }
+
+        private fun mergeParameters(options: List<String>, defaultOptions: List<String>): List<String> {
+            val userOptions = parseParametersList(options)
+            val defOptions = parseParametersList(defaultOptions)
+            val mergedOptions = HashMap(defOptions)
+            mergedOptions.putAll(userOptions)
+            return ContainerUtil.map(mergedOptions.keys) { key ->
+                if (mergedOptions[key]?.isEmpty() == true)
+                    key
+                else
+                    key + "=" + mergedOptions[key]
+            }
+        }
+    }
+}
@@ -0,0 +1,45 @@
+/*
+ * Copyright 2010-2019 JetBrains s.r.o. and Kotlin Programming Language contributors.
+ * Use of this source code is governed by the Apache 2.0 license that can be found in the license/LICENSE.txt file.
+ */
+
+package org.jetbrains.kotlin.idea.perf.profilers.async
+
+import com.intellij.openapi.util.SystemInfo
+import org.jetbrains.kotlin.idea.testFramework.logMessage
+
+interface ProfilerHandler {
+    fun startProfiling(activityName: String, options: List<String> = emptyList())
+
+    fun stopProfiling(snapshotsPath: String, activityName: String, options: List<String> = emptyList())
+
+    companion object {
+        private var instance: ProfilerHandler? = null
+
+        @Synchronized
+        fun getInstance(): ProfilerHandler {
+            if (instance == null) {
+                if (!SystemInfo.isWindows) {
+                    try {
+                        instance = AsyncProfilerHandler()
+                    } catch (e: Throwable) {
+                        logMessage { "asyncProfiler not found" }
+                    }
+                }
+            }
+
+            if (instance == null) {
+                // fallback to dummy
+                instance = DummyProfilerHandler
+            }
+            return instance!!
+        }
+    }
+
+}
+
+object DummyProfilerHandler : ProfilerHandler {
+    override fun startProfiling(activityName: String, options: List<String>) {}
+
+    override fun stopProfiling(snapshotsPath: String, activityName: String, options: List<String>) {}
+}