diff --git a/changelog.d/7960.misc b/changelog.d/7960.misc new file mode 100644 index 0000000000..be2a862f0d --- /dev/null +++ b/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. diff --git a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/extensions/MetricsExtensions.kt b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/extensions/MetricsExtensions.kt index 7f0e828f62..5aa175f994 100644 --- a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/extensions/MetricsExtensions.kt +++ b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/extensions/MetricsExtensions.kt @@ -43,6 +43,27 @@ inline fun List.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.measureSpannableMetric(block: List.() -> 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. * diff --git a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/metrics/SyncDurationMetricPlugin.kt b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/metrics/SyncDurationMetricPlugin.kt index 79ece002e9..e54eb3cccf 100644 --- a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/metrics/SyncDurationMetricPlugin.kt +++ b/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 } diff --git a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/sync/SyncResponseHandler.kt b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/sync/SyncResponseHandler.kt index cb407bb1cb..a9de4d3a3b 100644 --- a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/sync/SyncResponseHandler.kt +++ b/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) { - relevantPlugins.measureSpan("task", "start_crypto_service") { + private fun List.startCryptoService(isInitialSync: Boolean) { + 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?) { - relevantPlugins.measureSpan("task", "handle_to_device") { + private suspend fun List.handleToDevice(syncResponse: SyncResponse, reporter: ProgressReporter?) { + 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.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.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) { - relevantPlugins.measureSpan("task", "handle_account_data") { + private fun List.handleAccountData(reporter: ProgressReporter?, realm: Realm, syncResponse: SyncResponse) { + 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) { - relevantPlugins.measureSpan("task", "handle_presence") { + private fun List.handlePresence(realm: Realm, syncResponse: SyncResponse) { + 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) { - relevantPlugins.measureSpan("task", "aggregator_management") { + private suspend fun List.aggregateSyncResponse(aggregator: SyncResponsePostTreatmentAggregator) { + 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) { - relevantPlugins.measureSpan("task", "sync_response_post_treatment") { + private suspend fun List.postTreatmentSyncResponse(syncResponse: SyncResponse, isInitialSync: Boolean) { + 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) { - relevantPlugins.measureSpan("task", "crypto_sync_handler_onSyncCompleted") { + private fun List.markCryptoSyncCompleted(syncResponse: SyncResponse, cryptoStoreAggregator: CryptoStoreAggregator) { + measureSpan("task", "crypto_sync_handler_onSyncCompleted") { measureTimeMillis { cryptoSyncHandler.onSyncCompleted(syncResponse, cryptoStoreAggregator) }.also { diff --git a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/sync/SyncTask.kt b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/sync/SyncTask.kt index 8a287fb0b4..86346cabcf 100644 --- a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/sync/SyncTask.kt +++ b/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 diff --git a/vector/src/main/java/im/vector/app/features/analytics/metrics/sentry/SentrySyncDurationMetrics.kt b/vector/src/main/java/im/vector/app/features/analytics/metrics/sentry/SentrySyncDurationMetrics.kt index d69ed01526..04f4d38769 100644 --- a/vector/src/main/java/im/vector/app/features/analytics/metrics/sentry/SentrySyncDurationMetrics.kt +++ b/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 = 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") }