Startup Metrics not always captured via emulator [329145809]

Fixed

Bug

Status Update

No update yet.

Description

en...@meta.com

created issue #1

Mar 12, 2024 09:30AM

Component used: Version used: Benchmark Macro v.1.2.3 Devices/Android versions reproduced on: Android emulator (API 30)

I am often seeing the error: "Skipping results from iter $iteration, it didn't capture all metrics" from emulator runs of cold start tests. I currently have my test set to 10 iterations and get any where from 2-9 metrics in the output json file although I see 10 successful startups in the UI and. in the Benchmark logs.

If this is a bug in the library, we would appreciate if you could attach:

Sample project to trigger the issue.
A screenrecord or screenshots showing the issue (if UI related).

Comments

cc...@google.com <cc...@google.com> #2Mar 25, 2024 08:29PM

Project: platform/frameworks/support
Branch: androidx-master-dev

commit c60f33e229e31ab328ef6b59dab63b264954831c
Author: Alexandre Elias <aelias@google.com>
Date: Fri Jul 10 16:23:09 2020

Semantics no-op cleanups

Partly in response to lmr's broad code review, I did a pass of
superficial API/implementation cleanup. The main changes are:

- I changed each Boolean SemanticsProperty where false is equivalent to
not being present to take "Unit" instead. This is conceptually
clearer: it avoids questions like "can I cancel out a semantics from a
merged child by setting it to false?" Because "property = Unit" looks
weird, I also changed the style of these to "property()".

- I moved the Semantics id generator closer to where it's used, in
SemanticsModifierCore. I made it internal and an AtomicInt.
(Note that integer ids are heavily used in the Android
AccessibilityNodeInfo APIs so I can't simply remove them entirely.)

- I deleted dead code. Some examples include SemanticsHintOverrides,
a public API not connected to anything, and SemanticsPropertyKey
merge() open method which is never called. (In both cases I have
a different plan in mind for accessibility.)

Fixes: 145951226
Fixes: 145955412
Test: existing tests
Relnote: "Single-value semantics properties now use a calling style.
For example, 'semantics { hidden = true }' is now written as:
'semantics { hidden() }'."

Change-Id: Ic1afd12ea22c926babc9662f1804d80b33aa0cfc

M ui/integration-tests/benchmark/src/androidTest/java/androidx/ui/benchmark/test/LayoutNodeModifierBenchmark.kt
M ui/ui-core/api/0.1.0-dev15.txt
M ui/ui-core/api/current.txt
M ui/ui-core/api/public_plus_experimental_0.1.0-dev15.txt
M ui/ui-core/api/public_plus_experimental_current.txt
M ui/ui-core/api/restricted_0.1.0-dev15.txt
M ui/ui-core/api/restricted_current.txt
M ui/ui-core/src/androidAndroidTest/kotlin/androidx/ui/graphics/vector/VectorTest.kt
M ui/ui-core/src/androidAndroidTest/kotlin/androidx/ui/semantics/SemanticsTests.kt
M ui/ui-core/src/androidMain/kotlin/androidx/ui/core/AndroidActuals.kt
M ui/ui-core/src/androidMain/kotlin/androidx/ui/core/AndroidComposeView.kt
M ui/ui-core/src/androidMain/kotlin/androidx/ui/core/AndroidComposeViewAccessibilityDelegateCompat.kt
M ui/ui-core/src/androidMain/kotlin/androidx/ui/core/AndroidPopup.kt
M ui/ui-core/src/commonMain/kotlin/androidx/ui/core/Expect.kt
M ui/ui-core/src/commonMain/kotlin/androidx/ui/core/semantics/SemanticsConfiguration.kt
D ui/ui-core/src/commonMain/kotlin/androidx/ui/core/semantics/SemanticsHintOverrides.kt
M ui/ui-core/src/commonMain/kotlin/androidx/ui/core/semantics/SemanticsModifier.kt
M ui/ui-core/src/commonMain/kotlin/androidx/ui/core/semantics/SemanticsNode.kt
M ui/ui-core/src/commonMain/kotlin/androidx/ui/core/semantics/SemanticsOwner.kt
M ui/ui-core/src/commonMain/kotlin/androidx/ui/core/semantics/SemanticsWrapper.kt
M ui/ui-core/src/commonMain/kotlin/androidx/ui/semantics/SemanticsProperties.kt
M ui/ui-foundation/api/0.1.0-dev15.txt
M ui/ui-foundation/api/current.txt
M ui/ui-foundation/api/public_plus_experimental_0.1.0-dev15.txt
M ui/ui-foundation/api/public_plus_experimental_current.txt
M ui/ui-foundation/api/restricted_0.1.0-dev15.txt
M ui/ui-foundation/api/restricted_current.txt
M ui/ui-foundation/src/main/java/androidx/ui/foundation/Clickable.kt
M ui/ui-foundation/src/main/java/androidx/ui/foundation/Dialog.kt
M ui/ui-foundation/src/main/java/androidx/ui/foundation/Scroller.kt
M ui/ui-foundation/src/main/java/androidx/ui/foundation/selection/Selectable.kt
M ui/ui-foundation/src/main/java/androidx/ui/foundation/selection/Toggleable.kt
M ui/ui-foundation/src/main/java/androidx/ui/foundation/semantics/FoundationSemanticsProperties.kt
M ui/ui-material/src/androidTest/java/androidx/ui/material/ButtonTest.kt
M ui/ui-material/src/androidTest/java/androidx/ui/material/CardTest.kt
M ui/ui-material/src/androidTest/java/androidx/ui/material/CheckboxScreenshotTest.kt
M ui/ui-material/src/androidTest/java/androidx/ui/material/RadioButtonScreenshotTest.kt
M ui/ui-material/src/androidTest/java/androidx/ui/material/ScaffoldTest.kt
M ui/ui-material/src/androidTest/java/androidx/ui/material/SnackbarTest.kt
M ui/ui-material/src/androidTest/java/androidx/ui/material/SurfaceTest.kt
M ui/ui-material/src/androidTest/java/androidx/ui/material/ripple/RippleIndicationTest.kt
M ui/ui-material/src/androidTest/java/androidx/ui/material/textfield/TextFieldScreenshotTest.kt
M ui/ui-material/src/main/java/androidx/ui/material/AppBar.kt
M ui/ui-material/src/main/java/androidx/ui/material/TextFieldImpl.kt
M ui/ui-test/src/androidTest/java/androidx/ui/test/AssertsTest.kt
M ui/ui-test/src/androidTest/java/androidx/ui/test/CallSemanticsActionTest.kt
M ui/ui-test/src/androidTest/java/androidx/ui/test/ErrorMessagesTest.kt
M ui/ui-test/src/androidTest/java/androidx/ui/test/FindersTest.kt
M ui/ui-test/src/androidTest/java/androidx/ui/test/PrintToStringTest.kt
M ui/ui-test/src/androidTest/java/androidx/ui/test/ScrollToTest.kt
M ui/ui-test/src/androidTest/java/androidx/ui/test/TextActionsTest.kt
M ui/ui-test/src/main/java/androidx/ui/test/Actions.kt
M ui/ui-test/src/main/java/androidx/ui/test/Filters.kt
M ui/ui-text/api/0.1.0-dev15.txt
M ui/ui-text/api/current.txt
M ui/ui-text/api/public_plus_experimental_0.1.0-dev15.txt
M ui/ui-text/api/public_plus_experimental_current.txt
M ui/ui-text/api/restricted_0.1.0-dev15.txt
M ui/ui-text/api/restricted_current.txt
M ui/ui-text/src/commonMain/kotlin/androidx/ui/text/CoreTextField.kt
M ui/ui-text/src/commonMain/kotlin/androidx/ui/text/TextSemanticsProperties.kt

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

en...@meta.com <en...@meta.com> #3Apr 1, 2024 12:24PM

I've attempted to repro this issue with other apps and this seems to be exclusive to a particular app that I'm testing with. I wouldn't be able to provide traces or full logcat for IP reasons but I can provide a filtered log of one of the iterations that failed.

Uncaptured_Metrics_Logs.txt

8.6 KB

View

Download

cc...@google.com <cc...@google.com> #4Apr 1, 2024 03:57PM

Thanks very much for the logs!

Are you sure you're using benchmark 1.2.3?

In 1.2.0-alpha04 we removed the constraint to look for startActivityAndWait (see b/245414235), but it's still in your query/results. It's possible we had a branch management issue when releasing, but can you check the version of benchmark you're using?

On a newer version, the query results for this iteration look like they should work, I tried converting them to slices in the internal implementation of StartupTimingQuery:

    listOf(
        Slice("MetricsLogger:launchObserverNotifyIntentStarted",748393772361,29705),
        Slice("launching: androidx.benchmark.integration.macrobenchmark.target",748404581583,881311671),
        Slice("activityResume",748731008508,4916798),
        Slice("Choreographer#doFrame",748764833776,519637337),
        Slice("DrawFrame",748897201189,387112642),
        Slice("Choreographer#doFrame",749285086939,89017),
        Slice("Choreographer#doFrame",749305484396,730140),
        Slice("DrawFrame",749305899852,121651546),
    )

And received the following startup event:

SubMetrics(timeToInitialDisplayNs=879732248, timeToFullDisplayNs=null, timelineRangeNs=748404581583..749284313831)

So you should be good with new versions of macrobenchmark.

The other constraint we removed in that same fix was asserting that the launching event was contained in the startActivityAndWait event, which seems to be the problem in this iteration:

04-01 11:54:55.097  6289  6311 I System.out: query result line "startActivityAndWait",748335793781,1096645119
04-01 11:54:55.097  6289  6311 I System.out: query result line "launching: <app_test_package>",748404581583,881311671

748335793781 + 1096645119 is greater than 748404581583, so the launching: event starts after the startActivityAndWait slice from macrobenchmark. Not sure why that is without looking at a trace, but you could look to see if there's anything strange there (like startActivityAndWait not waiting for the actual launch somehow, that would do it).

en...@meta.com <en...@meta.com> #5Apr 1, 2024 05:35PM

Ah right, I'm blocked on using 1.2.3 in a specific use case due to

https://issuetracker.google.com/issues/329145808. I have a local workaround to use 1.2.3 but didn't use it for today's repro. Let me try to repro with 1.2.3 today

en...@meta.com <en...@meta.com> #6Apr 1, 2024 06:11PM

Okay, looks like I'm unable to repro this on 1.2.3 anymore. I'm getting an entirely different error consistently with 1.2.3 which is "java.util.NoSuchElementException: Collection contains no element matching the predicate." I'll create a separate issue for this if one doesn't exist already.

Feel free to close this issue out. Thanks for all your help!

ap...@google.com <ap...@google.com> #7Apr 1, 2024 07:22PM

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

commit d55b483632c5662ae95d19479ebbc14f8b23b0ff
Author: Chris Craik <ccraik@google.com>
Date: Mon Apr 01 11:27:57 2024

Add logs / error messages to all startup detection failures

Test: StartupTimingQueryTest
Bug: 329145809
Bug: 305733267

Relnote: "Added log.w / exception labels to all startup detection
failures. This does not change current behavior (so some errors throw,
and others silently fail to detect the startup), just makes it more
understandable. Generally the ones that Log.w() and fail to report
startup metrics are those where non-frame events are missing,
exceptions are thrown when startup is detected except for frame timing
information (from UI/RT slices)."

Likely will want to revisit this in the future to make detection
failure conditions more consistent, this change just makes errors more
comprehensible without needing to dig into the trace.

Change-Id: Id240f7698dfb977457362a137f0070e73dc2495c

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

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

cc...@google.com <cc...@google.com> #8Apr 1, 2024 08:20PM

Above CL should make problems like these a lot easier to diagnose (both missing metric, and collection contains no element matching predicate).

cc...@google.com <cc...@google.com> #9Apr 1, 2024 08:21PM

Marked as fixed.

Actual missing content issue was tracked/fixed in b/245414235

Treating this bug as about the discoverability/logging side, so closing this as fixed.

na...@google.com <na...@google.com> #10Apr 17, 2024 05:17PM

The following release(s) address this bug.It is possible this bug has only been partially addressed:

androidx.benchmark:benchmark-macro:1.3.0-alpha03