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

The issue is that Jetifier modifies jars and does not remove signatures. Below is the original class:

Classfile /tmp/non-jetified/org/bouncycastle/jce/provider/ExtCRLException.class
Last modified Mar 1, 2015; size 362 bytes
MD5 checksum 3968a716f9e60e1ad36c34157bd0239f
class org.bouncycastle.jce.provider.ExtCRLException extends java.security.cert.CRLException
minor version: 0
major version: 49
flags: ACC_SUPER
Constant pool:
#1 = Utf8 <init>
#2 = Utf8 cause
#3 = Utf8 getCause
#4 = Utf8 java/security/cert/CRLException
#5 = Utf8 org/bouncycastle/jce/provider/ExtCRLException
#6 = Class #4 // java/security/cert/CRLException
#7 = Class #5 // org/bouncycastle/jce/provider/ExtCRLException
#8 = Utf8 Ljava/lang/Throwable;
#9 = Utf8 (Ljava/lang/String;)V
#10 = Utf8 ()Ljava/lang/Throwable;
#11 = Utf8 (Ljava/lang/String;Ljava/lang/Throwable;)V
#12 = NameAndType #2:#8 // cause:Ljava/lang/Throwable;
#13 = NameAndType #1:#9 // "<init>":(Ljava/lang/String;)V
#14 = Fieldref #7.#12 // org/bouncycastle/jce/provider/ExtCRLException.cause:Ljava/lang/Throwable;
#15 = Methodref #6.#13 // java/security/cert/CRLException."<init>":(Ljava/lang/String;)V
#16 = Utf8 Code
{
java.lang.Throwable cause;
descriptor: Ljava/lang/Throwable;
flags:

org.bouncycastle.jce.provider.ExtCRLException(java.lang.String, java.lang.Throwable);
descriptor: (Ljava/lang/String;Ljava/lang/Throwable;)V
flags:
Code:
stack=2, locals=3, args_size=3
0: aload_0
1: aload_1
2: invokespecial #15 // Method java/security/cert/CRLException."<init>":(Ljava/lang/String;)V
5: aload_0
6: aload_2
7: putfield #14 // Field cause:Ljava/lang/Throwable;
10: return

public java.lang.Throwable getCause();
descriptor: ()Ljava/lang/Throwable;
flags: ACC_PUBLIC
Code:
stack=1, locals=1, args_size=1
0: aload_0
1: getfield #14 // Field cause:Ljava/lang/Throwable;
4: areturn
}

One processed with Jetifier:

Classfile /tmp/jetified/org/bouncycastle/jce/provider/ExtCRLException.class
Last modified Oct 14, 2019; size 362 bytes
MD5 checksum 76bc557706ee3480e53d88b21316913f
class org.bouncycastle.jce.provider.ExtCRLException extends java.security.cert.CRLException
minor version: 0
major version: 49
flags: ACC_SUPER
Constant pool:
#1 = Utf8 org/bouncycastle/jce/provider/ExtCRLException
#2 = Class #1 // org/bouncycastle/jce/provider/ExtCRLException
#3 = Utf8 java/security/cert/CRLException
#4 = Class #3 // java/security/cert/CRLException
#5 = Utf8 cause
#6 = Utf8 Ljava/lang/Throwable;
#7 = Utf8 <init>
#8 = Utf8 (Ljava/lang/String;Ljava/lang/Throwable;)V
#9 = Utf8 (Ljava/lang/String;)V
#10 = NameAndType #7:#9 // "<init>":(Ljava/lang/String;)V
#11 = Methodref #4.#10 // java/security/cert/CRLException."<init>":(Ljava/lang/String;)V
#12 = NameAndType #5:#6 // cause:Ljava/lang/Throwable;
#13 = Fieldref #2.#12 // org/bouncycastle/jce/provider/ExtCRLException.cause:Ljava/lang/Throwable;
#14 = Utf8 getCause
#15 = Utf8 ()Ljava/lang/Throwable;
#16 = Utf8 Code
{
java.lang.Throwable cause;
descriptor: Ljava/lang/Throwable;
flags:

org.bouncycastle.jce.provider.ExtCRLException(java.lang.String, java.lang.Throwable);
descriptor: (Ljava/lang/String;Ljava/lang/Throwable;)V
flags:
Code:
stack=2, locals=3, args_size=3
0: aload_0
1: aload_1
2: invokespecial #11 // Method java/security/cert/CRLException."<init>":(Ljava/lang/String;)V
5: aload_0
6: aload_2
7: putfield #13 // Field cause:Ljava/lang/Throwable;
10: return

public java.lang.Throwable getCause();
descriptor: ()Ljava/lang/Throwable;
flags: ACC_PUBLIC
Code:
stack=1, locals=1, args_size=1
0: aload_0
1: getfield #13 // Field cause:Ljava/lang/Throwable;
4: areturn
}

Changes in the constants pool cause changes in the code (indices change), which causes different MD5 checksums. This means that signatures will not match any more.

This started happening in 3.6.0-beta01 because we are using Jetifier with copyUnmodifiedLibsAlso=true flag (previously it was false).

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

@Chris You can work around this by updating gradle.properties with:

android.jetifier.blacklist=.*bcprov.*

This will avoid Jetifying the bouncycastle library.

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

Thanks Ivan!

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

Pending fix in:

https://android-review.googlesource.com/c/platform/frameworks/support/+/1151460

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

did this fix make it in for 3.6?

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

Jetifier 1.0.0-beta08 was released and has a fix for this.

To avoid waiting for new Android Studio you can workaround this in the meantime by forcing usage of a new version of jetifier in gradle:
buildscript {
dependencies {
classpath 'com.android.tools.build:gradle:x.y.z'
classpath 'com.android.tools.build.jetifier:jetifier-processor:1.0.0-beta08' // <- Add this
}
}

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

Reassigned to cc...@google.com.

Jetifier 1.0.0-beta08, which has the fix for this issue, will be integrated into AGP 3.6.0-rc01 and 4.0.0-alpha06:

https://android.googlesource.com/platform/tools/base/+/ef5e56702b626b6be642ecce7d0078b7b1a81bcb

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.