diff --git a/.github/workflows/android.yml b/.github/workflows/android.yml index 3202d87..07ccd2d 100644 --- a/.github/workflows/android.yml +++ b/.github/workflows/android.yml @@ -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: | @@ -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 @@ -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 @@ -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 diff --git a/papa-main-trace/api/papa-main-trace.api b/papa-main-trace/api/papa-main-trace.api index 4ba51d4..4f58971 100644 --- a/papa-main-trace/api/papa-main-trace.api +++ b/papa-main-trace/api/papa-main-trace.api @@ -1,7 +1,22 @@ +public final class papa/MainThreadMessageScopedLazy : kotlin/properties/ReadOnlyProperty { + public fun (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 { diff --git a/papa-main-trace/src/main/java/papa/MainThreadMessageScopedLazy.kt b/papa-main-trace/src/main/java/papa/MainThreadMessageScopedLazy.kt new file mode 100644 index 0000000..2bb2ba4 --- /dev/null +++ b/papa-main-trace/src/main/java/papa/MainThreadMessageScopedLazy.kt @@ -0,0 +1,26 @@ +package papa + +import kotlin.properties.ReadOnlyProperty +import kotlin.reflect.KProperty + +class MainThreadMessageScopedLazy(val provider: () -> T) : ReadOnlyProperty { + + 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 mainThreadMessageScopedLazy(provider: () -> T) = MainThreadMessageScopedLazy(provider) diff --git a/papa-main-trace/src/main/java/papa/MainThreadMessageSpy.kt b/papa-main-trace/src/main/java/papa/MainThreadMessageSpy.kt index d79c214..9a397e0 100644 --- a/papa-main-trace/src/main/java/papa/MainThreadMessageSpy.kt +++ b/papa-main-trace/src/main/java/papa/MainThreadMessageSpy.kt @@ -14,7 +14,46 @@ object MainThreadMessageSpy { private val tracers = mutableListOf() - 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 @@ -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) } diff --git a/papa-safetrace/src/main/java/papa/internal/SafeTraceMainThreadMessages.kt b/papa-safetrace/src/main/java/papa/internal/SafeTraceMainThreadMessages.kt index 2ed3e40..73f2826 100644 --- a/papa-safetrace/src/main/java/papa/internal/SafeTraceMainThreadMessages.kt +++ b/papa-safetrace/src/main/java/papa/internal/SafeTraceMainThreadMessages.kt @@ -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 && diff --git a/papa/api/papa.api b/papa/api/papa.api index 1b3bedd..e1a4ce1 100644 --- a/papa/api/papa.api +++ b/papa/api/papa.api @@ -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 (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 { @@ -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 { } diff --git a/papa/src/androidTest/java/papa/test/MainThreadMessageSpyTest.kt b/papa/src/androidTest/java/papa/test/MainThreadMessageSpyTest.kt new file mode 100644 index 0000000..300f1be --- /dev/null +++ b/papa/src/androidTest/java/papa/test/MainThreadMessageSpyTest.kt @@ -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() + + 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() + } +} \ No newline at end of file diff --git a/papa/src/androidTest/java/papa/test/PerfMonitoringTest.kt b/papa/src/androidTest/java/papa/test/PerfMonitoringTest.kt index bdcac71..4742f82 100644 --- a/papa/src/androidTest/java/papa/test/PerfMonitoringTest.kt +++ b/papa/src/androidTest/java/papa/test/PerfMonitoringTest.kt @@ -26,10 +26,11 @@ import org.hamcrest.Matcher import org.junit.Test import papa.AndroidComponentEvent import papa.AppStart.AppStartData +import papa.Choreographers +import papa.MainThreadMessageSpy import papa.PapaEvent.FrozenFrameOnTouch import papa.PapaEventListener import papa.internal.Perfs -import papa.internal.isChoreographerDoingFrame import papa.internal.mainHandler import papa.test.utilities.TestActivity import radiography.Radiography @@ -157,7 +158,7 @@ class PerfMonitoringTest { var isChoreographerDoingFrame = false mainHandler.post { Choreographer.getInstance().postFrameCallback { - isChoreographerDoingFrame = isChoreographerDoingFrame() + isChoreographerDoingFrame = Choreographers.isInChoreographerFrame() frameCallbackLatch.countDown() } } @@ -165,17 +166,60 @@ class PerfMonitoringTest { assertThat(isChoreographerDoingFrame).isTrue() } - @Test fun Choreographer_not_doing_Frame() { + @Test fun Choreographer_is_doing_Frame_no_spying() { + postOnMainBlocking { + MainThreadMessageSpy.stopSpyingMainThreadDispatching() + } val frameCallbackLatch = CountDownLatch(1) var isChoreographerDoingFrame = false mainHandler.post { - isChoreographerDoingFrame = isChoreographerDoingFrame() - frameCallbackLatch.countDown() + Choreographer.getInstance().postFrameCallback { + isChoreographerDoingFrame = Choreographers.isInChoreographerFrame() + frameCallbackLatch.countDown() + } } check(frameCallbackLatch.await(10, SECONDS)) + assertThat(isChoreographerDoingFrame).isTrue() + + // reset + postOnMainBlocking { + MainThreadMessageSpy.startSpyingMainThreadDispatching() + } + } + + @Test fun Choreographer_not_doing_Frame() { + var isChoreographerDoingFrame = false + postOnMainBlocking { + isChoreographerDoingFrame = Choreographers.isInChoreographerFrame() + } assertThat(isChoreographerDoingFrame).isFalse() } + @Test fun Choreographer_not_doing_Frame_no_spying() { + postOnMainBlocking { + MainThreadMessageSpy.stopSpyingMainThreadDispatching() + } + var isChoreographerDoingFrame = false + postOnMainBlocking { + isChoreographerDoingFrame = Choreographers.isInChoreographerFrame() + } + assertThat(isChoreographerDoingFrame).isFalse() + + // reset + postOnMainBlocking { + MainThreadMessageSpy.startSpyingMainThreadDispatching() + } + } + + private fun postOnMainBlocking(block: () -> Unit) { + val waitForMainPost = CountDownLatch(1) + mainHandler.post { + block() + waitForMainPost.countDown() + } + check(waitForMainPost.await(10, SECONDS)) + } + private fun dismissCheckForUpdates() { val uiDevice = UiDevice.getInstance(InstrumentationRegistry.getInstrumentation()) val deprecationDialog = uiDevice.wait( diff --git a/papa/src/main/java/papa/Choreographers.kt b/papa/src/main/java/papa/Choreographers.kt new file mode 100644 index 0000000..5e2efc2 --- /dev/null +++ b/papa/src/main/java/papa/Choreographers.kt @@ -0,0 +1,107 @@ +package papa + +import android.view.Choreographer +import android.view.Window +import papa.internal.isMainThread +import papa.internal.mainHandler +import papa.internal.onNextPreDraw +import papa.internal.postAtFrontOfQueueAsync +import kotlin.time.Duration.Companion.nanoseconds + +object Choreographers { + + private val pendingRenderedCallbacks = mutableListOf() + + private val isInChoreographerFrameMessage by mainThreadMessageScopedLazy { + "android.view.Choreographer\$FrameDisplayEventReceiver" in MainThreadMessageSpy.currentMessageAsString!! + } + + /** + * Whether the current call stack is rooted by a Choreographer#doFrame + * + * When [MainThreadMessageSpy.enabled] is true, we rely on the toString of the current main + * thread message to check this, and we cache the result for the duration of the current main + * thread message. When [MainThreadMessageSpy.enabled] is false, we capture a stacktrace (which is + * slower) and look for Choreographer#doFrame in the stacktrace. + * + * This approach is overall fragile and needs to be tested against new versions of Android. + */ + fun isInChoreographerFrame(): Boolean { + if (!isMainThread) { + return false + } + if (MainThreadMessageSpy.enabled) { + return isInChoreographerFrameMessage + } + // Fallback to slower method: capturing a stacktrace. + val stackTrace = RuntimeException().stackTrace + for (i in stackTrace.lastIndex downTo 0) { + val element = stackTrace[i] + if (element.className == "android.view.Choreographer" && + element.methodName == "doFrame" + ) { + return true + } + } + return false + } + + /** + * Runs [callback] after the current or next call to Choreographer#doFrame is done. This + * leverages [isInChoreographerFrame] to the same warnings apply. + */ + fun postOnFrameRendered(callback: OnFrameRenderedListener) { + if (isInChoreographerFrame()) { + postOnCurrentFrameRendered(callback) + } else { + Choreographer.getInstance().postFrameCallback { + postOnCurrentFrameRendered(callback) + } + } + } + + /** + * Should be called from within a choreographer frame callback. + */ + internal fun postOnCurrentFrameRendered(callback: OnFrameRenderedListener) { + val alreadyScheduled = pendingRenderedCallbacks.isNotEmpty() + pendingRenderedCallbacks += callback + if (alreadyScheduled) { + return + } + val runPendingCallbacks = { + val frameRenderedUptime = System.nanoTime().nanoseconds + for (pendingCallback in pendingRenderedCallbacks) { + try { + pendingCallback.onFrameRendered(frameRenderedUptime) + } catch (e: AbstractMethodError) { + throw RuntimeException("Lambda $pendingCallback does not implement " + + "${OnFrameRenderedListener::class.java}, try declaring it with " + + "${OnFrameRenderedListener::class.simpleName} { }", e) + } + } + pendingRenderedCallbacks.clear() + } + if (MainThreadMessageSpy.enabled) { + MainThreadMessageSpy.onCurrentMessageFinished(runPendingCallbacks) + } else { + // The frame callback runs somewhat in the middle of rendering, so by posting at the front + // of the queue from there we get the timestamp for right when the next frame is done + // rendering. + // The main thread is a single thread, and work always executes one task at a time. We're + // creating an async message that won't be reordered to execute after sync barriers (which are + // used for processing input events and rendering frames). "sync barriers" are essentially + // prioritized messages. When you post, you + // can post to the front or the back, and you're just inserting in a different place in the + // queue. When the queue is done with the current message, it looks at its head for the next + // message. Unless there's a special message enqueued called a sync barrier, which basically has + // top priority and will run prior to the current head if its time that's gone. Async prevents + // this behavior. + mainHandler.postAtFrontOfQueueAsync(runPendingCallbacks) + } + } + + fun Window.postOnWindowFrameRendered(callback: OnFrameRenderedListener) { + onNextPreDraw { postOnCurrentFrameRendered(callback) } + } +} diff --git a/papa/src/main/java/papa/InputEventTrigger.kt b/papa/src/main/java/papa/InputEventTrigger.kt index f721eb9..5e7b039 100644 --- a/papa/src/main/java/papa/InputEventTrigger.kt +++ b/papa/src/main/java/papa/InputEventTrigger.kt @@ -1,12 +1,49 @@ package papa import android.view.InputEvent +import android.view.Window +import papa.Choreographers.postOnWindowFrameRendered +import papa.internal.checkMainThread import kotlin.time.Duration -data class InputEventTrigger( +class InputEventTrigger private constructor( val inputEvent: InputEvent, val deliveryUptime: Duration -) +) { + var renderedUptime: Duration? = null + private set + val rendered: Boolean + get() = renderedUptime != null + + private val inputEventFrameRenderedCallbacks = + mutableListOf(OnFrameRenderedListener { renderedUptime = it }) + + fun onInputEventFrameRendered(listener: OnFrameRenderedListener) { + checkMainThread() + renderedUptime?.let { + listener.onFrameRendered(it) + return + } + inputEventFrameRenderedCallbacks.add(listener) + } + + companion object { + fun createTrackingWhenFrameRendered( + inputEventWindow: Window, + inputEvent: InputEvent, + deliveryUptime: Duration + ): InputEventTrigger { + val trigger = InputEventTrigger(inputEvent, deliveryUptime) + inputEventWindow.postOnWindowFrameRendered { + for (callback in trigger.inputEventFrameRenderedCallbacks) { + callback.onFrameRendered(it) + } + trigger.inputEventFrameRenderedCallbacks.clear() + } + return trigger + } + } +} fun InteractionTrigger.toInputEventTriggerOrNull(): InteractionTriggerWithPayload? { @Suppress("UNCHECKED_CAST") diff --git a/papa/src/main/java/papa/InteractionRuleClient.kt b/papa/src/main/java/papa/InteractionRuleClient.kt index 6e61c6e..34d4d49 100644 --- a/papa/src/main/java/papa/InteractionRuleClient.kt +++ b/papa/src/main/java/papa/InteractionRuleClient.kt @@ -2,10 +2,10 @@ package papa import android.view.Choreographer import android.view.Choreographer.FrameCallback +import papa.InteractionResult.Finished import papa.internal.checkMainThread import papa.internal.isMainThread import papa.internal.mainHandler -import papa.internal.onCurrentOrNextFrameRendered import kotlin.time.Duration import kotlin.time.Duration.Companion.minutes import kotlin.time.Duration.Companion.nanoseconds @@ -165,13 +165,13 @@ private class InteractionEngine( stopRunning() finishingInteractions += this recordEvent() - onCurrentOrNextFrameRendered { frameRenderedUptime -> + Choreographers.postOnFrameRendered { frameRenderedUptime -> trace.endTrace() choreographer.removeFrameCallback(this) finishingInteractions -= this val eventsCopy = sentEvents.toList() resultListener.onInteractionResult( - InteractionResult.Finished( + Finished( data = InteractionResultDataPayload( interactionTrigger = interactionTrigger, runningFrameCount = frameCountSinceStart, diff --git a/papa/src/main/java/papa/OnFrameRenderedListener.kt b/papa/src/main/java/papa/OnFrameRenderedListener.kt new file mode 100644 index 0000000..5358bc4 --- /dev/null +++ b/papa/src/main/java/papa/OnFrameRenderedListener.kt @@ -0,0 +1,7 @@ +package papa + +import kotlin.time.Duration + +fun interface OnFrameRenderedListener { + fun onFrameRendered(frameRenderedUptime: Duration) +} \ No newline at end of file diff --git a/papa/src/main/java/papa/internal/ApplicationHolder.kt b/papa/src/main/java/papa/internal/ApplicationHolder.kt index 496e0d2..e3fa412 100644 --- a/papa/src/main/java/papa/internal/ApplicationHolder.kt +++ b/papa/src/main/java/papa/internal/ApplicationHolder.kt @@ -1,6 +1,8 @@ package papa.internal import android.app.Application +import com.squareup.papa.R +import papa.MainThreadMessageSpy import papa.SafeTrace import papa.SafeTraceSetup @@ -12,14 +14,25 @@ internal object ApplicationHolder { var application: Application? = null private set - fun install(application: Application, isForegroundImportance: Boolean) { + fun install( + application: Application, + isForegroundImportance: Boolean + ) { this.application = application SafeTraceSetup.init(application) if (isForegroundImportance) { SafeTrace.beginAsyncSection(Perfs.LAUNCH_TRACE_NAME) } - InputTracker.install(application) + val resources = application.resources + if (resources.getBoolean(R.bool.papa_track_input_events)) { + InputTracker.install() + } FrozenFrameOnTouchDetector.install() - MainThreadTriggerTracer.install(application) + if (resources.getBoolean(R.bool.papa_spy_main_thread_messages)) { + MainThreadMessageSpy.startSpyingMainThreadDispatching() + } + if (resources.getBoolean(R.bool.papa_track_main_thread_triggers)) { + MainThreadTriggerTracer.install() + } } } \ No newline at end of file diff --git a/papa/src/main/java/papa/internal/Choreographers.kt b/papa/src/main/java/papa/internal/Choreographers.kt deleted file mode 100644 index 398cbb4..0000000 --- a/papa/src/main/java/papa/internal/Choreographers.kt +++ /dev/null @@ -1,66 +0,0 @@ -package papa.internal - -import android.view.Choreographer -import kotlin.time.Duration -import kotlin.time.Duration.Companion.nanoseconds - -private val pendingRenderedCallbacks = mutableListOf<(Duration) -> Unit>() - -internal fun onCurrentOrNextFrameRendered(callback: (Duration) -> Unit) { - if (isChoreographerDoingFrame()) { - onCurrentFrameRendered(callback) - } else { - Choreographer.getInstance().postFrameCallback { - onCurrentFrameRendered(callback) - } - } -} - -/** - * Note: this is somewhat slow and fragile. - */ -internal fun isChoreographerDoingFrame(): Boolean { - if (!isMainThread) { - return false - } - val stackTrace = RuntimeException().stackTrace - for (i in stackTrace.lastIndex downTo 0) { - val element = stackTrace[i] - if (element.className == "android.view.Choreographer" && - element.methodName == "doFrame" - ) { - return true - } - } - return false -} - -/** - * Should be called from within a choreographer frame callback - */ -internal fun onCurrentFrameRendered(callback: (Duration) -> Unit) { - val alreadyScheduled = pendingRenderedCallbacks.isNotEmpty() - pendingRenderedCallbacks += callback - if (alreadyScheduled) { - return - } - // The frame callback runs somewhat in the middle of rendering, so by posting at the front - // of the queue from there we get the timestamp for right when the next frame is done - // rendering. - // The main thread is a single thread, and work always executes one task at a time. We're - // creating an async message that won't be reordered to execute after sync barriers (which are - // used for processing input events and rendering frames). "sync barriers" are essentially - // prioritized messages. When you post, you - // can post to the front or the back, and you're just inserting in a different place in the - // queue. When the queue is done with the current message, it looks at its head for the next - // message. Unless there's a special message enqueued called a sync barrier, which basically has - // top priority and will run prior to the current head if its time that's gone. Async prevents - // this behavior. - mainHandler.postAtFrontOfQueueAsync { - val frameRenderedUptime = System.nanoTime().nanoseconds - for (pendingCallback in pendingRenderedCallbacks) { - pendingCallback(frameRenderedUptime) - } - pendingRenderedCallbacks.clear() - } -} diff --git a/papa/src/main/java/papa/internal/FrozenFrameOnTouchDetector.kt b/papa/src/main/java/papa/internal/FrozenFrameOnTouchDetector.kt index 368ba0e..c8a0ac0 100644 --- a/papa/src/main/java/papa/internal/FrozenFrameOnTouchDetector.kt +++ b/papa/src/main/java/papa/internal/FrozenFrameOnTouchDetector.kt @@ -11,9 +11,12 @@ import curtains.TouchEventInterceptor import curtains.phoneWindow import curtains.touchEventInterceptors import curtains.windowAttachCount +import papa.Choreographers.postOnWindowFrameRendered +import papa.OnFrameRenderedListener import papa.PapaEvent.FrozenFrameOnTouch import papa.PapaEventListener import papa.internal.FrozenFrameOnTouchDetector.install +import kotlin.time.Duration /** * Detects when the interval of time between when a touch event is issued and the next frame is @@ -42,25 +45,29 @@ internal object FrozenFrameOnTouchDetector { if (handledTime - motionEvent.eventTime > FrozenFrameOnTouch.FROZEN_FRAME_THRESHOLD) { val windowTitle = window.attributes.title.toString().substringAfter("/") touchDownWaitingRender = MotionEvent.obtain(motionEvent) - onCurrentOrNextFrameRendered { frameRenderedUptime -> - val localTouchDownWaitingRender = touchDownWaitingRender!! - val sentTime = localTouchDownWaitingRender.eventTime - val sentToReceive = handledTime - sentTime - val receiveToFrame = frameRenderedUptime.inWholeMilliseconds - handledTime - PapaEventListener.sendEvent( - FrozenFrameOnTouch( - activityName = windowTitle, - repeatTouchDownCount = repeatTouchDownCount, - deliverDurationUptimeMillis = sentToReceive, - dislayDurationUptimeMillis = receiveToFrame, - pressedView = pressedViewName + // When compiling with Java11 we get AbstractMethodError at runtime when this is a lambda. + @Suppress("ObjectLiteralToLambda") + window.postOnWindowFrameRendered(object : OnFrameRenderedListener { + override fun onFrameRendered(frameRenderedUptime: Duration) { + val localTouchDownWaitingRender = touchDownWaitingRender!! + val sentTime = localTouchDownWaitingRender.eventTime + val sentToReceive = handledTime - sentTime + val receiveToFrame = frameRenderedUptime.inWholeMilliseconds - handledTime + PapaEventListener.sendEvent( + FrozenFrameOnTouch( + activityName = windowTitle, + repeatTouchDownCount = repeatTouchDownCount, + deliverDurationUptimeMillis = sentToReceive, + dislayDurationUptimeMillis = receiveToFrame, + pressedView = pressedViewName + ) ) - ) - localTouchDownWaitingRender.recycle() - touchDownWaitingRender = null - repeatTouchDownCount = 0 - pressedViewName = null - } + localTouchDownWaitingRender.recycle() + touchDownWaitingRender = null + repeatTouchDownCount = 0 + pressedViewName = null + } + }) } } } diff --git a/papa/src/main/java/papa/internal/InputTracker.kt b/papa/src/main/java/papa/internal/InputTracker.kt index 2f4d7a5..abf2859 100644 --- a/papa/src/main/java/papa/internal/InputTracker.kt +++ b/papa/src/main/java/papa/internal/InputTracker.kt @@ -1,6 +1,5 @@ package papa.internal -import android.app.Application import android.os.Handler import android.os.Looper import android.os.SystemClock @@ -9,7 +8,6 @@ import android.view.MotionEvent import android.view.ViewConfiguration import android.view.ViewGroup import android.widget.AbsListView -import com.squareup.papa.R import curtains.Curtains import curtains.KeyEventInterceptor import curtains.OnRootViewAddedListener @@ -59,7 +57,8 @@ internal object InputTracker { interactionTrace = { SafeTrace.endAsyncSection(TAP_INTERACTION_SECTION, cookie) }, - payload = InputEventTrigger( + payload = InputEventTrigger.createTrackingWhenFrameRendered( + inputEventWindow = window, // Making a copy as motionEvent will get cleared once dispatched. inputEvent = MotionEvent.obtain(motionEvent), deliveryUptime = deliveryUptimeNanos.nanoseconds @@ -137,7 +136,8 @@ internal object InputTracker { interactionTrace = { SafeTrace.endAsyncSection(traceSectionName, cookie) }, - payload = InputEventTrigger( + payload = InputEventTrigger.createTrackingWhenFrameRendered( + inputEventWindow = window, inputEvent = keyEvent, deliveryUptime = deliveryUptimeNanos.nanoseconds ) @@ -150,10 +150,8 @@ internal object InputTracker { } } - internal fun install(application: Application) { - if (application.resources.getBoolean(R.bool.papa_track_input_events)) { + fun install() { Curtains.onRootViewsChangedListeners += listener - } } private const val INTERACTION_SUFFIX = "Interaction" diff --git a/papa/src/main/java/papa/internal/LaunchTracker.kt b/papa/src/main/java/papa/internal/LaunchTracker.kt index 469d25d..677d0d4 100644 --- a/papa/src/main/java/papa/internal/LaunchTracker.kt +++ b/papa/src/main/java/papa/internal/LaunchTracker.kt @@ -2,7 +2,10 @@ package papa.internal import android.app.Activity import android.os.SystemClock +import papa.Choreographers +import papa.OnFrameRenderedListener import papa.SafeTrace +import kotlin.time.Duration internal class LaunchTracker( val appLaunchedCallback: (Launch) -> Unit @@ -101,30 +104,33 @@ internal class LaunchTracker( // not drawing and another activity is resumed immediately after, whichever activity draws // first will end up being declared as the final launched activity. resumedActivity.window.onNextPreDraw { - onCurrentFrameRendered { frameRenderedUptime -> - val launchInProgress = launchInProgress ?: return@onCurrentFrameRendered - this.launchInProgress = null - - // We're ignoring a launch happening less than 500ms after the app became invisible. - val isRealLaunch = launchInProgress.invisibleDurationRealtimeMillis?.let { it >= 500 } - ?: true - // We're cancelling at the end so that all activity lifecycle events in between are still - // tracked as part of this fluke launch. - if (!isRealLaunch) { - return@onCurrentFrameRendered + // When compiling with Java11 we get AbstractMethodError at runtime when this is a lambda. + Choreographers.postOnCurrentFrameRendered(object : OnFrameRenderedListener { + override fun onFrameRendered(frameRenderedUptime: Duration) { + val launchInProgress = launchInProgress ?: return + this@LaunchTracker.launchInProgress = null + + // We're ignoring a launch happening less than 500ms after the app became invisible. + val isRealLaunch = launchInProgress.invisibleDurationRealtimeMillis?.let { it >= 500 } + ?: true + // We're cancelling at the end so that all activity lifecycle events in between are still + // tracked as part of this fluke launch. + if (!isRealLaunch) { + return + } + val launch = with(launchInProgress) { + Launch( + trampoline = activityHash != resumedActivityHash, + startUptimeMillis = startUptimeMillis, + startRealtimeMillis = startRealtimeMillis, + endUptimeMillis = frameRenderedUptime.inWholeMilliseconds, + invisibleDurationRealtimeMillis = invisibleDurationRealtimeMillis, + activityStartingTransition = activityStartingTransition + ) + } + appLaunchedCallback(launch) } - val launch = with(launchInProgress) { - Launch( - trampoline = activityHash != resumedActivityHash, - startUptimeMillis = startUptimeMillis, - startRealtimeMillis = startRealtimeMillis, - endUptimeMillis = frameRenderedUptime.inWholeMilliseconds, - invisibleDurationRealtimeMillis = invisibleDurationRealtimeMillis, - activityStartingTransition = activityStartingTransition - ) - } - appLaunchedCallback(launch) - } + }) } } } \ No newline at end of file diff --git a/papa/src/main/java/papa/internal/MainThreadTriggerTracer.kt b/papa/src/main/java/papa/internal/MainThreadTriggerTracer.kt index 67bd150..1e98f68 100644 --- a/papa/src/main/java/papa/internal/MainThreadTriggerTracer.kt +++ b/papa/src/main/java/papa/internal/MainThreadTriggerTracer.kt @@ -1,7 +1,5 @@ package papa.internal -import android.app.Application -import com.squareup.papa.R import papa.InteractionTrigger import papa.MainThreadMessageSpy import papa.MainThreadTriggerStack @@ -13,12 +11,9 @@ internal object MainThreadTriggerTracer { private const val ASYNC_SECTION_LABEL = "Main Message Interaction" - fun install(application: Application) { - if (!application.resources.getBoolean(R.bool.papa_track_main_thread_triggers)) { - return - } + fun install() { lateinit var currentTrigger: InteractionTrigger - MainThreadMessageSpy.startTracing { _, before -> + MainThreadMessageSpy.addTracer { _, before -> if (before) { val dispatchUptimeNanos = System.nanoTime() val asyncTraceCookie = dispatchUptimeNanos.toInt() diff --git a/papa/src/main/java/papa/internal/Perfs.kt b/papa/src/main/java/papa/internal/Perfs.kt index d0e34bb..d8c744d 100644 --- a/papa/src/main/java/papa/internal/Perfs.kt +++ b/papa/src/main/java/papa/internal/Perfs.kt @@ -24,6 +24,7 @@ import papa.AppUpdateStartStatus.NORMAL_START import papa.AppVisibilityState import papa.AppVisibilityState.INVISIBLE import papa.AppVisibilityState.VISIBLE +import papa.Choreographers import papa.PapaEvent.AppLaunch import papa.PapaEventListener import papa.PreLaunchState @@ -413,7 +414,7 @@ internal object Perfs { return } reportedFullDrawn = true - onCurrentOrNextFrameRendered { frameRenderedUptime -> + Choreographers.postOnFrameRendered { frameRenderedUptime -> appStartData = appStartData.copy( firstFrameAfterFullyDrawnElapsedUptimeMillis = frameRenderedUptime.inWholeMilliseconds - appStartData.processStartUptimeMillis ) diff --git a/papa/src/main/res/values/tart_bools.xml b/papa/src/main/res/values/tart_bools.xml index 3562c57..d73fb9d 100644 --- a/papa/src/main/res/values/tart_bools.xml +++ b/papa/src/main/res/values/tart_bools.xml @@ -1,5 +1,6 @@ + true true true diff --git a/papa/src/main/res/values/tart_public.xml b/papa/src/main/res/values/tart_public.xml index 721e78d..747bd2f 100644 --- a/papa/src/main/res/values/tart_public.xml +++ b/papa/src/main/res/values/tart_public.xml @@ -1,5 +1,6 @@ +