From 18c213ec10776cbf8fd2b62ccf555acc9c9fe0ba Mon Sep 17 00:00:00 2001 From: "Dmitriy.Panov" Date: Fri, 28 Jul 2023 19:18:48 +0200 Subject: [PATCH] build scripts: Jps file logger moved and renamed according to its purpose GitOrigin-RevId: d434dce677c88dfda922702eb69a2faa362dd163 --- .../build/impl/JpsCompilationRunner.kt | 197 +---------------- .../logging/jps/JpsFileLoggerFactory.java | 21 +- .../impl/logging/jps/JpsLoggerFactory.kt | 209 ++++++++++++++++++ 3 files changed, 223 insertions(+), 204 deletions(-) rename jps/standalone-builder/src/org/jetbrains/jps/gant/Log4jFileLoggerFactory.java => platform/build-scripts/src/org/jetbrains/intellij/build/impl/logging/jps/JpsFileLoggerFactory.java (64%) create mode 100644 platform/build-scripts/src/org/jetbrains/intellij/build/impl/logging/jps/JpsLoggerFactory.kt diff --git a/platform/build-scripts/src/org/jetbrains/intellij/build/impl/JpsCompilationRunner.kt b/platform/build-scripts/src/org/jetbrains/intellij/build/impl/JpsCompilationRunner.kt index 799c46b70563..6a890841c0ce 100644 --- a/platform/build-scripts/src/org/jetbrains/intellij/build/impl/JpsCompilationRunner.kt +++ b/platform/build-scripts/src/org/jetbrains/intellij/build/impl/JpsCompilationRunner.kt @@ -1,48 +1,34 @@ // Copyright 2000-2023 JetBrains s.r.o. and contributors. Use of this source code is governed by the Apache 2.0 license. -@file:Suppress("ReplacePutWithAssignment", "ReplaceGetOrSet", "HardCodedStringLiteral") - package org.jetbrains.intellij.build.impl import com.intellij.devkit.runtimeModuleRepository.jps.build.RuntimeModuleRepositoryBuildConstants -import com.intellij.openapi.diagnostic.DefaultLogger -import com.intellij.openapi.diagnostic.Logger import com.intellij.platform.diagnostic.telemetry.helpers.use import com.intellij.platform.diagnostic.telemetry.helpers.useWithScope -import com.intellij.util.containers.MultiMap -import com.jetbrains.plugin.structure.base.utils.createParentDirs import io.opentelemetry.api.common.AttributeKey import io.opentelemetry.api.common.Attributes import io.opentelemetry.api.trace.Span -import org.jetbrains.annotations.Nls import org.jetbrains.groovy.compiler.rt.GroovyRtConstants import org.jetbrains.intellij.build.CompilationContext import org.jetbrains.intellij.build.TraceManager.spanBuilder +import org.jetbrains.intellij.build.impl.logging.jps.withJpsLogging import org.jetbrains.jps.api.CmdlineRemoteProto.Message.ControllerMessage.ParametersMessage.TargetTypeBuildScope import org.jetbrains.jps.api.GlobalOptions import org.jetbrains.jps.backwardRefs.JavaBackwardReferenceIndexWriter import org.jetbrains.jps.build.Standalone -import org.jetbrains.jps.builders.BuildTarget import org.jetbrains.jps.builders.java.JavaModuleBuildTargetType -import org.jetbrains.jps.gant.Log4jFileLoggerFactory -import org.jetbrains.jps.incremental.MessageHandler import org.jetbrains.jps.incremental.artifacts.ArtifactBuildTargetType import org.jetbrains.jps.incremental.artifacts.impl.ArtifactSorter import org.jetbrains.jps.incremental.artifacts.impl.JpsArtifactUtil import org.jetbrains.jps.incremental.dependencies.DependencyResolvingBuilder import org.jetbrains.jps.incremental.groovy.JpsGroovycRunner -import org.jetbrains.jps.incremental.messages.* import org.jetbrains.jps.model.artifact.JpsArtifact import org.jetbrains.jps.model.artifact.JpsArtifactService import org.jetbrains.jps.model.artifact.elements.JpsModuleOutputPackagingElement import org.jetbrains.jps.model.java.JpsJavaExtensionService import org.jetbrains.jps.model.module.JpsModule -import java.beans.Introspector import java.nio.file.Files import java.nio.file.Path -import java.util.* -import java.util.concurrent.ConcurrentHashMap import java.util.concurrent.TimeUnit -import java.util.function.BiConsumer import kotlin.io.path.exists import kotlin.io.path.isDirectory import kotlin.io.path.listDirectoryEntries @@ -263,21 +249,6 @@ internal class JpsCompilationRunner(private val context: CompilationContext) { return ArtifactSorter.addIncludedArtifacts(artifacts) } - private fun setupAdditionalBuildLogging(compilationData: JpsCompilationData) { - val categoriesWithDebugLevel = compilationData.categoriesWithDebugLevel - val buildLogFile = compilationData.buildLogFile - try { - val factory = Log4jFileLoggerFactory(buildLogFile.toFile(), categoriesWithDebugLevel) - JpsLoggerFactory.fileLoggerFactory = factory - context.messages.info( - "Build log (${if (categoriesWithDebugLevel.isEmpty()) "info" else "debug level for $categoriesWithDebugLevel"}) " + - "will be written to $buildLogFile") - } - catch (t: Throwable) { - context.messages.warning("Cannot setup additional logging to $buildLogFile: ${t.message}") - } - } - private fun runBuild(moduleSet: Collection, allModules: Boolean, artifactNames: Collection, @@ -285,14 +256,7 @@ internal class JpsCompilationRunner(private val context: CompilationContext) { resolveProjectDependencies: Boolean, generateRuntimeModuleRepository: Boolean = false) { synchronized(context.paths.projectHome.toString().intern()) { - messageHandler = JpsMessageHandler(context) - if (context.options.compilationLogEnabled) { - setupAdditionalBuildLogging(compilationData) - } - - val oldLoggerFactory = Logger.getFactory() - Logger.setFactory(JpsLoggerFactory::class.java) - try { + withJpsLogging(context) { messageHandler -> val forceBuild = !context.options.incrementalCompilation || !context.compilationData.dataStorageRoot.exists() || !context.compilationData.dataStorageRoot.isDirectory() || @@ -376,167 +340,10 @@ internal class JpsCompilationRunner(private val context: CompilationContext) { compilationData.runtimeModuleRepositoryGenerated = true } } - finally { - Logger.setFactory(oldLoggerFactory) - } } } } -private class JpsLoggerFactory : Logger.Factory { - companion object { - var fileLoggerFactory: Logger.Factory? = null - } - - override fun getLoggerInstance(category: String): Logger = BackedLogger(category, fileLoggerFactory?.getLoggerInstance(category)) -} - -private class JpsMessageHandler(private val context: CompilationContext) : MessageHandler { - val errorMessagesByCompiler = MultiMap.createConcurrent() - val compilationStartTimeForTarget = ConcurrentHashMap() - val compilationFinishTimeForTarget = ConcurrentHashMap() - var progress = (-1.0).toFloat() - override fun processMessage(message: BuildMessage) { - val text = message.messageText - when (message.kind) { - BuildMessage.Kind.ERROR, BuildMessage.Kind.INTERNAL_BUILDER_ERROR -> { - val compilerName: String - val messageText: String - if (message is CompilerMessage) { - compilerName = message.compilerName - val sourcePath = message.sourcePath - messageText = if (sourcePath != null) { - """ - $sourcePath${if (message.line != -1L) ":" + message.line else ""}: - $text - """.trimIndent() - } - else { - text - } - } - else { - compilerName = "" - messageText = text - } - errorMessagesByCompiler.putValue(compilerName, messageText) - } - BuildMessage.Kind.WARNING -> context.messages.warning(text) - BuildMessage.Kind.INFO, BuildMessage.Kind.JPS_INFO -> if (message is BuilderStatisticsMessage) { - val buildKind = if (context.options.incrementalCompilation) " (incremental)" else "" - context.messages.reportStatisticValue("Compilation time '${message.builderName}'$buildKind, ms", message.elapsedTimeMs.toString()) - val sources = message.numberOfProcessedSources - context.messages.reportStatisticValue("Processed files by '${message.builderName}'$buildKind", sources.toString()) - if (!context.options.incrementalCompilation && sources > 0) { - context.messages.reportStatisticValue("Compilation time per file for '${message.builderName}', ms", - String.format(Locale.US, "%.2f", message.elapsedTimeMs.toDouble() / sources)) - } - } - else if (!text.isEmpty()) { - context.messages.info(text) - } - BuildMessage.Kind.PROGRESS -> if (message is ProgressMessage) { - progress = message.done - message.currentTargets?.let { - reportProgress(it.targets, message.messageText) - } - } - else if (message is BuildingTargetProgressMessage) { - val targets = message.targets - val target = targets.first() - val targetId = "${target.id}${if (targets.size > 1) " and ${targets.size} more" else ""} (${target.targetType.typeId})" - if (message.eventType == BuildingTargetProgressMessage.Event.STARTED) { - reportProgress(targets, "") - compilationStartTimeForTarget.put(targetId, System.nanoTime()) - } - else { - compilationFinishTimeForTarget.put(targetId, System.nanoTime()) - } - } - BuildMessage.Kind.OTHER, null -> context.messages.warning(text) - } - } - - fun printPerModuleCompilationStatistics(compilationStart: Long) { - if (compilationStartTimeForTarget.isEmpty()) { - return - } - - val csvPath = context.paths.logDir.resolve("compilation-time.csv").also { it.createParentDirs() } - Files.newBufferedWriter(csvPath).use { out -> - compilationFinishTimeForTarget.forEach(BiConsumer { k, v -> - val startTime = compilationStartTimeForTarget.getValue(k) - compilationStart - val finishTime = v - compilationStart - out.write("$k,$startTime,$finishTime\n") - }) - } - val buildMessages = context.messages - buildMessages.info("Compilation time per target:") - val compilationTimeForTarget = compilationFinishTimeForTarget.entries.map { - it.key to (it.value - compilationStartTimeForTarget.getValue(it.key)) - } - - buildMessages.info(" average: ${ - String.format("%.2f", ((compilationTimeForTarget.sumOf { it.second }.toDouble()) / compilationTimeForTarget.size) / 1000000) - }ms") - val topTargets = compilationTimeForTarget.sortedBy { it.second }.asReversed().take(10) - buildMessages.info(" top ${topTargets.size} targets by compilation time:") - for (entry in topTargets) { - buildMessages.info(" ${entry.first}: ${TimeUnit.NANOSECONDS.toMillis(entry.second)}ms") - } - } - - fun reportProgress(targets: Collection>, targetSpecificMessage: String) { - val targetsString = targets.joinToString(separator = ", ") { Introspector.decapitalize(it.presentableName) } - val progressText = if (progress >= 0) " (${(100 * progress).toInt()}%)" else "" - val targetSpecificText = if (targetSpecificMessage.isEmpty()) "" else ", $targetSpecificMessage" - context.messages.progress("Compiling$progressText: $targetsString$targetSpecificText") - } -} - -private class BackedLogger(category: String?, private val fileLogger: Logger?) : DefaultLogger(category) { - override fun error(@Nls message: String?, t: Throwable?, vararg details: String) { - if (t == null) { - messageHandler.processMessage(CompilerMessage(COMPILER_NAME, BuildMessage.Kind.ERROR, message)) - } - else { - messageHandler.processMessage(CompilerMessage.createInternalBuilderError(COMPILER_NAME, t)) - } - fileLogger?.error(message, t, *details) - } - - override fun warn(message: String?, t: Throwable?) { - messageHandler.processMessage(CompilerMessage(COMPILER_NAME, BuildMessage.Kind.WARNING, message)) - fileLogger?.warn(message, t) - } - - override fun info(message: String?, t: Throwable?) { - messageHandler.processMessage(CompilerMessage(COMPILER_NAME, BuildMessage.Kind.INFO, message + (t?.message?.let { ": $it" } ?: ""))) - fileLogger?.info(message, t) - } - - override fun isDebugEnabled(): Boolean = fileLogger != null && fileLogger.isDebugEnabled - - override fun debug(message: String?, t: Throwable?) { - fileLogger?.debug(message, t) - } - - override fun isTraceEnabled(): Boolean = fileLogger != null && fileLogger.isTraceEnabled - - override fun trace(message: String?) { - fileLogger?.trace(message) - } - - override fun trace(t: Throwable?) { - fileLogger?.trace(t) - } -} - -private lateinit var messageHandler: JpsMessageHandler - -@Nls -private const val COMPILER_NAME = "build runner" - private fun setSystemPropertyIfUndefined(name: String, value: String) { if (System.getProperty(name) == null) { System.setProperty(name, value) diff --git a/jps/standalone-builder/src/org/jetbrains/jps/gant/Log4jFileLoggerFactory.java b/platform/build-scripts/src/org/jetbrains/intellij/build/impl/logging/jps/JpsFileLoggerFactory.java similarity index 64% rename from jps/standalone-builder/src/org/jetbrains/jps/gant/Log4jFileLoggerFactory.java rename to platform/build-scripts/src/org/jetbrains/intellij/build/impl/logging/jps/JpsFileLoggerFactory.java index 398815785ba0..fa9f3fa8a531 100644 --- a/jps/standalone-builder/src/org/jetbrains/jps/gant/Log4jFileLoggerFactory.java +++ b/platform/build-scripts/src/org/jetbrains/intellij/build/impl/logging/jps/JpsFileLoggerFactory.java @@ -1,32 +1,35 @@ -// Copyright 2000-2022 JetBrains s.r.o. and contributors. Use of this source code is governed by the Apache 2.0 license. -package org.jetbrains.jps.gant; +// Copyright 2000-2023 JetBrains s.r.o. and contributors. Use of this source code is governed by the Apache 2.0 license. +package org.jetbrains.intellij.build.impl.logging.jps; import com.intellij.openapi.diagnostic.IdeaLogRecordFormatter; import com.intellij.openapi.diagnostic.JulLogger; +import com.intellij.openapi.diagnostic.Logger; +import com.intellij.openapi.diagnostic.Logger.Factory; import com.intellij.openapi.diagnostic.RollingFileHandler; +import org.jetbrains.annotations.ApiStatus; import org.jetbrains.annotations.NotNull; -import java.io.File; +import java.nio.file.Path; import java.util.Arrays; import java.util.Collections; import java.util.List; import java.util.logging.Level; -import java.util.logging.Logger; -public class Log4jFileLoggerFactory implements com.intellij.openapi.diagnostic.Logger.Factory { +@ApiStatus.Internal +public class JpsFileLoggerFactory implements Factory { private final RollingFileHandler myAppender; private final List myCategoriesWithDebugLevel; - public Log4jFileLoggerFactory(File logFile, String categoriesWithDebugLevel) { + public JpsFileLoggerFactory(Path logFile, String categoriesWithDebugLevel) { myCategoriesWithDebugLevel = categoriesWithDebugLevel.isEmpty() ? Collections.emptyList() : Arrays.asList(categoriesWithDebugLevel.split(",")); - myAppender = new RollingFileHandler(logFile.toPath(), 20_000_000L, 10, true); + myAppender = new RollingFileHandler(logFile, 20_000_000L, 10, true); myAppender.setFormatter(new IdeaLogRecordFormatter()); } @NotNull @Override - public com.intellij.openapi.diagnostic.Logger getLoggerInstance(@NotNull String category) { - final Logger logger = Logger.getLogger(category); + public Logger getLoggerInstance(@NotNull String category) { + var logger = java.util.logging.Logger.getLogger(category); JulLogger.clearHandlers(logger); logger.addHandler(myAppender); logger.setUseParentHandlers(false); diff --git a/platform/build-scripts/src/org/jetbrains/intellij/build/impl/logging/jps/JpsLoggerFactory.kt b/platform/build-scripts/src/org/jetbrains/intellij/build/impl/logging/jps/JpsLoggerFactory.kt new file mode 100644 index 000000000000..0c3166859b5e --- /dev/null +++ b/platform/build-scripts/src/org/jetbrains/intellij/build/impl/logging/jps/JpsLoggerFactory.kt @@ -0,0 +1,209 @@ +// Copyright 2000-2023 JetBrains s.r.o. and contributors. Use of this source code is governed by the Apache 2.0 license. +@file:Suppress("ReplacePutWithAssignment", "ReplaceGetOrSet", "HardCodedStringLiteral") + +package org.jetbrains.intellij.build.impl.logging.jps + +import com.intellij.openapi.diagnostic.DefaultLogger +import com.intellij.openapi.diagnostic.Logger +import com.intellij.util.containers.MultiMap +import com.jetbrains.plugin.structure.base.utils.createParentDirs +import org.jetbrains.annotations.ApiStatus.Internal +import org.jetbrains.annotations.Nls +import org.jetbrains.intellij.build.CompilationContext +import org.jetbrains.jps.builders.BuildTarget +import org.jetbrains.jps.incremental.MessageHandler +import org.jetbrains.jps.incremental.messages.* +import java.beans.Introspector +import java.nio.file.Files +import java.util.* +import java.util.concurrent.ConcurrentHashMap +import java.util.concurrent.TimeUnit +import java.util.function.BiConsumer + +@Internal +fun withJpsLogging(context: CompilationContext, action: (JpsMessageHandler) -> Unit) { + val messageHandler = JpsMessageHandler(context) + JpsLoggerFactory.messageHandler = messageHandler + if (context.options.compilationLogEnabled) { + val categoriesWithDebugLevel = context.compilationData.categoriesWithDebugLevel + val buildLogFile = context.compilationData.buildLogFile + try { + JpsLoggerFactory.fileLoggerFactory = JpsFileLoggerFactory(buildLogFile, categoriesWithDebugLevel) + context.messages.info( + "Build log (${if (categoriesWithDebugLevel.isEmpty()) "info" else "debug level for $categoriesWithDebugLevel"}) " + + "will be written to $buildLogFile" + ) + } + catch (t: Throwable) { + context.messages.warning("Cannot setup additional logging to $buildLogFile: ${t.message}") + } + } + val defaultLoggerFactory = Logger.getFactory() + Logger.setFactory(JpsLoggerFactory::class.java) + try { + action(messageHandler) + } + finally { + Logger.setFactory(defaultLoggerFactory) + } +} + +private class JpsLoggerFactory : Logger.Factory { + companion object { + lateinit var messageHandler: JpsMessageHandler + var fileLoggerFactory: JpsFileLoggerFactory? = null + } + + override fun getLoggerInstance(category: String): Logger { + return JpsLogger(category, fileLoggerFactory?.getLoggerInstance(category)) + } +} + +@Internal +class JpsMessageHandler(private val context: CompilationContext) : MessageHandler { + val errorMessagesByCompiler = MultiMap.createConcurrent() + private val compilationStartTimeForTarget = ConcurrentHashMap() + private val compilationFinishTimeForTarget = ConcurrentHashMap() + private var progress = (-1.0).toFloat() + override fun processMessage(message: BuildMessage) { + val text = message.messageText + when (message.kind) { + BuildMessage.Kind.ERROR, BuildMessage.Kind.INTERNAL_BUILDER_ERROR -> { + val compilerName: String + val messageText: String + if (message is CompilerMessage) { + compilerName = message.compilerName + val sourcePath = message.sourcePath + messageText = if (sourcePath != null) { + """ + $sourcePath${if (message.line != -1L) ":" + message.line else ""}: + $text + """.trimIndent() + } + else { + text + } + } + else { + compilerName = "" + messageText = text + } + errorMessagesByCompiler.putValue(compilerName, messageText) + } + BuildMessage.Kind.WARNING -> context.messages.warning(text) + BuildMessage.Kind.INFO, BuildMessage.Kind.JPS_INFO -> if (message is BuilderStatisticsMessage) { + val buildKind = if (context.options.incrementalCompilation) " (incremental)" else "" + context.messages.reportStatisticValue("Compilation time '${message.builderName}'$buildKind, ms", message.elapsedTimeMs.toString()) + val sources = message.numberOfProcessedSources + context.messages.reportStatisticValue("Processed files by '${message.builderName}'$buildKind", sources.toString()) + if (!context.options.incrementalCompilation && sources > 0) { + context.messages.reportStatisticValue("Compilation time per file for '${message.builderName}', ms", + String.format(Locale.US, "%.2f", message.elapsedTimeMs.toDouble() / sources)) + } + } + else if (!text.isEmpty()) { + context.messages.info(text) + } + BuildMessage.Kind.PROGRESS -> if (message is ProgressMessage) { + progress = message.done + message.currentTargets?.let { + reportProgress(it.targets, message.messageText) + } + } + else if (message is BuildingTargetProgressMessage) { + val targets = message.targets + val target = targets.first() + val targetId = "${target.id}${if (targets.size > 1) " and ${targets.size} more" else ""} (${target.targetType.typeId})" + if (message.eventType == BuildingTargetProgressMessage.Event.STARTED) { + reportProgress(targets, "") + compilationStartTimeForTarget.put(targetId, System.nanoTime()) + } + else { + compilationFinishTimeForTarget.put(targetId, System.nanoTime()) + } + } + BuildMessage.Kind.OTHER, null -> context.messages.warning(text) + } + } + + fun printPerModuleCompilationStatistics(compilationStart: Long) { + if (compilationStartTimeForTarget.isEmpty()) { + return + } + + val csvPath = context.paths.logDir.resolve("compilation-time.csv").also { it.createParentDirs() } + Files.newBufferedWriter(csvPath).use { out -> + compilationFinishTimeForTarget.forEach(BiConsumer { k, v -> + val startTime = compilationStartTimeForTarget.getValue(k) - compilationStart + val finishTime = v - compilationStart + out.write("$k,$startTime,$finishTime\n") + }) + } + val buildMessages = context.messages + buildMessages.info("Compilation time per target:") + val compilationTimeForTarget = compilationFinishTimeForTarget.entries.map { + it.key to (it.value - compilationStartTimeForTarget.getValue(it.key)) + } + + buildMessages.info(" average: ${ + String.format("%.2f", ((compilationTimeForTarget.sumOf { it.second }.toDouble()) / compilationTimeForTarget.size) / 1000000) + }ms") + val topTargets = compilationTimeForTarget.sortedBy { it.second }.asReversed().take(10) + buildMessages.info(" top ${topTargets.size} targets by compilation time:") + for (entry in topTargets) { + buildMessages.info(" ${entry.first}: ${TimeUnit.NANOSECONDS.toMillis(entry.second)}ms") + } + } + + private fun reportProgress(targets: Collection>, targetSpecificMessage: String) { + val targetsString = targets.joinToString(separator = ", ") { Introspector.decapitalize(it.presentableName) } + val progressText = if (progress >= 0) " (${(100 * progress).toInt()}%)" else "" + val targetSpecificText = if (targetSpecificMessage.isEmpty()) "" else ", $targetSpecificMessage" + context.messages.progress("Compiling$progressText: $targetsString$targetSpecificText") + } +} + +private class JpsLogger(category: String?, val fileLogger: Logger?) : DefaultLogger(category) { + companion object { + @Nls + const val COMPILER_NAME = "build runner" + } + + val messageHandler get() = JpsLoggerFactory.messageHandler + + override fun error(@Nls message: String?, t: Throwable?, vararg details: String) { + if (t == null) { + messageHandler.processMessage(CompilerMessage(COMPILER_NAME, BuildMessage.Kind.ERROR, message)) + } + else { + messageHandler.processMessage(CompilerMessage.createInternalBuilderError(COMPILER_NAME, t)) + } + fileLogger?.error(message, t, *details) + } + + override fun warn(message: String?, t: Throwable?) { + messageHandler.processMessage(CompilerMessage(COMPILER_NAME, BuildMessage.Kind.WARNING, message)) + fileLogger?.warn(message, t) + } + + override fun info(message: String?, t: Throwable?) { + messageHandler.processMessage(CompilerMessage(COMPILER_NAME, BuildMessage.Kind.INFO, message + (t?.message?.let { ": $it" } ?: ""))) + fileLogger?.info(message, t) + } + + override fun isDebugEnabled(): Boolean = fileLogger != null && fileLogger.isDebugEnabled + + override fun debug(message: String?, t: Throwable?) { + fileLogger?.debug(message, t) + } + + override fun isTraceEnabled(): Boolean = fileLogger != null && fileLogger.isTraceEnabled + + override fun trace(message: String?) { + fileLogger?.trace(message) + } + + override fun trace(t: Throwable?) { + fileLogger?.trace(t) + } +} \ No newline at end of file