From 731dd9c3e8a12f579f5b4541ec9c6b5376ddc77a Mon Sep 17 00:00:00 2001 From: Alexander Korepanov Date: Fri, 28 Oct 2022 11:03:14 +0200 Subject: [PATCH] [JS IR] More detailed time measurement for the IC infrastructure --- .../jetbrains/kotlin/cli/js/K2JsIrCompiler.kt | 30 +++++-------- .../kotlin/ir/backend/js/ic/CacheUpdater.kt | 44 ++++++++++++++----- .../kotlin/ir/backend/js/ic/ICUtils.kt | 24 ++++++++++ .../ir/backend/js/ic/JsExecutableProducer.kt | 42 +++++++++++++----- .../incremental/AbstractInvalidationTest.kt | 5 +-- .../js/test/AbstractJsKLibABITestCase.kt | 2 +- .../js/test/converters/JsIrBackendFacade.kt | 2 +- 7 files changed, 103 insertions(+), 46 deletions(-) diff --git a/compiler/cli/cli-js/src/org/jetbrains/kotlin/cli/js/K2JsIrCompiler.kt b/compiler/cli/cli-js/src/org/jetbrains/kotlin/cli/js/K2JsIrCompiler.kt index bb6a9304e29..8cf1ca8e917 100644 --- a/compiler/cli/cli-js/src/org/jetbrains/kotlin/cli/js/K2JsIrCompiler.kt +++ b/compiler/cli/cli-js/src/org/jetbrains/kotlin/cli/js/K2JsIrCompiler.kt @@ -251,18 +251,10 @@ class K2JsIrCompiler : CLICompiler() { compilerInterfaceFactory = { mainModule, cfg -> JsIrCompilerWithIC(mainModule, cfg, arguments.granularity) } ) - var tp = System.currentTimeMillis() - val icTimeMessages = mutableListOf("cache updater initialization: ${tp - start}ms") - - val artifacts = cacheUpdater.actualizeCaches { - val now = System.currentTimeMillis() - icTimeMessages += "$it: ${now - tp}ms" - tp = now - } - + val artifacts = cacheUpdater.actualizeCaches() messageCollector.report(INFO, "IC rebuilt overall time: ${System.currentTimeMillis() - start}ms") - for (icTimeMessage in icTimeMessages) { - messageCollector.report(INFO, " $icTimeMessage") + for ((event, duration) in cacheUpdater.getStopwatchLaps()) { + messageCollector.report(INFO, " $event: ${(duration / 1e6).toInt()}ms") } var libIndex = 0 @@ -337,17 +329,17 @@ class K2JsIrCompiler : CLICompiler() { relativeRequirePath = true ) - val outputs = jsExecutableProducer.buildExecutable( - multiModule = arguments.irPerModule, - outJsProgram = false, - rebuildCallback = { rebuiltModule -> - messageCollector.report(INFO, "IC module builder rebuilt module [${File(rebuiltModule).name}]") - } - ) - + val (outputs, rebuiltModules) = jsExecutableProducer.buildExecutable(arguments.irPerModule, outJsProgram = false) outputs.write(outputDir, outputName) messageCollector.report(INFO, "Executable production duration (IC): ${System.currentTimeMillis() - beforeIc2Js}ms") + for ((event, duration) in jsExecutableProducer.getStopwatchLaps()) { + messageCollector.report(INFO, " $event: ${(duration / 1e6).toInt()}ms") + } + + for (module in rebuiltModules) { + messageCollector.report(INFO, "IC module builder rebuilt JS for module [${File(module).name}]") + } return OK } diff --git a/compiler/ir/backend.js/src/org/jetbrains/kotlin/ir/backend/js/ic/CacheUpdater.kt b/compiler/ir/backend.js/src/org/jetbrains/kotlin/ir/backend/js/ic/CacheUpdater.kt index b66b6ebbd4e..947b7487d3a 100644 --- a/compiler/ir/backend.js/src/org/jetbrains/kotlin/ir/backend/js/ic/CacheUpdater.kt +++ b/compiler/ir/backend.js/src/org/jetbrains/kotlin/ir/backend/js/ic/CacheUpdater.kt @@ -57,6 +57,8 @@ class CacheUpdater( private val mainArguments: List?, private val compilerInterfaceFactory: JsIrCompilerICInterfaceFactory ) { + private val stopwatch = StopwatchIC().apply { startNext("Cache initializing and klibs loading") } + private val signatureHashCalculator = IdSignatureHashCalculator() private val libraries = loadLibraries(allModules) @@ -75,8 +77,14 @@ class CacheUpdater( private val dirtyFileStats = KotlinSourceFileMutableMap>() + init { + stopwatch.stop() + } + fun getDirtyFileStats(): KotlinSourceFileMap> = dirtyFileStats + fun getStopwatchLaps() = stopwatch.laps + private fun MutableMap>.addDirtFileStat(srcFile: KotlinSourceFile, state: DirtyFileState) { when (val stats = this[srcFile]) { null -> this[srcFile] = EnumSet.of(state) @@ -282,6 +290,7 @@ class CacheUpdater( decl.getter?.let(::addSymbol) decl.setter?.let(::addSymbol) } + is IrClass -> { if (addSymbol(decl)) { addNestedDeclarations(decl) @@ -494,6 +503,7 @@ class CacheUpdater( val newMetadata = addNewMetadata(dependentLibFile, dependentSrcFile, dependentSrcMetadata) newMetadata.importedSignaturesModified = true } + dependentSignatures.keys != newSignatures -> { val newMetadata = addNewMetadata(dependentLibFile, dependentSrcFile, dependentSrcMetadata) newMetadata.directDependencies[libFile, srcFile] = newSignatures.associateWith { @@ -660,15 +670,18 @@ class CacheUpdater( loadedFragments: Map, dirtyFileExports: KotlinSourceFileMap<*> ): List { + stopwatch.startNext("Processing IR - initializing backend context") val mainModule = loadedFragments[mainLibraryFile] ?: notFoundIcError("main lib loaded fragment", mainLibraryFile) val compilerForIC = compilerInterfaceFactory.createCompilerForIC(mainModule, compilerConfiguration) // Load declarations referenced during `context` initialization linker.loadUnboundSymbols(true) + stopwatch.startNext("Processing IR - updating intrinsics and builtins dependencies") updateStdlibIntrinsicDependencies(linker, mainModule, loadedFragments, dirtyFileExports) - return compilerForIC.compile( + stopwatch.startNext("Processing IR - lowering") + val result = compilerForIC.compile( allModules = loadedFragments.values, dirtyFiles = loadedFragments.flatMap { (libFile, libFragment) -> dirtyFileExports[libFile]?.let { libDirtyFiles -> @@ -677,54 +690,61 @@ class CacheUpdater( }, mainArguments = mainArguments ) + stopwatch.stop() + return result } - fun actualizeCaches(eventCallback: (String) -> Unit = {}): List { + fun actualizeCaches(): List { dirtyFileStats.clear() + stopwatch.startNext("Modified files - checking hashes and collecting") val modifiedFiles = loadModifiedFiles() + stopwatch.startNext("Modified files - collecting exported signatures") val dirtyFileExports = collectExportedSymbolsForDirtyFiles(modifiedFiles) + stopwatch.startNext("Modified files - loading and linking IR") val jsIrLinkerLoader = JsIrLinkerLoader(compilerConfiguration, mainLibrary, dependencyGraph, irFactory()) var loadedIr = jsIrLinkerLoader.loadIr(dirtyFileExports) - eventCallback("initial loading of updated files") - var iterations = 0 var lastDirtyFiles: KotlinSourceFileMap = dirtyFileExports while (true) { + stopwatch.startNext("Dependencies ($iterations) - calculating transitive hashes for inline functions") signatureHashCalculator.updateInlineFunctionTransitiveHashes(loadedIr.loadedFragments.values) + stopwatch.startNext("Dependencies ($iterations) - updating a dependency graph") val dirtyHeaders = rebuildDirtySourceMetadata(loadedIr.linker, loadedIr.loadedFragments, lastDirtyFiles) + stopwatch.startNext("Dependencies ($iterations) - collecting files with updated exports and imports") val filesWithModifiedExportsOrImports = collectFilesWithModifiedExportsAndImports(dirtyHeaders) + stopwatch.startNext("Dependencies ($iterations) - collecting exported signatures for files with updated exports and imports") val filesToRebuild = collectFilesToRebuildSignatures(filesWithModifiedExportsOrImports) - eventCallback("actualization iteration $iterations") if (filesToRebuild.isEmpty()) { break } - loadedIr = jsIrLinkerLoader.loadIr(filesToRebuild) - iterations++ - lastDirtyFiles = filesToRebuild dirtyFileExports.copyFilesFrom(filesToRebuild) + + stopwatch.startNext("Dependencies ($iterations) - loading and linking IR for files with modified exports and imports") + loadedIr = jsIrLinkerLoader.loadIr(filesToRebuild) + iterations++ } if (iterations != 0) { + stopwatch.startNext("Loading and linking all IR") loadedIr = jsIrLinkerLoader.loadIr(dirtyFileExports) - eventCallback("final loading of updated files") } + stopwatch.stop() val rebuiltFragments = compileDirtyFiles(loadedIr.linker, loadedIr.loadedFragments, dirtyFileExports) - eventCallback("updated files processing (lowering)") + stopwatch.startNext("Cache committing") val artifacts = buildModuleArtifactsAndCommitCache(loadedIr.linker, loadedIr.loadedFragments, rebuiltFragments) - eventCallback("cache committing") - + stopwatch.stop() return artifacts } } diff --git a/compiler/ir/backend.js/src/org/jetbrains/kotlin/ir/backend/js/ic/ICUtils.kt b/compiler/ir/backend.js/src/org/jetbrains/kotlin/ir/backend/js/ic/ICUtils.kt index 8f08ad8df3f..f45d75126f7 100644 --- a/compiler/ir/backend.js/src/org/jetbrains/kotlin/ir/backend/js/ic/ICUtils.kt +++ b/compiler/ir/backend.js/src/org/jetbrains/kotlin/ir/backend/js/ic/ICUtils.kt @@ -59,3 +59,27 @@ internal inline fun buildSetUntil(to: Int, builderAction: MutableSet.(Int internal inline fun buildMapUntil(to: Int, builderAction: MutableMap.(Int) -> Unit): Map { return buildMap(to) { repeat(to) { builderAction(it) } } } + +internal class StopwatchIC { + private var lapStart: Long = 0 + private var lapDescription: String? = null + + private val lapsImpl = mutableListOf>() + + val laps: List> + get() = lapsImpl + + fun startNext(description: String) { + val now = System.nanoTime() + stop(now) + lapDescription = description + lapStart = now + } + + fun stop(stopTime: Long? = null) { + lapDescription?.let { description -> + lapsImpl += description to ((stopTime ?: System.nanoTime()) - lapStart) + } + lapDescription = null + } +} diff --git a/compiler/ir/backend.js/src/org/jetbrains/kotlin/ir/backend/js/ic/JsExecutableProducer.kt b/compiler/ir/backend.js/src/org/jetbrains/kotlin/ir/backend/js/ic/JsExecutableProducer.kt index 87a6fef1126..eb75f2dd792 100644 --- a/compiler/ir/backend.js/src/org/jetbrains/kotlin/ir/backend/js/ic/JsExecutableProducer.kt +++ b/compiler/ir/backend.js/src/org/jetbrains/kotlin/ir/backend/js/ic/JsExecutableProducer.kt @@ -17,13 +17,23 @@ class JsExecutableProducer( private val caches: List, private val relativeRequirePath: Boolean ) { - fun buildExecutable(multiModule: Boolean, outJsProgram: Boolean, rebuildCallback: (String) -> Unit = {}) = if (multiModule) { - buildMultiModuleExecutable(outJsProgram, rebuildCallback) - } else { - buildSingleModuleExecutable(outJsProgram, rebuildCallback) + data class BuildResult(val compilationOut: CompilationOutputs, val buildModules: List) + + private val stopwatch = StopwatchIC() + + fun getStopwatchLaps() = buildMap { + stopwatch.laps.forEach { + this[it.first] = it.second + (this[it.first] ?: 0L) + } } - private fun buildSingleModuleExecutable(outJsProgram: Boolean, rebuildCallback: (String) -> Unit): CompilationOutputs { + fun buildExecutable(multiModule: Boolean, outJsProgram: Boolean) = if (multiModule) { + buildMultiModuleExecutable(outJsProgram) + } else { + buildSingleModuleExecutable(outJsProgram) + } + + private fun buildSingleModuleExecutable(outJsProgram: Boolean): BuildResult { val modules = caches.map { cacheArtifact -> cacheArtifact.loadJsIrModule() } val out = generateSingleWrappedModuleBody( moduleName = mainModuleName, @@ -33,31 +43,39 @@ class JsExecutableProducer( generateCallToMain = true, outJsProgram = outJsProgram ) - rebuildCallback(mainModuleName) - return out + return BuildResult(out, listOf(mainModuleName)) } - private fun buildMultiModuleExecutable(outJsProgram: Boolean, rebuildCallback: (String) -> Unit): CompilationOutputs { + private fun buildMultiModuleExecutable(outJsProgram: Boolean): BuildResult { + val rebuildModules = mutableListOf() + stopwatch.startNext("JS code cache loading") val jsMultiModuleCache = JsMultiModuleCache(caches) val cachedProgram = jsMultiModuleCache.loadProgramHeadersFromCache() + stopwatch.startNext("Cross module references resolving") val resolver = CrossModuleDependenciesResolver(moduleKind, cachedProgram.map { it.jsIrHeader }) val crossModuleReferences = resolver.resolveCrossModuleDependencies(relativeRequirePath) + stopwatch.startNext("Loading JS IR modules with updated cross module references") jsMultiModuleCache.loadRequiredJsIrModules(crossModuleReferences) fun JsMultiModuleCache.CachedModuleInfo.compileModule(moduleName: String, generateCallToMain: Boolean): CompilationOutputs { if (jsIrHeader.associatedModule == null) { + stopwatch.startNext("Fetching cached JS code") val compilationOutputs = jsMultiModuleCache.fetchCompiledJsCode(artifact) if (compilationOutputs != null) { return compilationOutputs } + // theoretically should never happen + stopwatch.startNext("Loading JS IR modules") jsIrHeader.associatedModule = artifact.loadJsIrModule() } + stopwatch.startNext("Initializing JS imports") val associatedModule = jsIrHeader.associatedModule ?: icError("can not load module $moduleName") val crossRef = crossModuleReferences[jsIrHeader] ?: icError("can not find cross references for module $moduleName") crossRef.initJsImportsForModule(associatedModule) + stopwatch.startNext("Generating JS code") val compiledModule = generateSingleWrappedModuleBody( moduleName = moduleName, moduleKind = moduleKind, @@ -67,8 +85,10 @@ class JsExecutableProducer( crossModuleReferences = crossRef, outJsProgram = outJsProgram ) + + stopwatch.startNext("Committing compiled JS code") jsMultiModuleCache.commitCompiledJsCode(artifact, compiledModule) - rebuildCallback(moduleName) + rebuildModules += moduleName return compiledModule } @@ -79,6 +99,8 @@ class JsExecutableProducer( val dependencies = cachedOtherModules.map { it.jsIrHeader.externalModuleName to it.compileModule(it.jsIrHeader.externalModuleName, false) } - return CompilationOutputs(mainModule.jsCode, mainModule.jsProgram, mainModule.sourceMap, dependencies) + stopwatch.stop() + val compilationOut = CompilationOutputs(mainModule.jsCode, mainModule.jsProgram, mainModule.sourceMap, dependencies) + return BuildResult(compilationOut, rebuildModules) } } diff --git a/js/js.tests/test/org/jetbrains/kotlin/incremental/AbstractInvalidationTest.kt b/js/js.tests/test/org/jetbrains/kotlin/incremental/AbstractInvalidationTest.kt index ad1f34ff837..4a751c1da09 100644 --- a/js/js.tests/test/org/jetbrains/kotlin/incremental/AbstractInvalidationTest.kt +++ b/js/js.tests/test/org/jetbrains/kotlin/incremental/AbstractInvalidationTest.kt @@ -190,7 +190,7 @@ abstract class AbstractInvalidationTest : KotlinTestWithEnvironment() { } } - private fun verifyJsExecutableProducerBuildModules(stepId: Int, gotRebuilt: Set, expectedRebuilt: List) { + private fun verifyJsExecutableProducerBuildModules(stepId: Int, gotRebuilt: List, expectedRebuilt: List) { val got = gotRebuilt.filter { it != STDLIB_MODULE_NAME } JUnit4Assertions.assertSameElements(got, expectedRebuilt) { "Mismatched rebuilt modules at step $stepId" @@ -255,8 +255,7 @@ abstract class AbstractInvalidationTest : KotlinTestWithEnvironment() { relativeRequirePath = true ) - val rebuiltModules = mutableSetOf() - val jsOutput = jsExecutableProducer.buildExecutable(multiModule = true, outJsProgram = true) { rebuiltModules += it } + val (jsOutput, rebuiltModules) = jsExecutableProducer.buildExecutable(multiModule = true, outJsProgram = true) verifyJsExecutableProducerBuildModules(projStep.id, rebuiltModules, projStep.dirtyJS) verifyJsCode(projStep.id, mainModuleName, jsOutput) } diff --git a/js/js.tests/test/org/jetbrains/kotlin/js/test/AbstractJsKLibABITestCase.kt b/js/js.tests/test/org/jetbrains/kotlin/js/test/AbstractJsKLibABITestCase.kt index 0ecf8af7573..53a5e87a3b4 100644 --- a/js/js.tests/test/org/jetbrains/kotlin/js/test/AbstractJsKLibABITestCase.kt +++ b/js/js.tests/test/org/jetbrains/kotlin/js/test/AbstractJsKLibABITestCase.kt @@ -181,7 +181,7 @@ abstract class AbstractJsKLibABITestCase : KtUsefulTestCase() { relativeRequirePath = true ) - return jsExecutableProducer.buildExecutable(multiModule = true, outJsProgram = true) {} + return jsExecutableProducer.buildExecutable(multiModule = true, outJsProgram = true).compilationOut } private fun buildBinaryNoIC( diff --git a/js/js.tests/test/org/jetbrains/kotlin/js/test/converters/JsIrBackendFacade.kt b/js/js.tests/test/org/jetbrains/kotlin/js/test/converters/JsIrBackendFacade.kt index ea21f2dafed..2b5e21fd04b 100644 --- a/js/js.tests/test/org/jetbrains/kotlin/js/test/converters/JsIrBackendFacade.kt +++ b/js/js.tests/test/org/jetbrains/kotlin/js/test/converters/JsIrBackendFacade.kt @@ -104,7 +104,7 @@ class JsIrBackendFacade( caches = testServices.jsIrIncrementalDataProvider.getCaches(), relativeRequirePath = false ) - jsExecutableProducer.buildExecutable(it.perModule, true) + jsExecutableProducer.buildExecutable(it.perModule, true).compilationOut }, tsDefinitions = null )