KT-45777: Track build time in nanoseconds instead of milliseconds

to ensure precision (otherwise, rounding errors to milliseconds may add up and cause unexplainable gaps in the running time). We can still use milliseconds in the final report after all the precise sub-build-times have been aggregated.
2022-01-24 09:57:56 +00:00
parent 52a21a4e1a
commit 37c6b1c2dc
14 changed files with 60 additions and 74 deletions
@@ -6,26 +6,24 @@
 package org.jetbrains.kotlin.build.report.metrics

 interface BuildMetricsReporter {
-    fun startMeasure(time: BuildTime, startNs: Long)
-    fun endMeasure(time: BuildTime, endNs: Long)
-    fun addTimeMetric(time: BuildTime, durationMs: Long)
+    fun startMeasure(time: BuildTime)
+    fun endMeasure(time: BuildTime)
+    fun addTimeMetricNs(time: BuildTime, durationNs: Long)
+    fun addTimeMetricMs(time: BuildTime, durationMs: Long) = addTimeMetricNs(time, durationMs * 1_000_000)

    fun addMetric(metric: BuildPerformanceMetric, value: Long)

    fun addAttribute(attribute: BuildAttribute)

    fun getMetrics(): BuildMetrics
-    fun addMetrics(metrics: BuildMetrics?)
+    fun addMetrics(metrics: BuildMetrics)
 }

 inline fun <T> BuildMetricsReporter.measure(time: BuildTime, fn: () -> T): T {
-    val start = System.nanoTime()
-    startMeasure(time, start)
-
+    startMeasure(time)
    try {
        return fn()
    } finally {
-        val end = System.nanoTime()
-        endMeasure(time, end)
+        endMeasure(time)
    }
 }
@@ -17,21 +17,21 @@ class BuildMetricsReporterImpl : BuildMetricsReporter, Serializable {
    private val myBuildMetrics = BuildPerformanceMetrics()
    private val myBuildAttributes = BuildAttributes()

-    override fun startMeasure(time: BuildTime, startNs: Long) {
+    override fun startMeasure(time: BuildTime) {
        if (time in myBuildTimeStartNs) {
            error("$time was restarted before it finished")
        }
-        myBuildTimeStartNs[time] = startNs
+        myBuildTimeStartNs[time] = System.nanoTime()
    }

-    override fun endMeasure(time: BuildTime, endNs: Long) {
+    override fun endMeasure(time: BuildTime) {
        val startNs = myBuildTimeStartNs.remove(time) ?: error("$time finished before it started")
-        val durationMs = (endNs - startNs) / 1_000_000
-        myBuildTimes.add(time, durationMs)
+        val durationNs = System.nanoTime() - startNs
+        myBuildTimes.addTimeNs(time, durationNs)
    }

-    override fun addTimeMetric(time: BuildTime, durationMs: Long) {
-        myBuildTimes.add(time, durationMs)
+    override fun addTimeMetricNs(time: BuildTime, durationNs: Long) {
+        myBuildTimes.addTimeNs(time, durationNs)
    }

    override fun addMetric(metric: BuildPerformanceMetric, value: Long) {
@@ -49,9 +49,7 @@ class BuildMetricsReporterImpl : BuildMetricsReporter, Serializable {
            buildAttributes = myBuildAttributes
        )

-    override fun addMetrics(metrics: BuildMetrics?) {
-        if (metrics == null) return
-
+    override fun addMetrics(metrics: BuildMetrics) {
        myBuildAttributes.addAll(metrics.buildAttributes)
        myBuildTimes.addAll(metrics.buildTimes)
        myBuildMetrics.addAll(metrics.buildPerformanceMetrics)
@@ -9,19 +9,23 @@ import java.io.Serializable
 import java.util.*

 class BuildTimes : Serializable {
-    private val myBuildTimes = EnumMap<BuildTime, Long>(BuildTime::class.java)
+    private val buildTimesNs = EnumMap<BuildTime, Long>(BuildTime::class.java)

    fun addAll(other: BuildTimes) {
-        for ((bt, timeMs) in other.myBuildTimes) {
-            add(bt, timeMs)
+        for ((buildTime, timeNs) in other.buildTimesNs) {
+            addTimeNs(buildTime, timeNs)
        }
    }

-    fun add(buildTime: BuildTime, timeMs: Long) {
-        myBuildTimes[buildTime] = myBuildTimes.getOrDefault(buildTime, 0) + timeMs
+    fun addTimeNs(buildTime: BuildTime, timeNs: Long) {
+        buildTimesNs[buildTime] = buildTimesNs.getOrDefault(buildTime, 0) + timeNs
    }

-    fun asMap(): Map<BuildTime, Long> = myBuildTimes
+    fun addTimeMs(buildTime: BuildTime, timeMs: Long) = addTimeNs(buildTime, timeMs * 1_000_000)
+
+    fun asMapNs(): Map<BuildTime, Long> = buildTimesNs
+
+    fun asMapMs(): Map<BuildTime, Long> = buildTimesNs.mapValues { it.value / 1_000_000 }

    companion object {
        const val serialVersionUID = 0L
@@ -6,13 +6,13 @@
 package org.jetbrains.kotlin.build.report.metrics

 object DoNothingBuildMetricsReporter : BuildMetricsReporter {
-    override fun startMeasure(time: BuildTime, startNs: Long) {
+    override fun startMeasure(time: BuildTime) {
    }

-    override fun endMeasure(time: BuildTime, endNs: Long) {
+    override fun endMeasure(time: BuildTime) {
    }

-    override fun addTimeMetric(time: BuildTime, durationMs: Long) {
+    override fun addTimeMetricNs(time: BuildTime, durationNs: Long) {
    }

    override fun addMetric(metric: BuildPerformanceMetric, value: Long) {
@@ -28,5 +28,5 @@ object DoNothingBuildMetricsReporter : BuildMetricsReporter {
            BuildAttributes()
        )

-    override fun addMetrics(metrics: BuildMetrics?) {}
+    override fun addMetrics(metrics: BuildMetrics) {}
 }
@@ -513,9 +513,9 @@ abstract class IncrementalCompilerRunner<
    protected fun reportPerformanceData(defaultPerformanceManager: CommonCompilerPerformanceManager) {
        defaultPerformanceManager.getMeasurementResults().forEach {
            when (it) {
-                is CompilerInitializationMeasurement -> reporter.addTimeMetric(BuildTime.COMPILER_INITIALIZATION, it.milliseconds)
-                is CodeAnalysisMeasurement -> reporter.addTimeMetric(BuildTime.CODE_ANALYSIS, it.milliseconds)
-                is CodeGenerationMeasurement -> reporter.addTimeMetric(BuildTime.CODE_GENERATION, it.milliseconds)
+                is CompilerInitializationMeasurement -> reporter.addTimeMetricMs(BuildTime.COMPILER_INITIALIZATION, it.milliseconds)
+                is CodeAnalysisMeasurement -> reporter.addTimeMetricMs(BuildTime.CODE_ANALYSIS, it.milliseconds)
+                is CodeGenerationMeasurement -> reporter.addTimeMetricMs(BuildTime.CODE_GENERATION, it.milliseconds)
            }
        }
    }
@@ -20,7 +20,7 @@ class GradleBuildMetricsData : Serializable {
 data class TaskData(
    val path: String,
    val typeFqName: String,
-    val timeMetrics: Map<String, Long>,
+    val buildTimesMs: Map<String, Long>,
    val performanceMetrics: Map<String, Long>,
    val buildAttributes: Map<String, Int>,
    val didWork: Boolean
@@ -3,11 +3,7 @@ package org.jetbrains.kotlin.compilerRunner
 import org.jetbrains.kotlin.build.report.metrics.BuildMetrics
 import org.jetbrains.kotlin.build.report.metrics.BuildMetricsReporterImpl
 import org.jetbrains.kotlin.build.report.metrics.BuildPerformanceMetric
-import org.jetbrains.kotlin.daemon.common.CompilationResultCategory
-import org.jetbrains.kotlin.daemon.common.CompilationResults
-import org.jetbrains.kotlin.daemon.common.LoopbackNetworkInterface
-import org.jetbrains.kotlin.daemon.common.SOCKET_ANY_FREE_PORT
-import org.jetbrains.kotlin.daemon.common.CompileIterationResult
+import org.jetbrains.kotlin.daemon.common.*
 import org.jetbrains.kotlin.gradle.logging.kotlinDebug
 import org.jetbrains.kotlin.gradle.utils.pathsAsStringRelativeTo
 import java.io.File
@@ -52,7 +48,7 @@ internal class GradleCompilationResults(
                (value as? List<String>)?.let { icLogLines = it }
            }
            CompilationResultCategory.BUILD_METRICS.code -> {
-                buildMetricsReporter.addMetrics(value as? BuildMetrics)
+                (value as? BuildMetrics)?.let { buildMetricsReporter.addMetrics(it) }
            }
        }
    }
@@ -18,9 +18,7 @@ import org.jetbrains.kotlin.gradle.logging.*
 import org.jetbrains.kotlin.gradle.plugin.internal.state.TaskExecutionResults
 import org.jetbrains.kotlin.gradle.plugin.internal.state.TaskLoggers
 import org.jetbrains.kotlin.gradle.report.*
-import org.jetbrains.kotlin.gradle.report.TaskExecutionInfo
 import org.jetbrains.kotlin.gradle.report.TaskExecutionProperties.ABI_SNAPSHOT
-import org.jetbrains.kotlin.gradle.report.TaskExecutionResult
 import org.jetbrains.kotlin.gradle.tasks.KotlinCompilerExecutionStrategy
 import org.jetbrains.kotlin.gradle.tasks.cleanOutputsAndLocalState
 import org.jetbrains.kotlin.gradle.tasks.throwGradleExceptionIfError
@@ -35,7 +33,6 @@ import java.util.*
 import java.util.concurrent.Callable
 import java.util.concurrent.Executors
 import javax.inject.Inject
-import kotlin.collections.ArrayList

 internal class ProjectFilesForCompilation(
    val projectRootFile: File,
@@ -324,7 +321,7 @@ internal class GradleKotlinCompilerWork @Inject constructor(
        metrics.addAttribute(BuildAttribute.IN_PROCESS_EXECUTION)
        cleanOutputsAndLocalState(outputFiles, log, metrics, reason = "in-process execution strategy is non-incremental")

-        metrics.startMeasure(BuildTime.NON_INCREMENTAL_COMPILATION_IN_PROCESS, System.nanoTime())
+        metrics.startMeasure(BuildTime.NON_INCREMENTAL_COMPILATION_IN_PROCESS)
        // in-process compiler should always be run in a different thread
        // to avoid leaking thread locals from compiler (see KT-28037)
        val threadPool = Executors.newSingleThreadExecutor()
@@ -338,7 +335,7 @@ internal class GradleKotlinCompilerWork @Inject constructor(
            bufferingMessageCollector.flush(messageCollector)
            threadPool.shutdown()

-            metrics.endMeasure(BuildTime.NON_INCREMENTAL_COMPILATION_IN_PROCESS, System.nanoTime())
+            metrics.endMeasure(BuildTime.NON_INCREMENTAL_COMPILATION_IN_PROCESS)
        }
    }

@@ -59,7 +59,7 @@ class KotlinBuildStatListener(val projectName: String, val reportStatistics: Lis
            if (event is TaskFinishEvent) {
                val result = event.result
                val taskPath = event.descriptor.taskPath
-                val duration = result.endTime - result.startTime
+                val durationMs = result.endTime - result.startTime
                val taskResult = when (result) {
                    is TaskSuccessResult -> when {
                        result.isFromCache -> TaskExecutionState.FROM_CACHE
@@ -72,7 +72,7 @@ class KotlinBuildStatListener(val projectName: String, val reportStatistics: Lis
                    else -> TaskExecutionState.UNKNOWN
                }

-                reportData(taskPath, duration, taskResult)
+                reportData(taskPath, durationMs, taskResult)
            }
        }
        if (measuredTimeMs > LIMIT_DURATION_MS) {
@@ -80,15 +80,16 @@ class KotlinBuildStatListener(val projectName: String, val reportStatistics: Lis
        }
    }

-    private fun reportData(taskPath: String, duration: Long, taskResult: TaskExecutionState) {
+    private fun reportData(taskPath: String, durationMs: Long, taskResult: TaskExecutionState) {
        val (reportDataDuration, compileStatData) = measureTimeMillisWithResult {
            if (!availableForStat(taskPath)) {
                return
            }

            val taskExecutionResult = TaskExecutionResults[taskPath]
-            val timeData = taskExecutionResult?.buildMetrics?.buildTimes?.asMap()?.filterValues { value -> value != 0L } ?: emptyMap()
-            val perfData = taskExecutionResult?.buildMetrics?.buildPerformanceMetrics?.asMap()?.filterValues { value -> value != 0L } ?: emptyMap()
+            val buildTimesMs = taskExecutionResult?.buildMetrics?.buildTimes?.asMapMs()?.filterValues { value -> value != 0L } ?: emptyMap()
+            val perfData =
+                taskExecutionResult?.buildMetrics?.buildPerformanceMetrics?.asMap()?.filterValues { value -> value != 0L } ?: emptyMap()
            val changes = when (val changedFiles = taskExecutionResult?.taskInfo?.changedFiles) {
                is ChangedFiles.Known -> changedFiles.modified.map { it.absolutePath } + changedFiles.removed.map { it.absolutePath }
                is ChangedFiles.Dependencies -> changedFiles.modified.map { it.absolutePath } + changedFiles.removed.map { it.absolutePath }
@@ -96,8 +97,8 @@ class KotlinBuildStatListener(val projectName: String, val reportStatistics: Lis

            }
            val compileStatData = CompileStatData(
-                duration = duration, taskResult = taskResult.name, label = label,
-                timeData = timeData, perfData = perfData, projectName = projectName, taskName = taskPath, changes = changes,
+                durationMs = durationMs, taskResult = taskResult.name, label = label,
+                buildTimesMs = buildTimesMs, perfData = perfData, projectName = projectName, taskName = taskPath, changes = changes,
                tags = taskExecutionResult?.taskInfo?.properties?.map { it.name } ?: emptyList(),
                nonIncrementalAttributes = taskExecutionResult?.buildMetrics?.buildAttributes?.asMap() ?: emptyMap(),
                hostName = hostName, kotlinVersion = "1.6", buildUuid = buildUuid, timeInMillis = System.currentTimeMillis()
@@ -16,7 +16,7 @@ data class CompileStatData(
    val label: String?,
    val taskName: String?,
    val taskResult: String,
-    val duration: Long,
+    val durationMs: Long,
    val tags: List<String>,
    val changes: List<String>,
    val buildUuid: String = "Unset",
@@ -25,7 +25,7 @@ data class CompileStatData(
    val timeInMillis: Long,
    val timestamp: String = formatter.format(timeInMillis),
    val nonIncrementalAttributes: Map<BuildAttribute, Int>,
-    val timeData: Map<BuildTime, Long>,
+    val buildTimesMs: Map<BuildTime, Long>,
    val perfData: Map<BuildPerformanceMetric, Long>
 ) {
    companion object {
@@ -50,8 +50,9 @@ class ReportStatisticsToBuildScan(
        }
        data.changes.joinTo(readableString, prefix = "Changes: [", postfix = "]; ") { it.substringAfterLast(File.separator) }

-        val timeData = data.timeData.map { (key, value) -> "${key.readableString}: ${value}ms"} //sometimes it is better to have separate variable to be able debug
-        val perfData = data.perfData.map { (key, value) -> "${key.readableString}: ${readableFileLength(value)}"}
+        val timeData =
+            data.buildTimesMs.map { (key, value) -> "${key.readableString}: ${value}ms" } //sometimes it is better to have separate variable to be able debug
+        val perfData = data.perfData.map { (key, value) -> "${key.readableString}: ${readableFileLength(value)}" }
        timeData.union(perfData).joinTo(readableString, ",", "Performance: [", "]")

        return splitStringIfNeed(readableString.toString(), lengthLimit)
@@ -24,10 +24,8 @@ import org.jetbrains.kotlin.gradle.plugin.internal.state.TaskExecutionResults
 import org.jetbrains.kotlin.gradle.report.data.BuildExecutionData
 import org.jetbrains.kotlin.gradle.report.data.BuildExecutionDataProcessor
 import org.jetbrains.kotlin.gradle.report.data.TaskExecutionData
-import org.jetbrains.kotlin.gradle.tasks.AbstractKotlinCompile
 import java.util.concurrent.ConcurrentHashMap
 import java.util.concurrent.ConcurrentLinkedQueue
-import kotlin.collections.ArrayList

 abstract class BuildMetricsReporterService : BuildService<BuildMetricsReporterService.Parameters>,
    OperationCompletionListener, AutoCloseable {
@@ -69,7 +67,7 @@ abstract class BuildMetricsReporterService : BuildService<BuildMetricsReporterSe
            }
            val didWork = result is TaskExecutionResult
            val buildMetrics = BuildMetrics()
-            buildMetrics.buildTimes.add(BuildTime.GRADLE_TASK, finishMs - startMs)
+            buildMetrics.buildTimes.addTimeMs(BuildTime.GRADLE_TASK, finishMs - startMs)

            buildMetricsMap[taskPath]?.also { buildMetrics.addAll(it.getMetrics()) }
            val taskExecutionResult = TaskExecutionResults[taskPath]
@@ -35,18 +35,13 @@ internal class MetricsWriter(
            }

            for (data in build.taskExecutionData) {
-                val path = data.taskPath
-                val type = data.type
-                val buildTimes = data.buildMetrics.buildTimes.asMap().mapKeys { (k, _) -> k.name }
-                val buildPerfMetrics = data.buildMetrics.buildPerformanceMetrics.asMap().mapKeys { (k, _) -> k.name }
-                val buildAttributes = data.buildMetrics.buildAttributes.asMap().mapKeys { (k, _) -> k.name }
-                buildMetricsData.taskData[path] =
+                buildMetricsData.taskData[data.taskPath] =
                    TaskData(
-                        path = path,
-                        typeFqName = type,
-                        timeMetrics = buildTimes,
-                        performanceMetrics = buildPerfMetrics,
-                        buildAttributes = buildAttributes,
+                        path = data.taskPath,
+                        typeFqName = data.type,
+                        buildTimesMs = data.buildMetrics.buildTimes.asMapMs().mapKeys { it.key.name },
+                        performanceMetrics = data.buildMetrics.buildPerformanceMetrics.asMap().mapKeys { it.key.name },
+                        buildAttributes = data.buildMetrics.buildAttributes.asMap().mapKeys { it.key.name },
                        didWork = data.didWork
                    )
            }
@@ -15,8 +15,6 @@ import java.io.File
 import java.io.Serializable
 import java.text.SimpleDateFormat
 import java.util.*
-import kotlin.collections.ArrayList
-import kotlin.collections.HashSet
 import kotlin.math.max

 internal class PlainTextBuildReportWriterDataProcessor(
@@ -88,9 +86,9 @@ internal class PlainTextBuildReportWriter(
    }

    private fun printBuildTimes(buildTimes: BuildTimes) {
-        val collectedBuildTimes = buildTimes.asMap()
+        val buildTimesMs = buildTimes.asMapMs()

-        if (collectedBuildTimes.isEmpty()) return
+        if (buildTimesMs.isEmpty()) return

        p.println("Time metrics:")
        p.withIndent {
@@ -98,7 +96,7 @@ internal class PlainTextBuildReportWriter(
            fun printBuildTime(buildTime: BuildTime) {
                if (!visitedBuildTimes.add(buildTime)) return

-                val timeMs = collectedBuildTimes[buildTime]
+                val timeMs = buildTimesMs[buildTime]
                if (timeMs != null) {
                    p.println("${buildTime.name}: ${formatTime(timeMs)}")
                    p.withIndent {