Several issues in PerformanceMetricsState [213499234]

Fixed

Bug

Status Update

No update yet.

Description

cc...@google.com

created issue #1

Jan 6, 2022 10:27PM

PerformanceMetricsStates doesn't appear to support arbitrarily long delays between writing and reading.

While it holds time ranges for for each state, that's isn't sufficient if, for example, there's a 3 frame delay for (not impossible for a frame that gets blocked on GPU composition, for example). You could have frames 1,2,3 where 1 & 3 have a single frame state key/value, but not 2.

Additionally, a couple other problems:

PerformanceMetricsStates#getIntervalStates uses nanoTime (via markSingleFrameStateForRemoval) to affect single frame states, which seems incorrect. It should be only using data from the times passed in.

It should instead be driven by the values passed in getIntervalStates(), since the time getIntervalStates is called may be some arbitrary point in the future. The behavior for single frame states should work even if they're not

getIntervalStates is destructive, so multiple JankStats instances will interfere (only the first will get single frame states). Instead, consider separating into two apis:

getIntervalStates() (as is, but just a getter, non destructive)
discardDataBeforeTimestamp() (discards data that happened before the end UI thread timestamp of last frame)

Comments

ch...@google.com <ch...@google.com> #2Jan 6, 2022 10:43PM

Trying to reproduce this on my 4.2.2 (v17) Nexus 4. Added this drawable:

<transition xmlns:android="

http://schemas.android.com/apk/res/android" >
<item android:drawable="@drawable/test_drawable_blue"/>
<item android:drawable="@drawable/test_drawable_green"/>
</transition>

where blue/green drawables look like this:

<shape
xmlns:android="

http://schemas.android.com/apk/res/android"
android:shape="rectangle">
<size
android:width="@dimen/drawable_large_size"
android:height="@dimen/drawable_small_size" />
<solid
android:color="@color/test_blue" />
</shape>

Then added this test:

@Test
public void testMutateTransitionDrawable() {
Drawable drawable = ResourcesCompat.getDrawable(mResources,
R.drawable.test_transition_drawable, null);
assertTrue(drawable instanceof TransitionDrawable);

Drawable mutated = drawable.mutate();
assertTrue(drawable instanceof TransitionDrawable);
assertTrue(mutated instanceof TransitionDrawable);
}

It passes on the device. Going to also try on other earlier devices a bit later in the day once they are charged.

ch...@google.com <ch...@google.com> #3Jan 13, 2022 11:35PM

Also not reproducible on Galaxy Nexus running 4.0.1 (v14), 4.0.4 (v15) and 4.2.2 (v17)

ap...@google.com <ap...@google.com> #4Jan 24, 2022 05:20PM

https://android-review.googlesource.com/c/platform/frameworks/support/+/960032 with the test. Closing as not reproducible. If this is still happening for you, we'd need to see either a test (same as in this CL) or a small, standalone sample project that reproduces this issue on v17 (or other) devices.

ch...@google.com <ch...@google.com> #5Jan 24, 2022 05:24PM

alpha problem (multiple instances) fixed, leaving bug open for other issues raised in #1

ch...@google.com <ch...@google.com> #6Mar 15, 2022 05:15PM

Specifically, these comments from #1 still need to be addressed:

1) PerformanceMetricsStates doesn't appear to support arbitrarily long delays between writing and reading.
While it holds time ranges for for each state, that's isn't sufficient if, for example, there's a 3 frame delay for (not impossible for a frame that gets blocked on GPU composition, for example). You could have frames 1,2,3 where 1 & 3 have a single frame state key/value, but not 2.
2) PerformanceMetricsStates#getIntervalStates uses nanoTime (via markSingleFrameStateForRemoval) to affect single frame states, which seems incorrect. It should be only using data from the times passed in.
It should instead be driven by the values passed in getIntervalStates(), since the time getIntervalStates is called may be some arbitrary point in the future. The behavior for single frame states should work even if they're not

For (2), that function is no longer called internally (and should be removed). The only other place that single frame states are removed is during a call to addSingleFrameState(). We use nanoTime there, because that is when the caller called the function, so it's the best time to use. That same time is used for both adding the state and removing any previous state, so it is consistent.
So I think the 'fix' here is just to remove markSingleFrameStateForRemoval(); the other logic seems okay.

For (1) I'm going to need clarification to understand the problem and proposed solution. When addSingleFrameState() is called, we log the time that it was added (and, later, when it is marked for removal). In processing a frame in the future, we check whether that state existed (was added but not yet marked for removal) within the timeframe of that frame. It's not clear what the problem is that's being described; whether there are delays in the system or not, we're still going to process/report single frame states exactly once, and only for frames which are in the correct envelope of time for those states.

ap...@google.com <ap...@google.com> #7Mar 15, 2022 08:28PM

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

commit 8aad27001a81138ac1aea014cc22793fbb976a6b
Author: Chet Haase <chet@google.com>
Date: Tue Mar 15 10:16:02 2022

Remove obsolete function for processing single frame states

markSingleFrameStateForRemoval() was historical and no longer used.
Removing to clean up the code and clarify the logic around the timing
of state removal.

Bug: 213499234
Test: JankStatsTest tests all pass
Change-Id: I8ffff839ed767ed564505962b2eeb0494be79396

M metrics/metrics-performance/src/main/java/androidx/metrics/performance/PerformanceMetricsState.kt

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

ch...@google.com <ch...@google.com> #8Mar 15, 2022 08:29PM

Reassigned to cc...@google.com.

CL in #7 fixes issue (2) in

comment #6

.
For issue (1) in #6, passing back to submitter for more info.

cc...@google.com <cc...@google.com> #9Mar 22, 2022 05:21PM

Reassigned to ch...@google.com.

Imagine you have the following events in order:

t=100 set state A=B
t=110 frame 1 occurs
t=120 set state A=C
t=130 set state A=D
t=140 frame 2 occurs
t=150 set state A=E
t=160 frame 3 occurs
t=170 callback from FrameMetricsListener fires with data from frame 1
t=180 callback from FrameMetricsListener fires with data from frame 2
t=190 callback from FrameMetricsListener fires with data from frame 3

Whether these are single frame states or not, you should be sending the following events:

frame1 = state{A=B}
frame2 = state{A=D} // C was overwritten
frame3 = state{A=E}

Currently though, you don't have enough data to reconstruct this information when the callbacks start firing. You're tracking add/removed for each state, but thats not enough to remember old values, once the values have changed. You want an event queue, something like the following:

[
   set state A=B (ts = 100)
   set state A=C (ts = 120)
   set state A=D (ts = 130)
   set state A=E (ts = 150)
]

Then, when the data for frame 1 occurs you know end of that frame is ts110, so it sends out frame1 = state{A=B} and drop the first item in the queue (take current data, and apply/drop recorded events up until ts=110).

When frame 2 occurs, 2nd and 3rd events are applied, so `frame2 = state{A=D} since C is overridden.

This concept can extend to add/remove state (for persistent state) and single frame states. With that queue, and the current callback state (most recent state issued to callback) you basically have two ops:

on add/remove/setFrameState (ui thread):
    synchronized(eventQueue) {
        eventQueue.push(event(..., System.nanoTime()))
    }

on framemetrics listener (handler thread):
    val eventsToApply = synchronized(eventQueue) {
        eventQueue.removeUntil(frame.end)
    }
    currentState = currentState.applyAll(eventsToApply)
    dispatchCallback(currentState, frame.end)

ap...@google.com <ap...@google.com> #10May 9, 2022 10:16PM

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

commit be9c1aa2cfb1295dbe2dc852f31f8a1e7ab39168
Author: Chet Haase <chet@google.com>
Date: Mon Apr 11 17:10:50 2022

Fixing frame timing issue, plus minor API change

Previously, state setting could potentially clobber existing states
which would have been valid for frames currently being processed.
The new approach stores all states without replacing existing ones
until they are done being processed.
More complex tests were added to ensure that these situations work.

Also, minor API change to switch MetricsStateHolder to simply Holder,
since it is already inside the PerformanceMetricsState class/namespace.

Bug: 226565716, 213499234
Test: Added new TestComplexFrameStateData, tested on API 32, 24, 16
Relnote: Previous Holder name was too verbose and unnecessary

Change-Id: I5a4d9095520399a146e6fd78eb50c86a7051738b

M metrics/metrics-performance/api/public_plus_experimental_current.txt
M metrics/metrics-performance/api/restricted_current.txt
M metrics/metrics-performance/src/main/java/androidx/metrics/performance/JankStats.kt
M metrics/metrics-performance/src/androidTest/java/androidx/metrics/performance/test/JankStatsTest.kt
M metrics/metrics-performance/src/main/java/androidx/metrics/performance/PerformanceMetricsState.kt
M metrics/integration-tests/janktest/src/main/java/androidx/metrics/performance/janktest/MessageListFragment.kt
M metrics/metrics-performance/src/androidTest/java/androidx/metrics/performance/test/DelayedActivity.kt
M metrics/metrics-performance/src/androidTest/java/androidx/metrics/performance/test/DelayedView.kt
M metrics/metrics-performance/api/current.txt

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

ch...@google.com <ch...@google.com> May 9, 2022 10:21PM

Marked as fixed.