feat: Add printing total run duration (#1773)

Flank · Apr 8, 2021 · 3a21357 · 3a21357
1 parent 18a682f
commit 3a21357
Show file tree

Hide file tree

Showing 14 changed files with 159 additions and 44 deletions.
diff --git a/test_runner/src/main/kotlin/ftl/Main.kt b/test_runner/src/main/kotlin/ftl/Main.kt
@@ -2,11 +2,13 @@
 package ftl
 
 import ftl.presentation.cli.MainCommand
+import ftl.reports.startDurationMeasurement
 import ftl.run.exception.withGlobalExceptionHandling
 import picocli.CommandLine
 
 fun main(args: Array<String>) {
     withGlobalExceptionHandling {
+        startDurationMeasurement()
         CommandLine(MainCommand()).execute(*args)
     }
 }
diff --git a/test_runner/src/main/kotlin/ftl/domain/RunTestAndroid.kt b/test_runner/src/main/kotlin/ftl/domain/RunTestAndroid.kt
@@ -10,13 +10,15 @@ import ftl.config.defaultAndroidConfig
 import ftl.config.loadAndroidConfig
 import ftl.config.plus
 import ftl.mock.MockServer
+import ftl.reports.addStepTime
 import ftl.reports.output.configure
 import ftl.reports.output.log
 import ftl.reports.output.outputReport
 import ftl.reports.output.toOutputReportConfiguration
 import ftl.run.dumpShards
 import ftl.run.newTestRun
 import ftl.util.DEVICE_SYSTEM
+import ftl.util.StopWatch
 import ftl.util.TEST_TYPE
 import ftl.util.loadFile
 import ftl.util.printVersionInfo
@@ -38,7 +40,7 @@ operator fun RunTestAndroid.invoke() {
     if (dryRun) {
         MockServer.start()
     }
-
+    val prepareStopWatch = StopWatch().start()
     createAndroidArgs(
         config = defaultAndroidConfig() +
             loadAndroidConfig(reader = loadFile(Paths.get(configPath))) +
@@ -60,6 +62,7 @@ operator fun RunTestAndroid.invoke() {
                 args.dumpShards()
             else {
                 logLn(args)
+                addStepTime("Preparation", prepareStopWatch.check())
                 args.newTestRun()
             }
         }

diff --git a/test_runner/src/main/kotlin/ftl/domain/RunTestIos.kt b/test_runner/src/main/kotlin/ftl/domain/RunTestIos.kt
@@ -10,13 +10,15 @@ import ftl.config.defaultIosConfig
 import ftl.config.loadIosConfig
 import ftl.config.plus
 import ftl.mock.MockServer
+import ftl.reports.addStepTime
 import ftl.reports.output.configure
 import ftl.reports.output.log
 import ftl.reports.output.outputReport
 import ftl.reports.output.toOutputReportConfiguration
 import ftl.run.dumpShards
 import ftl.run.newTestRun
 import ftl.util.DEVICE_SYSTEM
+import ftl.util.StopWatch
 import ftl.util.TEST_TYPE
 import ftl.util.loadFile
 import ftl.util.printVersionInfo
@@ -39,6 +41,7 @@ operator fun RunIosTest.invoke() {
         MockServer.start()
     }
 
+    val prepareStopWatch = StopWatch().start()
     createIosArgs(
         config = defaultIosConfig() +
             loadIosConfig(reader = loadFile(Paths.get(configPath))) +
@@ -56,6 +59,9 @@ operator fun RunIosTest.invoke() {
         if (dumpShards.not()) logLn(this)
     }.validate().run {
         if (dumpShards) dumpShards()
-        else runBlocking { newTestRun() }
+        else runBlocking {
+            addStepTime("Preparation", prepareStopWatch.check())
+            newTestRun()
+        }
     }
 }
diff --git a/test_runner/src/main/kotlin/ftl/reports/DurationReport.kt b/test_runner/src/main/kotlin/ftl/reports/DurationReport.kt
@@ -0,0 +1,38 @@
+package ftl.reports
+
+import flank.common.OutputLogLevel
+import flank.common.logLn
+import ftl.util.Duration
+import ftl.util.StopWatch
+import ftl.util.formatted
+
+val totalDurationStopWatch by lazy { StopWatch() }
+
+private val stepsTimes = mutableListOf<StepRunDuration>()
+
+data class StepRunDuration(
+    val name: String,
+    val duration: Duration
+)
+
+fun startDurationMeasurement() {
+    totalDurationStopWatch.start()
+}
+
+fun addStepTime(name: String, duration: Duration) {
+    stepsTimes.add(StepRunDuration(name, duration))
+}
+
+fun printTotalDuration() {
+    logLn(level = OutputLogLevel.DETAILED)
+    logLn(
+        "Total run duration: ${totalDurationStopWatch.check().formatted(alignSeconds = true)}",
+        level = OutputLogLevel.DETAILED
+    )
+    stepsTimes.forEach { stepRunDuration ->
+        logLn(
+            "\t- ${stepRunDuration.name}: ${stepRunDuration.duration.formatted()}",
+            level = OutputLogLevel.DETAILED
+        )
+    }
+}
diff --git a/test_runner/src/main/kotlin/ftl/run/NewTestRun.kt b/test_runner/src/main/kotlin/ftl/run/NewTestRun.kt
@@ -6,6 +6,7 @@ import ftl.args.IosArgs
 import ftl.json.SavedMatrix
 import ftl.json.updateMatrixMap
 import ftl.json.validate
+import ftl.reports.addStepTime
 import ftl.reports.output.log
 import ftl.reports.output.outputReport
 import ftl.reports.util.ReportManager
@@ -17,6 +18,7 @@ import ftl.run.model.TestResult
 import ftl.run.platform.common.printMatricesWebLinks
 import ftl.run.platform.runAndroidTests
 import ftl.run.platform.runIosTests
+import ftl.util.measureTime
 import kotlinx.coroutines.TimeoutCancellationException
 import kotlinx.coroutines.withTimeoutOrNull
 
@@ -32,12 +34,17 @@ suspend fun IArgs.newTestRun() = withTimeoutOrNull(parsedTimeout) {
                 matrixMap
             )
         }
-        ReportManager.generate(matrixMap, args, testShardChunks, ignoredTests)
-        cancelTestsOnTimeout(args.project, matrixMap.map) { fetchArtifacts(matrixMap, args) }
 
-        matrixMap.printMatricesWebLinks(project)
-        outputReport.log(matrixMap)
-        matrixMap.validate(ignoreFailedTests)
+        val duration = measureTime {
+            ReportManager.generate(matrixMap, args, testShardChunks, ignoredTests)
+            cancelTestsOnTimeout(args.project, matrixMap.map) { fetchArtifacts(matrixMap, args) }
+
+            matrixMap.printMatricesWebLinks(project)
+            outputReport.log(matrixMap)
+            matrixMap.validate(ignoreFailedTests)
+        }
+
+        addStepTime("Generating reports", duration)
     }
 }
 

diff --git a/test_runner/src/main/kotlin/ftl/run/exception/ExceptionHandler.kt b/test_runner/src/main/kotlin/ftl/run/exception/ExceptionHandler.kt
@@ -5,6 +5,7 @@ import ftl.json.SavedMatrix
 import ftl.reports.output.add
 import ftl.reports.output.generate
 import ftl.reports.output.outputReport
+import ftl.reports.printTotalDuration
 import ftl.run.cancelMatrices
 import ftl.util.closeCrashReporter
 import ftl.util.report
@@ -15,6 +16,7 @@ fun withGlobalExceptionHandling(block: () -> Int) {
     withGlobalExceptionHandling(block) {
         closeCrashReporter()
         outputReport.generate()
+        printTotalDuration()
         exitProcess(it)
     }
 }

diff --git a/test_runner/src/main/kotlin/ftl/run/platform/common/AfterRunTests.kt b/test_runner/src/main/kotlin/ftl/run/platform/common/AfterRunTests.kt
@@ -10,9 +10,11 @@ import ftl.gc.GcStorage.uploadSessionId
 import ftl.gc.GcTestMatrix
 import ftl.json.MatrixMap
 import ftl.json.createSavedMatrix
+import ftl.reports.addStepTime
 import ftl.run.common.saveSessionId
 import ftl.run.common.updateMatrixFile
 import ftl.util.StopWatch
+import ftl.util.formatted
 import ftl.util.isInvalid
 import ftl.util.webLink
 import kotlinx.coroutines.Dispatchers
@@ -33,10 +35,11 @@ internal suspend fun IArgs.afterRunTests(
     saveConfigFile(matrixMap)
     saveSessionId()
     uploadSessionId()
-    logLn(FtlConstants.indent + "${matrixMap.map.size} matrix ids created in ${stopwatch.check()}")
+    logLn(FtlConstants.indent + "${matrixMap.map.size} matrix ids created in ${stopwatch.check().formatted()}")
     val gcsBucket = GCS_STORAGE_LINK + resultsBucket + "/" + matrixMap.runPath
     logLn("${FtlConstants.indent}Raw results will be stored in your GCS bucket at [$gcsBucket]")
     matrixMap.printMatricesWebLinks(project)
+    addStepTime("Running tests", stopwatch.check())
 }
 
 private fun List<TestMatrix>.toSavedMatrixMap() =

diff --git a/test_runner/src/main/kotlin/ftl/run/status/TestMatrixStatusPrinter.kt b/test_runner/src/main/kotlin/ftl/run/status/TestMatrixStatusPrinter.kt
@@ -5,8 +5,10 @@ import com.google.testing.model.TestMatrix
 import flank.common.logLn
 import ftl.args.IArgs
 import ftl.config.FtlConstants
+import ftl.reports.addStepTime
 import ftl.util.MatrixState
 import ftl.util.StopWatch
+import ftl.util.formatted
 
 class TestMatrixStatusPrinter(
     private val args: IArgs,
@@ -22,10 +24,13 @@ class TestMatrixStatusPrinter(
     private val allMatricesCompleted get() = cache.values.all(MatrixState::completed)
 
     override fun invoke(matrix: TestMatrix) {
-        val time = stopWatch.check(alignSeconds = true)
-        printExecutionStatusList(time, matrix.testExecutions)
+        val time = stopWatch.check()
+        printExecutionStatusList(time.formatted(alignSeconds = true), matrix.testExecutions)
         cache[matrix.testMatrixId] = matrix.state
-        if (allMatricesCompleted) printTestMatrixStatusList(time)
+        if (allMatricesCompleted) {
+            printTestMatrixStatusList(time.formatted(alignSeconds = true))
+            addStepTime("Executing matrices", time)
+        }
     }
 
     private fun printTestMatrixStatusList(time: String) {

diff --git a/test_runner/src/main/kotlin/ftl/util/StopWatch.kt b/test_runner/src/main/kotlin/ftl/util/StopWatch.kt
@@ -1,7 +1,7 @@
 package ftl.util
 
 import ftl.run.exception.FlankGeneralError
-import java.util.Locale
+import java.util.concurrent.TimeUnit
 import java.util.concurrent.TimeUnit.MILLISECONDS
 
 class StopWatch {
@@ -13,21 +13,31 @@ class StopWatch {
         return this
     }
 
-    fun check(alignSeconds: Boolean = false): String {
+    fun check(): Duration {
         if (startTime == 0L) throw FlankGeneralError("startTime is zero. start not called")
 
-        val duration = System.currentTimeMillis() - startTime
+        return Duration(MILLISECONDS.toSeconds(System.currentTimeMillis() - startTime))
+    }
+}
+
+suspend fun measureTime(block: suspend () -> Unit) = StopWatch().run {
+    start()
+    block()
+    check()
+}
 
-        val minutes = MILLISECONDS.toMinutes(duration)
-        val seconds = MILLISECONDS.toSeconds(duration) % 60
+data class Duration(val seconds: Long)
 
-        // align seconds
-        // 3m  0s
-        // 2m 23s
-        val space = if (alignSeconds && seconds < 10)
-            "  " else
-            " "
+fun Duration.formatted(alignSeconds: Boolean = false): String {
+    val minutes = TimeUnit.SECONDS.toMinutes(seconds)
+    val seconds = seconds % 60
 
-        return String.format(Locale.getDefault(), "%dm$space%ds", minutes, seconds)
-    }
+    // align seconds
+    // 3m  0s
+    // 2m 23s
+    val space = if (alignSeconds && seconds < 10)
+        "  " else
+        " "
+
+    return "${minutes}m$space${seconds}s"
 }
diff --git a/test_runner/src/main/kotlin/ftl/util/StopWatchMatrix.kt b/test_runner/src/main/kotlin/ftl/util/StopWatchMatrix.kt
diff --git a/test_runner/src/test/kotlin/Debug.kt b/test_runner/src/test/kotlin/Debug.kt
@@ -1,6 +1,7 @@
 @file:Suppress("InvalidPackageDeclaration")
 
 import ftl.presentation.cli.MainCommand
+import ftl.reports.startDurationMeasurement
 import ftl.run.exception.withGlobalExceptionHandling
 import ftl.util.disableCrashReporting
 import picocli.CommandLine
@@ -18,6 +19,7 @@ fun main() {
         ?: "YOUR PROJECT ID"
 
     withGlobalExceptionHandling {
+        startDurationMeasurement()
         CommandLine(MainCommand()).execute(
 //            "--debug",
             "firebase",

diff --git a/test_runner/src/test/kotlin/ftl/run/status/TestMatrixStatusPrinterTest.kt b/test_runner/src/test/kotlin/ftl/run/status/TestMatrixStatusPrinterTest.kt
@@ -3,8 +3,10 @@ package ftl.run.status
 import com.google.testing.model.TestExecution
 import com.google.testing.model.TestMatrix
 import ftl.args.IArgs
+import ftl.util.Duration
 import ftl.util.MatrixState
 import ftl.util.StopWatch
+import ftl.util.formatted
 import io.mockk.every
 import io.mockk.mockk
 import io.mockk.verify
@@ -21,7 +23,8 @@ class TestMatrixStatusPrinterTest {
     @Test
     fun test() {
         // given
-        val time = "time"
+        val expectedDuration = Duration(4)
+        val time = expectedDuration.formatted(alignSeconds = true)
         val testMatricesIds = (0..1).map(Int::toString)
         val matrices = testMatricesIds.mapIndexed { index, s ->
             TestMatrix().apply {
@@ -34,7 +37,7 @@ class TestMatrixStatusPrinterTest {
             every { outputStyle } returns OutputStyle.Single
         }
         val stopWatch = mockk<StopWatch>(relaxed = true) {
-            every { check(any()) } returns time
+            every { check() } returns expectedDuration
         }
         val printExecutionStatusList = mockk<(String, List<TestExecution>?) -> Unit>(relaxed = true)
         val printMatrices = TestMatrixStatusPrinter(
@@ -46,16 +49,16 @@ class TestMatrixStatusPrinterTest {
         val expected = listOf(
             "",
             """
-  time 0 FINISHED
-  time 1 FINISHED
+  $time 0 FINISHED
+  $time 1 FINISHED
 """
         )
         // when
         testMatricesIds.forEachIndexed { index, _ ->
             printMatrices(matrices[index])
 
             // then
-            verify { stopWatch.check(true) }
+            verify { stopWatch.check() }
             verify { printExecutionStatusList(time, matrices[index].testExecutions) }
             assertEquals(expected[index], systemOutRule.log.filterMockk())
         }