For #20596 remove startup timeline probes
parent
7915ef8f3f
commit
707918cdc1
@ -0,0 +1,31 @@
|
||||
/* 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.SystemClock
|
||||
|
||||
/**
|
||||
* A class to store the application initialization time.
|
||||
* Time is stores in elapsed real time nano seconds
|
||||
*/
|
||||
internal class ApplicationInitTimeContainer(
|
||||
private val getElapsedRealtimeNanos: () -> Long = SystemClock::elapsedRealtimeNanos
|
||||
) {
|
||||
|
||||
var applicationInitNanos = -1L
|
||||
private set
|
||||
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()
|
||||
}
|
||||
}
|
||||
}
|
@ -1,107 +0,0 @@
|
||||
/* 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 java.io.FileNotFoundException
|
||||
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
|
||||
|
||||
var applicationInitNanos = -1L
|
||||
private set
|
||||
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 {
|
||||
val clockTicksPerSecond = stat.clockTicksPerSecond.also {
|
||||
// framework* 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.clockTicksPerSecondV2.set(it)
|
||||
}
|
||||
|
||||
// In our brief analysis, clock ticks per second was overwhelmingly equal to 100. To make
|
||||
// analysis easier in GLAM, we split the results into two separate metrics. See the
|
||||
// metric descriptions for more details.
|
||||
@Suppress("MagicNumber") // it's more confusing to separate the comment above from the value declaration.
|
||||
val durationMetric =
|
||||
if (clockTicksPerSecond == 100L) telemetry.frameworkPrimary else telemetry.frameworkSecondary
|
||||
|
||||
try {
|
||||
durationMetric.setRawNanos(getFrameworkStartNanos())
|
||||
} catch (e: FileNotFoundException) {
|
||||
// Privacy managers can add hooks that block access to reading system /proc files.
|
||||
// We want to catch these exception and report an error on accessing the file
|
||||
// rather than an implementation error.
|
||||
telemetry.frameworkStartReadError.set(true)
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
/**
|
||||
* @throws [java.io.FileNotFoundException]
|
||||
*/
|
||||
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)
|
||||
}
|
@ -1,73 +0,0 @@
|
||||
/* 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.SystemClock
|
||||
import android.system.Os
|
||||
import android.system.OsConstants
|
||||
import androidx.annotation.VisibleForTesting
|
||||
import androidx.annotation.VisibleForTesting.PRIVATE
|
||||
import java.io.File
|
||||
import java.util.concurrent.TimeUnit
|
||||
|
||||
private const val FIELD_POS_STARTTIME = 21 // starttime naming matches field in man page.
|
||||
|
||||
/**
|
||||
* Functionality from stat on the proc pseudo-filesystem common to unix systems. /proc contains
|
||||
* information related to active processes. /proc/$pid/stat contains information about the status of
|
||||
* the process by the given process id (pid).
|
||||
*
|
||||
* See the man page - `man 5 proc` - on linux for more information:
|
||||
* http://man7.org/linux/man-pages/man5/proc.5.html
|
||||
*/
|
||||
open class Stat {
|
||||
|
||||
/**
|
||||
* @throws [java.io.FileNotFoundException]
|
||||
*/
|
||||
@VisibleForTesting(otherwise = PRIVATE)
|
||||
open fun getStatText(pid: Int): String = File("/proc/$pid/stat").readText()
|
||||
|
||||
// See `man 3 sysconf` for details on Os.sysconf and OsConstants:
|
||||
// http://man7.org/linux/man-pages/man3/sysconf.3.html
|
||||
open val clockTicksPerSecond: Long get() = Os.sysconf(OsConstants._SC_CLK_TCK)
|
||||
private val nanosPerClockTick = TimeUnit.SECONDS.toNanos(1).let { nanosPerSecond ->
|
||||
// We use nanos per clock tick, rather than clock ticks per nanos, to mitigate float/double
|
||||
// rounding errors: this way we can use integer values and divide the larger value by the smaller one.
|
||||
nanosPerSecond / clockTicksPerSecond.toDouble()
|
||||
}
|
||||
|
||||
/**
|
||||
* Gets the process start time since system boot in ticks, including time spent in suspension/deep sleep.
|
||||
* This value can be compared against [SystemClock.elapsedRealtimeNanos]: you can convert between
|
||||
* measurements using [convertTicksToNanos] and [convertNanosToTicks].
|
||||
*
|
||||
* Ticks are "an arbitrary unit for measuring internal system time": https://superuser.com/a/101202
|
||||
* They are not aligned with CPU frequency and do not change at runtime but can theoretically
|
||||
* change between devices. On the Pixel 2, one tick is equivalent to one centisecond.
|
||||
*
|
||||
* We confirmed that this measurement and elapsedRealtimeNanos both include suspension time, and
|
||||
* are thus comparable, by* looking at their source:
|
||||
* - /proc/pid/stat starttime is set using boottime:
|
||||
* https://github.com/torvalds/linux/blob/79e178a57dae819ae724065b47c25720494cc9f2/fs/proc/array.c#L536
|
||||
* - elapsedRealtimeNanos is set using boottime:
|
||||
* https://cs.android.com/android/platform/superproject/+/master:system/core/libutils/SystemClock.cpp;l=60-68;drc=bab16584ce0525742b5370682c9132b2002ee110
|
||||
*
|
||||
* Perf note: this call reads from the pseudo-filesystem using the java File APIs, which isn't
|
||||
* likely to be a very optimized call path.
|
||||
*
|
||||
* Implementation inspired by https://stackoverflow.com/a/42195623.
|
||||
*/
|
||||
fun getProcessStartTimeTicks(pid: Int): Long {
|
||||
return getStatText(pid).split(' ')[FIELD_POS_STARTTIME].toLong()
|
||||
}
|
||||
|
||||
fun getProcessStartTimeStampNano(pid: Int): Long {
|
||||
return convertTicksToNanos(getProcessStartTimeTicks(pid)).toLong()
|
||||
}
|
||||
|
||||
fun convertTicksToNanos(ticks: Long): Double = ticks * nanosPerClockTick
|
||||
fun convertNanosToTicks(nanos: Long): Double = nanos / nanosPerClockTick
|
||||
}
|
@ -1,176 +0,0 @@
|
||||
/* 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.QuantityMetricType
|
||||
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 PRIMARY_TICKS = 100L
|
||||
private const val SECONDARY_TICKS = 50L
|
||||
|
||||
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 frameworkPrimary: TimespanMetricType
|
||||
@MockK(relaxed = true) private lateinit var frameworkSecondary: TimespanMetricType
|
||||
@MockK(relaxed = true) private lateinit var frameworkStartError: BooleanMetricType
|
||||
@MockK(relaxed = true) private lateinit var clockTicksPerSecondV2: QuantityMetricType
|
||||
|
||||
private var clockTicksPerSecondValue = -1L
|
||||
|
||||
private var elapsedRealtimeNanos = -1L
|
||||
private var processStartTimeTicks = -1L
|
||||
|
||||
@Before
|
||||
fun setUp() {
|
||||
MockKAnnotations.init(this)
|
||||
|
||||
elapsedRealtimeNanos = -1
|
||||
processStartTimeTicks = -1
|
||||
|
||||
// This value is hard-coded in the OS so we default to it as it's the expected value.
|
||||
clockTicksPerSecondValue = PRIMARY_TICKS
|
||||
|
||||
stat = spyk(object : Stat() {
|
||||
override val clockTicksPerSecond: Long get() = clockTicksPerSecondValue
|
||||
})
|
||||
every { stat.getProcessStartTimeTicks(any()) } answers { processStartTimeTicks }
|
||||
val getElapsedRealtimeNanos = { elapsedRealtimeNanos }
|
||||
|
||||
every { telemetry.frameworkPrimary } returns frameworkPrimary
|
||||
every { telemetry.frameworkSecondary } returns frameworkSecondary
|
||||
every { telemetry.frameworkStartError } returns frameworkStartError
|
||||
every { telemetry.clockTicksPerSecondV2 } returns clockTicksPerSecondV2
|
||||
|
||||
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 and clock ticks per second is 100 WHEN metrics are set THEN frameworkPrimary is set with the correct value`() {
|
||||
clockTicksPerSecondValue = PRIMARY_TICKS
|
||||
setProcessAppInitAndMetrics(processStart = 166_636_813, appInit = 1_845_312_345_673_925)
|
||||
verifyFrameworkStartSuccess(178_944_220_000_000, isPrimary = true) // calculated by hand.
|
||||
}
|
||||
|
||||
@Test
|
||||
fun `GIVEN app init is set to valid values and clock ticks per second is not 100 WHEN metrics are set THEN frameworkSecondary is set with the correct value`() {
|
||||
clockTicksPerSecondValue = SECONDARY_TICKS
|
||||
setProcessAppInitAndMetrics(processStart = 166_636_813, appInit = 1_845_312_345_673_925)
|
||||
verifyFrameworkStartSuccess(178_944_220_000_000, isPrimary = false) // calculated by hand.
|
||||
}
|
||||
|
||||
@Test // this overlaps with the success case test.
|
||||
fun `GIVEN app init has valid values and clock ticks per second is 100 WHEN onAppInit is called twice and metrics are set THEN frameworkPrimary uses the first app init value`() {
|
||||
clockTicksPerSecondValue = PRIMARY_TICKS
|
||||
testAppInitCalledTwice(isPrimary = true)
|
||||
}
|
||||
|
||||
@Test // this overlaps with the success case test.
|
||||
fun `GIVEN app init has valid values and clock ticks per second is not 100 WHEN onAppInit is called twice and metrics are set THEN frameworkSecondary uses the first app init value`() {
|
||||
clockTicksPerSecondValue = SECONDARY_TICKS
|
||||
testAppInitCalledTwice(isPrimary = false)
|
||||
}
|
||||
|
||||
private fun testAppInitCalledTwice(isPrimary: Boolean) {
|
||||
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, isPrimary) // calculated by hand.
|
||||
}
|
||||
|
||||
@Test
|
||||
fun `GIVEN app init have valid values and clock ticks per second is 100 WHEN metrics are set twice THEN frameworkPrimary is only set once`() {
|
||||
clockTicksPerSecondValue = PRIMARY_TICKS
|
||||
testMetricsSetTwice(isPrimary = true)
|
||||
}
|
||||
|
||||
@Test
|
||||
fun `GIVEN app init have valid values and clock ticks per second is not 100 WHEN metrics are set twice THEN frameworkSecondary is only set once`() {
|
||||
clockTicksPerSecondValue = SECONDARY_TICKS
|
||||
testMetricsSetTwice(isPrimary = false)
|
||||
}
|
||||
|
||||
private fun testMetricsSetTwice(isPrimary: Boolean) {
|
||||
setProcessAppInitAndMetrics(10, 100)
|
||||
metrics.setExpensiveMetric()
|
||||
|
||||
val (setMetric, unsetMetric) = getSetAndUnsetMetric(isPrimary)
|
||||
verify(exactly = 1) { setMetric.setRawNanos(any()) }
|
||||
verify { unsetMetric wasNot Called }
|
||||
verify(exactly = 1) { clockTicksPerSecondV2.set(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, isPrimary: Boolean) {
|
||||
val (setMetric, unsetMetric) = getSetAndUnsetMetric(isPrimary)
|
||||
verify { setMetric.setRawNanos(nanos) }
|
||||
verify { unsetMetric wasNot Called }
|
||||
|
||||
val expectedClockTicksPerSecond = getExpectedClockTicksPerSecond(isPrimary)
|
||||
verify { clockTicksPerSecondV2.set(expectedClockTicksPerSecond) }
|
||||
verify { frameworkStartError wasNot Called }
|
||||
}
|
||||
|
||||
private fun verifyFrameworkStartError() {
|
||||
verify { frameworkStartError.set(true) }
|
||||
verify { frameworkPrimary wasNot Called }
|
||||
verify { frameworkSecondary wasNot Called }
|
||||
verify { clockTicksPerSecondV2 wasNot Called }
|
||||
}
|
||||
|
||||
private fun getSetAndUnsetMetric(isPrimary: Boolean): Pair<TimespanMetricType, TimespanMetricType> {
|
||||
return if (isPrimary) {
|
||||
Pair(frameworkPrimary, frameworkSecondary)
|
||||
} else {
|
||||
Pair(frameworkSecondary, frameworkPrimary)
|
||||
}
|
||||
}
|
||||
|
||||
// This hard-codes some data that's passed into the test but I don't want to spend more time
|
||||
// so I don't bother cleaning it up now.
|
||||
private fun getExpectedClockTicksPerSecond(isPrimary: Boolean): Long =
|
||||
if (isPrimary) PRIMARY_TICKS else SECONDARY_TICKS
|
||||
}
|
@ -1,38 +0,0 @@
|
||||
/* 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.MockKAnnotations
|
||||
import io.mockk.impl.annotations.MockK
|
||||
import io.mockk.verifySequence
|
||||
import kotlinx.coroutines.ExperimentalCoroutinesApi
|
||||
import kotlinx.coroutines.test.runBlockingTest
|
||||
import mozilla.components.service.glean.private.NoReasonCodes
|
||||
import mozilla.components.service.glean.private.PingType
|
||||
import org.junit.Before
|
||||
import org.junit.Test
|
||||
|
||||
@ExperimentalCoroutinesApi
|
||||
class StartupHomeActivityLifecycleObserverTest {
|
||||
|
||||
@MockK(relaxed = true) private lateinit var frameworkStartMeasurement: StartupFrameworkStartMeasurement
|
||||
@MockK(relaxed = true) private lateinit var startupTimeline: PingType<NoReasonCodes>
|
||||
|
||||
@Before
|
||||
fun setUp() {
|
||||
MockKAnnotations.init(this)
|
||||
}
|
||||
|
||||
@Test
|
||||
fun `WHEN onStop is called THEN the metrics are set and the ping is submitted`() = runBlockingTest {
|
||||
val observer = StartupHomeActivityLifecycleObserver(frameworkStartMeasurement, startupTimeline, this)
|
||||
observer.onStop()
|
||||
|
||||
verifySequence {
|
||||
frameworkStartMeasurement.setExpensiveMetric()
|
||||
startupTimeline.submit()
|
||||
}
|
||||
}
|
||||
}
|
@ -1,45 +0,0 @@
|
||||
/* 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 org.junit.Assert.assertEquals
|
||||
import org.junit.Before
|
||||
import org.junit.Test
|
||||
|
||||
private const val STAT_CONTENTS = "32250 (a.fennec_aurora) S 831 831 0 0 -1 1077952832 670949 0 184936 0 15090 5387 0 0 20 0 119 0 166636813 9734365184 24664 18446744073709551615 1 1 0 0 0 0 4612 4097 1073792254 0 0 0 17 1 0 0 0 0 0 0 0 0 0 0 0 0 0"
|
||||
private const val CLOCK_TICKS_PER_SECOND = 100L // actual value on the Pixel 2.
|
||||
|
||||
class StatTest {
|
||||
|
||||
private lateinit var stat: StatTestImpl
|
||||
|
||||
@Before
|
||||
fun setUp() {
|
||||
stat = StatTestImpl()
|
||||
}
|
||||
|
||||
@Test
|
||||
fun `WHEN getting the process start time THEN the correct value is returned`() {
|
||||
val actual = stat.getProcessStartTimeTicks(pid = -1) // pid behavior is overridden.
|
||||
assertEquals(166636813, actual) // expected value calculated by hand.
|
||||
}
|
||||
|
||||
@Test
|
||||
fun `WHEN converting ticks to nanos THEN the correct value is returned`() {
|
||||
val actual = stat.convertTicksToNanos(166_636_813)
|
||||
assertEquals(1_666_368_130_000_000.0, actual, 0.0) // expected value calculated by hand.
|
||||
}
|
||||
|
||||
@Test
|
||||
fun `WHEN converting nanos to ticks THEN the correct value is returned`() {
|
||||
val actual = stat.convertNanosToTicks(1_666_368_135_432_102)
|
||||
assertEquals(166_636_813.5432102, actual, 0.0) // expected value calculated by hand.
|
||||
}
|
||||
}
|
||||
|
||||
class StatTestImpl : Stat() {
|
||||
override fun getStatText(pid: Int): String = STAT_CONTENTS
|
||||
override val clockTicksPerSecond: Long get() = CLOCK_TICKS_PER_SECOND
|
||||
}
|
Loading…
Reference in New Issue