From 3a213579b0b8ed7ca018314f0619146408292b35 Mon Sep 17 00:00:00 2001 From: piotradamczyk5 <65554637+piotradamczyk5@users.noreply.github.com> Date: Thu, 8 Apr 2021 19:52:53 +0200 Subject: [PATCH] feat: Add printing total run duration (#1773) --- test_runner/src/main/kotlin/ftl/Main.kt | 2 + .../main/kotlin/ftl/domain/RunTestAndroid.kt | 5 +- .../src/main/kotlin/ftl/domain/RunTestIos.kt | 8 +++- .../main/kotlin/ftl/reports/DurationReport.kt | 38 +++++++++++++++ .../src/main/kotlin/ftl/run/NewTestRun.kt | 17 +++++-- .../ftl/run/exception/ExceptionHandler.kt | 2 + .../ftl/run/platform/common/AfterRunTests.kt | 5 +- .../ftl/run/status/TestMatrixStatusPrinter.kt | 11 +++-- .../src/main/kotlin/ftl/util/StopWatch.kt | 36 +++++++++------ .../main/kotlin/ftl/util/StopWatchMatrix.kt | 12 ----- test_runner/src/test/kotlin/Debug.kt | 2 + .../run/status/TestMatrixStatusPrinterTest.kt | 13 ++++-- .../src/test/kotlin/ftl/util/StopWatchTest.kt | 46 ++++++++++++++++++- .../src/test/kotlin/ftl/util/UtilsTest.kt | 6 ++- 14 files changed, 159 insertions(+), 44 deletions(-) create mode 100644 test_runner/src/main/kotlin/ftl/reports/DurationReport.kt delete mode 100644 test_runner/src/main/kotlin/ftl/util/StopWatchMatrix.kt diff --git a/test_runner/src/main/kotlin/ftl/Main.kt b/test_runner/src/main/kotlin/ftl/Main.kt index 2a1eec4707..2da0fe2de9 100644 --- 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) { 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 index 5822dfe3e0..ccd651831c 100644 --- a/test_runner/src/main/kotlin/ftl/domain/RunTestAndroid.kt +++ b/test_runner/src/main/kotlin/ftl/domain/RunTestAndroid.kt @@ -10,6 +10,7 @@ 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 @@ -17,6 +18,7 @@ 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 index b45b988367..52dc10488a 100644 --- a/test_runner/src/main/kotlin/ftl/domain/RunTestIos.kt +++ b/test_runner/src/main/kotlin/ftl/domain/RunTestIos.kt @@ -10,6 +10,7 @@ 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 @@ -17,6 +18,7 @@ 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 new file mode 100644 index 0000000000..d543fe701c --- /dev/null +++ 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() + +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 index c08718909e..a64c3d672a 100644 --- 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 index cd20ca4f09..15e106d5cb 100644 --- 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 index bd3ad88fd2..c016ec66fd 100644 --- 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.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 index f066d468f7..aeccd15eca 100644 --- 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 index 95c48da8db..631e2aec99 100644 --- 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 deleted file mode 100644 index 0dcac2c473..0000000000 --- a/test_runner/src/main/kotlin/ftl/util/StopWatchMatrix.kt +++ /dev/null @@ -1,12 +0,0 @@ -package ftl.util - -import flank.common.logLn -import ftl.config.FtlConstants - -class StopWatchMatrix(private val stopwatch: StopWatch, private val matrixId: String) { - - fun puts(msg: String) { - val timestamp = stopwatch.check(alignSeconds = true) - logLn("${FtlConstants.indent}$timestamp $matrixId $msg") - } -} diff --git a/test_runner/src/test/kotlin/Debug.kt b/test_runner/src/test/kotlin/Debug.kt index 0dee0ecb24..ab8b1ec15e 100644 --- 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 index d53ac2556f..4cf7905295 100644 --- 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(relaxed = true) { - every { check(any()) } returns time + every { check() } returns expectedDuration } val printExecutionStatusList = mockk<(String, List?) -> Unit>(relaxed = true) val printMatrices = TestMatrixStatusPrinter( @@ -46,8 +49,8 @@ class TestMatrixStatusPrinterTest { val expected = listOf( "", """ - time 0 FINISHED - time 1 FINISHED + $time 0 FINISHED + $time 1 FINISHED """ ) // when @@ -55,7 +58,7 @@ class TestMatrixStatusPrinterTest { printMatrices(matrices[index]) // then - verify { stopWatch.check(true) } + verify { stopWatch.check() } verify { printExecutionStatusList(time, matrices[index].testExecutions) } assertEquals(expected[index], systemOutRule.log.filterMockk()) } diff --git a/test_runner/src/test/kotlin/ftl/util/StopWatchTest.kt b/test_runner/src/test/kotlin/ftl/util/StopWatchTest.kt index e369ed10c9..dbc5555786 100644 --- a/test_runner/src/test/kotlin/ftl/util/StopWatchTest.kt +++ b/test_runner/src/test/kotlin/ftl/util/StopWatchTest.kt @@ -14,7 +14,49 @@ class StopWatchTest { @Test fun `stopWatch recordTime`() { val watch = StopWatch().start() - assertThat(watch.check(alignSeconds = true)).isNotEmpty() - assertThat(watch.check()).isNotEmpty() + assertThat(watch.check().formatted(alignSeconds = true)).isNotEmpty() + assertThat(watch.check().formatted()).isNotEmpty() + } + + @Test + fun `should properly format time with align spaces set to true`() { + // given + val expectedResults = arrayOf( + "1m 1s", + "1m 11s" + ) + val testDurations = arrayOf( + Duration(61), + Duration(71) + ) + + // when + val actual = testDurations.map { it.formatted(true) } + + // then + actual.forEachIndexed { index, result -> + assertThat(result).isEqualTo(expectedResults[index]) + } + } + + @Test + fun `should properly format time with align spaces set to false`() { + // given + val expectedResults = arrayOf( + "1m 1s", + "1m 11s" + ) + val testDurations = arrayOf( + Duration(61), + Duration(71) + ) + + // when + val actual = testDurations.map { it.formatted() } + + // then + actual.forEachIndexed { index, result -> + assertThat(result).isEqualTo(expectedResults[index]) + } } } diff --git a/test_runner/src/test/kotlin/ftl/util/UtilsTest.kt b/test_runner/src/test/kotlin/ftl/util/UtilsTest.kt index 521d75fde9..5f4c3b3cbe 100644 --- a/test_runner/src/test/kotlin/ftl/util/UtilsTest.kt +++ b/test_runner/src/test/kotlin/ftl/util/UtilsTest.kt @@ -49,6 +49,7 @@ import java.io.File import java.util.concurrent.CountDownLatch import java.util.concurrent.atomic.AtomicBoolean import java.util.concurrent.atomic.AtomicInteger +import kotlin.system.exitProcess private const val VERIFICATION_FILE = "./should_exists.txt" private const val VERIFICATION_MESSAGE = "Killing thread intentionally" @@ -336,7 +337,10 @@ class UtilsTest { fun main(args: Array) { FtlConstants.useMock = true System.setProperty("runningTests", "true") - withGlobalExceptionHandling { CommandLine(Malicious()).execute(*args) } + withGlobalExceptionHandling( + block = { CommandLine(Malicious()).execute(*args) }, + exitProcessFunction = { exitProcess(it) } + ) } }