Slightly improve performance measurements rendering

Report the input module name and size once before any measurements
instead of duplicating it in all of them. Also, render measurements in a
table to improve readability.

Before:

info: PERF: INIT: Compiler initialized in 467 ms
info: PERF: ANALYZE: 1 files (2 lines) target main-java-production in 277 ms - 7.220 loc/s
info: PERF: IR: Translation 1 files (2 lines) target main-java-production in 291 ms - 6.873 loc/s
info: PERF: GENERATE: 1 files (2 lines) target main-java-production in 513 ms - 3.899 loc/s
info: PERF: IR: Generation 1 files (2 lines) target main-java-production in 142 ms - 14.085 loc/s

After:

info: PERF: main-java-production, 1 files (2 lines)
info: PERF: INIT: Compiler initialized in 421 ms
info: PERF:         ANALYZE     342 ms       5.848 loc/s
info: PERF:  IR TRANSLATION     296 ms       6.757 loc/s
info: PERF:        GENERATE     453 ms       4.415 loc/s
info: PERF:   IR GENERATION     137 ms      14.599 loc/s
This commit is contained in:
Alexander Udalov
2020-08-03 17:06:05 +02:00
parent 0045b501d5
commit c3cbcf6d7f
7 changed files with 70 additions and 82 deletions
@@ -89,8 +89,10 @@ abstract class CLICompiler<A : CommonCompilerArguments> : CLITool<A>() {
performanceManager.notifyCompilationFinished()
if (arguments.reportPerf) {
performanceManager.getMeasurementResults()
.forEach { it -> configuration.get(MESSAGE_COLLECTOR_KEY)!!.report(INFO, "PERF: " + it.render(), null) }
collector.report(INFO, "PERF: " + performanceManager.getTargetInfo())
for (measurement in performanceManager.getMeasurementResults()) {
collector.report(INFO, "PERF: " + measurement.render(), null)
}
}
if (arguments.dumpPerf != null) {
@@ -24,6 +24,13 @@ abstract class CommonCompilerPerformanceManager(private val presentableName: Str
private var irTranslationStart: Long = 0
private var irGenerationStart: Long = 0
private var targetDescription: String? = null
protected var files: Int? = null
protected var lines: Int? = null
fun getTargetInfo(): String =
"$targetDescription, $files files ($lines lines)"
fun getMeasurementResults(): List<PerformanceMeasurement> = measurements
fun enableCollectingPerformanceStatistics() {
@@ -34,9 +41,13 @@ abstract class CommonCompilerPerformanceManager(private val presentableName: Str
private fun deltaTime(start: Long): Long = PerformanceCounter.currentTime() - start
open fun notifyCompilerInitialized() {
open fun notifyCompilerInitialized(files: Int, lines: Int, targetDescription: String) {
if (!isEnabled) return
recordInitializationTime()
this.files = files
this.lines = lines
this.targetDescription = targetDescription
}
open fun notifyCompilationFinished() {
@@ -50,32 +61,30 @@ abstract class CommonCompilerPerformanceManager(private val presentableName: Str
analysisStart = PerformanceCounter.currentTime()
}
open fun notifyAnalysisFinished(files: Int, lines: Int, additionalDescription: String?) {
open fun notifyAnalysisFinished() {
val time = PerformanceCounter.currentTime() - analysisStart
measurements += CodeAnalysisMeasurement(files, lines, TimeUnit.NANOSECONDS.toMillis(time), additionalDescription)
measurements += CodeAnalysisMeasurement(lines, TimeUnit.NANOSECONDS.toMillis(time))
}
open fun notifyGenerationStarted() {
generationStart = PerformanceCounter.currentTime()
}
open fun notifyGenerationFinished(files: Int, lines: Int, additionalDescription: String) {
open fun notifyGenerationFinished() {
val time = PerformanceCounter.currentTime() - generationStart
measurements += CodeGenerationMeasurement(files, lines, TimeUnit.NANOSECONDS.toMillis(time), additionalDescription)
measurements += CodeGenerationMeasurement(lines, TimeUnit.NANOSECONDS.toMillis(time))
}
open fun notifyIRTranslationStarted() {
irTranslationStart = PerformanceCounter.currentTime()
}
open fun notifyIRTranslationFinished(files: Int, lines: Int, additionalDescription: String?) {
open fun notifyIRTranslationFinished() {
val time = deltaTime(irTranslationStart)
measurements += IRMeasurement(
files,
lines,
TimeUnit.NANOSECONDS.toMillis(time),
additionalDescription,
IRMeasurement.Kind.Translation
IRMeasurement.Kind.TRANSLATION
)
}
@@ -83,14 +92,12 @@ abstract class CommonCompilerPerformanceManager(private val presentableName: Str
irGenerationStart = PerformanceCounter.currentTime()
}
open fun notifyIRGenerationFinished(files: Int, lines: Int, additionalDescription: String) {
open fun notifyIRGenerationFinished() {
val time = deltaTime(irGenerationStart)
measurements += IRMeasurement(
files,
lines,
TimeUnit.NANOSECONDS.toMillis(time),
additionalDescription,
IRMeasurement.Kind.Generation
IRMeasurement.Kind.GENERATION
)
}
@@ -9,54 +9,41 @@ interface PerformanceMeasurement {
fun render(): String
}
class JitCompilationMeasurement(private val milliseconds: Long) : PerformanceMeasurement {
override fun render(): String = "JIT time is $milliseconds ms"
}
class CompilerInitializationMeasurement(private val milliseconds: Long) : PerformanceMeasurement {
override fun render(): String = "INIT: Compiler initialized in $milliseconds ms"
}
class CodeAnalysisMeasurement(val files: Int, val lines: Int, val milliseconds: Long, private val description: String?) :
PerformanceMeasurement {
val lps: Double = lines.toDouble() * 1000 / milliseconds
override fun render(): String =
"ANALYZE: $files files ($lines lines) ${description ?: ""}in $milliseconds ms - ${"%.3f".format(lps)} loc/s"
class CodeAnalysisMeasurement(private val lines: Int?, val milliseconds: Long) : PerformanceMeasurement {
override fun render(): String = formatMeasurement("ANALYZE", milliseconds, lines)
}
class CodeGenerationMeasurement(private val files: Int, val lines: Int, private val milliseconds: Long, private val description: String?) :
PerformanceMeasurement {
private val speed: Double = lines.toDouble() * 1000 / milliseconds
override fun render(): String =
"GENERATE: $files files ($lines lines) ${description}in $milliseconds ms - ${"%.3f".format(speed)} loc/s"
class CodeGenerationMeasurement(private val lines: Int?, private val milliseconds: Long) : PerformanceMeasurement {
override fun render(): String = formatMeasurement("GENERATE", milliseconds, lines)
}
class GarbageCollectionMeasurement(val garbageCollectionKind: String, val milliseconds: Long, val count: Long) : PerformanceMeasurement {
override fun render(): String = "GC time for $garbageCollectionKind is $milliseconds ms, $count collections"
}
class PerformanceCounterMeasurement(private val counterReport: String) : PerformanceMeasurement {
override fun render(): String = counterReport
}
class IRMeasurement(val files: Int, val lines: Int, val milliseconds: Long, private val description: String?, val kind: Kind) :
PerformanceMeasurement {
val lps: Double = lines.toDouble() * 1000 / milliseconds
override fun render(): String =
"IR: $kind $files files ($lines lines) ${description ?: ""}in $milliseconds ms - ${"%.3f".format(lps)} loc/s"
class IRMeasurement(val lines: Int?, val milliseconds: Long, val kind: Kind) : PerformanceMeasurement {
override fun render(): String = formatMeasurement("IR $kind", milliseconds, lines)
enum class Kind {
Generation, Translation
TRANSLATION, GENERATION
}
}
private fun formatMeasurement(name: String, time: Long, lines: Int?): String =
"%15s%8s ms".format(name, time) +
(lines?.let {
val lps = it.toDouble() * 1000 / time
"%12.3f loc/s".format(lps)
} ?: "")
@@ -147,9 +147,14 @@ class K2JVMCompiler : CLICompiler<K2JVMCompilerArguments>() {
ModuleChunk(listOf(module))
}
KotlinToJVMBytecodeCompiler.configureSourceRoots(configuration, moduleChunk.modules, buildFile)
val environment = createCoreEnvironment(rootDisposable, configuration, messageCollector)
?: return COMPILATION_ERROR
val chunk = moduleChunk.modules
KotlinToJVMBytecodeCompiler.configureSourceRoots(configuration, chunk, buildFile)
val environment = createCoreEnvironment(
rootDisposable, configuration, messageCollector,
chunk.map { input -> input.getModuleName() + "-" + input.getModuleType() }.let { names ->
names.singleOrNull() ?: names.joinToString()
}
) ?: return COMPILATION_ERROR
environment.registerJavacIfNeeded(arguments).let {
if (!it) return COMPILATION_ERROR
}
@@ -161,7 +166,7 @@ class K2JVMCompiler : CLICompiler<K2JVMCompilerArguments>() {
return COMPILATION_ERROR
}
KotlinToJVMBytecodeCompiler.compileModules(environment, buildFile, moduleChunk.modules)
KotlinToJVMBytecodeCompiler.compileModules(environment, buildFile, chunk)
return OK
} catch (e: CompilationException) {
messageCollector.report(
@@ -213,13 +218,17 @@ class K2JVMCompiler : CLICompiler<K2JVMCompilerArguments>() {
private fun createCoreEnvironment(
rootDisposable: Disposable,
configuration: CompilerConfiguration,
messageCollector: MessageCollector
messageCollector: MessageCollector,
targetDescription: String
): KotlinCoreEnvironment? {
if (messageCollector.hasErrors()) return null
val environment = KotlinCoreEnvironment.createForProduction(rootDisposable, configuration, EnvironmentConfigFiles.JVM_CONFIG_FILES)
configuration[CLIConfigurationKeys.PERF_MANAGER]?.notifyCompilerInitialized()
val sourceFiles = environment.getSourceFiles()
configuration[CLIConfigurationKeys.PERF_MANAGER]?.notifyCompilerInitialized(
sourceFiles.size, environment.countLinesOfCode(sourceFiles), targetDescription
)
return if (messageCollector.hasErrors()) null else environment
}
@@ -201,9 +201,7 @@ object KotlinToJVMBytecodeCompiler {
return compileModulesUsingFrontendIR(environment, buildFile, chunk)
}
val targetDescription = "in targets [" + chunk.joinToString { input -> input.getModuleName() + "-" + input.getModuleType() } + "]"
val result = repeatAnalysisIfNeeded(analyze(environment, targetDescription), environment, targetDescription)
val result = repeatAnalysisIfNeeded(analyze(environment), environment)
if (result == null || !result.shouldGenerateCode) return false
ProgressIndicatorAndCompilationCanceledStatus.checkCanceled()
@@ -384,9 +382,7 @@ object KotlinToJVMBytecodeCompiler {
environment.messageCollector
)
val debugTargetDescription = "target " + module.getModuleName() + "-" + module.getModuleType() + " "
val codeLines = environment.countLinesOfCode(ktFiles)
performanceManager?.notifyAnalysisFinished(ktFiles.size, codeLines, debugTargetDescription)
performanceManager?.notifyAnalysisFinished()
performanceManager?.notifyGenerationStarted()
val signaturer = IdSignatureDescriptor(JvmManglerDesc())
@@ -399,7 +395,7 @@ object KotlinToJVMBytecodeCompiler {
JvmGeneratorExtensions(), FirJvmKotlinMangler(session), IrFactoryImpl
)
performanceManager?.notifyIRTranslationFinished(ktFiles.size, codeLines, debugTargetDescription)
performanceManager?.notifyIRTranslationFinished()
val dummyBindingContext = NoScopeRecordCliBindingTrace().bindingContext
@@ -431,11 +427,7 @@ object KotlinToJVMBytecodeCompiler {
}
CodegenFactory.doCheckCancelled(generationState)
generationState.factory.done()
performanceManager?.notifyGenerationFinished(
ktFiles.size,
codeLines,
additionalDescription = debugTargetDescription
)
performanceManager?.notifyGenerationFinished()
ProgressIndicatorAndCompilationCanceledStatus.checkCanceled()
@@ -451,7 +443,7 @@ object KotlinToJVMBytecodeCompiler {
generationState.extraJvmDiagnosticsTrace.bindingContext, environment.messageCollector
)
performanceManager?.notifyIRGenerationFinished(ktFiles.size, codeLines, additionalDescription = debugTargetDescription)
performanceManager?.notifyIRGenerationFinished()
ProgressIndicatorAndCompilationCanceledStatus.checkCanceled()
outputs[module] = generationState
}
@@ -524,11 +516,7 @@ object KotlinToJVMBytecodeCompiler {
}
}
private fun repeatAnalysisIfNeeded(
result: AnalysisResult?,
environment: KotlinCoreEnvironment,
targetDescription: String?
): AnalysisResult? {
private fun repeatAnalysisIfNeeded(result: AnalysisResult?, environment: KotlinCoreEnvironment): AnalysisResult? {
if (result is AnalysisResult.RetryWithAdditionalRoots) {
val configuration = environment.configuration
@@ -551,7 +539,7 @@ object KotlinToJVMBytecodeCompiler {
configuration[CLIConfigurationKeys.MESSAGE_COLLECTOR_KEY]?.clear()
// Repeat analysis with additional Java roots (kapt generated sources)
return analyze(environment, targetDescription)
return analyze(environment)
}
return result
@@ -559,7 +547,7 @@ object KotlinToJVMBytecodeCompiler {
@Suppress("MemberVisibilityCanBePrivate") // Used in ExecuteKotlinScriptMojo
fun analyzeAndGenerate(environment: KotlinCoreEnvironment): GenerationState? {
val result = repeatAnalysisIfNeeded(analyze(environment, null), environment, null) ?: return null
val result = repeatAnalysisIfNeeded(analyze(environment), environment) ?: return null
if (!result.shouldGenerateCode) return null
@@ -568,7 +556,7 @@ object KotlinToJVMBytecodeCompiler {
return generate(environment, environment.configuration, result, environment.getSourceFiles(), null)
}
fun analyze(environment: KotlinCoreEnvironment, targetDescription: String?): AnalysisResult? {
fun analyze(environment: KotlinCoreEnvironment): AnalysisResult? {
val sourceFiles = environment.getSourceFiles()
val collector = environment.messageCollector
@@ -601,7 +589,7 @@ object KotlinToJVMBytecodeCompiler {
)
}
performanceManager?.notifyAnalysisFinished(sourceFiles.size, environment.countLinesOfCode(sourceFiles), targetDescription)
performanceManager?.notifyAnalysisFinished()
val analysisResult = analyzerWithCompilerReport.analysisResult
@@ -682,11 +670,7 @@ object KotlinToJVMBytecodeCompiler {
KotlinCodegenFacade.compileCorrectFiles(generationState)
performanceManager?.notifyGenerationFinished(
sourceFiles.size,
environment.countLinesOfCode(sourceFiles),
additionalDescription = if (module != null) "target " + module.getModuleName() + "-" + module.getModuleType() + " " else ""
)
performanceManager?.notifyGenerationFinished()
ProgressIndicatorAndCompilationCanceledStatus.checkCanceled()
@@ -12,7 +12,6 @@ import org.jetbrains.kotlin.cli.common.messages.PrintingMessageCollector
import org.jetbrains.kotlin.cli.jvm.K2JVMCompiler
import org.jetbrains.kotlin.config.Services
import org.jetbrains.kotlin.fir.TableTimeUnit.MS
import org.jetbrains.kotlin.fir.TableTimeUnit.S
import org.jetbrains.kotlin.fir.scopes.ProcessorAction
import org.jetbrains.kotlin.util.PerformanceCounter
import java.io.FileOutputStream
@@ -173,10 +172,10 @@ class FullPipelineModularizedTest : AbstractModularizedTest() {
return CumulativeTime(
gcInfo,
analysisMeasurement?.milliseconds ?: 0,
irMeasurements.firstOrNull { it.kind == IRMeasurement.Kind.Translation }?.milliseconds ?: 0,
irMeasurements.firstOrNull { it.kind == IRMeasurement.Kind.Generation }?.milliseconds ?: 0,
analysisMeasurement?.files ?: 0,
analysisMeasurement?.lines ?: 0
irMeasurements.firstOrNull { it.kind == IRMeasurement.Kind.TRANSLATION }?.milliseconds ?: 0,
irMeasurements.firstOrNull { it.kind == IRMeasurement.Kind.GENERATION }?.milliseconds ?: 0,
files ?: 0,
lines ?: 0
)
}
}
@@ -187,4 +186,4 @@ class FullPipelineModularizedTest : AbstractModularizedTest() {
runTestOnce(i)
}
}
}
}
@@ -32,7 +32,7 @@ class NonFirResolveModularizedTotalKotlinTest : AbstractModularizedTest() {
val time = measureNanoTime {
try {
KotlinToJVMBytecodeCompiler.analyze(environment, null)
KotlinToJVMBytecodeCompiler.analyze(environment)
} catch (e: Throwable) {
var exception: Throwable? = e
while (exception != null && exception != exception.cause) {