From dbf733d70a4bf7eb843cf25d7da59866e5d778f6 Mon Sep 17 00:00:00 2001 From: Michael Comella Date: Tue, 7 Apr 2020 14:41:12 -0700 Subject: [PATCH] For #8803: add StartupFrameworkStartMeasurement. This class controls the central logic around the metrics we want to record. --- .../perf/StartupFrameworkStartMeasurement.kt | 86 +++++++++++++ .../StartupFrameworkStartMeasurementTest.kt | 117 ++++++++++++++++++ 2 files changed, 203 insertions(+) create mode 100644 app/src/main/java/org/mozilla/fenix/perf/StartupFrameworkStartMeasurement.kt create mode 100644 app/src/test/java/org/mozilla/fenix/perf/StartupFrameworkStartMeasurementTest.kt diff --git a/app/src/main/java/org/mozilla/fenix/perf/StartupFrameworkStartMeasurement.kt b/app/src/main/java/org/mozilla/fenix/perf/StartupFrameworkStartMeasurement.kt new file mode 100644 index 000000000..5a3fe8923 --- /dev/null +++ b/app/src/main/java/org/mozilla/fenix/perf/StartupFrameworkStartMeasurement.kt @@ -0,0 +1,86 @@ +/* This Source Code Form is subject to the terms of the Mozilla Public + * License, v. 2.0. If a copy of the MPL was not distributed with this + * file, You can obtain one at http://mozilla.org/MPL/2.0/. */ + +package org.mozilla.fenix.perf + +import android.os.Process +import android.os.SystemClock +import kotlin.math.roundToLong +import org.mozilla.fenix.GleanMetrics.StartupTimeline as Telemetry + +/** + * A class to measure the time the Android framework executes before letting us execute our own code + * for the first time in Application's initializer: this value is captured in the + * [Telemetry.frameworkStart] probe. + * + * Since we cannot execute code at process start, this measurement does not fit within the Glean + * Timespan metric start/stop programming model so it lives in its own class. + */ +internal class StartupFrameworkStartMeasurement( + private val stat: Stat = Stat(), + private val telemetry: Telemetry = Telemetry, + private val getElapsedRealtimeNanos: () -> Long = SystemClock::elapsedRealtimeNanos +) { + + private var isMetricSet = false + + private var applicationInitNanos = -1L + private var isApplicationInitCalled = false + + fun onApplicationInit() { + // This gets called from multiple processes: don't do anything expensive. See call site for details. + // + // In the main process, there are multiple Application impl so we ensure it's only set by + // the first one. + if (!isApplicationInitCalled) { + isApplicationInitCalled = true + applicationInitNanos = getElapsedRealtimeNanos() + } + } + + /** + * Sets the values for metrics to record in glean. + * + * We defer these metrics, rather than setting them as soon as the values are available, + * because they are slow to fetch and we don't want to impact startup. + */ + fun setExpensiveMetric() { + // The application is only init once per process lifetime so we only set this value once. + if (isMetricSet) return + isMetricSet = true + + if (applicationInitNanos < 0) { + telemetry.frameworkStartError.set(true) + } else { + telemetry.frameworkStart.setRawNanos(getFrameworkStartNanos()) + + // frameworkStart is derived from the number of clock ticks per second. To ensure this + // value does not throw off our result, we capture it too. + telemetry.clockTicksPerSecond.add(stat.clockTicksPerSecond.toInt()) + } + } + + private fun getFrameworkStartNanos(): Long { + // Get our timestamps in ticks: we expect ticks to be less granular than nanoseconds so, + // to ensure our measurement uses the correct number of significant figures, we convert + // everything to ticks before getting the result. + // + // Similarly, we round app init to a whole integer tick value because process start only + // comes in integer ticks values. + val processStartTicks = stat.getProcessStartTimeTicks(Process.myPid()) + val applicationInitTicks = applicationInitNanos.nanosToTicks().roundToLong() + + val frameworkStartTicks = applicationInitTicks - processStartTicks + + // Glean only takes whole unit nanoseconds so we round to that. I'm not sure but it may be + // possible that capturing nanos in a double will produce a rounding error that chops off + // significant values. However, since we expect to be using a much smaller portion of the + // nano field - if ticks are actually less granular than nanoseconds - I don't expect for + // this to be a problem. + return frameworkStartTicks.ticksToNanos().roundToLong() + } + + private fun Long.nanosToTicks(): Double = stat.convertNanosToTicks(this) + private fun Long.ticksToNanos(): Double = stat.convertTicksToNanos(this) +} diff --git a/app/src/test/java/org/mozilla/fenix/perf/StartupFrameworkStartMeasurementTest.kt b/app/src/test/java/org/mozilla/fenix/perf/StartupFrameworkStartMeasurementTest.kt new file mode 100644 index 000000000..7fadf1f28 --- /dev/null +++ b/app/src/test/java/org/mozilla/fenix/perf/StartupFrameworkStartMeasurementTest.kt @@ -0,0 +1,117 @@ +/* This Source Code Form is subject to the terms of the Mozilla Public + * License, v. 2.0. If a copy of the MPL was not distributed with this + * file, You can obtain one at http://mozilla.org/MPL/2.0/. */ + +package org.mozilla.fenix.perf + +import io.mockk.Called +import io.mockk.MockKAnnotations +import io.mockk.every +import io.mockk.impl.annotations.MockK +import io.mockk.spyk +import io.mockk.verify +import mozilla.components.service.glean.private.BooleanMetricType +import mozilla.components.service.glean.private.CounterMetricType +import mozilla.components.service.glean.private.TimespanMetricType +import org.junit.Before +import org.junit.Test +import org.mozilla.fenix.GleanMetrics.StartupTimeline as Telemetry + +private const val CLOCK_TICKS_PER_SECOND = 100L + +class StartupFrameworkStartMeasurementTest { + + private lateinit var metrics: StartupFrameworkStartMeasurement + private lateinit var stat: Stat + + // We'd prefer to use the Glean test methods over these mocks but they require us to add + // Robolectric and it's not worth the impact on test duration. + @MockK private lateinit var telemetry: Telemetry + @MockK(relaxed = true) private lateinit var frameworkStart: TimespanMetricType + @MockK(relaxed = true) private lateinit var frameworkStartError: BooleanMetricType + @MockK(relaxed = true) private lateinit var clockTicksPerSecond: CounterMetricType + + private var elapsedRealtimeNanos = -1L + private var processStartTimeTicks = -1L + + @Before + fun setUp() { + MockKAnnotations.init(this) + + elapsedRealtimeNanos = -1 + processStartTimeTicks = -1 + + stat = spyk(object : Stat() { + override val clockTicksPerSecond: Long get() = CLOCK_TICKS_PER_SECOND + }) + every { stat.getProcessStartTimeTicks(any()) } answers { processStartTimeTicks } + val getElapsedRealtimeNanos = { elapsedRealtimeNanos } + + every { telemetry.frameworkStart } returns frameworkStart + every { telemetry.frameworkStartError } returns frameworkStartError + every { telemetry.clockTicksPerSecond } returns clockTicksPerSecond + + metrics = StartupFrameworkStartMeasurement(stat, telemetry, getElapsedRealtimeNanos) + } + + @Test + fun `GIVEN app init is invalid WHEN metrics are set THEN frameworkStartError is set to true`() { + setProcessAppInitAndMetrics(processStart = 10, appInit = -1) + verifyFrameworkStartError() + } + + @Test + fun `GIVEN app init is not called WHEN metrics are set THEN frameworkStartError is set to true`() { + metrics.setExpensiveMetric() + verifyFrameworkStartError() + } + + @Test + fun `GIVEN app init is set to valid values WHEN metrics are set THEN frameworkStart is set with the correct value`() { + setProcessAppInitAndMetrics(processStart = 166_636_813, appInit = 1_845_312_345_673_925) + verifyFrameworkStartSuccess(178_944_220_000_000) // calculated by hand. + } + + @Test // this overlaps with the success case test. + fun `GIVEN app init has valid values WHEN onAppInit is called twice and metrics are set THEN frameworkStart uses the first app init value`() { + processStartTimeTicks = 166_636_813 + + elapsedRealtimeNanos = 1_845_312_345_673_925 + metrics.onApplicationInit() + elapsedRealtimeNanos = 1_945_312_345_673_925 + metrics.onApplicationInit() + + metrics.setExpensiveMetric() + verifyFrameworkStartSuccess(178_944_220_000_000) // calculated by hand. + } + + @Test + fun `GIVEN app init have valid values WHEN metrics are set twice THEN frameworkStart is only set once`() { + setProcessAppInitAndMetrics(10, 100) + metrics.setExpensiveMetric() + verify(exactly = 1) { frameworkStart.setRawNanos(any()) } + verify(exactly = 1) { clockTicksPerSecond.add(any()) } + verify { frameworkStartError wasNot Called } + } + + private fun setProcessAppInitAndMetrics(processStart: Long, appInit: Long) { + processStartTimeTicks = processStart + + elapsedRealtimeNanos = appInit + metrics.onApplicationInit() + + metrics.setExpensiveMetric() + } + + private fun verifyFrameworkStartSuccess(nanos: Long) { + verify { frameworkStart.setRawNanos(nanos) } + verify { clockTicksPerSecond.add(CLOCK_TICKS_PER_SECOND.toInt()) } + verify { frameworkStartError wasNot Called } + } + + private fun verifyFrameworkStartError() { + verify { frameworkStartError.set(true) } + verify { frameworkStart wasNot Called } + verify { clockTicksPerSecond wasNot Called } + } +}