KT-54959 Add worker execution time to task action execution time

2022-11-18 12:31:23 +01:00
parent d6bbab7eff
commit 161d8d1cea
13 changed files with 187 additions and 95 deletions
@@ -15,6 +15,7 @@ import org.gradle.workers.WorkParameters
 import org.gradle.workers.WorkQueue
 import org.gradle.workers.WorkerExecutor
 import org.jetbrains.kotlin.build.report.metrics.BuildMetricsReporter
+import org.jetbrains.kotlin.build.report.metrics.BuildPerformanceMetric
 import org.jetbrains.kotlin.build.report.metrics.BuildTime
 import org.jetbrains.kotlin.build.report.metrics.measure
 import org.jetbrains.kotlin.gradle.tasks.*
@@ -36,6 +37,7 @@ internal class GradleCompilerRunnerWithWorkers(
        taskOutputsBackup: TaskOutputsBackup?
    ): WorkQueue {

+        buildMetrics.addTimeMetric(BuildPerformanceMetric.CALL_WORKER)
        val workQueue = workerExecutor.noIsolation()
        workQueue.submit(GradleKotlinCompilerWorkAction::class.java) { params ->
            params.compilerWorkArguments.set(workArgs)
@@ -12,6 +12,7 @@ import org.gradle.api.tasks.bundling.AbstractArchiveTask
 import org.gradle.jvm.tasks.Jar
 import org.gradle.workers.WorkQueue
 import org.jetbrains.kotlin.build.report.metrics.BuildMetricsReporter
+import org.jetbrains.kotlin.build.report.metrics.BuildPerformanceMetric
 import org.jetbrains.kotlin.build.report.metrics.BuildTime
 import org.jetbrains.kotlin.build.report.metrics.measure
 import org.jetbrains.kotlin.cli.common.arguments.*
@@ -220,6 +221,7 @@ internal open class GradleCompilerRunner(
        taskOutputsBackup: TaskOutputsBackup?
    ): WorkQueue? {
        try {
+            buildMetrics.addTimeMetric(BuildPerformanceMetric.CALL_WORKER)
            val kotlinCompilerRunnable = GradleKotlinCompilerWork(workArgs)
            kotlinCompilerRunnable.run()
        } catch (e: FailedCompilationException) {
@@ -124,6 +124,8 @@ internal class GradleKotlinCompilerWork @Inject constructor(
        get() = incrementalCompilationEnvironment != null

    override fun run() {
+        metrics.addTimeMetric(BuildPerformanceMetric.START_WORKER_EXECUTION)
+        metrics.startMeasure(BuildTime.RUN_COMPILATION_IN_WORKER)
        try {
            val gradlePrintingMessageCollector = GradlePrintingMessageCollector(log, allWarningsAsErrors)
            val gradleMessageCollector = GradleErrorMessageCollector(gradlePrintingMessageCollector, kotlinPluginVersion = kotlinPluginVersion)
@@ -141,6 +143,7 @@ internal class GradleKotlinCompilerWork @Inject constructor(
                withAbiSnapshot = incrementalCompilationEnvironment?.withAbiSnapshot,
                withArtifactTransform = incrementalCompilationEnvironment?.classpathChanges is ClasspathChanges.ClasspathSnapshotEnabled
            )
+            metrics.endMeasure(BuildTime.RUN_COMPILATION_IN_WORKER)
            val result = TaskExecutionResult(buildMetrics = metrics.getMetrics(), icLogLines = icLogLines, taskInfo = taskInfo)
            TaskExecutionResults[taskPath] = result
        }
@@ -297,6 +300,7 @@ internal class GradleKotlinCompilerWork @Inject constructor(
        log.info("Options for KOTLIN DAEMON: $compilationOptions")
        val servicesFacade = GradleIncrementalCompilerServicesFacadeImpl(log, bufferingMessageCollector)
        val compilationResults = GradleCompilationResults(log, projectRootFile)
+        metrics.addTimeMetric(BuildPerformanceMetric.CALL_KOTLIN_DAEMON)
        return metrics.measure(BuildTime.RUN_COMPILATION) {
            daemon.compile(sessionId, compilerArgs, compilationOptions, servicesFacade, compilationResults)
        }.also {
@@ -17,7 +17,7 @@ import org.gradle.api.services.BuildServiceParameters
 import org.gradle.tooling.events.FinishEvent
 import org.gradle.tooling.events.OperationCompletionListener
 import org.gradle.tooling.events.task.TaskFinishEvent
-import org.jetbrains.kotlin.build.report.metrics.SizeMetricType
+import org.jetbrains.kotlin.build.report.metrics.ValueType
 import org.jetbrains.kotlin.gradle.plugin.BuildEventsListenerRegistryHolder
 import org.jetbrains.kotlin.gradle.plugin.getKotlinPluginVersion
 import org.jetbrains.kotlin.gradle.plugin.stat.BuildFinishStatisticsData
@@ -121,7 +121,7 @@ abstract class BuildReportsService : BuildService<BuildReportsService.Parameters
                .includeVerboseEnvironment(parameters.reportingSettings.get().httpReportSettings?.verboseEnvironment ?: false),
            buildUuid = buildUuid,
            label = parameters.label.orNull,
-            totalTime = (System.nanoTime() - startTime) / 1_000_000,
+            totalTime = TimeUnit.NANOSECONDS.toMillis((System.nanoTime() - startTime)),
            finishTime = System.currentTimeMillis(),
            hostName = hostName,
            tags = tags.toList(),
@@ -249,13 +249,14 @@ abstract class BuildReportsService : BuildService<BuildReportsService.Parameters
            data.buildTimesMetrics.map { (key, value) -> "${key.readableString}: ${value}ms" } //sometimes it is better to have separate variable to be able debug
        val perfData = data.performanceMetrics.map { (key, value) ->
            when (key.type) {
-                SizeMetricType.BYTES -> "${key.readableString}: ${formatSize(value)}"
+                ValueType.BYTES -> "${key.readableString}: ${formatSize(value)}"
+                ValueType.MILLISECONDS -> DATE_FORMATTER.format(value)
                else -> "${key.readableString}: $value}"
            }
        }
        timeData.union(perfData).joinTo(readableString, ",", "Performance: [", "]")

-        return splitStringIfNeed(readableString.toString(), lengthLimit)
+        return splitStringIfNeed(readableString.toString(), CUSTOM_VALUE_LENGTH_LIMIT)
    }

    private fun splitStringIfNeed(str: String, lengthLimit: Int): List<String> {
@@ -287,7 +288,8 @@ abstract class BuildReportsService : BuildService<BuildReportsService.Parameters

    companion object {

-        const val lengthLimit = 100_000
+        const val CUSTOM_VALUE_LENGTH_LIMIT = 100_000
+        private val DATE_FORMATTER = SimpleDateFormat("yyyy-MM-dd'T'HH:mm:ss")

        fun getStartParameters(project: Project) = project.gradle.startParameter.let {
            GradleBuildStartParameters(
@@ -144,8 +144,8 @@ internal class PlainTextBuildReportWriter(

        repeat(indentLevel) { p.pushIndent() }
        when (sizeMetric.type) {
-            SizeMetricType.BYTES -> p.println("${sizeMetric.readableString}: ${formatSize(value)}")
-            SizeMetricType.NUMBER -> p.println("${sizeMetric.readableString}: $value")
+            ValueType.BYTES -> p.println("${sizeMetric.readableString}: ${formatSize(value)}")
+            ValueType.NUMBER -> p.println("${sizeMetric.readableString}: $value")
        }
        repeat(indentLevel) { p.popIndent() }
    }
@@ -9,7 +9,7 @@ import org.gradle.tooling.events.task.TaskFailureResult
 import org.gradle.tooling.events.task.TaskFinishEvent
 import org.gradle.tooling.events.task.TaskSkippedResult
 import org.gradle.tooling.events.task.TaskSuccessResult
-import org.jetbrains.kotlin.build.report.metrics.BuildMetrics
+import org.jetbrains.kotlin.build.report.metrics.*
 import org.jetbrains.kotlin.gradle.plugin.internal.state.TaskExecutionResults
 import org.jetbrains.kotlin.gradle.plugin.stat.CompileStatisticsData
 import org.jetbrains.kotlin.gradle.plugin.stat.StatTag
@@ -18,6 +18,7 @@ import org.jetbrains.kotlin.incremental.ChangedFiles
 import org.jetbrains.kotlin.utils.addToStdlib.ifTrue
 import java.lang.management.ManagementFactory
 import java.util.ArrayList
+import java.util.concurrent.TimeUnit


 private fun availableForStat(taskPath: String): Boolean {
@@ -51,10 +52,13 @@ internal fun prepareData(
    if (!availableForStat(taskPath)) {
        return null
    }
-    val buildMetrics = buildOperationRecords.firstOrNull { it.path == taskPath }?.buildMetrics
    val taskExecutionResult = TaskExecutionResults[taskPath]
-    val buildTimesMs = buildMetrics?.buildTimes?.asMapMs()?.filterValues { value -> value != 0L } ?: emptyMap()
-    val perfData = buildMetrics?.buildPerformanceMetrics?.asMap()?.filterValues { value -> value != 0L } ?: emptyMap()
+    val buildMetrics = buildOperationRecords.firstOrNull { it.path == taskPath }?.buildMetrics
+
+    val performanceMetrics = collectBuildPerformanceMetrics(taskExecutionResult, buildMetrics)
+    val buildTimesMetrics = collectBuildMetrics(taskExecutionResult, buildMetrics, performanceMetrics, result.startTime, System.currentTimeMillis())
+    val buildAttributes = collectBuildAttributes(taskExecutionResult, buildMetrics)
+
    val changes = when (val changedFiles = taskExecutionResult?.taskInfo?.changedFiles) {
        is ChangedFiles.Known -> changedFiles.modified.map { it.absolutePath } + changedFiles.removed.map { it.absolutePath }
        else -> emptyList<String>()
@@ -63,14 +67,13 @@ internal fun prepareData(
        durationMs = durationMs,
        taskResult = taskResult.name,
        label = label,
-        buildTimesMetrics = buildTimesMs,
-        performanceMetrics = perfData,
+        buildTimesMetrics = buildTimesMetrics,
+        performanceMetrics = performanceMetrics,
        projectName = projectName,
        taskName = taskPath,
        changes = changes,
-        tags = parseTags(taskExecutionResult, buildMetrics, additionalTags).map { it.name },
-        nonIncrementalAttributes = buildMetrics?.buildAttributes?.asMap()?.filter { it.value > 0 }?.keys
-            ?: emptySet(),
+        tags = collectTags(taskExecutionResult, buildMetrics, additionalTags).map { it.name },
+        nonIncrementalAttributes = collectBuildAttributes(taskExecutionResult, buildMetrics),
        hostName = BuildReportsService.hostName,
        kotlinVersion = kotlinVersion,
        buildUuid = uuid,
@@ -79,9 +82,61 @@ internal fun prepareData(
    )
 }

-private fun parseTags(taskExecutionResult: TaskExecutionResult?, buildMetrics: BuildMetrics?, additionalTags: List<StatTag>): List<StatTag> {
-    val tags = parseTags(taskExecutionResult, additionalTags)
-    val nonIncrementalAttributes = buildMetrics?.buildAttributes?.asMap() ?: emptyMap()
+private fun collectBuildAttributes(taskExecutionResult: TaskExecutionResult?, buildMetrics: BuildMetrics?): Set<BuildAttribute> {
+    val attributes = HashSet<BuildAttribute>()
+    buildMetrics?.buildAttributes?.asMap()?.filter { it.value > 0 }?.keys?.also { attributes.addAll(it) }
+    taskExecutionResult?.buildMetrics?.buildAttributes?.asMap()?.filter { it.value > 0 }?.keys?.also { attributes.addAll(it) }
+    return attributes
+}
+
+
+private fun collectBuildPerformanceMetrics(
+    taskExecutionResult: TaskExecutionResult?,
+    buildMetrics: BuildMetrics?,
+): Map<BuildPerformanceMetric, Long> {
+    val taskBuildPerformanceMetrics = HashMap<BuildPerformanceMetric, Long>()
+    taskExecutionResult?.buildMetrics?.buildPerformanceMetrics?.asMap()?.let { taskBuildPerformanceMetrics.putAll(it) }
+    buildMetrics?.buildPerformanceMetrics?.asMap()?.let { taskBuildPerformanceMetrics.putAll(it) }
+    taskBuildPerformanceMetrics.filterValues { value -> value != 0L }
+    return taskBuildPerformanceMetrics
+}
+private fun collectBuildMetrics(
+    taskExecutionResult: TaskExecutionResult?,
+    buildMetrics: BuildMetrics?,
+    performanceMetrics: Map<BuildPerformanceMetric, Long>,
+    gradleTaskStartTime: Long? = null,
+    taskFinishEventTime: Long? = null,
+): Map<BuildTime, Long> {
+    val taskBuildMetrics = HashMap<BuildTime, Long>()
+    taskExecutionResult?.buildMetrics?.buildTimes?.asMapMs()?.let { taskBuildMetrics.putAll(it) }
+    buildMetrics?.buildTimes?.asMapMs()?.let { taskBuildMetrics.putAll(it) }
+    gradleTaskStartTime?.let { startTime ->
+        performanceMetrics[BuildPerformanceMetric.START_TASK_ACTION_EXECUTION]?.let { actionStartTime ->
+            taskBuildMetrics.put(BuildTime.GRADLE_TASK_PREPARATION, actionStartTime - startTime)
+        }
+    }
+    taskFinishEventTime?.let { listenerNotificationTime ->
+        performanceMetrics[BuildPerformanceMetric.FINISH_KOTLIN_DAEMON_EXECUTION]?.let { daemonFinishTime ->
+            taskBuildMetrics.put(BuildTime.TASK_FINISH_LISTENER_NOTIFICATION, listenerNotificationTime - daemonFinishTime)
+        }
+    }
+    performanceMetrics[BuildPerformanceMetric.CALL_WORKER]?.let { callWorkerTime ->
+        performanceMetrics[BuildPerformanceMetric.START_WORKER_EXECUTION]?.let { startWorkerExecutionTime ->
+            taskBuildMetrics.put(BuildTime.RUN_WORKER_DELAY, TimeUnit.NANOSECONDS.toMillis(startWorkerExecutionTime - callWorkerTime))
+        }
+
+    }
+    taskBuildMetrics.filterValues { value -> value != 0L }
+    return taskBuildMetrics
+}
+
+private fun collectTags(
+    taskExecutionResult: TaskExecutionResult?,
+    buildMetrics: BuildMetrics?,
+    additionalTags: List<StatTag>
+): List<StatTag> {
+    val tags = collectTags(taskExecutionResult, additionalTags)
+    val nonIncrementalAttributes = collectBuildAttributes(taskExecutionResult, buildMetrics)
    if (nonIncrementalAttributes.isEmpty()) {
        tags.add(StatTag.INCREMENTAL)
    } else {
@@ -90,7 +145,7 @@ private fun parseTags(taskExecutionResult: TaskExecutionResult?, buildMetrics: B
    return tags
 }

-private fun parseTags(
+private fun collectTags(
    taskExecutionResult: TaskExecutionResult?,
    additionalTags: List<StatTag>,
 ): MutableList<StatTag>{
@@ -388,7 +388,8 @@ abstract class AbstractKotlinCompile<T : CommonCompilerArguments> @Inject constr
    @TaskAction
    fun execute(inputChanges: InputChanges) {
        val buildMetrics = metrics.get()
-        buildMetrics.measure(BuildTime.GRADLE_TASK_ACTION) {
+        buildMetrics.addTimeMetric(BuildPerformanceMetric.START_TASK_ACTION_EXECUTION)
+        buildMetrics.measure(BuildTime.OUT_OF_WORKER_TASK_ACTION) {
            KotlinBuildStatsService.applyIfInitialised {
                if (name.contains("Test"))
                    it.report(BooleanMetrics.TESTS_EXECUTED, true)