From 59d2ecb195b9c237183a676d8054fff1bdf1253e Mon Sep 17 00:00:00 2001 From: Ivan Dlugos Date: Thu, 15 Aug 2024 20:52:41 +0200 Subject: [PATCH 1/8] tmp: test many times to reproduce the issue --- tests/android.yml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/android.yml b/tests/android.yml index e978ffd..d74964d 100644 --- a/tests/android.yml +++ b/tests/android.yml @@ -6,7 +6,7 @@ apps: activity: MainActivity path: 'https://github.com/saucelabs/my-demo-app-rn/releases/download/v1.3.0/Android-MyDemoAppRN.1.3.0.build-244.apk' startupTimeTest: - runs: 15 + runs: 100 diffMin: 0 diffMax: 2000 stdDevMax: 100 From 14b97a25bc9b4a7e6feecb52d177e8971df9e19e Mon Sep 17 00:00:00 2001 From: Ivan Dlugos Date: Fri, 16 Aug 2024 08:54:39 +0200 Subject: [PATCH 2/8] tmp reduce matrix tests for now --- .github/workflows/test.yml | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml index c9f4c57..05a7a1a 100644 --- a/.github/workflows/test.yml +++ b/.github/workflows/test.yml @@ -9,8 +9,8 @@ jobs: test: strategy: matrix: - os: [android, ios] - run: [1, 2, 3, 4, 5] + os: [android] # xxx, ios] + run: [1] # xxx [1, 2, 3, 4, 5] runs-on: ubuntu-latest name: ${{ matrix.os }} ${{ matrix.run }}/5 steps: From f0b6f4aaab631a51de8ffbb0f4b30c28d7ed355c Mon Sep 17 00:00:00 2001 From: Ivan Dlugos Date: Fri, 16 Aug 2024 15:05:57 +0200 Subject: [PATCH 3/8] reconnect appium driver on error --- src/test/kotlin/StartupTimeTest.kt | 102 ++++++++++++++++------------- src/test/kotlin/TestBase.kt | 23 +++++-- 2 files changed, 75 insertions(+), 50 deletions(-) diff --git a/src/test/kotlin/StartupTimeTest.kt b/src/test/kotlin/StartupTimeTest.kt index 579f985..6d78476 100644 --- a/src/test/kotlin/StartupTimeTest.kt +++ b/src/test/kotlin/StartupTimeTest.kt @@ -39,7 +39,11 @@ class StartupTimeTest : TestBase() { fun `startup time`() { Assumptions.assumeTrue(baseOptions.startupTimeTest != null) - val measuredTimes = collectStartupTimes() + val measuredTimes = try { + collectStartupTimes() + } finally { + resetDriver() + } val filteredTimes = mutableListOf>() for (j in apps.indices) { @@ -95,66 +99,69 @@ class StartupTimeTest : TestBase() { private fun collectStartupTimes(): List> { val measuredTimes = mutableListOf>() - withDriver { driver -> - for (appIndex in apps.indices) { - val app = apps[appIndex] - val needsTimes = options.runs - ceil(options.runs * 0.1).toInt() + for (appIndex in apps.indices) { + val app = apps[appIndex] + val needsTimes = options.runs - ceil(options.runs * 0.1).toInt() - for (retry in 1..options.retries) { - if (retry > 1) { - printf( - "$logAppPrefix retrying startup time collection: %d/%d", - app.name, - retry, - options.retries - ) - } + for (retry in 1..options.retries) { + if (retry > 1) { + printf( + "$logAppPrefix retrying startup time collection: %d/%d", + app.name, + retry, + options.retries + ) + } - // sleep before the first test to improve the first run time - Thread.sleep(1_000) + // sleep before the first test to improve the first run time + Thread.sleep(1_000) - // clear logcat before test runs - if (baseOptions.platform == TestOptions.Platform.Android) { - driver.manage().logs().get("logcat") - } + val appTimes = try { + withDriver { collectAppStartupTimes(app, it) } + } catch (e: Exception) { + printf( + "$logAppPrefix startup time collection failed with %s", + app.name, + e.toString() + ) + continue + } - val appTimes = collectAppStartupTimes(app, driver) + printf( + "$logAppPrefix collected %d/%d startup times (try %d/%d)", + app.name, + appTimes.size, + options.runs, + retry, + options.retries + ) + + if (appTimes.size == 0 || appTimes.size < needsTimes) { printf( - "$logAppPrefix collected %d/%d startup times (try %d/%d)", + "$logAppPrefix not enough startup times collected: %d/%d. Expected at least %d", app.name, appTimes.size, options.runs, - retry, - options.retries + needsTimes ) + continue + } - if (appTimes.size == 0 || appTimes.size < needsTimes) { + if (options.stdDevMax > 0) { + val stdDev = Stats.of(filterOutliers(appTimes)).populationStandardDeviation() + if (stdDev > options.stdDevMax.toDouble()) { printf( - "$logAppPrefix not enough startup times collected: %d/%d. Expected at least %d", + "$logAppPrefix stddev on the filtered startup-time list is too high: %.2f, expected %.2f at most.", app.name, - appTimes.size, - options.runs, - needsTimes + stdDev, + options.stdDevMax.toDouble() ) continue } - - if (options.stdDevMax > 0) { - val stdDev = Stats.of(filterOutliers(appTimes)).populationStandardDeviation() - if (stdDev > options.stdDevMax.toDouble()) { - printf( - "$logAppPrefix stddev on the filtered startup-time list is too high: %.2f, expected %.2f at most.", - app.name, - stdDev, - options.stdDevMax.toDouble() - ) - continue - } - } - - measuredTimes.add(appTimes) - break } + + measuredTimes.add(appTimes) + break } } @@ -162,6 +169,11 @@ class StartupTimeTest : TestBase() { } private fun collectAppStartupTimes(app: AppInfo, driver: AppiumDriver): MutableList { + // clear logcat before test runs + if (baseOptions.platform == TestOptions.Platform.Android) { + driver.manage().logs().get("logcat") + } + val appTimes = mutableListOf() for (i in 1..options.runs) { printf("$logAppPrefix measuring startup times: %d/%d", app.name, i, options.runs) diff --git a/src/test/kotlin/TestBase.kt b/src/test/kotlin/TestBase.kt index 1ac4f63..f87c145 100644 --- a/src/test/kotlin/TestBase.kt +++ b/src/test/kotlin/TestBase.kt @@ -8,6 +8,19 @@ abstract class TestBase( protected val apps = baseOptions.apps protected val logAppPrefix = "App %-${apps.maxOfOrNull { it.name.length }}s" private val results = ResultFile() + private var _driver: AppiumDriver? = null + private val driver: AppiumDriver + get() { + if (_driver == null) { + _driver = baseOptions.createDriver() + } + return _driver as AppiumDriver + } + + protected fun resetDriver() { + _driver?.quit() + _driver = null + } @Suppress("NOTHING_TO_INLINE") // Inline ensures the logger prints the actual caller. protected inline fun printf(format: String, vararg args: Any?, logLevel: Level = Level.INFO) { @@ -20,12 +33,12 @@ abstract class TestBase( results.builder.save() } - protected fun withDriver(cb: (driver: AppiumDriver) -> Any) { - val driver = baseOptions.createDriver() + protected fun withDriver(cb: (driver: AppiumDriver) -> T) : T { try { - cb(driver) - } finally { - driver.quit() + return cb(driver) + } catch (e: Exception) { + resetDriver() + throw e } } } From 47c30548677cfb56e103d85e1f641f7c8701a230 Mon Sep 17 00:00:00 2001 From: Ivan Dlugos Date: Fri, 16 Aug 2024 15:23:50 +0200 Subject: [PATCH 4/8] chore: update changelog --- CHANGELOG.md | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 666dd37..d48cd24 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,11 @@ # Changelog +## Unreleased + +### Features + +* Automatically reconnect the appium client in case of startup time collection failure. ([#22](https://github.com/getsentry/action-app-sdk-overhead-metrics/pull/22)) + ## 1.7.0 ### Features From f178e30138845a85fdde0910485efde772fb602e Mon Sep 17 00:00:00 2001 From: Ivan Dlugos Date: Fri, 16 Aug 2024 15:39:36 +0200 Subject: [PATCH 5/8] rename: resetDriver to closeDriver --- src/test/kotlin/StartupTimeTest.kt | 153 ++++++++++++++++------------- src/test/kotlin/TestBase.kt | 4 +- 2 files changed, 85 insertions(+), 72 deletions(-) diff --git a/src/test/kotlin/StartupTimeTest.kt b/src/test/kotlin/StartupTimeTest.kt index 6d78476..45aed08 100644 --- a/src/test/kotlin/StartupTimeTest.kt +++ b/src/test/kotlin/StartupTimeTest.kt @@ -42,7 +42,7 @@ class StartupTimeTest : TestBase() { val measuredTimes = try { collectStartupTimes() } finally { - resetDriver() + closeDriver() } val filteredTimes = mutableListOf>() @@ -116,17 +116,7 @@ class StartupTimeTest : TestBase() { // sleep before the first test to improve the first run time Thread.sleep(1_000) - val appTimes = try { - withDriver { collectAppStartupTimes(app, it) } - } catch (e: Exception) { - printf( - "$logAppPrefix startup time collection failed with %s", - app.name, - e.toString() - ) - continue - } - + val appTimes = collectAppStartupTimes(app) printf( "$logAppPrefix collected %d/%d startup times (try %d/%d)", app.name, @@ -168,80 +158,103 @@ class StartupTimeTest : TestBase() { return measuredTimes } - private fun collectAppStartupTimes(app: AppInfo, driver: AppiumDriver): MutableList { + private fun collectAppStartupTimes(app: AppInfo): MutableList { // clear logcat before test runs if (baseOptions.platform == TestOptions.Platform.Android) { - driver.manage().logs().get("logcat") + withDriver { it.manage().logs().get("logcat") } } val appTimes = mutableListOf() for (i in 1..options.runs) { - printf("$logAppPrefix measuring startup times: %d/%d", app.name, i, options.runs) - - // kill the app and sleep before running the next iteration - when (baseOptions.platform) { - TestOptions.Platform.Android -> { - val androidDriver = (driver as AndroidDriver) - printf("%s", "${app.name} is installed: ${driver.isAppInstalled(app.name)}") - - try { - val result = androidDriver.executeScript("mobile: startActivity", - ImmutableMap.of("intent", "${app.name}/.${app.activity!!}", "wait", true)).toString() - val error = Regex("Error: (.*)").find(result)?.groupValues - if (error != null) { - throw Exception(error[0]) - } - } catch (e: Exception) { - // in case the app can't be launched or crashes on startup, print logcat output - val logs = driver.manage().logs().get("logcat").all.joinToString("\n") - printf("%s", logs) - throw(e) - } + try { + withDriver { driver -> + printf("$logAppPrefix measuring startup times: %d/%d", app.name, i, options.runs) - androidDriver.terminateApp(app.name).shouldBe(true) - - val logEntries = driver.manage().logs().get("logcat") - val regex = Regex("Displayed ${app.name}/\\.${app.activity}: \\+(?:([0-9]+)s)?([0-9]+)ms") - val times = logEntries.mapNotNull { - val groups = regex.find(it.message)?.groupValues - if (groups == null) { - null - } else { - printf("$logAppPrefix logcat entry processed: %s", app.name, it.message) - val seconds = if (groups[1].isEmpty()) 0 else groups[1].toLong() - seconds * 1000 + groups[2].toLong() - } - } - if (times.size == 1) { - appTimes.add(times.first()) - } else { - printf("Expected 1 startup time in logcat, matching Regex '%s', but found %d", regex.pattern, times.size) - } + collectAppStartupTime(driver, app, appTimes) + + // sleep before running the next iteration + Thread.sleep(sleepTimeMs) } + } catch (e: Exception) { + printf( + "$logAppPrefix startup time collection failed with %s", + app.name, + e.toString() + ) + continue + } - TestOptions.Platform.IOS -> { - val iosDriver = (driver as IOSDriver) - val countBefore = driver.events.commands.filter { it.name == "execute" }.count() - iosDriver.activateApp(app.name) - // Note: with Appium 9 we can no longer filter by actual command name, see https://github.com/appium/java-client/issues/2219 - val times = driver.events.commands - .filter { it.name == "execute" } - .map { it.endTimestamp - it.startTimestamp } + } + return appTimes + } + private fun collectAppStartupTime( + driver: AppiumDriver, + app: AppInfo, + appTimes: MutableList + ) { + when (baseOptions.platform) { + TestOptions.Platform.Android -> { + val androidDriver = (driver as AndroidDriver) + printf("%s", "${app.name} is installed: ${driver.isAppInstalled(app.name)}") + driver.terminateApp(app.name) + + try { + val result = androidDriver.executeScript( + "mobile: startActivity", + ImmutableMap.of("intent", "${app.name}/.${app.activity!!}", "wait", true) + ).toString() + val error = Regex("Error: (.*)").find(result)?.groupValues + if (error != null) { + throw Exception(error[0]) + } + } catch (e: Exception) { + // in case the app can't be launched or crashes on startup, print logcat output + val logs = driver.manage().logs().get("logcat").all.joinToString("\n") + printf("%s", logs) + throw (e) + } - if (times.size == countBefore + 1) { - appTimes.add(times.last()) + val logEntries = driver.manage().logs().get("logcat") + val regex = Regex("Displayed ${app.name}/\\.${app.activity}: \\+(?:([0-9]+)s)?([0-9]+)ms") + val times = logEntries.mapNotNull { + val groups = regex.find(it.message)?.groupValues + if (groups == null) { + null } else { - printf("Expected %d activateApp events, but found %d", countBefore + 1, times.size) + printf("$logAppPrefix logcat entry processed: %s", app.name, it.message) + val seconds = if (groups[1].isEmpty()) 0 else groups[1].toLong() + seconds * 1000 + groups[2].toLong() } - - iosDriver.terminateApp(app.name) + } + if (times.size == 1) { + appTimes.add(times.first()) + } else { + printf( + "Expected 1 startup time in logcat, matching Regex '%s', but found %d", + regex.pattern, + times.size + ) } } - // sleep before the next test run - Thread.sleep(sleepTimeMs) + TestOptions.Platform.IOS -> { + val iosDriver = (driver as IOSDriver) + driver.terminateApp(app.name) + val countBefore = driver.events.commands.filter { it.name == "execute" }.count() + iosDriver.activateApp(app.name) + // Note: with Appium 9 we can no longer filter by actual command name, see https://github.com/appium/java-client/issues/2219 + val times = driver.events.commands + .filter { it.name == "execute" } + .map { it.endTimestamp - it.startTimestamp } + + if (times.size == countBefore + 1) { + appTimes.add(times.last()) + } else { + printf("Expected %d activateApp events, but found %d", countBefore + 1, times.size) + } + + } } - return appTimes } } diff --git a/src/test/kotlin/TestBase.kt b/src/test/kotlin/TestBase.kt index f87c145..ebc0870 100644 --- a/src/test/kotlin/TestBase.kt +++ b/src/test/kotlin/TestBase.kt @@ -17,7 +17,7 @@ abstract class TestBase( return _driver as AppiumDriver } - protected fun resetDriver() { + protected fun closeDriver() { _driver?.quit() _driver = null } @@ -37,7 +37,7 @@ abstract class TestBase( try { return cb(driver) } catch (e: Exception) { - resetDriver() + closeDriver() throw e } } From 169ea17627ed2fdd041b199b845cba6fedbc1a84 Mon Sep 17 00:00:00 2001 From: Ivan Dlugos Date: Fri, 16 Aug 2024 15:40:09 +0200 Subject: [PATCH 6/8] roll back temporary changes --- .github/workflows/test.yml | 4 ++-- tests/android.yml | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml index 05a7a1a..c9f4c57 100644 --- a/.github/workflows/test.yml +++ b/.github/workflows/test.yml @@ -9,8 +9,8 @@ jobs: test: strategy: matrix: - os: [android] # xxx, ios] - run: [1] # xxx [1, 2, 3, 4, 5] + os: [android, ios] + run: [1, 2, 3, 4, 5] runs-on: ubuntu-latest name: ${{ matrix.os }} ${{ matrix.run }}/5 steps: diff --git a/tests/android.yml b/tests/android.yml index d74964d..e978ffd 100644 --- a/tests/android.yml +++ b/tests/android.yml @@ -6,7 +6,7 @@ apps: activity: MainActivity path: 'https://github.com/saucelabs/my-demo-app-rn/releases/download/v1.3.0/Android-MyDemoAppRN.1.3.0.build-244.apk' startupTimeTest: - runs: 100 + runs: 15 diffMin: 0 diffMax: 2000 stdDevMax: 100 From 6fe3973dc90ce76ccf00a46e0647abcb0515cf86 Mon Sep 17 00:00:00 2001 From: Ivan Dlugos Date: Fri, 16 Aug 2024 19:35:59 +0200 Subject: [PATCH 7/8] explicitly throw in case all tries fail --- src/test/kotlin/StartupTimeTest.kt | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/src/test/kotlin/StartupTimeTest.kt b/src/test/kotlin/StartupTimeTest.kt index 45aed08..c529043 100644 --- a/src/test/kotlin/StartupTimeTest.kt +++ b/src/test/kotlin/StartupTimeTest.kt @@ -153,6 +153,10 @@ class StartupTimeTest : TestBase() { measuredTimes.add(appTimes) break } + + if (measuredTimes.size != appIndex + 1) { + throw Exception("$logAppPrefix - all tries to collect startup times have failed") + } } return measuredTimes From 4b211105db60ab43362c4ef56b24a89a066fa58a Mon Sep 17 00:00:00 2001 From: Ivan Dlugos <6349682+vaind@users.noreply.github.com> Date: Fri, 16 Aug 2024 20:10:36 +0200 Subject: [PATCH 8/8] Apply suggestions from code review --- CHANGELOG.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index d48cd24..27bc0dc 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,6 +1,6 @@ # Changelog -## Unreleased +## 1.8.0 ### Features