1541493: Add thread-safe timing API (586b73ba) · Commits · The Tor Project / Applications / android-components

components/service/glean/docs/metrics/adding-new-metrics.md

+27 −16

Original line number	Diff line number	Diff line
		@@ -329,18 +329,22 @@ rendering:
		...
		```

		Now you can use the timespan from the application's code:
		Now you can use the timespan from the application's code. Each time interval that
		the timespan metric records must be associated with an object provided by the user.
		This is so that intervals can be measured concurrently. For example, to measure page
		load time on a number of tabs that are loading at the same time, each time interval
		should be associated with an object that uniquely represents each tab.

		```Kotlin
		import org.mozilla.yourApplication.GleanMetrics.Rendering
		import org.mozilla.yourApplication.GleanMetrics.Pages

		fun onPageStart(e: Event) {
		Pages.pageLoad.start(e.target)
		}

		Rendering.imageDecodeTime.start() // start the timer
		try {
		// ... decode an image ...
		} catch (e: Exception) {
		Rendering.imageDecodeTime.cancel() // cancel the timer -- nothing is recorded
		fun onPageLoaded(e: Event) {
		Pages.pageLoad.stopAndSum(e.target)
		}
		Rendering.imageDecodeTime.stopAndSum() // stop the timer
		```

		The time reported in the telemetry ping will be the sum of all of these
		@@ -349,13 +353,13 @@ timespans recorded during the lifetime of the ping.
		There are test APIs available too:

		```Kotlin
		import org.mozilla.yourApplication.GleanMetrics.Rendering
		import org.mozilla.yourApplication.GleanMetrics.Pages
		Glean.enableTestingMode()

		// Was anything recorded?
		assertTrue(Rendering.imageDecodeTime.testHasValue())
		assertTrue(Pages.pageLoad.testHasValue())
		// Does the timer have the expected value
		assertTrue(Rendering.imageDecodeTime.testGetValue() > 0)
		assertTrue(Pages.pageLoad.testGetValue() > 0)
		```

		## Timing Distributions
		@@ -388,15 +392,22 @@ pages:
		```


		Now that the timing distribution is defined in `metrics.yaml` you can use the metric to record data
		in the application code:
		Now you can use the timing distribution from the application's code. Each time interval that
		the timing distribution metric records must be associated with an object provided by the user.
		This is so that intervals can be measured concurrently. For example, to measure page
		load time on a number of tabs that are loading at the same time, each time interval
		should be associated with an object that uniquely represents each tab.

		```Kotlin
		import org.mozilla.yourApplication.GleanMetrics.Pages

		// ...
		pages.pageLoad.accumulate(1L) // Accumulates a sample of 1 millisecond
		pages.pageLoad.accumulate(10L) // Accumulates a sample of 10 milliseconds
		fun onPageStart(e: Event) {
		Pages.pageLoad.start(e.target)
		}

		fun onPageLoaded(e: Event) {
		Pages.pageLoad.stopAndAccumulate(e.target)
		}
		```

		There are test APIs available too. For convenience, properties `sum` and `count` are exposed to

components/service/glean/src/main/java/mozilla/components/service/glean/private/TimespanMetricType.kt

+32 −11

Original line number	Diff line number	Diff line
		@@ -5,7 +5,9 @@
		package mozilla.components.service.glean.private

		import android.support.annotation.VisibleForTesting
		import mozilla.components.service.glean.Dispatchers
		import mozilla.components.service.glean.storages.TimespansStorageEngine
		import mozilla.components.service.glean.timing.TimingManager
		import mozilla.components.support.base.log.logger.Logger

		/**
		@@ -30,39 +32,58 @@ data class TimespanMetricType(
		private val logger = Logger("glean/TimespanMetricType")

		/**
		* Start tracking time for the provided metric. This records an error if it’s
		* already tracking time (i.e. start was already called with no corresponding
		* [stopAndSum]): in that case the original start time will be preserved.
		* Start tracking time for the provided metric and associated object. This
		* records an error if it’s already tracking time (i.e. start was already
		* called with no corresponding [stopAndSum]): in that case the original
		* start time will be preserved.
		*
		* @param anyObject The object to associate with this timing. This allows
		* for concurrent timing of events associated with different objects to the
		* same timespan metric.
		*/
		fun start() {
		fun start(anyObject: Any) {
		if (!shouldRecord(logger)) {
		return
		}

		TimespansStorageEngine.start(this)
		TimingManager.start(this, anyObject)
		}

		/**
		* Stop tracking time for the provided metric. Add the elapsed time to the time currently
		* stored in the metric. This will record an error if no [start] was called.
		* Stop tracking time for the provided metric and associated object. Add the
		* elapsed time to the time currently stored in the metric. This will record
		* an error if no [start] was called.
		*
		* @param anyObject The object to associate with this timing. This allows
		* for concurrent timing of events associated with different objects to the
		* same timespan metric.
		*/
		fun stopAndSum() {
		fun stopAndSum(anyObject: Any) {
		if (!shouldRecord(logger)) {
		return
		}

		TimespansStorageEngine.stopAndSum(this, timeUnit)
		TimingManager.stop(this, anyObject)?.let { elapsedNanos ->
		@Suppress("EXPERIMENTAL_API_USAGE")
		Dispatchers.API.launch {
		TimespansStorageEngine.sum(this@TimespanMetricType, timeUnit, elapsedNanos)
		}
		}
		}

		/**
		* Abort a previous [start] call. No error is recorded if no [start] was called.
		*
		* @param anyObject The object to associate with this timing. This allows
		* for concurrent timing of events associated with different objects to the
		* same timespan metric.
		*/
		fun cancel() {
		fun cancel(anyObject: Any) {
		if (!shouldRecord(logger)) {
		return
		}

		TimespansStorageEngine.cancel(this)
		TimingManager.cancel(this, anyObject)
		}

		/**

components/service/glean/src/main/java/mozilla/components/service/glean/private/TimingDistributionMetricType.kt

+51 −11

Original line number	Diff line number	Diff line
		@@ -8,6 +8,7 @@ import android.support.annotation.VisibleForTesting
		import mozilla.components.service.glean.Dispatchers
		import mozilla.components.service.glean.storages.TimingDistributionData
		import mozilla.components.service.glean.storages.TimingDistributionsStorageEngine
		import mozilla.components.service.glean.timing.TimingManager
		import mozilla.components.support.base.log.logger.Logger

		/**
		@@ -33,25 +34,64 @@ data class TimingDistributionMetricType(
		private val logger = Logger("glean/TimingDistributionMetricType")

		/**
		* Accumulates a sample value to the timing distribution.
		* Start tracking time for the provided metric and associated object. This
		* records an error if it’s already tracking time (i.e. start was already
		* called with no corresponding [stopAndAccumulate]): in that case the original
		* start time will be preserved.
		*
		* @param sample This is the sample to accumulate
		* @param anyObject The object to associate with this timing. This allows
		* for concurrent timing of events associated with different objects to the
		* same timespan metric.
		*/
		fun accumulate(sample: Long) {
		fun start(anyObject: Any) {
		if (!shouldRecord(logger)) {
		return
		}

		TimingManager.start(this, anyObject)
		}

		/**
		* Stop tracking time for the provided metric and associated object. Add a
		* count to the corresponding bucket in the timing distribution.
		* This will record an error if no [start] was called.
		*
		* @param anyObject The object to associate with this timing. This allows
		* for concurrent timing of events associated with different objects to the
		* same timespan metric.
		*/
		fun stopAndAccumulate(anyObject: Any) {
		if (!shouldRecord(logger)) {
		return
		}

		TimingManager.stop(this, anyObject)?.let { elapsedNanos ->
		@Suppress("EXPERIMENTAL_API_USAGE")
		Dispatchers.API.launch {
		// Delegate storing the string to the storage engine.
		TimingDistributionsStorageEngine.accumulate(
		metricData = this@TimingDistributionMetricType,
		sample = sample,
		sample = elapsedNanos,
		timeUnit = timeUnit
		)
		}
		}
		}

		/**
		* Abort a previous [start] call. No error is recorded if no [start] was called.
		*
		* @param anyObject The object to associate with this timing. This allows
		* for concurrent timing of events associated with different objects to the
		* same timespan metric.
		*/
		fun cancel(anyObject: Any) {
		if (!shouldRecord(logger)) {
		return
		}

		TimingManager.cancel(this, anyObject)
		}

		/**
		* Tests whether a value is stored for the metric for testing purposes only. This function will

components/service/glean/src/main/java/mozilla/components/service/glean/scheduler/GleanLifecycleObserver.kt

+2 −2

Original line number	Diff line number	Diff line
		@@ -22,7 +22,7 @@ internal class GleanLifecycleObserver : LifecycleObserver {
		fun onEnterBackground() {
		// We're going to background, so store how much time we spent
		// on foreground.
		GleanBaseline.duration.stopAndSum()
		GleanBaseline.duration.stopAndSum(this)
		Glean.handleBackgroundEvent()
		}

		@@ -39,6 +39,6 @@ internal class GleanLifecycleObserver : LifecycleObserver {
		// Note that this is sending the length of the last foreground session
		// because it belongs to the baseline ping and that ping is sent every
		// time the app goes to background.
		GleanBaseline.duration.start()
		GleanBaseline.duration.start(this)
		}
		}

components/service/glean/src/main/java/mozilla/components/service/glean/storages/TimespansStorageEngine.kt

+15 −90

Original line number	Diff line number	Diff line
		@@ -6,17 +6,14 @@ package mozilla.components.service.glean.storages

		import android.annotation.SuppressLint
		import android.content.SharedPreferences
		import android.os.SystemClock
		import android.support.annotation.VisibleForTesting
		import mozilla.components.service.glean.error.ErrorRecording.ErrorType
		import mozilla.components.service.glean.error.ErrorRecording.recordError
		import mozilla.components.service.glean.private.CommonMetricData
		import mozilla.components.service.glean.private.TimeUnit
		import mozilla.components.service.glean.utils.getAdjustedTime

		import mozilla.components.support.base.log.logger.Logger
		import org.json.JSONArray
		import org.json.JSONObject
		import java.util.concurrent.TimeUnit as AndroidTimeUnit

		/**
		* This singleton handles the in-memory storage logic for timespans. It is meant to be used by
		@@ -33,12 +30,6 @@ internal open class TimespansStorageEngineImplementation(
		override val logger: Logger = Logger("glean/TimespansStorageEngine")
		) : GenericStorageEngine<Long>() {

		/**
		* A map that stores the start times from the API consumers, not yet
		* committed to any store (i.e. [start] was called but no [stopAndSum] yet).
		*/
		private val uncommittedStartTimes = mutableMapOf<String, Long>()

		/**
		* An internal map to keep track of the desired time units for the recorded timespans.
		* We need this in order to get a snapshot of the data, with the right time unit,
		@@ -103,75 +94,20 @@ internal open class TimespansStorageEngineImplementation(
		}

		/**
		* Helper function used for getting the elapsed time, since the process
		* started, using a monotonic clock.
		* We need to have this as an helper so that we can override it in tests.
		*
		* @return the time, in nanoseconds, since the process started.
		*/
		internal fun getElapsedNanos(): Long = SystemClock.elapsedRealtimeNanos()

		/**
		* Convenience method to get a time in a different, supported time unit.
		*
		* @param timeUnit the required time unit, one in [TimeUnit]
		* @param elapsedNanos a time in nanoseconds
		*
		* @return the time in the desired time unit
		*/
		private fun getAdjustedTime(timeUnit: TimeUnit, elapsedNanos: Long): Long {
		return when (timeUnit) {
		TimeUnit.Nanosecond -> elapsedNanos
		TimeUnit.Microsecond -> AndroidTimeUnit.NANOSECONDS.toMicros(elapsedNanos)
		TimeUnit.Millisecond -> AndroidTimeUnit.NANOSECONDS.toMillis(elapsedNanos)
		TimeUnit.Second -> AndroidTimeUnit.NANOSECONDS.toSeconds(elapsedNanos)
		TimeUnit.Minute -> AndroidTimeUnit.NANOSECONDS.toMinutes(elapsedNanos)
		TimeUnit.Hour -> AndroidTimeUnit.NANOSECONDS.toHours(elapsedNanos)
		TimeUnit.Day -> AndroidTimeUnit.NANOSECONDS.toDays(elapsedNanos)
		}
		}

		/**
		* Start tracking time for the provided metric. This records an error if it’s
		* already tracking time (i.e. start was already called with no corresponding
		* [stopAndSum]): in that case the original start time will be preserved.
		*
		* @param metricData the metric information for the timespan
		*/
		fun start(metricData: CommonMetricData) {
		val timespanName = metricData.identifier

		if (timespanName in uncommittedStartTimes) {
		recordError(
		metricData,
		ErrorType.InvalidValue,
		"Timespan already started",
		logger
		)
		return
		}

		synchronized(this) {
		uncommittedStartTimes[timespanName] = getElapsedNanos()
		}
		}

		/**
		* Stop tracking time for the provided metric. Add the elapsed time to the time currently
		* stored in the metric. This will record an error if no [start] was called.
		* Add the elapsed time to the time currently stored in the metric.
		*
		* @param metricData the metric information for the timespan
		* @param timeUnit the time unit we want the data in when snapshotting
		* @param elapsedNanos the time to record, in nanoseconds
		*/
		@Synchronized
		fun stopAndSum(
		fun sum(
		metricData: CommonMetricData,
		timeUnit: TimeUnit
		timeUnit: TimeUnit,
		elapsedNanos: Long
		) {
		// Look for the start time: if it's there, commit the timespan.
		val timespanName = metricData.identifier
		uncommittedStartTimes.remove(timespanName)?.let { startTime ->
		val elapsedNanos = getElapsedNanos() - startTime

		// Store the time unit: we'll need it when snapshotting.
		timeUnitsMap[timespanName] = timeUnit
		@@ -185,17 +121,6 @@ internal open class TimespansStorageEngineImplementation(
		} ?: newValue
		}
		}
		}

		/**
		* Abort a previous [start] call. No error is recorded if no [start] was called.
		*
		* @param metricData the metric information for the timespan
		*/
		@Synchronized
		fun cancel(metricData: CommonMetricData) {
		uncommittedStartTimes.remove(metricData.identifier)
		}

		/**
		* Get a snapshot of the stored timespans and adjust it to the desired time units.