RUMM-2599 ApplicationLaunch logic changes by fuzzybinary · Pull Request #1278 · DataDog/dd-sdk-android

fuzzybinary · 2023-02-10T21:02:56Z

What does this PR do?

ApplicationLaunch now starts immediately when the first event is sent to RUM provided we are in the Foreground. The view's start time is now the process start time (or as close as we can get it), and the application_start event is also triggered immediately. The "duration" of the application_start event is equal to the time from when the process started, until the first event sent to RUM.

Additional Notes

This may change the timing for application_start for some clients, but should make it shorter in most cases since instead of timing to first view (or first event that causes ApplicationLaunch) we time until the first event sent to RUM regardless of what that event is.

Review checklist (to be filled by reviewers)

Feature or bugfix MUST have appropriate tests (unit, integration, e2e)
Make sure you discussed the feature or bugfix with the maintaining team in an Issue
Make sure each commit and the PR mention the Issue number (cf the CONTRIBUTING doc)

ApplicationLaunch now starts immediately when the first event is sent to RUM provided we are in the Foreground. The view's start time is now the process start time (or as close as we can get it), and the `application_start` event is also triggered immediately. The "duration" of the `application_start` event is equal to the time from when the process started, until the first event sent to RUM.

plousada · 2023-02-13T09:41:55Z

+
+internal interface AppStartTimeProvider {
+    /**
+     * Provide the application start time in nanoseconds from device boot, or our best guess if


from device boot
From application boot, no?

Also, can we elaborate on the "our best guess" with the actual implementation?
i.e. from RUM class load in Android < N

I can yes. I left it vague so that if it changes we wouldn't have to worry about updating the documentation or have it be wrong.

Also, the time is actually nanoseconds since device boot (it's using System.nanoTime or the elapsedRealtime functions, which are both timed from JVM or device boot time.

Also also, I remember another reason I said "our best guess" which is that the specifics would be in the implementation. This is saying to implementers "give us the exact value, or your best guess." The implementation (DefaultAppStartTimeProvider) could be documented with exactly how we're doing it if we want.

Ok, now I understand what you meant by "from device boot".
Initially I interpreted it as "we are returning the time difference between the app started and the time you booted your device"

mariusc83 · 2023-02-13T10:10:58Z

    @WorkerThread
    override fun handleEvent(event: RumRawEvent, writer: DataWriter<Any>): RumScope {
+        if (!applicationDisplayed) {
+            val isForegroundProcess = CoreFeature.processImportance ==


have you added a UnitTest for this case ? I didn't see it, maybe I missed it ?

Yes it's just that they didn't change. They're 𝕄 start a foreground ViewScope 𝕎 handleEvent(StartView) in RumViewManagerScopeTest. They only test for ViewEvents, but I think other test handle other possible events.

0xnm · 2023-02-13T16:30:34Z

+            val isForegroundProcess = CoreFeature.processImportance ==
+                ActivityManager.RunningAppProcessInfo.IMPORTANCE_FOREGROUND
+            if (isForegroundProcess) {
+                startApplicationLaunchView(event, writer)


But it also means that if event we've got is StartView, another ViewScope will be started immediately after this one. Is it expected?

Yes. ApplicationLaunch will then take the time between AppStartTimeProvied.appStartTimeNs and the start time of the new View.

0xnm · 2023-02-13T16:33:39Z

    @WorkerThread
    override fun handleEvent(event: RumRawEvent, writer: DataWriter<Any>): RumScope {
+        if (!applicationDisplayed) {
+            val isForegroundProcess = CoreFeature.processImportance ==


I'm actually curious how this is going to work in the following scenario: app originally started with IMPORTANCE_BACKGROUND, but then came into the foreground while still being active (same process).

In that case (since we resolve processImportance only once, at the CoreFeature initialization time -> at the app start time), we will never report startup time for such cases, right?

Yes. I think that's the correct logic as that would skep application start time, but this is for sure where I'm confused about the logic.

I'm curious if Android also can pre-warm apps (didn't dig into this topic tbh). I would suggest doing some tests using either our sample app or Reddit client. We can maybe emulate start by the user, background invocation using adb (like background invocation can maybe to send some intent to the service, etc).

Indeed that's the expected logic as we don't have any other event than the process start time to compute for the warm app launch. There's no catchable event except for the Activity's lifecycle which is already too late.

0xnm · 2023-02-13T16:45:18Z

+        val appStartTimeNs = System.nanoTime() - TimeUnit.MILLISECONDS.toNanos(500)
+        whenever(mockAppStartTimeProvider.appStartTimeNs) doReturn appStartTimeNs


We can use a random value for appStartTimeNs here.

Suggested change

val appStartTimeNs = System.nanoTime() - TimeUnit.MILLISECONDS.toNanos(500)

whenever(mockAppStartTimeProvider.appStartTimeNs) doReturn appStartTimeNs

val appStartTimeNs = forge.aPositiveLong()

whenever(mockAppStartTimeProvider.appStartTimeNs) doReturn appStartTimeNs

0xnm · 2023-02-13T16:47:12Z

-        @IntForgery(min = Build.VERSION_CODES.N) apiVersion: Int
-    ) {
-        // Given
+        val appStartTimeNs = System.nanoTime() - TimeUnit.MILLISECONDS.toNanos(500)


Suggested change

val appStartTimeNs = System.nanoTime() - TimeUnit.MILLISECONDS.toNanos(500)

val appStartTimeNs = forge.aPositiveLong()

0xnm · 2023-02-13T16:49:01Z

            RumRawEvent.StartAction::class.java,
            RumRawEvent.StartResource::class.java
        )
-        internal val validAppLaunchEventTypes = arrayOf<Class<*>>(


we need also to delete Forge.validAppLaunchEvent() in RumRawEventExt file in tests

0xnm · 2023-02-13T16:49:56Z

-        val childView: RumViewScope = mock()
-        val startViewEvent = forge.startViewEvent()
+
+        val fakeEvent = forge.addErrorEvent()


we need to make sure that it is working with any event, so I would suggest to add a method in the RumRawEventExt file which will return any RumRawEvent available and use it here.

0xnm · 2023-02-13T16:51:59Z

-                .isCloseTo(System.nanoTime(), Offset.offset(TimeUnit.MILLISECONDS.toNanos(100)))
+        val appStartTimeMs = TimeUnit.NANOSECONDS.toMillis(appStartTimeNs)
+        argumentCaptor<ActionEvent> {
+            verify(mockWriter, atLeastOnce()).write(eq(mockEventBatchWriter), capture())


Do we expect more calls here? If we expect only one call, we can use times(1), or simply omit it and use verify(mockWriter).write(...)

Yes we do, I think we get 2-3 (which is why I added the atLeastOnce(). I have to verify what they are but I know you get a ViewEvent first, then another, then the ActionEvent with application_started as the type.

Oh yeah, it makes sense since we create Application Launch scope and then delegate action to it.

And I guess then the number of interactions vary from the type of the original event handled? Because some events can cause an instant write (like fatal errors).

0xnm

I've left few suggestions. However, it seems that unit-tests are failing, so we probably have something wrong in the logic.

0xnm · 2023-02-15T10:20:43Z

+    fun `M return process start time W appStartTime { N+ }`() {
+        // GIVEN
+        val mockBuildSdkVersionProvider: BuildSdkVersionProvider = mock()
+        whenever(mockBuildSdkVersionProvider.version()) doReturn Build.VERSION_CODES.O


minor: can also probably use IntForgery with min = Build.VERSION_CODES.N as for the test below

0xnm · 2023-02-15T13:15:58Z

    // region Internal

+    @WorkerThread
+    internal fun startApplicationLaunchView(event: RumRawEvent, writer: DataWriter<Any>) {


Can be private I think

Suggested change

internal fun startApplicationLaunchView(event: RumRawEvent, writer: DataWriter<Any>) {

private fun startApplicationLaunchView(event: RumRawEvent, writer: DataWriter<Any>) {

0xnm · 2023-02-15T13:18:50Z

+            writer
+        )
+        childrenScopes.add(viewScope)
+        applicationDisplayed = true


should we pull this line up? just in case if inner handleEvent also access this flag at some point.

0xnm · 2023-02-15T13:20:45Z

+        val scopes = if (fakeEvent is RumRawEvent.StartView) 2 else 1
+        assertThat(testedScope.childrenScopes).hasSize(scopes)


minor suggestion (just to distinguish from scopes as collection)

Suggested change

val scopes = if (fakeEvent is RumRawEvent.StartView) 2 else 1

assertThat(testedScope.childrenScopes).hasSize(scopes)

val scopesCount = if (fakeEvent is RumRawEvent.StartView) 2 else 1

assertThat(testedScope.childrenScopes).hasSize(scopesCount)

0xnm · 2023-02-15T13:23:18Z

        testedScope.applicationDisplayed = false
-        val fakeEvent = forge.validAppLaunchEvent()
+        val fakeEvent = forge.anyRumEvent()
+        val appStartTimeNs = fakeEvent.eventTime.nanoTime - TimeUnit.MILLISECONDS.toNanos(500)


or we can a bit more randomness and simply do val appStartTimeNs = forge.aLong(min = 0L, max = fakeEvent.eventTime.nanoTime)

👍 Though I think we probably want to go min, say fakeTime - 1000ms second to fakeTime - 100ms? What do you think?

It is ok for me. We don't have thresholds to filter out too big times, so we can accept any positive value as min (we just try to avoid hardcoded values in our tests).

0xnm · 2023-02-15T13:24:12Z

-        @IntForgery(min = Build.VERSION_CODES.N) apiVersion: Int
-    ) {
-        // Given
+        val appStartTimeNs = fakeEvent.eventTime.nanoTime - TimeUnit.MILLISECONDS.toNanos(500)


Suggested change

val appStartTimeNs = fakeEvent.eventTime.nanoTime - TimeUnit.MILLISECONDS.toNanos(500)

val appStartTimeNs = forge.aLong(min = 0L, max = fakeEvent.eventTime.nanoTime)

0xnm · 2023-02-15T13:25:59Z

        instrumentation.waitForIdleSync()

-        // one for the Application start action
+        expectedEvents.add(ExpectedApplicationStart())


should we align the naming used? Seems we have ApplicationStart and ApplicationLaunch at the same time.

UPD: seems we are a bit late, both definitions already live in the codebase.

I'll fix so it's "ApplicationStartEvent" and "ApplicaitonLaunchView" which I know doesn't make things that much clearer but at least it will be consistent.

Some tests were using "anyRumEvent" that would break if a new view started. Fix so we can exclude that event for those tests.

The test to ensure that events sent before the application was displayed that orphan silently, should not use the logger was failing because any events that are sent to the ViewManagerScope when the application is not displayed are no longer orphaned, as they go to the ApplicationLaunch view. Occasionally, the test would log something unrelated to orphaning which was failing the test.

0xnm

I think it looks good now, let's wait for the product decision first then before merging.

xgouchet · 2023-02-20T08:46:43Z

    @WorkerThread
    override fun handleEvent(event: RumRawEvent, writer: DataWriter<Any>): RumScope {
+        if (!applicationDisplayed) {
+            val isForegroundProcess = CoreFeature.processImportance ==


Indeed that's the expected logic as we don't have any other event than the process start time to compute for the warm app launch. There's no catchable event except for the Activity's lifecycle which is already too late.

fuzzybinary requested a review from a team as a code owner February 10, 2023 21:02

plousada reviewed Feb 13, 2023

View reviewed changes

mariusc83 reviewed Feb 13, 2023

View reviewed changes

0xnm reviewed Feb 13, 2023

View reviewed changes

plousada approved these changes Feb 13, 2023

View reviewed changes

fuzzybinary force-pushed the RUMM-2599-application-launch-view branch 2 times, most recently from 1901c99 to 65409a6 Compare February 14, 2023 19:39

RUMM-2599 Comments from code review and fix integration tests

0bc387d

fuzzybinary force-pushed the RUMM-2599-application-launch-view branch from 65409a6 to 0bc387d Compare February 14, 2023 19:44

0xnm reviewed Feb 15, 2023

View reviewed changes

fuzzybinary added 2 commits February 15, 2023 11:30

RUMM-2599 Comments from code review, fix tests

4d9090f

Some tests were using "anyRumEvent" that would break if a new view started. Fix so we can exclude that event for those tests.

fuzzybinary force-pushed the RUMM-2599-application-launch-view branch from ca3f6cb to 06bd307 Compare February 15, 2023 21:22

0xnm approved these changes Feb 16, 2023

View reviewed changes

xgouchet approved these changes Feb 20, 2023

View reviewed changes

fuzzybinary merged commit dfd6c81 into develop Feb 21, 2023

fuzzybinary deleted the RUMM-2599-application-launch-view branch February 21, 2023 20:03

xgouchet added this to the 1.18.0 milestone Dec 13, 2023

		val appStartTimeNs = System.nanoTime() - TimeUnit.MILLISECONDS.toNanos(500)
		whenever(mockAppStartTimeProvider.appStartTimeNs) doReturn appStartTimeNs

	val appStartTimeNs = System.nanoTime() - TimeUnit.MILLISECONDS.toNanos(500)
	val appStartTimeNs = forge.aPositiveLong()

	internal fun startApplicationLaunchView(event: RumRawEvent, writer: DataWriter<Any>) {
	private fun startApplicationLaunchView(event: RumRawEvent, writer: DataWriter<Any>) {

		val scopes = if (fakeEvent is RumRawEvent.StartView) 2 else 1
		assertThat(testedScope.childrenScopes).hasSize(scopes)

	val appStartTimeNs = fakeEvent.eventTime.nanoTime - TimeUnit.MILLISECONDS.toNanos(500)
	val appStartTimeNs = forge.aLong(min = 0L, max = fakeEvent.eventTime.nanoTime)

Uh oh!

Conversation

fuzzybinary commented Feb 10, 2023

What does this PR do?

Additional Notes

Review checklist (to be filled by reviewers)

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

fuzzybinary Feb 13, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

0xnm left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

0xnm left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

fuzzybinary Feb 13, 2023 •

edited

Loading