[JS IR] More detailed time measurement for the IC infrastructure

compiler/cli/cli-js/src/org/jetbrains/kotlin/cli/js/K2JsIrCompiler.kt

@@ -251,18 +251,10 @@ class K2JsIrCompiler : CLICompiler<K2JSCompilerArguments>() {
                 compilerInterfaceFactory = { mainModule, cfg -> JsIrCompilerWithIC(mainModule, cfg, arguments.granularity) }
             )
 
-            var tp = System.currentTimeMillis()
+            val artifacts = cacheUpdater.actualizeCaches()
-            val icTimeMessages = mutableListOf("cache updater initialization: ${tp - start}ms")
-
-            val artifacts = cacheUpdater.actualizeCaches {
-                val now = System.currentTimeMillis()
-                icTimeMessages += "$it: ${now - tp}ms"
-                tp = now
-            }
-
             messageCollector.report(INFO, "IC rebuilt overall time: ${System.currentTimeMillis() - start}ms")
-            for (icTimeMessage in icTimeMessages) {
+            for ((event, duration) in cacheUpdater.getStopwatchLaps()) {
-                messageCollector.report(INFO, "  $icTimeMessage")
+                messageCollector.report(INFO, "  $event: ${(duration / 1e6).toInt()}ms")
             }
 
             var libIndex = 0
@@ -337,17 +329,17 @@ class K2JsIrCompiler : CLICompiler<K2JSCompilerArguments>() {
                     relativeRequirePath = true
                 )
 
-                val outputs = jsExecutableProducer.buildExecutable(
+                val (outputs, rebuiltModules) = jsExecutableProducer.buildExecutable(arguments.irPerModule, outJsProgram = false)
-                    multiModule = arguments.irPerModule,
-                    outJsProgram = false,
-                    rebuildCallback = { rebuiltModule ->
-                        messageCollector.report(INFO, "IC module builder rebuilt module [${File(rebuiltModule).name}]")
-                    }
-                )
-
                 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
             }

compiler/ir/backend.js/src/org/jetbrains/kotlin/ir/backend/js/ic/CacheUpdater.kt

@@ -57,6 +57,8 @@ class CacheUpdater(
     private val mainArguments: List<String>?,
     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<EnumSet<DirtyFileState>>()
 
+    init {
+        stopwatch.stop()
+    }
+
     fun getDirtyFileStats(): KotlinSourceFileMap<EnumSet<DirtyFileState>> = dirtyFileStats
 
+    fun getStopwatchLaps() = stopwatch.laps
+
     private fun MutableMap<KotlinSourceFile, EnumSet<DirtyFileState>>.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<KotlinLibraryFile, IrModuleFragment>,
         dirtyFileExports: KotlinSourceFileMap<*>
     ): List<JsIrFragmentAndBinaryAst> {
+        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<ModuleArtifact> {
+    fun actualizeCaches(): List<ModuleArtifact> {
         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<KotlinSourceFileExports> = 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
     }
 }

compiler/ir/backend.js/src/org/jetbrains/kotlin/ir/backend/js/ic/ICUtils.kt

@@ -59,3 +59,27 @@ internal inline fun <E> buildSetUntil(to: Int, builderAction: MutableSet<E>.(Int
 internal inline fun <K, V> buildMapUntil(to: Int, builderAction: MutableMap<K, V>.(Int) -> Unit): Map<K, V> {
     return buildMap(to) { repeat(to) { builderAction(it) } }
 }
+
+internal class StopwatchIC {
+    private var lapStart: Long = 0
+    private var lapDescription: String? = null
+
+    private val lapsImpl = mutableListOf<Pair<String, Long>>()
+
+    val laps: List<Pair<String, Long>>
+        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
+    }
+}

compiler/ir/backend.js/src/org/jetbrains/kotlin/ir/backend/js/ic/JsExecutableProducer.kt

@@ -17,13 +17,23 @@ class JsExecutableProducer(
     private val caches: List<ModuleArtifact>,
     private val relativeRequirePath: Boolean
 ) {
-    fun buildExecutable(multiModule: Boolean, outJsProgram: Boolean, rebuildCallback: (String) -> Unit = {}) = if (multiModule) {
+    data class BuildResult(val compilationOut: CompilationOutputs, val buildModules: List<String>)
-        buildMultiModuleExecutable(outJsProgram, rebuildCallback)
+
-    } else {
+    private val stopwatch = StopwatchIC()
-        buildSingleModuleExecutable(outJsProgram, rebuildCallback)
+
+    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 BuildResult(out, listOf(mainModuleName))
-        return out
     }
 
-    private fun buildMultiModuleExecutable(outJsProgram: Boolean, rebuildCallback: (String) -> Unit): CompilationOutputs {
+    private fun buildMultiModuleExecutable(outJsProgram: Boolean): BuildResult {
+        val rebuildModules = mutableListOf<String>()
+        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)
     }
 }

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<String>, expectedRebuilt: List<String>) {
+        private fun verifyJsExecutableProducerBuildModules(stepId: Int, gotRebuilt: List<String>, expectedRebuilt: List<String>) {
             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<String>()
+                val (jsOutput, rebuiltModules) = jsExecutableProducer.buildExecutable(multiModule = true, outJsProgram = true)
-                val jsOutput = jsExecutableProducer.buildExecutable(multiModule = true, outJsProgram = true) { rebuiltModules += it }
                 verifyJsExecutableProducerBuildModules(projStep.id, rebuiltModules, projStep.dirtyJS)
                 verifyJsCode(projStep.id, mainModuleName, jsOutput)
             }

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(

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
             )