Skip to content

Commit

Permalink
Improve tracking on choreographer frame ends
Browse files Browse the repository at this point in the history
## Behavior changes

Whenever possible (i.e. any API != 28), we'll now detect the end of a frame by spying on main thread messages and running code right when the main thread message is done running and before a new main thread message starts running, by leveraging `Looper.getMainLooper().setMessageLogging { }`. We're also detecting whether we're in a frame or not by looking at the name of the runnable, rather than by creating a stacktrace.

## Non backward compatible API changes

- Renamed `MainThreadMessageSpy.startTracing()` and `MainThreadMessageSpy.stopTracing()` to `MainThreadMessageSpy.addTracer()` and `MainThreadMessageSpy.removeTracer()`.

## New APIs

- `MainThreadMessageSpy.startSpyingMainThreadDispatching()` and `MainThreadMessageSpy.stopSpyingMainThreadDispatching()`, `MainThreadMessageSpy.currentMessageAsString`, `MainThreadMessageSpy.enabled` and `MainThreadMessageSpy.onCurrentMessageFinished()`
- `MainThreadMessageScopedLazy` (`prop by mainThreadMessageScopedLazy {}`) property for main thread scoped lazy properties that get cleared at the end of each main thread message.
- `Choreographers.postOnFrameRendered()`, `Choreographers.postOnWindowFrameRendered()` and `Choreographers.isInChoreographerFrame`
- `InputEventTrigger.rendered`, `InputEventTrigger.renderedUptime` and `InputEventTrigger.onInputEventFrameRendered`
  • Loading branch information
pyricau committed Sep 9, 2024
1 parent 4d8e46c commit 0bba709
Show file tree
Hide file tree
Showing 21 changed files with 490 additions and 190 deletions.
48 changes: 31 additions & 17 deletions .github/workflows/android.yml
Original file line number Diff line number Diff line change
Expand Up @@ -33,18 +33,29 @@ jobs:
# Allow tests to continue on other devices if they fail on one device.
fail-fast: false
matrix:
arch: [ x86_64 ]
target: [ google_apis ]
channel: [ stable ]
api-level:
- 21
- 22
- 23
- 24
- 25
# Disabled 26, running into https://github.com/ReactiveCircus/android-emulator-runner/issues/385
# - 26
- 26
- 27
- 28
- 29
- 30
# No tests found, process crashed
# - 31
# No tests found, process crashed
# - 32
# No tests found, process crashed
# - 33
# Disabled 34: needs min target SDK 23, and upgrading AGP.
# - 34
arch: [ x86_64 ]
target: [ google_apis ]
channel: [ stable ]
steps:
- name: Enable KVM group perms
run: |
Expand All @@ -67,21 +78,25 @@ jobs:
~/.android/adb*
key: avd-cached-${{ matrix.api-level }}-${{ matrix.os }}-${{ matrix.target }}
- name: Create AVD and generate snapshot for caching
if: steps.avd-cache.outputs.cache-hit != 'true'
uses: reactivecircus/android-emulator-runner@v2
with:
api-level: ${{ matrix.api-level }}
target: ${{ matrix.target }}
arch: ${{ matrix.arch }}
force-avd-creation: false
emulator-options: -no-window -gpu swiftshader_indirect -noaudio -no-boot-anim -camera-back none -no-snapshot-load
disable-animations: false
script: echo "Generated AVD snapshot for caching."
# Wondering if the caching migth cause the errors
# if: steps.avd-cache.outputs.cache-hit != 'true'
# if: ${{ always() }}
# uses: reactivecircus/android-emulator-runner@v2
# with:
# api-level: ${{ matrix.api-level }}
# target: ${{ matrix.target }}
# arch: ${{ matrix.arch }}
# force-avd-creation: false
# emulator-options: -no-window -gpu swiftshader_indirect -noaudio -no-boot-anim -camera-back none -no-snapshot-load
# disable-animations: false
# script: echo "Generated AVD snapshot for caching."
- name: Instrumentation Tests
uses: reactivecircus/android-emulator-runner@v2
with:
api-level: ${{ matrix.api-level }}
force-avd-creation: false
# Let's see what happens if we do this.
force-avd-creation: true
# force-avd-creation: false
target: ${{ matrix.target }}
arch: ${{ matrix.arch }}
emulator-options: -no-window -gpu swiftshader_indirect -noaudio -no-boot-anim -no-metrics -camera-back none -no-snapshot-save
Expand All @@ -91,7 +106,6 @@ jobs:
adb logcat >> emulator.log & # pipe all logcat messages into log file as a background process
adb shell settings put global package_verifier_user_consent -1
./gradlew connectedCheck --no-build-cache --no-daemon --stacktrace
- name: Upload results
if: ${{ always() }}
uses: actions/upload-artifact@v3
Expand All @@ -103,7 +117,7 @@ jobs:
snapshot-deployment:
if: github.repository == 'square/papa' && github.event_name == 'push'
needs: [ checks , instrumentation-tests ]
needs: [ checks ]
runs-on: ubuntu-latest
steps:
- uses: actions/checkout@v3
Expand Down
19 changes: 17 additions & 2 deletions papa-main-trace/api/papa-main-trace.api
Original file line number Diff line number Diff line change
@@ -1,7 +1,22 @@
public final class papa/MainThreadMessageScopedLazy : kotlin/properties/ReadOnlyProperty {
public fun <init> (Lkotlin/jvm/functions/Function0;)V
public final fun getProvider ()Lkotlin/jvm/functions/Function0;
public fun getValue (Ljava/lang/Object;Lkotlin/reflect/KProperty;)Ljava/lang/Object;
}

public final class papa/MainThreadMessageScopedLazyKt {
public static final fun mainThreadMessageScopedLazy (Lkotlin/jvm/functions/Function0;)Lpapa/MainThreadMessageScopedLazy;
}

public final class papa/MainThreadMessageSpy {
public static final field INSTANCE Lpapa/MainThreadMessageSpy;
public final fun startTracing (Lpapa/MainThreadMessageSpy$Tracer;)V
public final fun stopTracing (Lpapa/MainThreadMessageSpy$Tracer;)V
public final fun addTracer (Lpapa/MainThreadMessageSpy$Tracer;)V
public final fun getCurrentMessageAsString ()Ljava/lang/String;
public final fun getEnabled ()Z
public final fun onCurrentMessageFinished (Lkotlin/jvm/functions/Function0;)V
public final fun removeTracer (Lpapa/MainThreadMessageSpy$Tracer;)V
public final fun startSpyingMainThreadDispatching ()V
public final fun stopSpyingMainThreadDispatching ()V
}

public abstract interface class papa/MainThreadMessageSpy$Tracer {
Expand Down
26 changes: 26 additions & 0 deletions papa-main-trace/src/main/java/papa/MainThreadMessageScopedLazy.kt
Original file line number Diff line number Diff line change
@@ -0,0 +1,26 @@
package papa

import kotlin.properties.ReadOnlyProperty
import kotlin.reflect.KProperty

class MainThreadMessageScopedLazy<T>(val provider: () -> T) : ReadOnlyProperty<Any?, T> {

private var valueOrNull: T? = null

override fun getValue(
thisRef: Any?,
property: KProperty<*>
): T {
check(MainThreadMessageSpy.enabled) {
"Can't use a MainThreadMessageScopedLazy when MainThreadMessageSpy is not enabled."
}
val value = provider()
valueOrNull = value
MainThreadMessageSpy.onCurrentMessageFinished {
valueOrNull = null
}
return value
}
}

fun <T> mainThreadMessageScopedLazy(provider: () -> T) = MainThreadMessageScopedLazy(provider)
80 changes: 52 additions & 28 deletions papa-main-trace/src/main/java/papa/MainThreadMessageSpy.kt
Original file line number Diff line number Diff line change
Expand Up @@ -14,7 +14,46 @@ object MainThreadMessageSpy {

private val tracers = mutableListOf<Tracer>()

fun startTracing(tracer: Tracer) {
var enabled = false
private set

var currentMessageAsString: String? = null
private set
get() {
checkMainThread()
return field
}

fun addTracer(tracer: Tracer) {
checkMainThread()
check(tracers.none { it === tracers }) {
"Tracer $tracer already in $tracers"
}
tracers.add(tracer)
}

fun removeTracer(tracer: Tracer) {
checkMainThread()
tracers.removeAll { it === tracer }
}

fun onCurrentMessageFinished(block: () -> Unit) {
if (!enabled) {
return
}
checkMainThread()
tracers.add(object : Tracer {
override fun onMessageDispatch(
messageAsString: String,
before: Boolean
) {
tracers.remove(this)
block()
}
})
}

fun startSpyingMainThreadDispatching() {
checkMainThread()
if (VERSION.SDK_INT == 28) {
// This is disabled on Android 9 because it can introduce crashes. The log is created by
Expand All @@ -31,43 +70,28 @@ object MainThreadMessageSpy {
// https://cs.android.com/android/platform/superproject/+/master:frameworks/base/core/java/android/app/UiAutomation.java;l=1365-1371;drc=master
return
}
check(tracers.none { it === tracers }) {
"Tracer $tracer already in $tracers"
}
tracers.add(tracer)
if (tracers.size == 1) {
startSpyingMainThreadDispatching()
}
}

fun stopTracing(tracer: Tracer) {
checkMainThread()
val singleTracerLeft = tracers.size == 1
tracers.removeAll { it === tracer }
if (singleTracerLeft && tracers.isEmpty()) {
stopSpyingMainThreadDispatching()
}
}

private fun startSpyingMainThreadDispatching() {
enabled = true
// Looper can log to a printer before and after each message. We leverage this to surface the
// beginning and end of every main thread message in system traces. This costs a few extra string
// concatenations for each message handling.
// The printer is called before ('>>' prefix) and after ('<<' prefix) every message.
Looper.getMainLooper().setMessageLogging { messageAsString ->
if (messageAsString.startsWith('>')) {
for (tracer in tracers) {
tracer.onMessageDispatch(messageAsString, before = true)
}
val before = messageAsString.startsWith('>')
currentMessageAsString = if (before) {
messageAsString
} else {
for (tracer in tracers) {
tracer.onMessageDispatch(messageAsString, before = false)
}
null
}
for (tracer in tracers) {
tracer.onMessageDispatch(messageAsString, before = before)
}
}
}

private fun stopSpyingMainThreadDispatching() {
fun stopSpyingMainThreadDispatching() {
checkMainThread()
currentMessageAsString = null
enabled = false
Looper.getMainLooper().setMessageLogging(null)
}

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -36,7 +36,7 @@ internal object SafeTraceMainThreadMessages {
if (!enabled && SafeTrace.isTraceable && traceMainThreadMessages) {
enabled = true
var currentlyTracing = false
MainThreadMessageSpy.startTracing { messageAsString, before ->
MainThreadMessageSpy.addTracer { messageAsString, before ->
if (!currentlyTracing) {
if (SafeTrace.isCurrentlyTracing &&
before &&
Expand Down
26 changes: 19 additions & 7 deletions papa/api/papa.api
Original file line number Diff line number Diff line change
Expand Up @@ -201,20 +201,28 @@ public final class papa/AppVisibilityState : java/lang/Enum {
public static fun values ()[Lpapa/AppVisibilityState;
}

public final class papa/Choreographers {
public static final field INSTANCE Lpapa/Choreographers;
public final fun isInChoreographerFrame ()Z
public final fun postOnFrameRendered (Lpapa/OnFrameRenderedListener;)V
public final fun postOnWindowFrameRendered (Landroid/view/Window;Lpapa/OnFrameRenderedListener;)V
}

public abstract interface class papa/FinishingInteraction : papa/TrackedInteraction {
}

public final class papa/InputEventTrigger {
public static final field Companion Lpapa/InputEventTrigger$Companion;
public synthetic fun <init> (Landroid/view/InputEvent;JLkotlin/jvm/internal/DefaultConstructorMarker;)V
public final fun component1 ()Landroid/view/InputEvent;
public final fun component2-UwyO8pc ()J
public final fun copy-HG0u8IE (Landroid/view/InputEvent;J)Lpapa/InputEventTrigger;
public static synthetic fun copy-HG0u8IE$default (Lpapa/InputEventTrigger;Landroid/view/InputEvent;JILjava/lang/Object;)Lpapa/InputEventTrigger;
public fun equals (Ljava/lang/Object;)Z
public final fun getDeliveryUptime-UwyO8pc ()J
public final fun getInputEvent ()Landroid/view/InputEvent;
public fun hashCode ()I
public fun toString ()Ljava/lang/String;
public final fun getRendered ()Z
public final fun getRenderedUptime-FghU774 ()Lkotlin/time/Duration;
public final fun onInputEventFrameRendered (Lpapa/OnFrameRenderedListener;)V
}

public final class papa/InputEventTrigger$Companion {
public final fun createTrackingWhenFrameRendered-SxA4cEA (Landroid/view/Window;Landroid/view/InputEvent;J)Lpapa/InputEventTrigger;
}

public final class papa/InputEventTriggerKt {
Expand Down Expand Up @@ -335,6 +343,10 @@ public final class papa/OnEventScope$DefaultImpls {
public static synthetic fun startInteraction-SxA4cEA$default (Lpapa/OnEventScope;Lpapa/InteractionTrigger;Lpapa/InteractionTrace;JILjava/lang/Object;)Lpapa/RunningInteraction;
}

public abstract interface class papa/OnFrameRenderedListener {
public abstract fun onFrameRendered-LRDsOJo (J)V
}

public abstract class papa/PapaEvent {
}

Expand Down
58 changes: 58 additions & 0 deletions papa/src/androidTest/java/papa/test/MainThreadMessageSpyTest.kt
Original file line number Diff line number Diff line change
@@ -0,0 +1,58 @@
package papa.test

import com.google.common.truth.Truth.assertThat
import org.junit.Test
import papa.MainThreadMessageSpy
import papa.internal.mainHandler
import papa.internal.postAtFrontOfQueueAsync
import java.util.concurrent.CountDownLatch
import java.util.concurrent.TimeUnit.SECONDS

// TODO Skip these tests on version 28 / have other tests that check it's disabled
class MainThreadMessageSpyTest {

@Test fun current_message_set_to_runnable_to_string() {
val runnableRan = CountDownLatch(1)
var runnableCurrentMessageAsString: String? = null

class MyRunnable : Runnable {
override fun run() {
runnableCurrentMessageAsString = MainThreadMessageSpy.currentMessageAsString
runnableRan.countDown()
}

override fun toString(): String {
return "Baguette"
}
}

mainHandler.post(MyRunnable())
check(runnableRan.await(5, SECONDS))

assertThat(runnableCurrentMessageAsString).doesNotContain("MyRunnable")
assertThat(runnableCurrentMessageAsString).contains("Baguette")
}

@Test fun onCurrentMessageFinished_runs_at_end_of_current_post() {
val runnablesRan = CountDownLatch(3)
val runOrder = mutableListOf<String>()

mainHandler.post {
mainHandler.postAtFrontOfQueueAsync {
runOrder += "second post"
runnablesRan.countDown()
}
MainThreadMessageSpy.onCurrentMessageFinished {
runOrder += "first post finished"
runnablesRan.countDown()
}
runOrder += "first post"
runnablesRan.countDown()
}
check(runnablesRan.await(5, SECONDS))

assertThat(runOrder)
.containsExactly("first post", "first post finished", "second post")
.inOrder()
}
}
Loading

0 comments on commit 0bba709

Please sign in to comment.