Merge pull request #7985 from vector-im/feature/bma/slowDownSentry

Slow down sentry

changelog.d/7960.misc

@@ -0,0 +1 @@
+Sentry: Report sync duration and metrics for initial sync and for sync after pause. Not for regular sync.

matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/extensions/MetricsExtensions.kt

@@ -43,6 +43,27 @@ inline fun List<MetricPlugin>.measureMetric(block: () -> Unit) {
     }
 }
 
+/**
+ * Executes the given [block] while measuring the transaction.
+ *
+ * @param block Action/Task to be executed within this span.
+ */
+@OptIn(ExperimentalContracts::class)
+inline fun List<SpannableMetricPlugin>.measureSpannableMetric(block: List<SpannableMetricPlugin>.() -> Unit) {
+    contract {
+        callsInPlace(block, InvocationKind.EXACTLY_ONCE)
+    }
+    try {
+        this.forEach { plugin -> plugin.startTransaction() } // Start the transaction.
+        block()
+    } catch (throwable: Throwable) {
+        this.forEach { plugin -> plugin.onError(throwable) } // Capture if there is any exception thrown.
+        throw throwable
+    } finally {
+        this.forEach { plugin -> plugin.finishTransaction() } // Finally, finish this transaction.
+    }
+}
+
 /**
  * Executes the given [block] while measuring a span.
  *

matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/metrics/SyncDurationMetricPlugin.kt

@@ -29,4 +29,6 @@ interface SyncDurationMetricPlugin : SpannableMetricPlugin {
     override fun logTransaction(message: String?) {
         Timber.tag(loggerTag.value).v("## syncResponseHandler() : $message")
     }
+
+    fun shouldReport(isInitialSync: Boolean, isAfterPause: Boolean): Boolean = true
 }

matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/sync/SyncResponseHandler.kt

@@ -19,8 +19,9 @@ package org.matrix.android.sdk.internal.session.sync
 import com.zhuinden.monarchy.Monarchy
 import io.realm.Realm
 import org.matrix.android.sdk.api.MatrixConfiguration
-import org.matrix.android.sdk.api.extensions.measureMetric
 import org.matrix.android.sdk.api.extensions.measureSpan
+import org.matrix.android.sdk.api.extensions.measureSpannableMetric
+import org.matrix.android.sdk.api.metrics.SpannableMetricPlugin
 import org.matrix.android.sdk.api.metrics.SyncDurationMetricPlugin
 import org.matrix.android.sdk.api.session.pushrules.PushRuleService
 import org.matrix.android.sdk.api.session.pushrules.RuleScope
@@ -67,12 +68,13 @@ internal class SyncResponseHandler @Inject constructor(
     suspend fun handleResponse(
             syncResponse: SyncResponse,
             fromToken: String?,
+            afterPause: Boolean,
             reporter: ProgressReporter?
     ) {
         val isInitialSync = fromToken == null
         Timber.v("Start handling sync, is InitialSync: $isInitialSync")
 
-        relevantPlugins.measureMetric {
+        relevantPlugins.filter { it.shouldReport(isInitialSync, afterPause) }.measureSpannableMetric {
             startCryptoService(isInitialSync)
 
             // Handle the to device events before the room ones
@@ -101,8 +103,8 @@ internal class SyncResponseHandler @Inject constructor(
         }
     }
 
-    private fun startCryptoService(isInitialSync: Boolean) {
+    private fun List<SpannableMetricPlugin>.startCryptoService(isInitialSync: Boolean) {
-        relevantPlugins.measureSpan("task", "start_crypto_service") {
+        measureSpan("task", "start_crypto_service") {
             measureTimeMillis {
                 if (!cryptoService.isStarted()) {
                     Timber.v("Should start cryptoService")
@@ -115,8 +117,8 @@ internal class SyncResponseHandler @Inject constructor(
         }
     }
 
-    private suspend fun handleToDevice(syncResponse: SyncResponse, reporter: ProgressReporter?) {
+    private suspend fun List<SpannableMetricPlugin>.handleToDevice(syncResponse: SyncResponse, reporter: ProgressReporter?) {
-        relevantPlugins.measureSpan("task", "handle_to_device") {
+        measureSpan("task", "handle_to_device") {
             measureTimeMillis {
                 Timber.v("Handle toDevice")
                 reportSubtask(reporter, InitialSyncStep.ImportingAccountCrypto, 100, 0.1f) {
@@ -130,14 +132,14 @@ internal class SyncResponseHandler @Inject constructor(
         }
     }
 
-    private suspend fun startMonarchyTransaction(
+    private suspend fun List<SpannableMetricPlugin>.startMonarchyTransaction(
             syncResponse: SyncResponse,
             isInitialSync: Boolean,
             reporter: ProgressReporter?,
             aggregator: SyncResponsePostTreatmentAggregator
     ) {
         // Start one big transaction
-        relevantPlugins.measureSpan("task", "monarchy_transaction") {
+        measureSpan("task", "monarchy_transaction") {
             monarchy.awaitTransaction { realm ->
                 // IMPORTANT nothing should be suspend here as we are accessing the realm instance (thread local)
                 handleRooms(reporter, syncResponse, realm, isInitialSync, aggregator)
@@ -149,14 +151,14 @@ internal class SyncResponseHandler @Inject constructor(
         }
     }
 
-    private fun handleRooms(
+    private fun List<SpannableMetricPlugin>.handleRooms(
             reporter: ProgressReporter?,
             syncResponse: SyncResponse,
             realm: Realm,
             isInitialSync: Boolean,
             aggregator: SyncResponsePostTreatmentAggregator
     ) {
-        relevantPlugins.measureSpan("task", "handle_rooms") {
+        measureSpan("task", "handle_rooms") {
             measureTimeMillis {
                 Timber.v("Handle rooms")
                 reportSubtask(reporter, InitialSyncStep.ImportingAccountRoom, 1, 0.8f) {
@@ -170,8 +172,8 @@ internal class SyncResponseHandler @Inject constructor(
         }
     }
 
-    private fun handleAccountData(reporter: ProgressReporter?, realm: Realm, syncResponse: SyncResponse) {
+    private fun List<SpannableMetricPlugin>.handleAccountData(reporter: ProgressReporter?, realm: Realm, syncResponse: SyncResponse) {
-        relevantPlugins.measureSpan("task", "handle_account_data") {
+        measureSpan("task", "handle_account_data") {
             measureTimeMillis {
                 reportSubtask(reporter, InitialSyncStep.ImportingAccountData, 1, 0.1f) {
                     Timber.v("Handle accountData")
@@ -183,8 +185,8 @@ internal class SyncResponseHandler @Inject constructor(
         }
     }
 
-    private fun handlePresence(realm: Realm, syncResponse: SyncResponse) {
+    private fun List<SpannableMetricPlugin>.handlePresence(realm: Realm, syncResponse: SyncResponse) {
-        relevantPlugins.measureSpan("task", "handle_presence") {
+        measureSpan("task", "handle_presence") {
             measureTimeMillis {
                 Timber.v("Handle Presence")
                 presenceSyncHandler.handle(realm, syncResponse.presence)
@@ -194,8 +196,8 @@ internal class SyncResponseHandler @Inject constructor(
         }
     }
 
-    private suspend fun aggregateSyncResponse(aggregator: SyncResponsePostTreatmentAggregator) {
+    private suspend fun List<SpannableMetricPlugin>.aggregateSyncResponse(aggregator: SyncResponsePostTreatmentAggregator) {
-        relevantPlugins.measureSpan("task", "aggregator_management") {
+        measureSpan("task", "aggregator_management") {
             // Everything else we need to do outside the transaction
             measureTimeMillis {
                 aggregatorHandler.handle(aggregator)
@@ -205,8 +207,8 @@ internal class SyncResponseHandler @Inject constructor(
         }
     }
 
-    private suspend fun postTreatmentSyncResponse(syncResponse: SyncResponse, isInitialSync: Boolean) {
+    private suspend fun List<SpannableMetricPlugin>.postTreatmentSyncResponse(syncResponse: SyncResponse, isInitialSync: Boolean) {
-        relevantPlugins.measureSpan("task", "sync_response_post_treatment") {
+        measureSpan("task", "sync_response_post_treatment") {
             measureTimeMillis {
                 syncResponse.rooms?.let {
                     checkPushRules(it, isInitialSync)
@@ -219,8 +221,8 @@ internal class SyncResponseHandler @Inject constructor(
         }
     }
 
-    private fun markCryptoSyncCompleted(syncResponse: SyncResponse, cryptoStoreAggregator: CryptoStoreAggregator) {
+    private fun List<SpannableMetricPlugin>.markCryptoSyncCompleted(syncResponse: SyncResponse, cryptoStoreAggregator: CryptoStoreAggregator) {
-        relevantPlugins.measureSpan("task", "crypto_sync_handler_onSyncCompleted") {
+        measureSpan("task", "crypto_sync_handler_onSyncCompleted") {
             measureTimeMillis {
                 cryptoSyncHandler.onSyncCompleted(syncResponse, cryptoStoreAggregator)
             }.also {

matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/sync/SyncTask.kt

@@ -151,7 +151,7 @@ internal class DefaultSyncTask @Inject constructor(
                     syncStatisticsData.requestInitSyncTime = SystemClock.elapsedRealtime()
                     syncStatisticsData.downloadInitSyncTime = syncStatisticsData.requestInitSyncTime
                     logDuration("INIT_SYNC Database insertion", loggerTag, clock) {
-                        syncResponseHandler.handleResponse(syncResponse, token, syncRequestStateTracker)
+                        syncResponseHandler.handleResponse(syncResponse, null, afterPause = true, syncRequestStateTracker)
                     }
                     syncResponseToReturn = syncResponse
                 }
@@ -184,7 +184,7 @@ internal class DefaultSyncTask @Inject constructor(
                             toDevice = nbToDevice,
                     )
             )
-            syncResponseHandler.handleResponse(syncResponse, token, null)
+            syncResponseHandler.handleResponse(syncResponse, token, afterPause = params.afterPause, null)
             syncResponseToReturn = syncResponse
             Timber.tag(loggerTag.value).d("Incremental sync done")
             syncRequestStateTracker.setSyncRequestState(SyncRequestState.IncrementalSyncDone)
@@ -264,7 +264,7 @@ internal class DefaultSyncTask @Inject constructor(
             Timber.tag(loggerTag.value).d("INIT_SYNC $nbOfJoinedRooms rooms, $nbOfJoinedRoomsInFile ephemeral stored into files")
 
             logDuration("INIT_SYNC Database insertion", loggerTag, clock) {
-                syncResponseHandler.handleResponse(syncResponse, null, syncRequestStateTracker)
+                syncResponseHandler.handleResponse(syncResponse, null, afterPause = true, syncRequestStateTracker)
             }
             initialSyncStatusRepository.setStep(InitialSyncStatus.STEP_SUCCESS)
             syncResponse

vector/src/main/java/im/vector/app/features/analytics/metrics/sentry/SentrySyncDurationMetrics.kt

@@ -34,6 +34,11 @@ class SentrySyncDurationMetrics @Inject constructor() : SyncDurationMetricPlugin
     // Stacks to keep spans in LIFO order.
     private var spans: Stack<ISpan> = Stack()
 
+    override fun shouldReport(isInitialSync: Boolean, isAfterPause: Boolean): Boolean {
+        // Report only for initial sync and for sync after pause
+        return isInitialSync || isAfterPause
+    }
+
     /**
      * Starts the span for a sub-task.
      *
@@ -69,6 +74,7 @@ class SentrySyncDurationMetrics @Inject constructor() : SyncDurationMetricPlugin
 
     override fun finishTransaction() {
         transaction?.finish()
+        transaction = null
         logTransaction("Sentry transaction finished")
     }