Add extra analytics for notification performance (#6237)

* Add extra analytics for notification performance

Add technical spans to track how long a notification fetching work request takes to run, then how long it takes to actually fetch the events for the notifications

* Remove `withContext(io)` for `FetchNotificationsWorker`

The default `Dispatchers.Default` dispatcher used should be good enough and more performant

* Add network check span

libraries/push/impl/build.gradle.kts

@@ -86,6 +86,7 @@ dependencies {
     testImplementation(projects.features.networkmonitor.test)
     testImplementation(projects.services.appnavstate.impl)
     testImplementation(projects.services.appnavstate.test)
+    testImplementation(projects.services.analytics.test)
     testImplementation(projects.services.toolbox.impl)
     testImplementation(projects.services.toolbox.test)
     testImplementation(projects.libraries.featureflag.test)

libraries/push/impl/src/main/kotlin/io/element/android/libraries/push/impl/notifications/NotificationRenderer.kt

@@ -25,6 +25,9 @@ import io.element.android.libraries.push.impl.notifications.model.NotifiableMess
 import io.element.android.libraries.push.impl.notifications.model.NotifiableRingingCallEvent
 import io.element.android.libraries.push.impl.notifications.model.SimpleNotifiableEvent
 import io.element.android.libraries.sessionstorage.api.SessionStore
+import io.element.android.services.analytics.api.AnalyticsLongRunningTransaction
+import io.element.android.services.analytics.api.AnalyticsService
+import io.element.android.services.analytics.api.finishLongRunningTransaction
 import kotlinx.coroutines.flow.first
 import timber.log.Timber
 
@@ -36,6 +39,7 @@ class NotificationRenderer(
     private val notificationDataFactory: NotificationDataFactory,
     private val enterpriseService: EnterpriseService,
     private val sessionStore: SessionStore,
+    private val analyticsService: AnalyticsService,
 ) {
     suspend fun render(
         currentUser: MatrixUser,
@@ -124,6 +128,12 @@ class NotificationRenderer(
                 notification = summaryNotification.notification
             )
         }
+
+        for (event in eventsToProcess) {
+            // Finish long-running transaction
+            val uploaded = analyticsService.finishLongRunningTransaction(AnalyticsLongRunningTransaction.PushToNotification(event.eventId.value))
+            Timber.d("Push-to-notification for event ${event.eventId} uploaded: $uploaded")
+        }
     }
 }
 

libraries/push/impl/src/main/kotlin/io/element/android/libraries/push/impl/push/DefaultPushHandler.kt

@@ -40,6 +40,8 @@ import io.element.android.libraries.pushproviders.api.PushData
 import io.element.android.libraries.pushproviders.api.PushHandler
 import io.element.android.libraries.pushstore.api.UserPushStoreFactory
 import io.element.android.libraries.pushstore.api.clientsecret.PushClientSecret
+import io.element.android.services.analytics.api.AnalyticsLongRunningTransaction
+import io.element.android.services.analytics.api.AnalyticsService
 import kotlinx.coroutines.CoroutineScope
 import kotlinx.coroutines.flow.first
 import kotlinx.coroutines.flow.launchIn
@@ -69,6 +71,7 @@ class DefaultPushHandler(
     private val fallbackNotificationFactory: FallbackNotificationFactory,
     private val syncOnNotifiableEvent: SyncOnNotifiableEvent,
     private val featureFlagService: FeatureFlagService,
+    private val analyticsService: AnalyticsService,
 ) : PushHandler {
     init {
         processPushEventResults()
@@ -215,6 +218,13 @@ class DefaultPushHandler(
      * @param providerInfo the provider info.
      */
     override suspend fun handle(pushData: PushData, providerInfo: String) {
+        // Start measuring how long it takes to display a notification from when the push is received
+        Timber.d("Calculating push-to-notification for event ${pushData.eventId}")
+        val parent = analyticsService.startLongRunningTransaction(AnalyticsLongRunningTransaction.PushToNotification(pushData.eventId.value))
+        if (featureFlagService.isFeatureEnabled(FeatureFlags.SyncNotificationsWithWorkManager)) {
+            analyticsService.startLongRunningTransaction(AnalyticsLongRunningTransaction.PushToWorkManager(pushData.eventId.value), parent)
+        }
+
         Timber.tag(loggerTag.value).d("## handling pushData: ${pushData.roomId}/${pushData.eventId}")
         if (buildMeta.lowPrivacyLoggingEnabled) {
             Timber.tag(loggerTag.value).d("## pushData: $pushData")

libraries/push/impl/src/main/kotlin/io/element/android/libraries/push/impl/workmanager/FetchNotificationsWorker.kt

@@ -19,7 +19,6 @@ import dev.zacsweers.metro.ContributesIntoMap
 import dev.zacsweers.metro.binding
 import io.element.android.features.networkmonitor.api.NetworkMonitor
 import io.element.android.features.networkmonitor.api.NetworkStatus
-import io.element.android.libraries.core.coroutine.CoroutineDispatchers
 import io.element.android.libraries.core.extensions.runCatchingExceptions
 import io.element.android.libraries.di.annotations.ApplicationContext
 import io.element.android.libraries.matrix.api.auth.SessionRestorationException
@@ -31,10 +30,13 @@ import io.element.android.libraries.push.impl.notifications.NotificationResolver
 import io.element.android.libraries.workmanager.api.WorkManagerScheduler
 import io.element.android.libraries.workmanager.api.di.MetroWorkerFactory
 import io.element.android.libraries.workmanager.api.di.WorkerKey
+import io.element.android.services.analytics.api.AnalyticsLongRunningTransaction
+import io.element.android.services.analytics.api.AnalyticsService
+import io.element.android.services.analytics.api.finishLongRunningTransaction
+import io.element.android.services.analytics.api.recordTransaction
 import io.element.android.services.toolbox.api.sdk.BuildVersionSdkIntProvider
 import kotlinx.coroutines.flow.MutableSharedFlow
 import kotlinx.coroutines.flow.first
-import kotlinx.coroutines.withContext
 import kotlinx.coroutines.withTimeoutOrNull
 import timber.log.Timber
 import kotlin.time.Duration.Companion.seconds
@@ -48,22 +50,45 @@ class FetchNotificationsWorker(
     private val queue: NotificationResolverQueue,
     private val workManagerScheduler: WorkManagerScheduler,
     private val syncOnNotifiableEvent: SyncOnNotifiableEvent,
-    private val coroutineDispatchers: CoroutineDispatchers,
     private val workerDataConverter: SyncNotificationsWorkerDataConverter,
     private val buildVersionSdkIntProvider: BuildVersionSdkIntProvider,
+    private val analyticsService: AnalyticsService,
 ) : CoroutineWorker(context, workerParams) {
-    override suspend fun doWork(): Result = withContext(coroutineDispatchers.io) {
+    override suspend fun doWork(): Result {
         Timber.d("FetchNotificationsWorker started")
-        val requests = workerDataConverter.deserialize(inputData) ?: return@withContext Result.failure()
+        val requests = workerDataConverter.deserialize(inputData) ?: return Result.failure()
         // Wait for network to be available, but not more than 10 seconds
+        val networkTimeoutSpans = requests.mapNotNull { request ->
+            val parent = analyticsService.getLongRunningTransaction(AnalyticsLongRunningTransaction.PushToWorkManager(request.eventId.value))
+            parent?.startChild("Waiting for network connectivity", "await_network")
+        }
         val hasNetwork = withTimeoutOrNull(10.seconds) {
             networkMonitor.connectivity.first { it == NetworkStatus.Connected }
         } != null
+
+        for (span in networkTimeoutSpans) {
+            span.finish()
+        }
+
         if (!hasNetwork) {
             Timber.w("No network, retrying later")
-            return@withContext Result.retry()
+            for (request in requests) {
+                val eventId = request.eventId.value
+                analyticsService.finishLongRunningTransaction(AnalyticsLongRunningTransaction.PushToWorkManager(eventId))
+                val parent = analyticsService.getLongRunningTransaction(AnalyticsLongRunningTransaction.PushToNotification(eventId))
+                // Since we're retrying, start a new transaction
+                analyticsService.startLongRunningTransaction(AnalyticsLongRunningTransaction.PushToWorkManager(eventId), parent)
+            }
+            return Result.retry()
         }
 
+        val pendingAnalyticTransactions = requests.mapNotNull { request ->
+            analyticsService.finishLongRunningTransaction(AnalyticsLongRunningTransaction.PushToWorkManager(request.eventId.value))
+            val parent = analyticsService.getLongRunningTransaction(AnalyticsLongRunningTransaction.PushToNotification(request.eventId.value))
+            val transactionName = "WorkManager to event fetched"
+            parent?.startChild(transactionName)?.let { request.eventId to it }
+        }.toMap()
+
         val failedSyncForSessions = mutableMapOf<SessionId, Throwable>()
 
         val groupedRequests = requests.groupBy { it.sessionId }.toMutableMap()
@@ -72,10 +97,17 @@ class FetchNotificationsWorker(
             eventResolver.resolveEvents(sessionId, notificationRequests)
                 .fold(
                     onSuccess = { result ->
+                        for ((_, transaction) in pendingAnalyticTransactions) {
+                            transaction.finish()
+                        }
                         // Update the resolved results in the queue
                         (queue.results as MutableSharedFlow).emit(requests to result)
                     },
                     onFailure = {
+                        for ((_, transaction) in pendingAnalyticTransactions) {
+                            transaction.attachError(it)
+                            transaction.finish()
+                        }
                         failedSyncForSessions[sessionId] = it
                         Timber.e(it, "Failed to resolve notification events for session $sessionId")
                     }
@@ -92,6 +124,18 @@ class FetchNotificationsWorker(
                     continue
                 }
                 val requestsToRetry = groupedRequests[failedSessionId] ?: continue
+
+                for (request in requestsToRetry) {
+                    val failedTransaction = pendingAnalyticTransactions[request.eventId]
+                    failedTransaction?.attachError(exception)
+                    failedTransaction?.finish()
+
+                    val eventId = request.eventId.value
+                    val parent = analyticsService.getLongRunningTransaction(AnalyticsLongRunningTransaction.PushToNotification(eventId))
+                    // Since we're retrying, start a new transaction
+                    analyticsService.startLongRunningTransaction(AnalyticsLongRunningTransaction.PushToWorkManager(eventId), parent)
+                }
+
                 Timber.d("Re-scheduling ${requestsToRetry.size} failed notification requests for session $failedSessionId")
                 workManagerScheduler.submit(
                     SyncNotificationWorkManagerRequest(
@@ -106,9 +150,11 @@ class FetchNotificationsWorker(
 
         Timber.d("Notifications processed successfully")
 
-        performOpportunisticSyncIfNeeded(groupedRequests)
+        analyticsService.recordTransaction("Opportunistic sync", "opportunistic_sync") {
+            performOpportunisticSyncIfNeeded(groupedRequests)
+        }
 
-        Result.success()
+        return Result.success()
     }
 
     private suspend fun performOpportunisticSyncIfNeeded(

libraries/push/impl/src/test/kotlin/io/element/android/libraries/push/impl/notifications/DefaultNotificationDrawerManagerTest.kt

@@ -40,6 +40,7 @@ import io.element.android.libraries.sessionstorage.api.SessionStore
 import io.element.android.libraries.sessionstorage.api.observer.SessionObserver
 import io.element.android.libraries.sessionstorage.test.InMemorySessionStore
 import io.element.android.libraries.sessionstorage.test.observer.FakeSessionObserver
+import io.element.android.services.analytics.test.FakeAnalyticsService
 import io.element.android.services.appnavstate.api.AppNavigationState
 import io.element.android.services.appnavstate.api.AppNavigationStateService
 import io.element.android.services.appnavstate.test.FakeAppNavigationStateService
@@ -508,6 +509,7 @@ fun TestScope.createDefaultNotificationDrawerManager(
     sessionStore: SessionStore = InMemorySessionStore(),
     enterpriseService: EnterpriseService = FakeEnterpriseService(),
     sessionObserver: SessionObserver = FakeSessionObserver(),
+    analyticsService: FakeAnalyticsService = FakeAnalyticsService(),
 ): DefaultNotificationDrawerManager {
     return DefaultNotificationDrawerManager(
         notificationDisplayer = notificationDisplayer,
@@ -521,6 +523,7 @@ fun TestScope.createDefaultNotificationDrawerManager(
             ),
             enterpriseService = enterpriseService,
             sessionStore = sessionStore,
+            analyticsService = analyticsService,
         ),
         appNavigationStateService = appNavigationStateService,
         coroutineScope = backgroundScope,

libraries/push/impl/src/test/kotlin/io/element/android/libraries/push/impl/notifications/NotificationRendererTest.kt

@@ -29,6 +29,7 @@ import io.element.android.libraries.push.impl.notifications.fixtures.anInviteNot
 import io.element.android.libraries.push.impl.notifications.model.NotifiableEvent
 import io.element.android.libraries.sessionstorage.api.SessionStore
 import io.element.android.libraries.sessionstorage.test.InMemorySessionStore
+import io.element.android.services.analytics.test.FakeAnalyticsService
 import io.element.android.tests.testutils.lambda.lambdaRecorder
 import io.element.android.tests.testutils.lambda.value
 import kotlinx.coroutines.test.runTest
@@ -122,9 +123,11 @@ fun createNotificationRenderer(
     notificationDataFactory: NotificationDataFactory = FakeNotificationDataFactory(),
     enterpriseService: EnterpriseService = FakeEnterpriseService(),
     sessionStore: SessionStore = InMemorySessionStore(),
+    analyticsService: FakeAnalyticsService = FakeAnalyticsService(),
 ) = NotificationRenderer(
     notificationDisplayer = notificationDisplayer,
     notificationDataFactory = notificationDataFactory,
     enterpriseService = enterpriseService,
     sessionStore = sessionStore,
+    analyticsService = analyticsService,
 )

libraries/push/impl/src/test/kotlin/io/element/android/libraries/push/impl/push/DefaultPushHandlerTest.kt

@@ -56,6 +56,7 @@ import io.element.android.libraries.pushstore.test.userpushstore.FakeUserPushSto
 import io.element.android.libraries.pushstore.test.userpushstore.clientsecret.FakePushClientSecret
 import io.element.android.libraries.workmanager.api.WorkManagerRequest
 import io.element.android.libraries.workmanager.test.FakeWorkManagerScheduler
+import io.element.android.services.analytics.test.FakeAnalyticsService
 import io.element.android.services.toolbox.test.sdk.FakeBuildVersionSdkIntProvider
 import io.element.android.services.toolbox.test.systemclock.FakeSystemClock
 import io.element.android.tests.testutils.lambda.any
@@ -683,6 +684,7 @@ class DefaultPushHandlerTest {
         syncOnNotifiableEvent: SyncOnNotifiableEvent = SyncOnNotifiableEvent {},
         featureFlagService: FakeFeatureFlagService = FakeFeatureFlagService(initialState = mapOf(FeatureFlags.SyncNotificationsWithWorkManager.key to false)),
         workManagerScheduler: FakeWorkManagerScheduler = FakeWorkManagerScheduler(),
+        analyticsService: FakeAnalyticsService = FakeAnalyticsService(),
     ): DefaultPushHandler {
         return DefaultPushHandler(
             onNotifiableEventReceived = FakeOnNotifiableEventReceived(onNotifiableEventsReceived),
@@ -715,6 +717,7 @@ class DefaultPushHandlerTest {
             ),
             syncOnNotifiableEvent = syncOnNotifiableEvent,
             featureFlagService = featureFlagService,
+            analyticsService = analyticsService,
         )
     }
 }

libraries/push/impl/src/test/kotlin/io/element/android/libraries/push/impl/workmanager/FetchNotificationWorkerTest.kt

@@ -29,9 +29,9 @@ import io.element.android.libraries.push.test.notifications.FakeNotificationReso
 import io.element.android.libraries.workmanager.api.WorkManagerRequest
 import io.element.android.libraries.workmanager.api.di.MetroWorkerFactory
 import io.element.android.libraries.workmanager.test.FakeWorkManagerScheduler
+import io.element.android.services.analytics.test.FakeAnalyticsService
 import io.element.android.services.toolbox.test.sdk.FakeBuildVersionSdkIntProvider
 import io.element.android.tests.testutils.lambda.lambdaRecorder
-import io.element.android.tests.testutils.testCoroutineDispatchers
 import kotlinx.coroutines.ExperimentalCoroutinesApi
 import kotlinx.coroutines.test.TestScope
 import kotlinx.coroutines.test.advanceTimeBy
@@ -168,6 +168,7 @@ class FetchNotificationWorkerTest {
         ),
         workManagerScheduler: FakeWorkManagerScheduler = FakeWorkManagerScheduler(),
         syncOnNotifiableEvent: SyncOnNotifiableEvent = SyncOnNotifiableEvent {},
+        analyticsService: FakeAnalyticsService = FakeAnalyticsService(),
     ) = FetchNotificationsWorker(
         workerParams = createWorkerParams(workDataOf("requests" to input)),
         context = InstrumentationRegistry.getInstrumentation().context,
@@ -176,9 +177,9 @@ class FetchNotificationWorkerTest {
         queue = queue,
         workManagerScheduler = workManagerScheduler,
         syncOnNotifiableEvent = syncOnNotifiableEvent,
-        coroutineDispatchers = testCoroutineDispatchers(),
         workerDataConverter = SyncNotificationsWorkerDataConverter(DefaultJsonProvider()),
         buildVersionSdkIntProvider = FakeBuildVersionSdkIntProvider(33),
+        analyticsService = analyticsService,
     )
 
     private fun TestScope.createWorkerParams(

services/analytics/api/src/main/kotlin/io/element/android/services/analytics/api/AnalyticsLongRunningTransaction.kt

@@ -28,4 +28,6 @@ sealed class AnalyticsLongRunningTransaction(
     data object LoadJoinedRoomFlow : AnalyticsLongRunningTransaction("Load joined room UI", "ui.load")
     data object LoadMessagesUi : AnalyticsLongRunningTransaction("Load messages UI", "ui.load")
     data object DisplayFirstTimelineItems : AnalyticsLongRunningTransaction("Get and display first timeline items", null)
+    data class PushToNotification(val eventId: String) : AnalyticsLongRunningTransaction(AnalyticsTransactions.pushToNotification)
+    data class PushToWorkManager(val eventId: String) : AnalyticsLongRunningTransaction("Push to WorkManager")
 }

services/analytics/api/src/main/kotlin/io/element/android/services/analytics/api/AnalyticsService.kt

@@ -108,11 +108,12 @@ fun AnalyticsService.cancelLongRunningTransaction(
 fun AnalyticsService.finishLongRunningTransaction(
     longRunningTransaction: AnalyticsLongRunningTransaction,
     action: (AnalyticsTransaction) -> Unit = {},
-) {
+): Boolean {
-    removeLongRunningTransaction(longRunningTransaction)?.let {
+    return removeLongRunningTransaction(longRunningTransaction)?.let {
         action(it)
         it.finish()
-    }
+        true
+    } ?: false
 }
 
 inline fun <T> AnalyticsService.inBridgeSdkSpan(parentTraceId: String?, block: (AnalyticsSdkSpan) -> T): T {

services/analytics/impl/build.gradle.kts

@@ -40,5 +40,6 @@ dependencies {
     testImplementation(projects.services.analytics.test)
     testImplementation(projects.services.analyticsproviders.test)
     testImplementation(projects.services.appnavstate.test)
+    testImplementation(projects.features.networkmonitor.test)
     testImplementation(projects.services.toolbox.test)
 }

services/analyticsproviders/api/src/main/kotlin/io/element/android/services/analyticsproviders/api/AnalyticsTransactions.kt

@@ -37,6 +37,12 @@ object AnalyticsTransactions {
         operation = "ux",
         description = "Send to sent state in timeline",
     )
+
+    val pushToNotification = TransactionDefinition(
+        name = "Push to notification",
+        operation = "push_to_notification",
+        description = "Time from receiving a push notification until it's displayed",
+    )
 }
 
 data class TransactionDefinition(