Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feat: automatic reconnect #22

Merged
merged 8 commits into from
Aug 16, 2024
Merged

feat: automatic reconnect #22

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
8 commits
Select commit Hold shift + click to select a range
59d2ecb
tmp: test many times to reproduce the issue
vaind Aug 15, 2024
14b97a2
tmp reduce matrix tests for now
vaind Aug 16, 2024
f0b6f4a
reconnect appium driver on error
vaind Aug 16, 2024
47c3054
chore: update changelog
vaind Aug 16, 2024
f178e30
rename: resetDriver to closeDriver
vaind Aug 16, 2024
169ea17
roll back temporary changes
vaind Aug 16, 2024
6fe3973
explicitly throw in case all tries fail
vaind Aug 16, 2024
4b21110
Apply suggestions from code review
vaind Aug 16, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
6 changes: 6 additions & 0 deletions CHANGELOG.md
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,5 +1,11 @@
# Changelog

## 1.8.0

### 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
Expand Down
231 changes: 130 additions & 101 deletions src/test/kotlin/StartupTimeTest.kt
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -39,7 +39,11 @@ class StartupTimeTest : TestBase() {
fun `startup time`() {
Assumptions.assumeTrue(baseOptions.startupTimeTest != null)

val measuredTimes = collectStartupTimes()
val measuredTimes = try {
collectStartupTimes()
} finally {
closeDriver()
}
val filteredTimes = mutableListOf<List<Long>>()

for (j in apps.indices) {
Expand Down Expand Up @@ -95,141 +99,166 @@ class StartupTimeTest : TestBase() {
private fun collectStartupTimes(): List<List<Long>> {
val measuredTimes = mutableListOf<List<Long>>()

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 = collectAppStartupTimes(app)
printf(
"$logAppPrefix collected %d/%d startup times (try %d/%d)",
app.name,
appTimes.size,
options.runs,
retry,
options.retries
)

val appTimes = collectAppStartupTimes(app, driver)
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
}
if (measuredTimes.size != appIndex + 1) {
throw Exception("$logAppPrefix - all tries to collect startup times have failed")
}
}

return measuredTimes
}

private fun collectAppStartupTimes(app: AppInfo, driver: AppiumDriver): MutableList<Long> {
private fun collectAppStartupTimes(app: AppInfo): MutableList<Long> {
// clear logcat before test runs
if (baseOptions.platform == TestOptions.Platform.Android) {
withDriver { it.manage().logs().get("logcat") }
}

val appTimes = mutableListOf<Long>()
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<Long>
) {
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
}
}
23 changes: 18 additions & 5 deletions src/test/kotlin/TestBase.kt
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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 closeDriver() {
_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) {
Expand All @@ -20,12 +33,12 @@ abstract class TestBase(
results.builder.save()
}

protected fun withDriver(cb: (driver: AppiumDriver) -> Any) {
val driver = baseOptions.createDriver()
protected fun <T> withDriver(cb: (driver: AppiumDriver) -> T) : T {
try {
cb(driver)
} finally {
driver.quit()
return cb(driver)
} catch (e: Exception) {
closeDriver()
throw e
}
}
}