From a6d6c89f4567268a2c39b35f2674e8a5206053f0 Mon Sep 17 00:00:00 2001 From: Amit Kumar Date: Wed, 2 Nov 2022 23:07:00 +0530 Subject: [PATCH 1/6] Add spannable tracking around SyncResponseHandler --- .../sdk/api/extensions/MetricsExtensions.kt | 28 +++ .../sdk/api/metrics/SpannableMetricPlugin.kt | 36 ++++ .../api/metrics/SyncDurationMetricPlugin.kt | 32 ++++ .../session/sync/SyncResponseHandler.kt | 177 +++++++++++------- .../analytics/metrics/VectorPlugins.kt | 4 +- .../sentry/SentrySyncDurationMetrics.kt | 85 +++++++++ 6 files changed, 292 insertions(+), 70 deletions(-) create mode 100644 matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/metrics/SpannableMetricPlugin.kt create mode 100644 matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/metrics/SyncDurationMetricPlugin.kt create mode 100644 vector/src/main/java/im/vector/app/features/analytics/metrics/sentry/SentrySyncDurationMetrics.kt 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 9487a270863..8bd3e083fc3 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 @@ -17,12 +17,16 @@ package org.matrix.android.sdk.api.extensions import org.matrix.android.sdk.api.metrics.MetricPlugin +import org.matrix.android.sdk.api.metrics.SpannableMetricPlugin import kotlin.contracts.ExperimentalContracts import kotlin.contracts.InvocationKind import kotlin.contracts.contract /** * Executes the given [block] while measuring the transaction. + * + * @param metricMeasurementPlugins Relevant plugins used for tracking. + * @param block Action/Task to be executed within this span. */ @OptIn(ExperimentalContracts::class) inline fun measureMetric(metricMeasurementPlugins: List, block: () -> Unit) { @@ -39,3 +43,27 @@ inline fun measureMetric(metricMeasurementPlugins: List, block: () metricMeasurementPlugins.forEach { plugin -> plugin.finishTransaction() } // Finally, finish this transaction. } } + +/** + * Executes the given [block] while measuring a span. + * + * @param metricMeasurementPlugins Relevant plugins used for tracking. + * @param operation Name of the new span. + * @param description Description of the new span. + * @param block Action/Task to be executed within this span. + */ +@OptIn(ExperimentalContracts::class) +inline fun measureSpan(metricMeasurementPlugins: List, operation: String, description: String, block: () -> Unit) { + contract { + callsInPlace(block, InvocationKind.EXACTLY_ONCE) + } + try { + metricMeasurementPlugins.forEach { plugin -> plugin.startSpan(operation, description) } // Start the transaction. + block() + } catch (throwable: Throwable) { + metricMeasurementPlugins.forEach { plugin -> plugin.onError(throwable) } // Capture if there is any exception thrown. + throw throwable + } finally { + metricMeasurementPlugins.forEach { plugin -> plugin.finishSpan() } // Finally, finish this transaction. + } +} diff --git a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/metrics/SpannableMetricPlugin.kt b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/metrics/SpannableMetricPlugin.kt new file mode 100644 index 00000000000..eecf7668eb3 --- /dev/null +++ b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/metrics/SpannableMetricPlugin.kt @@ -0,0 +1,36 @@ +/* + * Copyright (c) 2022 New Vector Ltd + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package org.matrix.android.sdk.api.metrics + +/** + * A plugin that tracks span along with transactions. + */ +interface SpannableMetricPlugin : MetricPlugin { + + /** + * Starts the span for a sub-task. + * + * @param operation Name of the new span. + * @param description Description of the new span. + */ + fun startSpan(operation: String, description: String) + + /** + * Finish the span when sub-task is completed. + */ + fun finishSpan() +} 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 new file mode 100644 index 00000000000..79ece002e98 --- /dev/null +++ b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/metrics/SyncDurationMetricPlugin.kt @@ -0,0 +1,32 @@ +/* + * Copyright 2022 The Matrix.org Foundation C.I.C. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package org.matrix.android.sdk.api.metrics + +import org.matrix.android.sdk.api.logger.LoggerTag +import timber.log.Timber + +private val loggerTag = LoggerTag("SyncDurationMetricPlugin", LoggerTag.CRYPTO) + +/** + * An spannable metric plugin for sync response handling task. + */ +interface SyncDurationMetricPlugin : SpannableMetricPlugin { + + override fun logTransaction(message: String?) { + Timber.tag(loggerTag.value).v("## syncResponseHandler() : $message") + } +} 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 05216d1de13..ad29ab41433 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 @@ -17,6 +17,10 @@ package org.matrix.android.sdk.internal.session.sync import com.zhuinden.monarchy.Monarchy +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.metrics.SyncDurationMetricPlugin import org.matrix.android.sdk.api.session.pushrules.PushRuleService import org.matrix.android.sdk.api.session.pushrules.RuleScope import org.matrix.android.sdk.api.session.sync.InitialSyncStep @@ -52,9 +56,12 @@ internal class SyncResponseHandler @Inject constructor( private val tokenStore: SyncTokenStore, private val processEventForPushTask: ProcessEventForPushTask, private val pushRuleService: PushRuleService, - private val presenceSyncHandler: PresenceSyncHandler + private val presenceSyncHandler: PresenceSyncHandler, + matrixConfiguration: MatrixConfiguration, ) { + private val metricPlugins = matrixConfiguration.metricPlugins + suspend fun handleResponse( syncResponse: SyncResponse, fromToken: String?, @@ -63,96 +70,128 @@ internal class SyncResponseHandler @Inject constructor( val isInitialSync = fromToken == null Timber.v("Start handling sync, is InitialSync: $isInitialSync") - measureTimeMillis { - if (!cryptoService.isStarted()) { - Timber.v("Should start cryptoService") - cryptoService.start() + val relevantPlugins = metricPlugins.filterIsInstance() + measureMetric(relevantPlugins) { + // "start_crypto_service" span + measureSpan(relevantPlugins, "task", "start_crypto_service") { + measureTimeMillis { + if (!cryptoService.isStarted()) { + Timber.v("Should start cryptoService") + cryptoService.start() + } + cryptoService.onSyncWillProcess(isInitialSync) + }.also { + Timber.v("Finish handling start cryptoService in $it ms") + } } - cryptoService.onSyncWillProcess(isInitialSync) - }.also { - Timber.v("Finish handling start cryptoService in $it ms") - } - // Handle the to device events before the room ones - // to ensure to decrypt them properly - measureTimeMillis { - Timber.v("Handle toDevice") - reportSubtask(reporter, InitialSyncStep.ImportingAccountCrypto, 100, 0.1f) { - if (syncResponse.toDevice != null) { - cryptoSyncHandler.handleToDevice(syncResponse.toDevice, reporter) + // Handle the to device events before the room ones + // to ensure to decrypt them properly + + // "handle_to_device" span + measureSpan(relevantPlugins, "task", "handle_to_device") { + measureTimeMillis { + Timber.v("Handle toDevice") + reportSubtask(reporter, InitialSyncStep.ImportingAccountCrypto, 100, 0.1f) { + if (syncResponse.toDevice != null) { + cryptoSyncHandler.handleToDevice(syncResponse.toDevice, reporter) + } + } + }.also { + Timber.v("Finish handling toDevice in $it ms") } } - }.also { - Timber.v("Finish handling toDevice in $it ms") - } - val aggregator = SyncResponsePostTreatmentAggregator() - // Prerequisite for thread events handling in RoomSyncHandler + val aggregator = SyncResponsePostTreatmentAggregator() + + // Prerequisite for thread events handling in RoomSyncHandler // Disabled due to the new fallback // if (!lightweightSettingsStorage.areThreadMessagesEnabled()) { // threadsAwarenessHandler.fetchRootThreadEventsIfNeeded(syncResponse) // } - // Start one big transaction - monarchy.awaitTransaction { realm -> - // IMPORTANT nothing should be suspend here as we are accessing the realm instance (thread local) - measureTimeMillis { - Timber.v("Handle rooms") - reportSubtask(reporter, InitialSyncStep.ImportingAccountRoom, 1, 0.8f) { - if (syncResponse.rooms != null) { - roomSyncHandler.handle(realm, syncResponse.rooms, isInitialSync, aggregator, reporter) + // Start one big transaction + // Big "monarchy_transaction" span + measureSpan(relevantPlugins, "task", "monarchy_transaction") { + monarchy.awaitTransaction { realm -> + // IMPORTANT nothing should be suspend here as we are accessing the realm instance (thread local) + // Child "handle_rooms" span + measureSpan(relevantPlugins, "task", "handle_rooms") { + measureTimeMillis { + Timber.v("Handle rooms") + reportSubtask(reporter, InitialSyncStep.ImportingAccountRoom, 1, 0.8f) { + if (syncResponse.rooms != null) { + roomSyncHandler.handle(realm, syncResponse.rooms, isInitialSync, aggregator, reporter) + } + } + }.also { + Timber.v("Finish handling rooms in $it ms") + } + } + + // Child "handle_account_data" span + measureSpan(relevantPlugins, "task", "handle_account_data") { + measureTimeMillis { + reportSubtask(reporter, InitialSyncStep.ImportingAccountData, 1, 0.1f) { + Timber.v("Handle accountData") + userAccountDataSyncHandler.handle(realm, syncResponse.accountData) + } + }.also { + Timber.v("Finish handling accountData in $it ms") + } + } + + // Child "handle_presence" span + measureSpan(relevantPlugins, "task", "handle_presence") { + measureTimeMillis { + Timber.v("Handle Presence") + presenceSyncHandler.handle(realm, syncResponse.presence) + }.also { + Timber.v("Finish handling Presence in $it ms") + } } + tokenStore.saveToken(realm, syncResponse.nextBatch) } - }.also { - Timber.v("Finish handling rooms in $it ms") } - measureTimeMillis { - reportSubtask(reporter, InitialSyncStep.ImportingAccountData, 1, 0.1f) { - Timber.v("Handle accountData") - userAccountDataSyncHandler.handle(realm, syncResponse.accountData) + // "aggregator_management" span + measureSpan(relevantPlugins, "task", "aggregator_management") { + // Everything else we need to do outside the transaction + measureTimeMillis { + aggregatorHandler.handle(aggregator) + }.also { + Timber.v("Aggregator management took $it ms") } - }.also { - Timber.v("Finish handling accountData in $it ms") } - measureTimeMillis { - Timber.v("Handle Presence") - presenceSyncHandler.handle(realm, syncResponse.presence) - }.also { - Timber.v("Finish handling Presence in $it ms") + // "sync_response_post_treatment" span + measureSpan(relevantPlugins, "task", "sync_response_post_treatment") { + measureTimeMillis { + syncResponse.rooms?.let { + checkPushRules(it, isInitialSync) + userAccountDataSyncHandler.synchronizeWithServerIfNeeded(it.invite) + dispatchInvitedRoom(it) + } + }.also { + Timber.v("SyncResponse.rooms post treatment took $it ms") + } } - tokenStore.saveToken(realm, syncResponse.nextBatch) - } - - // Everything else we need to do outside the transaction - measureTimeMillis { - aggregatorHandler.handle(aggregator) - }.also { - Timber.v("Aggregator management took $it ms") - } - measureTimeMillis { - syncResponse.rooms?.let { - checkPushRules(it, isInitialSync) - userAccountDataSyncHandler.synchronizeWithServerIfNeeded(it.invite) - dispatchInvitedRoom(it) + // "crypto_sync_handler_onSyncCompleted" span + measureSpan(relevantPlugins, "task", "crypto_sync_handler_onSyncCompleted") { + measureTimeMillis { + cryptoSyncHandler.onSyncCompleted(syncResponse) + }.also { + Timber.v("cryptoSyncHandler.onSyncCompleted took $it ms") + } } - }.also { - Timber.v("SyncResponse.rooms post treatment took $it ms") - } - measureTimeMillis { - cryptoSyncHandler.onSyncCompleted(syncResponse) - }.also { - Timber.v("cryptoSyncHandler.onSyncCompleted took $it ms") - } - - // post sync stuffs - monarchy.writeAsync { - roomSyncHandler.postSyncSpaceHierarchyHandle(it) + // post sync stuffs + monarchy.writeAsync { + roomSyncHandler.postSyncSpaceHierarchyHandle(it) + } + Timber.v("On sync completed") } - Timber.v("On sync completed") } private fun dispatchInvitedRoom(roomsSyncResponse: RoomsSyncResponse) { diff --git a/vector/src/main/java/im/vector/app/features/analytics/metrics/VectorPlugins.kt b/vector/src/main/java/im/vector/app/features/analytics/metrics/VectorPlugins.kt index 64f143a2fd3..4278c1011bc 100644 --- a/vector/src/main/java/im/vector/app/features/analytics/metrics/VectorPlugins.kt +++ b/vector/src/main/java/im/vector/app/features/analytics/metrics/VectorPlugins.kt @@ -17,6 +17,7 @@ package im.vector.app.features.analytics.metrics import im.vector.app.features.analytics.metrics.sentry.SentryDownloadDeviceKeysMetrics +import im.vector.app.features.analytics.metrics.sentry.SentrySyncDurationMetrics import org.matrix.android.sdk.api.metrics.MetricPlugin import javax.inject.Inject import javax.inject.Singleton @@ -27,9 +28,10 @@ import javax.inject.Singleton @Singleton data class VectorPlugins @Inject constructor( val sentryDownloadDeviceKeysMetrics: SentryDownloadDeviceKeysMetrics, + val sentrySyncDurationMetrics: SentrySyncDurationMetrics, ) { /** * Returns [List] of all [MetricPlugin] hold by this class. */ - fun plugins(): List = listOf(sentryDownloadDeviceKeysMetrics) + fun plugins(): List = listOf(sentryDownloadDeviceKeysMetrics, sentrySyncDurationMetrics) } 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 new file mode 100644 index 00000000000..7742ac21a29 --- /dev/null +++ b/vector/src/main/java/im/vector/app/features/analytics/metrics/sentry/SentrySyncDurationMetrics.kt @@ -0,0 +1,85 @@ +/* + * Copyright (c) 2022 New Vector Ltd + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package im.vector.app.features.analytics.metrics.sentry + +import io.sentry.ISpan +import io.sentry.ITransaction +import io.sentry.Sentry +import io.sentry.SpanStatus +import org.matrix.android.sdk.api.metrics.SyncDurationMetricPlugin +import java.util.EmptyStackException +import java.util.Stack +import javax.inject.Inject + +/** + * Sentry based implementation of SyncDurationMetricPlugin. + */ +class SentrySyncDurationMetrics @Inject constructor() : SyncDurationMetricPlugin { + private var transaction: ITransaction? = null + + // Stacks to keep spans in LIFO order. + private var spans: Stack = Stack() + + /** + * Starts the span for a sub-task. + * + * @param operation Name of the new span. + * @param description Description of the new span. + * + * @throws IllegalStateException if this is called without starting a transaction ie. `measureSpan` must be called within `measureMetric`. + */ + override fun startSpan(operation: String, description: String) { + val span = Sentry.getSpan() ?: throw IllegalStateException("measureSpan block must be called within measureMetric") + val innerSpan = span.startChild(operation, description) + spans.push(innerSpan) + logTransaction("Sentry span started: operation=[$operation], description=[$description]") + } + + override fun finishSpan() { + try { + spans.pop() + } catch (e: EmptyStackException) { + null + }?.finish() + logTransaction("Sentry span finished") + } + + override fun startTransaction() { + transaction = Sentry.startTransaction("sync_response_handler", "task", true) + logTransaction("Sentry transaction started") + } + + override fun finishTransaction() { + transaction?.finish() + logTransaction("Sentry transaction finished") + } + + override fun onError(throwable: Throwable) { + try { + spans.peek() + } catch (e: EmptyStackException) { + null + }?.apply { + this.throwable = throwable + this.status = SpanStatus.INTERNAL_ERROR + } ?: transaction?.apply { + this.throwable = throwable + this.status = SpanStatus.INTERNAL_ERROR + } + logTransaction("Sentry transaction encountered error ${throwable.message}") + } +} From e3128819c61115a1e94ce905505bffd670b7618f Mon Sep 17 00:00:00 2001 From: Amit Kumar Date: Thu, 3 Nov 2022 13:30:19 +0530 Subject: [PATCH 2/6] Update LICENSE header --- .../org/matrix/android/sdk/api/metrics/SpannableMetricPlugin.kt | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/metrics/SpannableMetricPlugin.kt b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/metrics/SpannableMetricPlugin.kt index eecf7668eb3..54aa21877ec 100644 --- a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/metrics/SpannableMetricPlugin.kt +++ b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/metrics/SpannableMetricPlugin.kt @@ -1,5 +1,5 @@ /* - * Copyright (c) 2022 New Vector Ltd + * Copyright (c) 2022 The Matrix.org Foundation C.I.C. * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. From f3ccec8bf42da3d2ca39b0a162aef46019cc746f Mon Sep 17 00:00:00 2001 From: Amit Kumar Date: Wed, 9 Nov 2022 13:42:38 +0530 Subject: [PATCH 3/6] Refactor handleResponse and MetricsExtensions --- .../sdk/api/extensions/MetricsExtensions.kt | 16 +- .../session/sync/SyncResponseHandler.kt | 237 ++++++++++-------- 2 files changed, 146 insertions(+), 107 deletions(-) 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 8bd3e083fc3..2d266294b32 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 @@ -29,18 +29,18 @@ import kotlin.contracts.contract * @param block Action/Task to be executed within this span. */ @OptIn(ExperimentalContracts::class) -inline fun measureMetric(metricMeasurementPlugins: List, block: () -> Unit) { +inline fun List.measureMetric(block: () -> Unit) { contract { callsInPlace(block, InvocationKind.EXACTLY_ONCE) } try { - metricMeasurementPlugins.forEach { plugin -> plugin.startTransaction() } // Start the transaction. + this.forEach { plugin -> plugin.startTransaction() } // Start the transaction. block() } catch (throwable: Throwable) { - metricMeasurementPlugins.forEach { plugin -> plugin.onError(throwable) } // Capture if there is any exception thrown. + this.forEach { plugin -> plugin.onError(throwable) } // Capture if there is any exception thrown. throw throwable } finally { - metricMeasurementPlugins.forEach { plugin -> plugin.finishTransaction() } // Finally, finish this transaction. + this.forEach { plugin -> plugin.finishTransaction() } // Finally, finish this transaction. } } @@ -53,17 +53,17 @@ inline fun measureMetric(metricMeasurementPlugins: List, block: () * @param block Action/Task to be executed within this span. */ @OptIn(ExperimentalContracts::class) -inline fun measureSpan(metricMeasurementPlugins: List, operation: String, description: String, block: () -> Unit) { +inline fun List.measureSpan(operation: String, description: String, block: () -> Unit) { contract { callsInPlace(block, InvocationKind.EXACTLY_ONCE) } try { - metricMeasurementPlugins.forEach { plugin -> plugin.startSpan(operation, description) } // Start the transaction. + this.forEach { plugin -> plugin.startSpan(operation, description) } // Start the transaction. block() } catch (throwable: Throwable) { - metricMeasurementPlugins.forEach { plugin -> plugin.onError(throwable) } // Capture if there is any exception thrown. + this.forEach { plugin -> plugin.onError(throwable) } // Capture if there is any exception thrown. throw throwable } finally { - metricMeasurementPlugins.forEach { plugin -> plugin.finishSpan() } // Finally, finish this transaction. + this.forEach { plugin -> plugin.finishSpan() } // Finally, finish this transaction. } } 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 ad29ab41433..6083483b29d 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 @@ -17,6 +17,7 @@ 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 @@ -60,7 +61,7 @@ internal class SyncResponseHandler @Inject constructor( matrixConfiguration: MatrixConfiguration, ) { - private val metricPlugins = matrixConfiguration.metricPlugins + private val relevantPlugins = matrixConfiguration.metricPlugins.filterIsInstance() suspend fun handleResponse( syncResponse: SyncResponse, @@ -70,127 +71,165 @@ internal class SyncResponseHandler @Inject constructor( val isInitialSync = fromToken == null Timber.v("Start handling sync, is InitialSync: $isInitialSync") - val relevantPlugins = metricPlugins.filterIsInstance() - measureMetric(relevantPlugins) { - // "start_crypto_service" span - measureSpan(relevantPlugins, "task", "start_crypto_service") { - measureTimeMillis { - if (!cryptoService.isStarted()) { - Timber.v("Should start cryptoService") - cryptoService.start() - } - cryptoService.onSyncWillProcess(isInitialSync) - }.also { - Timber.v("Finish handling start cryptoService in $it ms") - } - } + relevantPlugins.measureMetric { + startCryptoService(isInitialSync) // Handle the to device events before the room ones // to ensure to decrypt them properly - - // "handle_to_device" span - measureSpan(relevantPlugins, "task", "handle_to_device") { - measureTimeMillis { - Timber.v("Handle toDevice") - reportSubtask(reporter, InitialSyncStep.ImportingAccountCrypto, 100, 0.1f) { - if (syncResponse.toDevice != null) { - cryptoSyncHandler.handleToDevice(syncResponse.toDevice, reporter) - } - } - }.also { - Timber.v("Finish handling toDevice in $it ms") - } - } + handleToDevice(syncResponse, reporter) val aggregator = SyncResponsePostTreatmentAggregator() // Prerequisite for thread events handling in RoomSyncHandler -// Disabled due to the new fallback -// if (!lightweightSettingsStorage.areThreadMessagesEnabled()) { -// threadsAwarenessHandler.fetchRootThreadEventsIfNeeded(syncResponse) -// } - - // Start one big transaction - // Big "monarchy_transaction" span - measureSpan(relevantPlugins, "task", "monarchy_transaction") { - monarchy.awaitTransaction { realm -> - // IMPORTANT nothing should be suspend here as we are accessing the realm instance (thread local) - // Child "handle_rooms" span - measureSpan(relevantPlugins, "task", "handle_rooms") { - measureTimeMillis { - Timber.v("Handle rooms") - reportSubtask(reporter, InitialSyncStep.ImportingAccountRoom, 1, 0.8f) { - if (syncResponse.rooms != null) { - roomSyncHandler.handle(realm, syncResponse.rooms, isInitialSync, aggregator, reporter) - } - } - }.also { - Timber.v("Finish handling rooms in $it ms") - } - } + // Disabled due to the new fallback + // if (!lightweightSettingsStorage.areThreadMessagesEnabled()) { + // threadsAwarenessHandler.fetchRootThreadEventsIfNeeded(syncResponse) + // } - // Child "handle_account_data" span - measureSpan(relevantPlugins, "task", "handle_account_data") { - measureTimeMillis { - reportSubtask(reporter, InitialSyncStep.ImportingAccountData, 1, 0.1f) { - Timber.v("Handle accountData") - userAccountDataSyncHandler.handle(realm, syncResponse.accountData) - } - }.also { - Timber.v("Finish handling accountData in $it ms") - } - } + startMonarchyTransaction(syncResponse, isInitialSync, reporter, aggregator) - // Child "handle_presence" span - measureSpan(relevantPlugins, "task", "handle_presence") { - measureTimeMillis { - Timber.v("Handle Presence") - presenceSyncHandler.handle(realm, syncResponse.presence) - }.also { - Timber.v("Finish handling Presence in $it ms") - } - } - tokenStore.saveToken(realm, syncResponse.nextBatch) + aggregateSyncResponse(aggregator) + + postTreatmentSyncResponse(syncResponse, isInitialSync) + + markCryptoSyncCompleted(syncResponse) + + handlePostSync() + + Timber.v("On sync completed") + } + } + + private fun startCryptoService(isInitialSync: Boolean) { + // "start_crypto_service" span + relevantPlugins.measureSpan("task", "start_crypto_service") { + measureTimeMillis { + if (!cryptoService.isStarted()) { + Timber.v("Should start cryptoService") + cryptoService.start() } + cryptoService.onSyncWillProcess(isInitialSync) + }.also { + Timber.v("Finish handling start cryptoService in $it ms") } + } + } - // "aggregator_management" span - measureSpan(relevantPlugins, "task", "aggregator_management") { - // Everything else we need to do outside the transaction - measureTimeMillis { - aggregatorHandler.handle(aggregator) - }.also { - Timber.v("Aggregator management took $it ms") + private suspend fun handleToDevice(syncResponse: SyncResponse, reporter: ProgressReporter?) { + // "handle_to_device" span + relevantPlugins.measureSpan("task", "handle_to_device") { + measureTimeMillis { + Timber.v("Handle toDevice") + reportSubtask(reporter, InitialSyncStep.ImportingAccountCrypto, 100, 0.1f) { + if (syncResponse.toDevice != null) { + cryptoSyncHandler.handleToDevice(syncResponse.toDevice, reporter) + } } + }.also { + Timber.v("Finish handling toDevice in $it ms") } + } + } + + private suspend fun startMonarchyTransaction(syncResponse: SyncResponse, isInitialSync: Boolean, reporter: ProgressReporter?, aggregator: SyncResponsePostTreatmentAggregator) { + // Start one big transaction + // Big "monarchy_transaction" span + relevantPlugins.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) + handleAccountData(reporter, realm, syncResponse) + handlePresence(realm, syncResponse) - // "sync_response_post_treatment" span - measureSpan(relevantPlugins, "task", "sync_response_post_treatment") { - measureTimeMillis { - syncResponse.rooms?.let { - checkPushRules(it, isInitialSync) - userAccountDataSyncHandler.synchronizeWithServerIfNeeded(it.invite) - dispatchInvitedRoom(it) + tokenStore.saveToken(realm, syncResponse.nextBatch) + } + } + } + + private fun handleRooms(reporter: ProgressReporter?, syncResponse: SyncResponse, realm: Realm, isInitialSync: Boolean, aggregator: SyncResponsePostTreatmentAggregator) { + // Child "handle_rooms" span + relevantPlugins.measureSpan("task", "handle_rooms") { + measureTimeMillis { + Timber.v("Handle rooms") + reportSubtask(reporter, InitialSyncStep.ImportingAccountRoom, 1, 0.8f) { + if (syncResponse.rooms != null) { + roomSyncHandler.handle(realm, syncResponse.rooms, isInitialSync, aggregator, reporter) } - }.also { - Timber.v("SyncResponse.rooms post treatment took $it ms") } + }.also { + Timber.v("Finish handling rooms in $it ms") } + } + } - // "crypto_sync_handler_onSyncCompleted" span - measureSpan(relevantPlugins, "task", "crypto_sync_handler_onSyncCompleted") { - measureTimeMillis { - cryptoSyncHandler.onSyncCompleted(syncResponse) - }.also { - Timber.v("cryptoSyncHandler.onSyncCompleted took $it ms") + private fun handleAccountData(reporter: ProgressReporter?, realm: Realm, syncResponse: SyncResponse) { + // Child "handle_account_data" span + relevantPlugins.measureSpan("task", "handle_account_data") { + measureTimeMillis { + reportSubtask(reporter, InitialSyncStep.ImportingAccountData, 1, 0.1f) { + Timber.v("Handle accountData") + userAccountDataSyncHandler.handle(realm, syncResponse.accountData) } + }.also { + Timber.v("Finish handling accountData in $it ms") + } + } + } + + private fun handlePresence(realm: Realm, syncResponse: SyncResponse) { + // Child "handle_presence" span + relevantPlugins.measureSpan("task", "handle_presence") { + measureTimeMillis { + Timber.v("Handle Presence") + presenceSyncHandler.handle(realm, syncResponse.presence) + }.also { + Timber.v("Finish handling Presence in $it ms") } + } + } - // post sync stuffs - monarchy.writeAsync { - roomSyncHandler.postSyncSpaceHierarchyHandle(it) + private suspend fun aggregateSyncResponse(aggregator: SyncResponsePostTreatmentAggregator) { + // "aggregator_management" span + relevantPlugins.measureSpan("task", "aggregator_management") { + // Everything else we need to do outside the transaction + measureTimeMillis { + aggregatorHandler.handle(aggregator) + }.also { + Timber.v("Aggregator management took $it ms") } - Timber.v("On sync completed") + } + } + + private suspend fun postTreatmentSyncResponse(syncResponse: SyncResponse, isInitialSync: Boolean) { + // "sync_response_post_treatment" span + relevantPlugins.measureSpan("task", "sync_response_post_treatment") { + measureTimeMillis { + syncResponse.rooms?.let { + checkPushRules(it, isInitialSync) + userAccountDataSyncHandler.synchronizeWithServerIfNeeded(it.invite) + dispatchInvitedRoom(it) + } + }.also { + Timber.v("SyncResponse.rooms post treatment took $it ms") + } + } + } + + private fun markCryptoSyncCompleted(syncResponse: SyncResponse) { + // "crypto_sync_handler_onSyncCompleted" span + relevantPlugins.measureSpan("task", "crypto_sync_handler_onSyncCompleted") { + measureTimeMillis { + cryptoSyncHandler.onSyncCompleted(syncResponse) + }.also { + Timber.v("cryptoSyncHandler.onSyncCompleted took $it ms") + } + } + } + + private fun handlePostSync() { + // post sync stuffs + monarchy.writeAsync { + roomSyncHandler.postSyncSpaceHierarchyHandle(it) } } From e2c1a96a6ac8370d00ec4b7e25a8211ded990696 Mon Sep 17 00:00:00 2001 From: Amit Kumar Date: Wed, 9 Nov 2022 13:51:00 +0530 Subject: [PATCH 4/6] Update changelog.d --- changelog.d/7514.sdk | 1 + 1 file changed, 1 insertion(+) create mode 100644 changelog.d/7514.sdk diff --git a/changelog.d/7514.sdk b/changelog.d/7514.sdk new file mode 100644 index 00000000000..f335156a49f --- /dev/null +++ b/changelog.d/7514.sdk @@ -0,0 +1 @@ +[Metrics] Add `SpannableMetricPlugin` to support spans within transactions. From 5ced6c3bf03c3a12d6c0aa2f7a4f35a43443e864 Mon Sep 17 00:00:00 2001 From: Amit Kumar Date: Wed, 9 Nov 2022 15:03:32 +0530 Subject: [PATCH 5/6] Improve code docs and comments --- .../sdk/api/extensions/MetricsExtensions.kt | 2 -- .../sdk/internal/crypto/DeviceListManager.kt | 2 +- .../session/sync/SyncResponseHandler.kt | 25 ++++++++++--------- 3 files changed, 14 insertions(+), 15 deletions(-) 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 2d266294b32..7f0e828f628 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 @@ -25,7 +25,6 @@ import kotlin.contracts.contract /** * Executes the given [block] while measuring the transaction. * - * @param metricMeasurementPlugins Relevant plugins used for tracking. * @param block Action/Task to be executed within this span. */ @OptIn(ExperimentalContracts::class) @@ -47,7 +46,6 @@ inline fun List.measureMetric(block: () -> Unit) { /** * Executes the given [block] while measuring a span. * - * @param metricMeasurementPlugins Relevant plugins used for tracking. * @param operation Name of the new span. * @param description Description of the new span. * @param block Action/Task to be executed within this span. diff --git a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/DeviceListManager.kt b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/DeviceListManager.kt index 2ac6b8c8541..7e9e156003c 100755 --- a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/DeviceListManager.kt +++ b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/DeviceListManager.kt @@ -355,7 +355,7 @@ internal class DeviceListManager @Inject constructor( val relevantPlugins = metricPlugins.filterIsInstance() val response: KeysQueryResponse - measureMetric(relevantPlugins) { + relevantPlugins.measureMetric { response = try { downloadKeysForUsersTask.execute(params) } catch (throwable: Throwable) { 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 6083483b29d..05d50d95952 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 @@ -101,7 +101,6 @@ internal class SyncResponseHandler @Inject constructor( } private fun startCryptoService(isInitialSync: Boolean) { - // "start_crypto_service" span relevantPlugins.measureSpan("task", "start_crypto_service") { measureTimeMillis { if (!cryptoService.isStarted()) { @@ -116,7 +115,6 @@ internal class SyncResponseHandler @Inject constructor( } private suspend fun handleToDevice(syncResponse: SyncResponse, reporter: ProgressReporter?) { - // "handle_to_device" span relevantPlugins.measureSpan("task", "handle_to_device") { measureTimeMillis { Timber.v("Handle toDevice") @@ -131,9 +129,13 @@ internal class SyncResponseHandler @Inject constructor( } } - private suspend fun startMonarchyTransaction(syncResponse: SyncResponse, isInitialSync: Boolean, reporter: ProgressReporter?, aggregator: SyncResponsePostTreatmentAggregator) { + private suspend fun startMonarchyTransaction( + syncResponse: SyncResponse, + isInitialSync: Boolean, + reporter: ProgressReporter?, + aggregator: SyncResponsePostTreatmentAggregator + ) { // Start one big transaction - // Big "monarchy_transaction" span relevantPlugins.measureSpan("task", "monarchy_transaction") { monarchy.awaitTransaction { realm -> // IMPORTANT nothing should be suspend here as we are accessing the realm instance (thread local) @@ -146,8 +148,13 @@ internal class SyncResponseHandler @Inject constructor( } } - private fun handleRooms(reporter: ProgressReporter?, syncResponse: SyncResponse, realm: Realm, isInitialSync: Boolean, aggregator: SyncResponsePostTreatmentAggregator) { - // Child "handle_rooms" span + private fun handleRooms( + reporter: ProgressReporter?, + syncResponse: SyncResponse, + realm: Realm, + isInitialSync: Boolean, + aggregator: SyncResponsePostTreatmentAggregator + ) { relevantPlugins.measureSpan("task", "handle_rooms") { measureTimeMillis { Timber.v("Handle rooms") @@ -163,7 +170,6 @@ internal class SyncResponseHandler @Inject constructor( } private fun handleAccountData(reporter: ProgressReporter?, realm: Realm, syncResponse: SyncResponse) { - // Child "handle_account_data" span relevantPlugins.measureSpan("task", "handle_account_data") { measureTimeMillis { reportSubtask(reporter, InitialSyncStep.ImportingAccountData, 1, 0.1f) { @@ -177,7 +183,6 @@ internal class SyncResponseHandler @Inject constructor( } private fun handlePresence(realm: Realm, syncResponse: SyncResponse) { - // Child "handle_presence" span relevantPlugins.measureSpan("task", "handle_presence") { measureTimeMillis { Timber.v("Handle Presence") @@ -189,7 +194,6 @@ internal class SyncResponseHandler @Inject constructor( } private suspend fun aggregateSyncResponse(aggregator: SyncResponsePostTreatmentAggregator) { - // "aggregator_management" span relevantPlugins.measureSpan("task", "aggregator_management") { // Everything else we need to do outside the transaction measureTimeMillis { @@ -201,7 +205,6 @@ internal class SyncResponseHandler @Inject constructor( } private suspend fun postTreatmentSyncResponse(syncResponse: SyncResponse, isInitialSync: Boolean) { - // "sync_response_post_treatment" span relevantPlugins.measureSpan("task", "sync_response_post_treatment") { measureTimeMillis { syncResponse.rooms?.let { @@ -216,7 +219,6 @@ internal class SyncResponseHandler @Inject constructor( } private fun markCryptoSyncCompleted(syncResponse: SyncResponse) { - // "crypto_sync_handler_onSyncCompleted" span relevantPlugins.measureSpan("task", "crypto_sync_handler_onSyncCompleted") { measureTimeMillis { cryptoSyncHandler.onSyncCompleted(syncResponse) @@ -227,7 +229,6 @@ internal class SyncResponseHandler @Inject constructor( } private fun handlePostSync() { - // post sync stuffs monarchy.writeAsync { roomSyncHandler.postSyncSpaceHierarchyHandle(it) } From ecd51e7e6e5643647c8061ba207d11362de35cb6 Mon Sep 17 00:00:00 2001 From: Amit Kumar Date: Wed, 9 Nov 2022 18:07:24 +0530 Subject: [PATCH 6/6] Check if Sentry is enabled before tracking --- .../sentry/SentryDownloadDeviceKeysMetrics.kt | 6 ++++-- .../metrics/sentry/SentrySyncDurationMetrics.kt | 16 ++++++++++------ 2 files changed, 14 insertions(+), 8 deletions(-) diff --git a/vector/src/main/java/im/vector/app/features/analytics/metrics/sentry/SentryDownloadDeviceKeysMetrics.kt b/vector/src/main/java/im/vector/app/features/analytics/metrics/sentry/SentryDownloadDeviceKeysMetrics.kt index 92213d380c1..488b72bfd99 100644 --- a/vector/src/main/java/im/vector/app/features/analytics/metrics/sentry/SentryDownloadDeviceKeysMetrics.kt +++ b/vector/src/main/java/im/vector/app/features/analytics/metrics/sentry/SentryDownloadDeviceKeysMetrics.kt @@ -26,8 +26,10 @@ class SentryDownloadDeviceKeysMetrics @Inject constructor() : DownloadDeviceKeys private var transaction: ITransaction? = null override fun startTransaction() { - transaction = Sentry.startTransaction("download_device_keys", "task") - logTransaction("Sentry transaction started") + if (Sentry.isEnabled()) { + transaction = Sentry.startTransaction("download_device_keys", "task") + logTransaction("Sentry transaction started") + } } override fun finishTransaction() { 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 7742ac21a29..d69ed01526f 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 @@ -43,10 +43,12 @@ class SentrySyncDurationMetrics @Inject constructor() : SyncDurationMetricPlugin * @throws IllegalStateException if this is called without starting a transaction ie. `measureSpan` must be called within `measureMetric`. */ override fun startSpan(operation: String, description: String) { - val span = Sentry.getSpan() ?: throw IllegalStateException("measureSpan block must be called within measureMetric") - val innerSpan = span.startChild(operation, description) - spans.push(innerSpan) - logTransaction("Sentry span started: operation=[$operation], description=[$description]") + if (Sentry.isEnabled()) { + val span = Sentry.getSpan() ?: throw IllegalStateException("measureSpan block must be called within measureMetric") + val innerSpan = span.startChild(operation, description) + spans.push(innerSpan) + logTransaction("Sentry span started: operation=[$operation], description=[$description]") + } } override fun finishSpan() { @@ -59,8 +61,10 @@ class SentrySyncDurationMetrics @Inject constructor() : SyncDurationMetricPlugin } override fun startTransaction() { - transaction = Sentry.startTransaction("sync_response_handler", "task", true) - logTransaction("Sentry transaction started") + if (Sentry.isEnabled()) { + transaction = Sentry.startTransaction("sync_response_handler", "task", true) + logTransaction("Sentry transaction started") + } } override fun finishTransaction() {