Add more info to fir bench report & format as table

Properly measure raw fir builder time in fir benchmark

compiler/fir/modularized-tests/tests/org/jetbrains/kotlin/fir/FirResolveModularizedTotalKotlinTest.kt

@@ -57,16 +57,7 @@ class FirResolveModularizedTotalKotlinTest : AbstractModularizedTest() {
         val builder = RawFirBuilder(session, stubMode = false)
 
         val totalTransformer = FirTotalResolveTransformer()
-        val firFiles = ktFiles.toList().mapNotNull {
+        val firFiles = bench.buildFiles(builder, ktFiles)
-            var firFile: FirFile? = null
-            val time = measureNanoTime {
-                firFile = builder.buildFirFile(it)
-                (session.service<FirProvider>() as FirProviderImpl).recordFile(firFile!!)
-            }
-            bench.countBuilder(builder, time)
-            firFile
-        }.toList()
-
 
         println("Raw FIR up, files: ${firFiles.size}")
 

compiler/fir/resolve/tests/org/jetbrains/kotlin/fir/FirResolveBench.kt

@@ -17,6 +17,7 @@ import org.jetbrains.kotlin.fir.visitors.FirTransformer
 import org.jetbrains.kotlin.fir.visitors.FirVisitorVoid
 import org.jetbrains.kotlin.psi.KtFile
 import org.jetbrains.kotlin.psi.psiUtil.startOffset
+import org.jetbrains.kotlin.utils.addToStdlib.sumByLong
 import java.io.PrintStream
 import kotlin.math.max
 import kotlin.reflect.KClass
@@ -35,8 +36,17 @@ private data class ErrorTypeReport(val report: String, var count: Int = 0)
 
 class FirResolveBench(val withProgress: Boolean) {
 
-    val timePerTransformer = mutableMapOf<KClass<*>, Long>()
+
-    val counterPerTransformer = mutableMapOf<KClass<*>, Long>()
+    data class Measure(
+        var time: Long = 0,
+        var user: Long = 0,
+        var cpu: Long = 0,
+        var gcTime: Long = 0,
+        var gcCollections: Int = 0,
+        var files: Int = 0
+    ) {}
+
+    val timePerTransformer = mutableMapOf<KClass<*>, Measure>()
     var resolvedTypes = 0
     var errorTypes = 0
     var unresolvedTypes = 0
@@ -51,9 +61,59 @@ class FirResolveBench(val withProgress: Boolean) {
 
     private val errorTypesReports = mutableMapOf<String, ErrorTypeReport>()
 
-    fun countBuilder(builder: RawFirBuilder, time: Long) {
+    fun buildFiles(
-        timePerTransformer.merge(builder::class, time) { a, b -> a + b }
+        builder: RawFirBuilder,
-        counterPerTransformer.merge(builder::class, 1) { a, b -> a + b }
+        ktFiles: List<KtFile>
+    ): List<FirFile> {
+        return ktFiles.map { file ->
+            val before = vmStateSnapshot()
+            var firFile: FirFile? = null
+            val time = measureNanoTime {
+                firFile = builder.buildFirFile(file)
+                (builder.session.service<FirProvider>() as FirProviderImpl).recordFile(firFile!!)
+            }
+            val after = vmStateSnapshot()
+            val diff = after - before
+            recordTime(builder::class, diff, time)
+            firFile!!
+        }
+    }
+
+    private fun recordTime(stageClass: KClass<*>, diff: VMCounters, time: Long) {
+        timePerTransformer.computeIfAbsent(stageClass) { Measure() }.apply {
+            this.time += time
+            this.files += 1
+            this.user += diff.userTime
+            this.cpu += diff.cpuTime
+            this.gcCollections += diff.gcInfo.values.sumBy { it.collections.toInt() }
+            this.gcTime += diff.gcInfo.values.sumByLong { it.gcTime }
+        }
+    }
+
+    private fun runStage(transformer: FirTransformer<Nothing?>, firFileSequence: Sequence<FirFile>) {
+        for (firFile in firFileSequence) {
+            var fail = false
+            val before = vmStateSnapshot()
+            val time = measureNanoTime {
+                try {
+                    transformer.transformFile(firFile, null)
+                } catch (e: Throwable) {
+                    val ktFile = firFile.psi as KtFile
+                    println("Fail in file: ${ktFile.virtualFilePath}")
+                    fail = true
+                    fails += FailureInfo(transformer::class, e, ktFile.virtualFilePath)
+                    //println(ktFile.text)
+                    //throw e
+                }
+            }
+            if (!fail) {
+                val after = vmStateSnapshot()
+                val diff = after - before
+                recordTime(transformer::class, diff, time)
+
+            }
+            //totalLength += StringBuilder().apply { FirRenderer(this).visitFile(firFile) }.length
+        }
     }
 
     fun processFiles(
@@ -65,26 +125,7 @@ class FirResolveBench(val withProgress: Boolean) {
             for ((stage, transformer) in transformers.withIndex()) {
                 println("Starting stage #$stage. $transformer")
                 val firFileSequence = if (withProgress) firFiles.progress("   ~ ") else firFiles.asSequence()
-                for (firFile in firFileSequence) {
+                runStage(transformer, firFileSequence)
-                    var fail = false
-                    val time = measureNanoTime {
-                        try {
-                            transformer.transformFile(firFile, null)
-                        } catch (e: Throwable) {
-                            val ktFile = firFile.psi as KtFile
-                            println("Fail in file: ${ktFile.virtualFilePath}")
-                            fail = true
-                            fails += FailureInfo(transformer::class, e, ktFile.virtualFilePath)
-                            //println(ktFile.text)
-                            //throw e
-                        }
-                    }
-                    if (!fail) {
-                        timePerTransformer.merge(transformer::class, time) { a, b -> a + b }
-                        counterPerTransformer.merge(transformer::class, 1) { a, b -> a + b }
-                    }
-                    //totalLength += StringBuilder().apply { FirRenderer(this).visitFile(firFile) }.length
-                }
                 checkFirProvidersConsistency(firFiles)
             }
 
@@ -210,21 +251,52 @@ class FirResolveBench(val withProgress: Boolean) {
         stream.println("ERRONEOUSLY RESOLVED IMPLICIT TYPES: $implicitTypes (${implicitTypes percentOf resolvedTypes} of resolved)")
         stream.println("UNIQUE ERROR TYPES: ${errorTypesReports.size}")
 
+        printTable(stream) {
+            row {
+                cell("Stage", LEFT)
+                cells("Time", "Time per file", "Files: OK/E/T", "CPU", "User", "GC", "GC count")
+            }
+            separator()
+            timePerTransformer.forEach { (transformer, measure) ->
+                val time = measure.time
+                val counter = measure.files
+                row {
+                    cell(transformer.simpleName.toString(), LEFT)
+                    timeCell(time, fractionDigits = 0)
+                    timeCell(time / counter)
+                    cell("$counter/${fileCount - counter}/$fileCount")
+                    timeCell(measure.cpu, fractionDigits = 0)
+                    timeCell(measure.user)
+                    timeCell(measure.gcTime, inputUnit = TableTimeUnit.MS)
+                    cell(measure.gcCollections.toString())
+                }
+            }
 
-        var totalTime = 0L
+            if (timePerTransformer.keys.size > 0) {
-        var totalFiles = 0L
+                separator()
+                val totalTime = timePerTransformer.values.sumByLong { it.time }
+                val totalCpuTime = timePerTransformer.values.sumByLong { it.cpu }
+                val totalUserTime = timePerTransformer.values.sumByLong { it.user }
+                val totalGcTime = timePerTransformer.values.sumByLong { it.gcTime }
+                val totalGcCollections = timePerTransformer.values.sumBy { it.gcCollections }
+                val averageFiles = timePerTransformer.values.map { it.files }.average().toLong()
+
+
+                row {
+                    cell("Total", LEFT)
+                    timeCell(totalTime, fractionDigits = 0)
+                    timeCell(totalTime / averageFiles)
+                    cell("$averageFiles")
+                    cell("$averageFiles")
+                    timeCell(totalCpuTime, fractionDigits = 0)
+                    timeCell(totalUserTime)
+                    timeCell(totalGcTime, inputUnit = TableTimeUnit.MS)
+                    cell(totalGcCollections.toString())
+                }
+            }
 
-        timePerTransformer.forEach { (transformer, time) ->
-            val counter = counterPerTransformer[transformer]!!
-            stream.println("${transformer.simpleName}, TIME: ${time * 1e-6} ms, TIME PER FILE: ${(time / counter) * 1e-6} ms, FILES: OK/E/T $counter/${fileCount - counter}/$fileCount")
-            totalTime += time
-            totalFiles += counter
         }
 
-        if (counterPerTransformer.keys.size > 0) {
-            totalFiles /= counterPerTransformer.keys.size
-            stream.println("Total, TIME: ${totalTime * 1e-6} ms, TIME PER FILE: ${(totalTime / totalFiles) * 1e-6} ms")
-        }
     }
 }
 

compiler/fir/resolve/tests/org/jetbrains/kotlin/fir/TableRendering.kt

@@ -0,0 +1,149 @@
+/*
+ * 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.fir
+
+import java.text.DecimalFormat
+
+class RTableContext {
+    val data: MutableList<Row> = mutableListOf()
+    var cols = 0
+    fun row(names: List<String>) = row(names.map { Cell(it) })
+
+    sealed class Row {
+        class Data(val cells: List<Cell>) : Row()
+        class Separator() : Row()
+    }
+
+    @JvmName("rowCells")
+    fun row(cells: List<Cell>) {
+        cols = maxOf(cells.size, cols)
+        data += Row.Data(cells)
+    }
+
+    fun row(vararg names: String) {
+        row(listOf(*names))
+    }
+
+    fun separator() {
+        data += Row.Separator()
+    }
+
+    inner class RTableRowContext() {
+        val rowData = mutableListOf<Cell>()
+        val LEFT = false
+        val RIGHT = true
+        fun cell(text: String?, align: Boolean = RIGHT) {
+            rowData += Cell(text.toString(), align)
+        }
+
+        fun cells(texts: List<String>, align: Boolean = RIGHT) {
+            rowData += texts.map { Cell(it, align) }
+        }
+
+        fun cells(vararg texts: String, align: Boolean = RIGHT) {
+            cells(listOf(*texts), align)
+        }
+    }
+
+    inline fun row(body: RTableRowContext.() -> Unit) {
+        val ctx = RTableRowContext()
+        ctx.body()
+        row(ctx.rowData)
+    }
+
+    data class Cell(val text: String, val alignRight: Boolean = true) {
+        fun padText(size: Int): String {
+            return if (alignRight) {
+                text.padStart(size)
+            } else {
+                text.padEnd(size)
+            }
+        }
+    }
+
+    fun printout(out: Appendable) {
+        val colSize = IntArray(cols) { index ->
+            data.filterIsInstance<Row.Data>().fold(0) { acc, row -> maxOf(acc, row.cells[index].text.length) }
+        }
+
+
+        fun appendHLine(prefix: String, sep: String, postfix: String) {
+            out.append(prefix)
+            for ((index, size) in colSize.withIndex()) {
+                if (index != 0) {
+                    out.append(sep)
+                    out.append(HLINE)
+                }
+                out.append(HLINE.repeat(size))
+            }
+            out.append(postfix)
+            out.appendln()
+        }
+
+        appendHLine(CORNER_LU, TOP_T, CORNER_RU)
+        for (row in data) {
+            when (row) {
+                is Row.Data -> {
+                    out.append(VLINE)
+                    for ((index, cell) in row.cells.withIndex()) {
+                        out.append(cell.padText(colSize[index]))
+                        out.append(VLINE)
+                        out.append(" ")
+                    }
+                    out.appendln()
+                }
+                is Row.Separator -> {
+                    appendHLine(LEFT_T, CROSS, RIGHT_T)
+                }
+            }
+
+        }
+        appendHLine(CORNER_LD, BOT_T, CORNER_RD)
+    }
+
+    companion object {
+        private const val CROSS = "┼"
+        private const val VLINE = "│"
+        private const val HLINE = "─"
+        private const val CORNER_LU = "┌"
+        private const val CORNER_RU = "┐"
+        private const val CORNER_LD = "└"
+        private const val CORNER_RD = "┘"
+        private const val LEFT_T = "├"
+        private const val RIGHT_T = "┤"
+        private const val TOP_T = "┬"
+        private const val BOT_T = "┴"
+    }
+}
+
+
+internal enum class TableTimeUnit(val postfixText: String, val nsMultiplier: Double, val fractionDigits: Int) {
+    NS("ns", 1.0, 0),
+    MICS("mcs", 1e-3, 3),
+    MS("ms", 1e-6, 6),
+    S("s", 1e-9, 9);
+
+    fun convert(value: Long, from: TableTimeUnit): Double {
+        return value / from.nsMultiplier * this.nsMultiplier
+    }
+}
+
+internal inline fun RTableContext.RTableRowContext.timeCell(
+    time: Long,
+    outputUnit: TableTimeUnit = TableTimeUnit.MS,
+    inputUnit: TableTimeUnit = TableTimeUnit.NS,
+    fractionDigits: Int = outputUnit.fractionDigits
+) {
+    val df = DecimalFormat()
+    df.maximumFractionDigits = fractionDigits
+    df.isGroupingUsed = true
+
+    cell("${df.format(outputUnit.convert(time, inputUnit))} ${outputUnit.postfixText}")
+}
+
+internal inline fun printTable(out: Appendable = System.out, body: RTableContext.() -> Unit) {
+    RTableContext().apply(body).printout(out)
+}

compiler/fir/resolve/tests/org/jetbrains/kotlin/fir/VMCounters.kt

@@ -0,0 +1,58 @@
+/*
+ * 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.fir
+
+import org.jetbrains.kotlin.daemon.common.threadCpuTime
+import org.jetbrains.kotlin.daemon.common.threadUserTime
+import sun.management.ManagementFactoryHelper
+
+
+data class GCInfo(val name: String, val gcTime: Long, val collections: Long) {
+    operator fun minus(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>) {
+
+
+    operator fun minus(other: VMCounters): VMCounters {
+        return VMCounters(
+            userTime - other.userTime,
+            cpuTime - other.cpuTime,
+            merge(gcInfo, other.gcInfo) { a, b -> a - b }
+        )
+    }
+
+}
+
+
+private fun <K, V> merge(first: Map<K, V>, second: Map<K, V>, valueOp: (V, V) -> V): Map<K, V> {
+    val result = first.toMutableMap()
+    for ((k, v) in second) {
+        result.merge(k, v, valueOp)
+    }
+    return result
+}
+
+object Init {
+    init {
+        ManagementFactoryHelper.getThreadMXBean().isThreadCpuTimeEnabled = true
+    }
+}
+
+fun vmStateSnapshot(): VMCounters {
+    Init
+    val threadMXBean = ManagementFactoryHelper.getThreadMXBean()
+
+    return VMCounters(
+        threadMXBean.threadUserTime(), threadMXBean.threadCpuTime(),
+        ManagementFactoryHelper.getGarbageCollectorMXBeans().associate { it.name to GCInfo(it.name, it.collectionTime, it.collectionCount) }
+    )
+}