Macrobench startup traces cutting off too early, failing to capture metric [193827052]

Duplicate

of 194105203

Bug

Status Update

No update yet.

Description

cc...@google.com

created issue #1

Jul 15, 2021 10:14PM

Seeing traces cutting off too early, before e.g. startActivityAndWait have fully completed, which results in an exception like the following:

java.lang.IllegalStateException: Error, different metrics observed in different iterations.

Iteration 1 missing keys [startupMs]Please report a bug, and include a logcat capture, and all traces captured by this test run:
/storage/emulated/0/Android/media/androidx.benchmark.integration.macrobenchmark.test/TrivialStartupBenchmark_startup[startup=COLD,compilation=SpeedProfile[iterations=3]]_iter000_2021-07-15-22-21-37.trace
/storage/emulated/0/Android/media/androidx.benchmark.integration.macrobenchmark.test/TrivialStartupBenchmark_startup[startup=COLD,compilation=SpeedProfile[iterations=3]]_iter001_2021-07-15-22-21-41.trace
/storage/emulated/0/Android/media/androidx.benchmark.integration.macrobenchmark.test/TrivialStartupBenchmark_startup[startup=COLD,compilation=SpeedProfile[iterations=3]]_iter002_2021-07-15-22-21-44.trace
DeviceInfo(Brand=google, Model=Pixel 4a (5G), SDK=30, BuildFp=google/bramble/bramble:11/RQ3A.210605.003/7295351:userdebug/dev-keys)
...

See attached trace.

Seeing this in CI frequently with androidx.benchmark.integration.macrobenchmark.SmallListStartupBenchmark, e.g. https://android-build.googleplex.com/builds/tests/view?invocationId=I51900009972024845&redirect=http%3A%2F%2Fab%2FI51900009972024845&testClass=SmallListStartupBenchmark&testMethod=startup%5Bstartup%3DHOT%2Ccompilation%3DNone%5D&testPackage=androidx.benchmark.integration.macrobenchmark

This is likely due to switch either to am start (http://aosp/1751627), or reduction of sleep before killing the trace (http://aosp/1751631).

nometric.trace

3 MB

Download

Comments

ap...@google.com <ap...@google.com> #2Jul 16, 2021 05:36PM

Marked as fixed.

Project: platform/frameworks/support
Branch: androidx-main

commit 34896025ba5ff8390ba945fba7183768c0cb8c5c
Author: Chris Craik <ccraik@google.com>
Date: Thu Jul 15 17:42:54 2021

Fix missing metric crash by sleeping longer after launch before killing Perfetto

Fixed: 193827052
Test: Ran variant of TrivialStartupBenchmark many times (see below)

100ms delay - 5 / 50 failures
200ms delay - 2 / 50 failures
300ms delay - 2 / 50 failures
400ms delay - 0 / 50 failures
500ms delay - 0 / 200 failures

Previously, this was a 400ms delay, but startActivityAndWait is now
more aggressive about ending early, due to the removal of UiAutomator
polling. 500ms is chosen to be more conservative.

This should drastically reduce the rate of missing metric failures,
can increase further if problem still occurs.

Change-Id: Ib669755f6db5f79e309b2112c31e6e6ddfaf5f39

M benchmark/benchmark-macro/src/main/java/androidx/benchmark/macro/perfetto/PerfettoCapture.kt

https://android-review.googlesource.com/1768983

cc...@google.com <cc...@google.com> Jul 20, 2021 05:58PM

Status: Assigned (reopened)

ap...@google.com <ap...@google.com> #3Jul 28, 2021 01:21AM

Project: platform/frameworks/support
Branch: androidx-main

commit 91d9b082ebc3265cdd568e69a1920881602f325a
Author: Chris Craik <ccraik@google.com>
Date: Tue Jul 27 17:15:46 2021

Workaround missing metrics

Bug: 193827052
Test: MetricResultExtensionsTest

Change-Id: I9bf08b13aeb5f362a7aee7f2a5adc818240c2d3c

M benchmark/benchmark-macro/src/androidTest/java/androidx/benchmark/macro/MetricResultExtensionsTest.kt
M benchmark/benchmark-macro/src/main/java/androidx/benchmark/macro/MetricResultExtensions.kt

https://android-review.googlesource.com/1780807

ap...@google.com <ap...@google.com> #4Oct 13, 2021 12:08AM

Project: platform/frameworks/support
Branch: androidx-main

commit 58159e0dc33a81efa1179e35d50a2ded001dd561
Author: Chris Craik <ccraik@google.com>
Date: Tue Oct 12 15:33:01 2021

Poll /sys/kernel/tracing/tracing_on before returning from trace capture start

Test: PerfettoCaptureTest
Bug: 193827052
Bug: 194105203
Bug: 200302931

Relnote: """Fix for traces not starting early enough, and missing
metric data. This is expected to fix "Unable to read any metrics
during benchmark" exceptions that were caused by library itself."

Ran PerfettoCaptureTest hundreds of times in a row on a old device
(shamu API 24), the sleep() at the beginning no longer is required, as
it's handled by the polling.

From Perfetto team (

b/194105203

)- tracing_on is always a better way to
ensure that new trace events won't be missing from the trace.

Additionally, changed PerfettoCaptureTest to clarify between begin/end
of trace content dropping problems.

Change-Id: I6dfcbda59c6f5887433f3b1227613f8789ca6307

M benchmark/benchmark-common/src/main/java/androidx/benchmark/perfetto/PerfettoHelper.kt
M benchmark/benchmark-macro/src/androidTest/java/androidx/benchmark/macro/perfetto/PerfettoCaptureTest.kt
M benchmark/benchmark-macro/src/main/java/androidx/benchmark/macro/perfetto/PerfettoTraceProcessor.kt
M benchmark/benchmark-common/src/main/java/androidx/benchmark/Shell.kt

https://android-review.googlesource.com/1855765

cc...@google.com <cc...@google.com> Nov 3, 2021 06:15PM

Status: Duplicate of

194105203

Issue 193827052