For #18426: add telemetry for app.onCreate subsections.

Hopefully this will help us understand behavior of the `application_on_create` probe, specifically that it seems to take longer in telemetry than in does locally compared to `home_activity_on_create` (comparing the medians to local runs)..
3 years ago · 9024eca01e
parent 5c0f30fd5c
commit 9024eca01e
4 changed files with 109 additions and 38 deletions
--- a/app/metrics.yaml
+++ b/app/metrics.yaml
@ -4130,7 +4130,9 @@ perf.startup:
    type: timing_distribution
    time_unit: millisecond
    description: |
-      The duration of `FenixApplication.onCreate` in the main process.
+      The duration of `FenixApplication.onCreate` in the main process. This does
+      not measure the duration of migration code (via
+      `MigratingFenixApplication` included in the Beta and Release channels.
    bugs:
      - https://github.com/mozilla-mobile/fenix/issues/17969
    data_reviews:
@ -4141,6 +4143,61 @@ perf.startup:
      - perf-android-fe@mozilla.com
      - mcomella@mozilla.com
    expires: "2021-08-11"
+  app_on_create_to_glean_init:
+    type: timing_distribution
+    time_unit: millisecond
+    description: |
+      A subsection of the duration of `FenixApplication.onCreate` and thus the
+      `application_on_create` probe from the start of the method through when
+      `initializeGlean` is called. Note: `initializeGlean` is a no-op for Beta
+      and Release builds which instead initialize it during
+      `MigratingFenixApplication`, which we don't currently measure.
+    bugs:
+      - https://github.com/mozilla-mobile/fenix/issues/18426
+    data_reviews:
+      - https://github.com/mozilla-mobile/fenix/pull/18525#issue-594961170
+    data_sensitivity:
+      - technical
+    notification_emails:
+      - perf-android-fe@mozilla.com
+      - mcomella@mozilla.com
+    expires: "2021-08-11"
+  app_on_create_to_megazord_init:
+    type: timing_distribution
+    time_unit: millisecond
+    description: |
+      A subsection of the duration of `FenixApplication.onCreate` and thus the
+      `application_on_create` probe from after the `app_on_create_to_glean_init`
+      probe until we block for the megazord to complete set up.
+    bugs:
+      - https://github.com/mozilla-mobile/fenix/issues/18426
+    data_reviews:
+      - https://github.com/mozilla-mobile/fenix/pull/18525#issue-594961170
+    data_sensitivity:
+      - technical
+    notification_emails:
+      - perf-android-fe@mozilla.com
+      - mcomella@mozilla.com
+    expires: "2021-08-11"
+  app_on_create_to_setup_in_main:
+    type: timing_distribution
+    time_unit: millisecond
+    description: |
+      A subsection of the duration of `FenixApplication.onCreate` and thus the
+      `application_on_create` probe from after the
+      `app_on_create_to_megazord_init` probe until the end of
+      `setupInMainProcessOnly`, which is expected to be the end of the
+      `onCreate` call (unless the implementation later changes).
+    bugs:
+      - https://github.com/mozilla-mobile/fenix/issues/18426
+    data_reviews:
+      - https://github.com/mozilla-mobile/fenix/pull/18525#issue-594961170
+    data_sensitivity:
+      - technical
+    notification_emails:
+      - perf-android-fe@mozilla.com
+      - mcomella@mozilla.com
+    expires: "2021-08-11"
  home_activity_on_create:
    type: timing_distribution
    time_unit: millisecond
--- a/app/src/main/java/org/mozilla/fenix/FenixApplication.kt
+++ b/app/src/main/java/org/mozilla/fenix/FenixApplication.kt
@ -49,6 +49,7 @@ import org.mozilla.fenix.GleanMetrics.PerfStartup
 import org.mozilla.fenix.components.Components
 import org.mozilla.fenix.components.metrics.MetricServiceType
 import org.mozilla.fenix.components.metrics.SecurePrefsTelemetry
+import org.mozilla.fenix.ext.measureNoInline
 import org.mozilla.fenix.ext.settings
 import org.mozilla.fenix.perf.ProfilerMarkerFactProcessor
 import org.mozilla.fenix.perf.StartupTimeline
@ -79,7 +80,10 @@ open class FenixApplication : LocaleAwareApplication(), Provider {
        private set

    override fun onCreate() {
-        val methodDurationTimerId = PerfStartup.applicationOnCreate.start() // DO NOT MOVE ANYTHING ABOVE HERE.
+        // We use start/stop instead of measure so we don't measure outside the main process.
+        val completeMethodDurationTimerId = PerfStartup.applicationOnCreate.start() // DO NOT MOVE ANYTHING ABOVE HERE.
+        val subsectionThroughGleanTimerId = PerfStartup.appOnCreateToGleanInit.start()
+
        super.onCreate()

        setupInAllProcesses()
@ -100,10 +104,12 @@ open class FenixApplication : LocaleAwareApplication(), Provider {
            initializeGlean()
        }

+        PerfStartup.appOnCreateToGleanInit.stopAndAccumulate(subsectionThroughGleanTimerId)
+
        setupInMainProcessOnly()

-        // We use start/stop instead of measure so we don't measure outside the main process.
-        PerfStartup.applicationOnCreate.stopAndAccumulate(methodDurationTimerId) // DO NOT MOVE ANYTHING BELOW HERE.
+        // DO NOT MOVE ANYTHING BELOW THIS stop CALL.
+        PerfStartup.applicationOnCreate.stopAndAccumulate(completeMethodDurationTimerId)
    }

    protected open fun initializeGlean() {
@ -141,48 +147,52 @@ open class FenixApplication : LocaleAwareApplication(), Provider {

    @CallSuper
    open fun setupInMainProcessOnly() {
-        ProfilerMarkerFactProcessor.create { components.core.engine.profiler }.register()
+        PerfStartup.appOnCreateToMegazordInit.measureNoInline {
+            ProfilerMarkerFactProcessor.create { components.core.engine.profiler }.register()

-        run {
-            // Attention: Do not invoke any code from a-s in this scope.
-            val megazordSetup = setupMegazord()
+            run {
+                // Attention: Do not invoke any code from a-s in this scope.
+                val megazordSetup = setupMegazord()

-            setDayNightTheme()
-            components.strictMode.enableStrictMode(true)
-            warmBrowsersCache()
+                setDayNightTheme()
+                components.strictMode.enableStrictMode(true)
+                warmBrowsersCache()

-            // Make sure the engine is initialized and ready to use.
-            components.strictMode.resetAfter(StrictMode.allowThreadDiskReads()) {
-                components.core.engine.warmUp()
-            }
-            initializeWebExtensionSupport()
-            restoreBrowserState()
-            restoreDownloads()
-
-            // Just to make sure it is impossible for any application-services pieces
-            // to invoke parts of itself that require complete megazord initialization
-            // before that process completes, we wait here, if necessary.
-            if (!megazordSetup.isCompleted) {
-                runBlockingIncrement { megazordSetup.await() }
+                // Make sure the engine is initialized and ready to use.
+                components.strictMode.resetAfter(StrictMode.allowThreadDiskReads()) {
+                    components.core.engine.warmUp()
+                }
+                initializeWebExtensionSupport()
+                restoreBrowserState()
+                restoreDownloads()
+
+                // Just to make sure it is impossible for any application-services pieces
+                // to invoke parts of itself that require complete megazord initialization
+                // before that process completes, we wait here, if necessary.
+                if (!megazordSetup.isCompleted) {
+                    runBlockingIncrement { megazordSetup.await() }
+                }
            }
        }

-        setupLeakCanary()
-        startMetricsIfEnabled()
-        setupPush()
+        PerfStartup.appOnCreateToSetupInMain.measureNoInline {
+            setupLeakCanary()
+            startMetricsIfEnabled()
+            setupPush()

-        visibilityLifecycleCallback = VisibilityLifecycleCallback(getSystemService())
-        registerActivityLifecycleCallbacks(visibilityLifecycleCallback)
+            visibilityLifecycleCallback = VisibilityLifecycleCallback(getSystemService())
+            registerActivityLifecycleCallbacks(visibilityLifecycleCallback)

-        // Storage maintenance disabled, for now, as it was interfering with background migrations.
-        // See https://github.com/mozilla-mobile/fenix/issues/7227 for context.
-        // if ((System.currentTimeMillis() - settings().lastPlacesStorageMaintenance) > ONE_DAY_MILLIS) {
-        //    runStorageMaintenance()
-        // }
+            // Storage maintenance disabled, for now, as it was interfering with background migrations.
+            // See https://github.com/mozilla-mobile/fenix/issues/7227 for context.
+            // if ((System.currentTimeMillis() - settings().lastPlacesStorageMaintenance) > ONE_DAY_MILLIS) {
+            //    runStorageMaintenance()
+            // }

-        initVisualCompletenessQueueAndQueueTasks()
+            initVisualCompletenessQueueAndQueueTasks()

-        components.appStartupTelemetry.onFenixApplicationOnCreate()
+            components.appStartupTelemetry.onFenixApplicationOnCreate()
+        }
    }

    private fun restoreBrowserState() = GlobalScope.launch(Dispatchers.Main) {
--- a/app/src/main/java/org/mozilla/fenix/HomeActivity.kt
+++ b/app/src/main/java/org/mozilla/fenix/HomeActivity.kt
@ -78,6 +78,7 @@ import org.mozilla.fenix.ext.alreadyOnDestination
 import org.mozilla.fenix.ext.breadcrumb
 import org.mozilla.fenix.ext.components
 import org.mozilla.fenix.ext.enableSystemInsetsHandling
+import org.mozilla.fenix.ext.measureNoInline
 import org.mozilla.fenix.ext.metrics
 import org.mozilla.fenix.ext.nav
 import org.mozilla.fenix.ext.settings
@ -165,7 +166,7 @@ open class HomeActivity : LocaleAwareAppCompatActivity(), NavHostActivity {

    private lateinit var navigationToolbar: Toolbar

-    final override fun onCreate(savedInstanceState: Bundle?): Unit = PerfStartup.homeActivityOnCreate.measure {
+    final override fun onCreate(savedInstanceState: Bundle?): Unit = PerfStartup.homeActivityOnCreate.measureNoInline {
        // DO NOT MOVE ANYTHING ABOVE THIS addMarker CALL.
        components.core.engine.profiler?.addMarker("Activity.onCreate", "HomeActivity")

--- a/docs/metrics.md
+++ b/docs/metrics.md
@ -341,7 +341,10 @@ In addition to those built-in metrics, the following metrics are added to the pi
 | perf.awesomebar.session_suggestions |[timing_distribution](https://mozilla.github.io/glean/book/user/metrics/timing_distribution.html) |Duration of a session awesomebar suggestion query.  |[mozilla-mobile/fenix#10276](https://github.com/mozilla-mobile/fenix/pull/10276#pullrequestreview-411101979)||2020-11-15 |1, 2 |
 | perf.awesomebar.shortcuts_suggestions |[timing_distribution](https://mozilla.github.io/glean/book/user/metrics/timing_distribution.html) |Duration of a shortcuts awesomebar suggestion query.  |[mozilla-mobile/fenix#10276](https://github.com/mozilla-mobile/fenix/pull/10276#pullrequestreview-411101979)||2020-11-15 |1, 2 |
 | perf.awesomebar.synced_tabs_suggestions |[timing_distribution](https://mozilla.github.io/glean/book/user/metrics/timing_distribution.html) |Duration of a synced tabs awesomebar suggestion query.  |[mozilla-mobile/fenix#10276](https://github.com/mozilla-mobile/fenix/pull/10276#pullrequestreview-411101979)||2020-11-15 |1, 2 |
-| perf.startup.application_on_create |[timing_distribution](https://mozilla.github.io/glean/book/user/metrics/timing_distribution.html) |The duration of `FenixApplication.onCreate` in the main process.  |[mozilla-mobile/fenix#17973](https://github.com/mozilla-mobile/fenix/pull/17973#issue-572183889)||2021-08-11 |1 |
+| perf.startup.app_on_create_to_glean_init |[timing_distribution](https://mozilla.github.io/glean/book/user/metrics/timing_distribution.html) |A subsection of the duration of `FenixApplication.onCreate` and thus the `application_on_create` probe from the start of the method through when `initializeGlean` is called. Note: `initializeGlean` is a no-op for Beta and Release builds which instead initialize it during `MigratingFenixApplication`, which we don't currently measure.  |[mozilla-mobile/fenix#18525](https://github.com/mozilla-mobile/fenix/pull/18525#issue-594961170)||2021-08-11 |1 |
+| perf.startup.app_on_create_to_megazord_init |[timing_distribution](https://mozilla.github.io/glean/book/user/metrics/timing_distribution.html) |A subsection of the duration of `FenixApplication.onCreate` and thus the `application_on_create` probe from after the `app_on_create_to_glean_init` probe until we block for the megazord to complete set up.  |[mozilla-mobile/fenix#18525](https://github.com/mozilla-mobile/fenix/pull/18525#issue-594961170)||2021-08-11 |1 |
+| perf.startup.app_on_create_to_setup_in_main |[timing_distribution](https://mozilla.github.io/glean/book/user/metrics/timing_distribution.html) |A subsection of the duration of `FenixApplication.onCreate` and thus the `application_on_create` probe from after the `app_on_create_to_megazord_init` probe until the end of `setupInMainProcessOnly`, which is expected to be the end of the `onCreate` call (unless the implementation later changes).  |[mozilla-mobile/fenix#18525](https://github.com/mozilla-mobile/fenix/pull/18525#issue-594961170)||2021-08-11 |1 |
+| perf.startup.application_on_create |[timing_distribution](https://mozilla.github.io/glean/book/user/metrics/timing_distribution.html) |The duration of `FenixApplication.onCreate` in the main process. This does not measure the duration of migration code (via `MigratingFenixApplication` included in the Beta and Release channels.  |[mozilla-mobile/fenix#17973](https://github.com/mozilla-mobile/fenix/pull/17973#issue-572183889)||2021-08-11 |1 |
 | perf.startup.home_activity_on_create |[timing_distribution](https://mozilla.github.io/glean/book/user/metrics/timing_distribution.html) |The duration of `HomeActivity.onCreate`.  |[mozilla-mobile/fenix#17973](https://github.com/mozilla-mobile/fenix/pull/17973#issue-572183889)||2021-08-11 |1 |
 | preferences.accessibility_services |[string_list](https://mozilla.github.io/glean/book/user/metrics/string_list.html) |Whether or not the user has touch exploration or switch services enabled. These are built into the Android OS, not Fenix prefs. default: ""  |[mozilla-mobile/fenix#11211](https://github.com/mozilla-mobile/fenix/pull/11211), [mozilla-mobile/fenix#15713](https://github.com/mozilla-mobile/fenix/pull/15713#issuecomment-703972068)||2021-08-01 |2 |
 | preferences.open_links_in_a_private_tab |[string_list](https://mozilla.github.io/glean/book/user/metrics/string_list.html) |Whether or not the user has enabled open links in a private tab. default: false  |[mozilla-mobile/fenix#11211](https://github.com/mozilla-mobile/fenix/pull/11211), [mozilla-mobile/fenix#15713](https://github.com/mozilla-mobile/fenix/pull/15713#issuecomment-703972068)||2021-08-01 |2 |