From cab06c4b529b6dcfe7517708894f26654fb26c71 Mon Sep 17 00:00:00 2001 From: Benoit Marty Date: Fri, 21 Jan 2022 16:32:31 +0100 Subject: [PATCH 1/4] Analytics: report performance event about sync request --- .../matrix/android/sdk/api/session/Session.kt | 3 +- .../api/session/statistics/StatisticEvent.kt | 37 +++++++++++++++++++ .../session/statistics/StatisticsListener.kt | 23 ++++++++++++ .../sdk/internal/session/sync/SyncTask.kt | 23 +++++++++++- .../internal/session/sync/job/SyncService.kt | 2 +- .../internal/session/sync/job/SyncThread.kt | 9 +++-- .../internal/session/sync/job/SyncWorker.kt | 2 +- .../extensions/PerformanceTimerExt.kt | 36 ++++++++++++++++++ .../app/features/session/SessionListener.kt | 11 +++++- 9 files changed, 137 insertions(+), 9 deletions(-) create mode 100644 matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/session/statistics/StatisticEvent.kt create mode 100644 matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/session/statistics/StatisticsListener.kt create mode 100644 vector/src/main/java/im/vector/app/features/analytics/extensions/PerformanceTimerExt.kt diff --git a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/session/Session.kt b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/session/Session.kt index 36ab007314..be924e2063 100644 --- a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/session/Session.kt +++ b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/session/Session.kt @@ -54,6 +54,7 @@ import org.matrix.android.sdk.api.session.securestorage.SecureStorageService import org.matrix.android.sdk.api.session.securestorage.SharedSecretStorageService import org.matrix.android.sdk.api.session.signout.SignOutService import org.matrix.android.sdk.api.session.space.SpaceService +import org.matrix.android.sdk.api.session.statistics.StatisticsListener import org.matrix.android.sdk.api.session.sync.FilterService import org.matrix.android.sdk.api.session.sync.SyncState import org.matrix.android.sdk.api.session.sync.model.SyncResponse @@ -287,7 +288,7 @@ interface Session : /** * A global session listener to get notified for some events. */ - interface Listener : SessionLifecycleObserver { + interface Listener : StatisticsListener, SessionLifecycleObserver { /** * Called when the session received new invites to room so the client can react to it once. */ diff --git a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/session/statistics/StatisticEvent.kt b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/session/statistics/StatisticEvent.kt new file mode 100644 index 0000000000..4d05aa0194 --- /dev/null +++ b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/session/statistics/StatisticEvent.kt @@ -0,0 +1,37 @@ +/* + * 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. + * 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.session.statistics + +/** + * Statistic Events. You can subscribe to received such events using [Session.Listener] + */ +sealed interface StatisticEvent { + /** + * Initial sync request and response downloading, not including parsing and storage of response + */ + data class InitialSyncRequest(val durationMs: Int) : StatisticEvent + + /** + * Initial sync treatment: parsing and storage of response + */ + data class InitialSyncTreatment(val durationMs: Int) : StatisticEvent + + /** + * Incremental sync event + */ + data class SyncTreatment(val durationMs: Int, val afterPause: Boolean) : StatisticEvent +} diff --git a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/session/statistics/StatisticsListener.kt b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/session/statistics/StatisticsListener.kt new file mode 100644 index 0000000000..a2cb7910a7 --- /dev/null +++ b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/session/statistics/StatisticsListener.kt @@ -0,0 +1,23 @@ +/* + * 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. + * 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.session.statistics + +import org.matrix.android.sdk.api.session.Session + +interface StatisticsListener { + fun onStatisticsEvent(session: Session, statisticEvent: StatisticEvent) = Unit +} 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 621a08a414..1f27757205 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 @@ -16,10 +16,13 @@ package org.matrix.android.sdk.internal.session.sync +import android.os.SystemClock import okhttp3.ResponseBody import org.matrix.android.sdk.api.logger.LoggerTag +import org.matrix.android.sdk.api.session.Session import org.matrix.android.sdk.api.session.initsync.InitSyncStep import org.matrix.android.sdk.api.session.initsync.SyncStatusService +import org.matrix.android.sdk.api.session.statistics.StatisticEvent import org.matrix.android.sdk.api.session.sync.model.LazyRoomSyncEphemeral import org.matrix.android.sdk.api.session.sync.model.SyncResponse import org.matrix.android.sdk.internal.di.SessionFilesDirectory @@ -28,6 +31,8 @@ import org.matrix.android.sdk.internal.network.GlobalErrorReceiver import org.matrix.android.sdk.internal.network.TimeOutInterceptor import org.matrix.android.sdk.internal.network.executeRequest import org.matrix.android.sdk.internal.network.toFailure +import org.matrix.android.sdk.internal.session.SessionListeners +import org.matrix.android.sdk.internal.session.dispatchTo import org.matrix.android.sdk.internal.session.filter.FilterRepository import org.matrix.android.sdk.internal.session.homeserver.GetHomeServerCapabilitiesTask import org.matrix.android.sdk.internal.session.initsync.DefaultSyncStatusService @@ -49,7 +54,8 @@ internal interface SyncTask : Task { data class Params( val timeout: Long, - val presence: SyncPresence? + val presence: SyncPresence?, + val afterPause: Boolean ) } @@ -62,6 +68,8 @@ internal class DefaultSyncTask @Inject constructor( private val syncTokenStore: SyncTokenStore, private val getHomeServerCapabilitiesTask: GetHomeServerCapabilitiesTask, private val userStore: UserStore, + private val session: Session, + private val sessionListeners: SessionListeners, private val syncTaskSequencer: SyncTaskSequencer, private val globalErrorReceiver: GlobalErrorReceiver, @SessionFilesDirectory @@ -105,6 +113,7 @@ internal class DefaultSyncTask @Inject constructor( val readTimeOut = (params.timeout + TIMEOUT_MARGIN).coerceAtLeast(TimeOutInterceptor.DEFAULT_LONG_TIMEOUT) var syncResponseToReturn: SyncResponse? = null + var start = SystemClock.elapsedRealtime() if (isInitialSync) { Timber.tag(loggerTag.value).d("INIT_SYNC with filter: ${requestParams["filter"]}") val initSyncStrategy = initialSyncStrategy @@ -113,6 +122,8 @@ internal class DefaultSyncTask @Inject constructor( roomSyncEphemeralTemporaryStore.reset() workingDir.mkdirs() val file = downloadInitSyncResponse(requestParams) + sendStatistics(StatisticEvent.InitialSyncRequest((SystemClock.elapsedRealtime() - start).toInt())) + start = SystemClock.elapsedRealtime() syncResponseToReturn = reportSubtask(defaultSyncStatusService, InitSyncStep.ImportingAccount, 1, 0.7F) { handleSyncFile(file, initSyncStrategy) } @@ -127,6 +138,8 @@ internal class DefaultSyncTask @Inject constructor( ) } } + sendStatistics(StatisticEvent.InitialSyncRequest((SystemClock.elapsedRealtime() - start).toInt())) + start = SystemClock.elapsedRealtime() logDuration("INIT_SYNC Database insertion", loggerTag) { syncResponseHandler.handleResponse(syncResponse, token, defaultSyncStatusService) } @@ -134,6 +147,7 @@ internal class DefaultSyncTask @Inject constructor( } } defaultSyncStatusService.endAll() + sendStatistics(StatisticEvent.InitialSyncTreatment((SystemClock.elapsedRealtime() - start).toInt())) } else { Timber.tag(loggerTag.value).d("Start incremental sync request") defaultSyncStatusService.setStatus(SyncStatusService.Status.IncrementalSyncIdle) @@ -160,6 +174,7 @@ internal class DefaultSyncTask @Inject constructor( syncResponseToReturn = syncResponse Timber.tag(loggerTag.value).d("Incremental sync done") defaultSyncStatusService.setStatus(SyncStatusService.Status.IncrementalSyncDone) + sendStatistics(StatisticEvent.SyncTreatment((SystemClock.elapsedRealtime() - start).toInt(), params.afterPause)) } Timber.tag(loggerTag.value).d("Sync task finished on Thread: ${Thread.currentThread().name}") // Should throw if null as it's a mandatory value. @@ -239,6 +254,12 @@ internal class DefaultSyncTask @Inject constructor( } } + private fun sendStatistics(statisticEvent: StatisticEvent) { + session.dispatchTo(sessionListeners) { session, listener -> + listener.onStatisticsEvent(session, statisticEvent) + } + } + companion object { private const val MAX_NUMBER_OF_RETRY_AFTER_TIMEOUT = 50 diff --git a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/sync/job/SyncService.kt b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/sync/job/SyncService.kt index c17b31b910..0ecf91f6fa 100644 --- a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/sync/job/SyncService.kt +++ b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/sync/job/SyncService.kt @@ -152,7 +152,7 @@ abstract class SyncService : Service() { private suspend fun doSync() { Timber.v("## Sync: Execute sync request with timeout $syncTimeoutSeconds seconds") - val params = SyncTask.Params(syncTimeoutSeconds * 1000L, SyncPresence.Offline) + val params = SyncTask.Params(syncTimeoutSeconds * 1000L, SyncPresence.Offline, afterPause = false) try { // never do that in foreground, let the syncThread work syncTask.execute(params) diff --git a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/sync/job/SyncThread.kt b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/sync/job/SyncThread.kt index b6ea7a68f7..2460720adc 100644 --- a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/sync/job/SyncThread.kt +++ b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/sync/job/SyncThread.kt @@ -173,13 +173,14 @@ internal class SyncThread @Inject constructor(private val syncTask: SyncTask, if (state !is SyncState.Running) { updateStateTo(SyncState.Running(afterPause = true)) } + val afterPause = state.let { it is SyncState.Running && it.afterPause } val timeout = when { - previousSyncResponseHasToDevice -> 0L /* Force timeout to 0 */ - state.let { it is SyncState.Running && it.afterPause } -> 0L /* No timeout after a pause */ - else -> DEFAULT_LONG_POOL_TIMEOUT + previousSyncResponseHasToDevice -> 0L /* Force timeout to 0 */ + afterPause -> 0L /* No timeout after a pause */ + else -> DEFAULT_LONG_POOL_TIMEOUT } Timber.tag(loggerTag.value).d("Execute sync request with timeout $timeout") - val params = SyncTask.Params(timeout, SyncPresence.Online) + val params = SyncTask.Params(timeout, SyncPresence.Online, afterPause = afterPause) val sync = syncScope.launch { previousSyncResponseHasToDevice = doSync(params) } diff --git a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/sync/job/SyncWorker.kt b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/sync/job/SyncWorker.kt index bdccb59221..423a4e553f 100644 --- a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/sync/job/SyncWorker.kt +++ b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/sync/job/SyncWorker.kt @@ -113,7 +113,7 @@ internal class SyncWorker(context: Context, workerParameters: WorkerParameters, * Will return true if the sync response contains some toDevice events. */ private suspend fun doSync(timeout: Long): Boolean { - val taskParams = SyncTask.Params(timeout * 1000, SyncPresence.Offline) + val taskParams = SyncTask.Params(timeout * 1000, SyncPresence.Offline, afterPause = false) val syncResponse = syncTask.execute(taskParams) return syncResponse.toDevice?.events?.isNotEmpty().orFalse() } diff --git a/vector/src/main/java/im/vector/app/features/analytics/extensions/PerformanceTimerExt.kt b/vector/src/main/java/im/vector/app/features/analytics/extensions/PerformanceTimerExt.kt new file mode 100644 index 0000000000..6f01196536 --- /dev/null +++ b/vector/src/main/java/im/vector/app/features/analytics/extensions/PerformanceTimerExt.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 im.vector.app.features.analytics.extensions + +import im.vector.app.features.analytics.plan.PerformanceTimer +import org.matrix.android.sdk.api.session.statistics.StatisticEvent + +fun StatisticEvent.toPerformanceTimer(): PerformanceTimer? { + return when (this) { + is StatisticEvent.InitialSyncRequest -> + PerformanceTimer(name = PerformanceTimer.Name.InitialSyncRequest, timeMs = durationMs) + is StatisticEvent.InitialSyncTreatment -> + PerformanceTimer(name = PerformanceTimer.Name.InitialSyncParsing, timeMs = durationMs) + is StatisticEvent.SyncTreatment -> + if (afterPause) { + PerformanceTimer(name = PerformanceTimer.Name.StartupIncrementalSync, timeMs = durationMs) + } else { + // We do not report + null + } + } +} diff --git a/vector/src/main/java/im/vector/app/features/session/SessionListener.kt b/vector/src/main/java/im/vector/app/features/session/SessionListener.kt index c1ee0b527e..e218910943 100644 --- a/vector/src/main/java/im/vector/app/features/session/SessionListener.kt +++ b/vector/src/main/java/im/vector/app/features/session/SessionListener.kt @@ -20,16 +20,21 @@ import androidx.lifecycle.LiveData import androidx.lifecycle.MutableLiveData import im.vector.app.core.extensions.postLiveEvent import im.vector.app.core.utils.LiveEvent +import im.vector.app.features.analytics.AnalyticsTracker +import im.vector.app.features.analytics.extensions.toPerformanceTimer import im.vector.app.features.call.vectorCallService import kotlinx.coroutines.cancelChildren import kotlinx.coroutines.launch import org.matrix.android.sdk.api.failure.GlobalError import org.matrix.android.sdk.api.session.Session +import org.matrix.android.sdk.api.session.statistics.StatisticEvent import javax.inject.Inject import javax.inject.Singleton @Singleton -class SessionListener @Inject constructor() : Session.Listener { +class SessionListener @Inject constructor( + private val analyticsTracker: AnalyticsTracker +) : Session.Listener { private val _globalErrorLiveData = MutableLiveData>() val globalErrorLiveData: LiveData> @@ -45,6 +50,10 @@ class SessionListener @Inject constructor() : Session.Listener { } } + override fun onStatisticsEvent(session: Session, statisticEvent: StatisticEvent) { + statisticEvent.toPerformanceTimer()?.let { analyticsTracker.capture(it) } + } + override fun onSessionStopped(session: Session) { session.coroutineScope.coroutineContext.cancelChildren() } From f6d856d8284503c70ef91d761435d3fe4f3830ab Mon Sep 17 00:00:00 2001 From: Benoit Marty Date: Fri, 21 Jan 2022 17:42:40 +0100 Subject: [PATCH 2/4] Analytics: report performance event about sync request - send number of joined rooms --- .../api/session/statistics/StatisticEvent.kt | 6 +-- .../sdk/internal/session/sync/SyncTask.kt | 45 +++++++++++++++---- .../extensions/PerformanceTimerExt.kt | 18 ++++++-- 3 files changed, 55 insertions(+), 14 deletions(-) diff --git a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/session/statistics/StatisticEvent.kt b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/session/statistics/StatisticEvent.kt index 4d05aa0194..32207c9cd7 100644 --- a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/session/statistics/StatisticEvent.kt +++ b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/session/statistics/StatisticEvent.kt @@ -23,15 +23,15 @@ sealed interface StatisticEvent { /** * Initial sync request and response downloading, not including parsing and storage of response */ - data class InitialSyncRequest(val durationMs: Int) : StatisticEvent + data class InitialSyncRequest(val durationMs: Int, val nbOfRooms: Int) : StatisticEvent /** * Initial sync treatment: parsing and storage of response */ - data class InitialSyncTreatment(val durationMs: Int) : StatisticEvent + data class InitialSyncTreatment(val durationMs: Int, val nbOfRooms: Int) : StatisticEvent /** * Incremental sync event */ - data class SyncTreatment(val durationMs: Int, val afterPause: Boolean) : StatisticEvent + data class SyncTreatment(val durationMs: Int, val afterPause: Boolean, val nbOfRooms: Int) : StatisticEvent } 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 1f27757205..a2943d8ed6 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 @@ -113,7 +113,7 @@ internal class DefaultSyncTask @Inject constructor( val readTimeOut = (params.timeout + TIMEOUT_MARGIN).coerceAtLeast(TimeOutInterceptor.DEFAULT_LONG_TIMEOUT) var syncResponseToReturn: SyncResponse? = null - var start = SystemClock.elapsedRealtime() + val syncStatisticsData = SyncStatisticsData(isInitialSync, params.afterPause) if (isInitialSync) { Timber.tag(loggerTag.value).d("INIT_SYNC with filter: ${requestParams["filter"]}") val initSyncStrategy = initialSyncStrategy @@ -122,8 +122,7 @@ internal class DefaultSyncTask @Inject constructor( roomSyncEphemeralTemporaryStore.reset() workingDir.mkdirs() val file = downloadInitSyncResponse(requestParams) - sendStatistics(StatisticEvent.InitialSyncRequest((SystemClock.elapsedRealtime() - start).toInt())) - start = SystemClock.elapsedRealtime() + syncStatisticsData.intermediateTime = SystemClock.elapsedRealtime() syncResponseToReturn = reportSubtask(defaultSyncStatusService, InitSyncStep.ImportingAccount, 1, 0.7F) { handleSyncFile(file, initSyncStrategy) } @@ -138,8 +137,7 @@ internal class DefaultSyncTask @Inject constructor( ) } } - sendStatistics(StatisticEvent.InitialSyncRequest((SystemClock.elapsedRealtime() - start).toInt())) - start = SystemClock.elapsedRealtime() + syncStatisticsData.intermediateTime = SystemClock.elapsedRealtime() logDuration("INIT_SYNC Database insertion", loggerTag) { syncResponseHandler.handleResponse(syncResponse, token, defaultSyncStatusService) } @@ -147,7 +145,6 @@ internal class DefaultSyncTask @Inject constructor( } } defaultSyncStatusService.endAll() - sendStatistics(StatisticEvent.InitialSyncTreatment((SystemClock.elapsedRealtime() - start).toInt())) } else { Timber.tag(loggerTag.value).d("Start incremental sync request") defaultSyncStatusService.setStatus(SyncStatusService.Status.IncrementalSyncIdle) @@ -174,8 +171,9 @@ internal class DefaultSyncTask @Inject constructor( syncResponseToReturn = syncResponse Timber.tag(loggerTag.value).d("Incremental sync done") defaultSyncStatusService.setStatus(SyncStatusService.Status.IncrementalSyncDone) - sendStatistics(StatisticEvent.SyncTreatment((SystemClock.elapsedRealtime() - start).toInt(), params.afterPause)) } + syncStatisticsData.nbOfRooms = syncResponseToReturn?.rooms?.join?.size ?: 0 + sendStatistics(syncStatisticsData) Timber.tag(loggerTag.value).d("Sync task finished on Thread: ${Thread.currentThread().name}") // Should throw if null as it's a mandatory value. return syncResponseToReturn!! @@ -254,7 +252,38 @@ internal class DefaultSyncTask @Inject constructor( } } - private fun sendStatistics(statisticEvent: StatisticEvent) { + /** + * Aggregator to send stat event. + */ + class SyncStatisticsData( + val isInitSync: Boolean, + val isAfterPause: Boolean + ) { + val startTime = SystemClock.elapsedRealtime() + var intermediateTime: Long = 0 + var nbOfRooms: Int = 0 + } + + private fun sendStatistics(data: SyncStatisticsData) { + if (data.isInitSync) { + sendStatisticEvent(StatisticEvent.InitialSyncRequest( + durationMs = (data.intermediateTime - data.startTime).toInt(), + nbOfRooms = data.nbOfRooms + )) + sendStatisticEvent(StatisticEvent.InitialSyncTreatment( + durationMs = (SystemClock.elapsedRealtime() - data.intermediateTime).toInt(), + nbOfRooms = data.nbOfRooms + )) + } else { + sendStatisticEvent(StatisticEvent.SyncTreatment( + durationMs = (SystemClock.elapsedRealtime() - data.startTime).toInt(), + afterPause = data.isAfterPause, + nbOfRooms = data.nbOfRooms + )) + } + } + + private fun sendStatisticEvent(statisticEvent: StatisticEvent) { session.dispatchTo(sessionListeners) { session, listener -> listener.onStatisticsEvent(session, statisticEvent) } diff --git a/vector/src/main/java/im/vector/app/features/analytics/extensions/PerformanceTimerExt.kt b/vector/src/main/java/im/vector/app/features/analytics/extensions/PerformanceTimerExt.kt index 6f01196536..5203d87971 100644 --- a/vector/src/main/java/im/vector/app/features/analytics/extensions/PerformanceTimerExt.kt +++ b/vector/src/main/java/im/vector/app/features/analytics/extensions/PerformanceTimerExt.kt @@ -22,12 +22,24 @@ import org.matrix.android.sdk.api.session.statistics.StatisticEvent fun StatisticEvent.toPerformanceTimer(): PerformanceTimer? { return when (this) { is StatisticEvent.InitialSyncRequest -> - PerformanceTimer(name = PerformanceTimer.Name.InitialSyncRequest, timeMs = durationMs) + PerformanceTimer( + name = PerformanceTimer.Name.InitialSyncRequest, + timeMs = durationMs, + itemCount = nbOfRooms + ) is StatisticEvent.InitialSyncTreatment -> - PerformanceTimer(name = PerformanceTimer.Name.InitialSyncParsing, timeMs = durationMs) + PerformanceTimer( + name = PerformanceTimer.Name.InitialSyncParsing, + timeMs = durationMs, + itemCount = nbOfRooms + ) is StatisticEvent.SyncTreatment -> if (afterPause) { - PerformanceTimer(name = PerformanceTimer.Name.StartupIncrementalSync, timeMs = durationMs) + PerformanceTimer( + name = PerformanceTimer.Name.StartupIncrementalSync, + timeMs = durationMs, + itemCount = nbOfRooms + ) } else { // We do not report null From cf86fe34d5abd46221e35ac663dbfcc73fea196c Mon Sep 17 00:00:00 2001 From: Benoit Marty Date: Mon, 24 Jan 2022 22:37:07 +0100 Subject: [PATCH 3/4] Improve SDK API (self review) --- .../api/session/statistics/StatisticEvent.kt | 16 +++--- .../sdk/internal/session/sync/SyncTask.kt | 49 ++++++++++--------- .../extensions/PerformanceTimerExt.kt | 39 ++++++++------- .../app/features/session/SessionListener.kt | 6 ++- 4 files changed, 60 insertions(+), 50 deletions(-) diff --git a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/session/statistics/StatisticEvent.kt b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/session/statistics/StatisticEvent.kt index 32207c9cd7..946792d31e 100644 --- a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/session/statistics/StatisticEvent.kt +++ b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/session/statistics/StatisticEvent.kt @@ -21,17 +21,17 @@ package org.matrix.android.sdk.api.session.statistics */ sealed interface StatisticEvent { /** - * Initial sync request and response downloading, not including parsing and storage of response + * Initial sync request, response downloading, and treatment (parsing and storage) of response */ - data class InitialSyncRequest(val durationMs: Int, val nbOfRooms: Int) : StatisticEvent - - /** - * Initial sync treatment: parsing and storage of response - */ - data class InitialSyncTreatment(val durationMs: Int, val nbOfRooms: Int) : StatisticEvent + data class InitialSyncRequest(val requestDurationMs: Int, + val downloadDurationMs: Int, + val treatmentDurationMs: Int, + val nbOfJoinedRooms: Int) : StatisticEvent /** * Incremental sync event */ - data class SyncTreatment(val durationMs: Int, val afterPause: Boolean, val nbOfRooms: Int) : StatisticEvent + data class SyncTreatment(val durationMs: Int, + val afterPause: Boolean, + val nbOfJoinedRooms: Int) : StatisticEvent } 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 a2943d8ed6..c15473f627 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 @@ -121,8 +121,7 @@ internal class DefaultSyncTask @Inject constructor( if (initSyncStrategy is InitialSyncStrategy.Optimized) { roomSyncEphemeralTemporaryStore.reset() workingDir.mkdirs() - val file = downloadInitSyncResponse(requestParams) - syncStatisticsData.intermediateTime = SystemClock.elapsedRealtime() + val file = downloadInitSyncResponse(requestParams, syncStatisticsData) syncResponseToReturn = reportSubtask(defaultSyncStatusService, InitSyncStep.ImportingAccount, 1, 0.7F) { handleSyncFile(file, initSyncStrategy) } @@ -137,7 +136,9 @@ internal class DefaultSyncTask @Inject constructor( ) } } - syncStatisticsData.intermediateTime = SystemClock.elapsedRealtime() + // We cannot distinguish request and download in this case. + syncStatisticsData.requestInitSyncTime = SystemClock.elapsedRealtime() + syncStatisticsData.downloadInitSyncTime = syncStatisticsData.requestInitSyncTime logDuration("INIT_SYNC Database insertion", loggerTag) { syncResponseHandler.handleResponse(syncResponse, token, defaultSyncStatusService) } @@ -172,6 +173,7 @@ internal class DefaultSyncTask @Inject constructor( Timber.tag(loggerTag.value).d("Incremental sync done") defaultSyncStatusService.setStatus(SyncStatusService.Status.IncrementalSyncDone) } + syncStatisticsData.treatmentSyncTime = SystemClock.elapsedRealtime() syncStatisticsData.nbOfRooms = syncResponseToReturn?.rooms?.join?.size ?: 0 sendStatistics(syncStatisticsData) Timber.tag(loggerTag.value).d("Sync task finished on Thread: ${Thread.currentThread().name}") @@ -179,7 +181,7 @@ internal class DefaultSyncTask @Inject constructor( return syncResponseToReturn!! } - private suspend fun downloadInitSyncResponse(requestParams: Map): File { + private suspend fun downloadInitSyncResponse(requestParams: Map, syncStatisticsData: SyncStatisticsData): File { val workingFile = File(workingDir, "initSync.json") val status = initialSyncStatusRepository.getStep() if (workingFile.exists() && status >= InitialSyncStatus.STEP_DOWNLOADED) { @@ -194,7 +196,7 @@ internal class DefaultSyncTask @Inject constructor( getSyncResponse(requestParams, MAX_NUMBER_OF_RETRY_AFTER_TIMEOUT) } } - + syncStatisticsData.requestInitSyncTime = SystemClock.elapsedRealtime() if (syncResponse.isSuccessful) { logDuration("INIT_SYNC Download and save to file", loggerTag) { reportSubtask(defaultSyncStatusService, InitSyncStep.Downloading, 1, 0.1f) { @@ -205,6 +207,7 @@ internal class DefaultSyncTask @Inject constructor( } } } + syncStatisticsData.downloadInitSyncTime = SystemClock.elapsedRealtime() } else { throw syncResponse.toFailure(globalErrorReceiver) .also { Timber.tag(loggerTag.value).w("INIT_SYNC request failure: $this") } @@ -260,27 +263,29 @@ internal class DefaultSyncTask @Inject constructor( val isAfterPause: Boolean ) { val startTime = SystemClock.elapsedRealtime() - var intermediateTime: Long = 0 + var requestInitSyncTime = startTime + var downloadInitSyncTime = startTime + var treatmentSyncTime = startTime var nbOfRooms: Int = 0 } private fun sendStatistics(data: SyncStatisticsData) { - if (data.isInitSync) { - sendStatisticEvent(StatisticEvent.InitialSyncRequest( - durationMs = (data.intermediateTime - data.startTime).toInt(), - nbOfRooms = data.nbOfRooms - )) - sendStatisticEvent(StatisticEvent.InitialSyncTreatment( - durationMs = (SystemClock.elapsedRealtime() - data.intermediateTime).toInt(), - nbOfRooms = data.nbOfRooms - )) - } else { - sendStatisticEvent(StatisticEvent.SyncTreatment( - durationMs = (SystemClock.elapsedRealtime() - data.startTime).toInt(), - afterPause = data.isAfterPause, - nbOfRooms = data.nbOfRooms - )) - } + sendStatisticEvent( + if (data.isInitSync) { + (StatisticEvent.InitialSyncRequest( + requestDurationMs = (data.requestInitSyncTime - data.startTime).toInt(), + downloadDurationMs = (data.downloadInitSyncTime - data.requestInitSyncTime).toInt(), + treatmentDurationMs = (data.treatmentSyncTime - data.downloadInitSyncTime).toInt(), + nbOfJoinedRooms = data.nbOfRooms, + )) + } else { + StatisticEvent.SyncTreatment( + durationMs = (data.treatmentSyncTime - data.startTime).toInt(), + afterPause = data.isAfterPause, + nbOfJoinedRooms = data.nbOfRooms + ) + } + ) } private fun sendStatisticEvent(statisticEvent: StatisticEvent) { diff --git a/vector/src/main/java/im/vector/app/features/analytics/extensions/PerformanceTimerExt.kt b/vector/src/main/java/im/vector/app/features/analytics/extensions/PerformanceTimerExt.kt index 5203d87971..11b4b670d3 100644 --- a/vector/src/main/java/im/vector/app/features/analytics/extensions/PerformanceTimerExt.kt +++ b/vector/src/main/java/im/vector/app/features/analytics/extensions/PerformanceTimerExt.kt @@ -19,30 +19,33 @@ package im.vector.app.features.analytics.extensions import im.vector.app.features.analytics.plan.PerformanceTimer import org.matrix.android.sdk.api.session.statistics.StatisticEvent -fun StatisticEvent.toPerformanceTimer(): PerformanceTimer? { +fun StatisticEvent.toListOfPerformanceTimer(): List { return when (this) { - is StatisticEvent.InitialSyncRequest -> - PerformanceTimer( - name = PerformanceTimer.Name.InitialSyncRequest, - timeMs = durationMs, - itemCount = nbOfRooms + is StatisticEvent.InitialSyncRequest -> + listOf( + PerformanceTimer( + name = PerformanceTimer.Name.InitialSyncRequest, + timeMs = requestDurationMs + downloadDurationMs, + itemCount = nbOfJoinedRooms + ), + PerformanceTimer( + name = PerformanceTimer.Name.InitialSyncParsing, + timeMs = treatmentDurationMs, + itemCount = nbOfJoinedRooms + ) ) - is StatisticEvent.InitialSyncTreatment -> - PerformanceTimer( - name = PerformanceTimer.Name.InitialSyncParsing, - timeMs = durationMs, - itemCount = nbOfRooms - ) - is StatisticEvent.SyncTreatment -> + is StatisticEvent.SyncTreatment -> if (afterPause) { - PerformanceTimer( - name = PerformanceTimer.Name.StartupIncrementalSync, - timeMs = durationMs, - itemCount = nbOfRooms + listOf( + PerformanceTimer( + name = PerformanceTimer.Name.StartupIncrementalSync, + timeMs = durationMs, + itemCount = nbOfJoinedRooms + ) ) } else { // We do not report - null + emptyList() } } } diff --git a/vector/src/main/java/im/vector/app/features/session/SessionListener.kt b/vector/src/main/java/im/vector/app/features/session/SessionListener.kt index e218910943..37db55959f 100644 --- a/vector/src/main/java/im/vector/app/features/session/SessionListener.kt +++ b/vector/src/main/java/im/vector/app/features/session/SessionListener.kt @@ -21,7 +21,7 @@ import androidx.lifecycle.MutableLiveData import im.vector.app.core.extensions.postLiveEvent import im.vector.app.core.utils.LiveEvent import im.vector.app.features.analytics.AnalyticsTracker -import im.vector.app.features.analytics.extensions.toPerformanceTimer +import im.vector.app.features.analytics.extensions.toListOfPerformanceTimer import im.vector.app.features.call.vectorCallService import kotlinx.coroutines.cancelChildren import kotlinx.coroutines.launch @@ -51,7 +51,9 @@ class SessionListener @Inject constructor( } override fun onStatisticsEvent(session: Session, statisticEvent: StatisticEvent) { - statisticEvent.toPerformanceTimer()?.let { analyticsTracker.capture(it) } + statisticEvent.toListOfPerformanceTimer().forEach { + analyticsTracker.capture(it) + } } override fun onSessionStopped(session: Session) { From 80d9b64e5afa3d65ee5fc1e857e2575be6d62380 Mon Sep 17 00:00:00 2001 From: Benoit Marty Date: Mon, 24 Jan 2022 22:49:34 +0100 Subject: [PATCH 4/4] Cover also the error case. --- .../org/matrix/android/sdk/internal/session/sync/SyncTask.kt | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) 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 c15473f627..1ee62ad774 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 @@ -207,11 +207,11 @@ internal class DefaultSyncTask @Inject constructor( } } } - syncStatisticsData.downloadInitSyncTime = SystemClock.elapsedRealtime() } else { throw syncResponse.toFailure(globalErrorReceiver) .also { Timber.tag(loggerTag.value).w("INIT_SYNC request failure: $this") } } + syncStatisticsData.downloadInitSyncTime = SystemClock.elapsedRealtime() initialSyncStatusRepository.setStep(InitialSyncStatus.STEP_DOWNLOADED) } return workingFile