Status Update
No update yet.
Comments
cc...@google.com
Tried replacing the UI automator with a thread.sleep - same behavior. Launching the app with context.startActivity takes 4+ seconds to just kick off the startup for some reason (and this is a warm startup of a trivial app).
Carmen / Michael, ever seen this?
cc...@google.com
Relevant logcat - the activity start request is apparently slowed down for 5 seconds intentionally. Public bug about this behavior:
06-24 22:40:10.835 1462 2016 I ActivityTaskManager: START u0 {act=androidx.benchmark.integration.macrobenchmark.target.TRIVIAL_STARTUP_ACTIVITY flg=0x10008000 pkg=androidx.benchmark.integration.macrobenchmark.target cmp=androidx.benchmark.integration.macrobenchmark.target/.TrivialStartupActivity} from uid 10315
06-24 22:40:10.836 1462 2016 W ActivityTaskManager: Activity start request from 10315 stopped
06-24 22:40:14.538 1462 1555 D CompatibilityChangeReporter: Compat change id reported: 135634846; UID 10314; state: DISABLED
06-24 22:40:14.538 1462 1555 D CompatibilityChangeReporter: Compat change id reported: 135754954; UID 10314; state: ENABLED
06-24 22:40:14.538 1462 1578 D CompatibilityChangeReporter: Compat change id reported: 143937733; UID 10314; state: ENABLED
06-24 22:40:14.545 763 763 D Zygote : Forked child process 24588
06-24 22:40:14.548 1462 1578 I ActivityManager: Start proc 24588:androidx.benchmark.integration.macrobenchmark.target/u0a314 for pre-top-activity {androidx.benchmark.integration.macrobenchmark.target/androidx.benchmark.integration.macrobenchmark.target.TrivialStartupActivity}
cc...@google.com
Tried to invoke the intent differently via androidx.test - via ActivityScenario, and via InstrumentationActivityInvoker more directly, both of which didn't solve the latency issue, and had other problems.
Found a way that works pretty nicely - am start-activity \"${intent.toUri(...)}\". We were originally interested in swapping to that to avoid needing UiAutomator to detect launch completion (also a bonus!) - the toUri was the bit I was missing before. Problem is that we need to rewrite things to pipe errors through, since some start-activity errors come out in stdout, and some in stderr.
WIP cl cuts the time per launch iteration down from 16 seconds -> 8s. (I'm sure there's still more to optimize there - several other conservative waits that we can potentially improve.)
ap...@google.com
Branch: androidx-main
commit 4e10e6b81ffd6ad29a1947aa675abaa3bc0d1208
Author: Chris Craik <ccraik@google.com>
Date: Thu Jun 24 15:53:33 2021
Switch to am start-activity for startActivityAndWait
Test: MacrobenchmarkScopeTest
Test: ShellUtilsTest
Fixes: 192009149
Bug: 181810492
Relnote:"""Switched startActivityAndWait to invoke `am start`, which reduces
waiting by approximately 5 seconds, at the cost of no longer supporting
intent parcelables."""
This avoids a 5 second wait in context.startActivity() after every
home button press. Speeds up TrivialStartupBenchmark from 5m38s->8m1s,
a 46% reduction in runtime (bramble on R).
Reworked shell utils to enable capturing stderr, since am start prints
some errors to stdout, and some to stderr.
Additionally:
- adds tracing to startActivityAndWait
- re-enables MacrobenchScopeTest in CI, adding clear error if package missing
Change-Id: I5a6f55819fe095da1317b55405a6a5a9fe3cb758
M benchmark/macro/build.gradle
M benchmark/macro/src/androidTest/java/androidx/benchmark/macro/MacrobenchmarkScopeTest.kt
M benchmark/macro/src/androidTest/java/androidx/benchmark/macro/perfetto/ShellUtilsTest.kt
M benchmark/macro/src/main/java/androidx/benchmark/macro/MacrobenchmarkScope.kt
M benchmark/macro/src/main/java/androidx/benchmark/macro/perfetto/ShellUtils.kt
M testutils/testutils-macrobenchmark/src/main/java/androidx/testutils/MacrobenchUtils.kt
Description
Trivial hot startup test (
TrivialStartupBenchmark#startup[startup=WARM,compilation=None])Launch itself takes approx 45ms.
waitOnPackageLaunch() takes > 5.5 seconds. Of that, more than 4.5 seconds is spent waiting for the app to actually launch (that is, time elapsed before the
launching: <packagename>trace section).It looks like the wait finishes several hundred millis later, due to UiAutomator polling every 1 second. The gap at the end of the trace is an intentional sleep, to ensure trace content isn't lost (400ms).