Merge pull request #5043 from vector-im/feature/bma/track_performance

Track performance

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.
          */

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, response downloading, and treatment (parsing and storage) of response
+     */
+    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 nbOfJoinedRooms: Int) : StatisticEvent
+}

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
+}

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<SyncTask.Params, SyncResponse> {
 
     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
+        val syncStatisticsData = SyncStatisticsData(isInitialSync, params.afterPause)
         if (isInitialSync) {
             Timber.tag(loggerTag.value).d("INIT_SYNC with filter: ${requestParams["filter"]}")
             val initSyncStrategy = initialSyncStrategy
@@ -112,7 +121,7 @@ internal class DefaultSyncTask @Inject constructor(
                 if (initSyncStrategy is InitialSyncStrategy.Optimized) {
                     roomSyncEphemeralTemporaryStore.reset()
                     workingDir.mkdirs()
-                    val file = downloadInitSyncResponse(requestParams)
+                    val file = downloadInitSyncResponse(requestParams, syncStatisticsData)
                     syncResponseToReturn = reportSubtask(defaultSyncStatusService, InitSyncStep.ImportingAccount, 1, 0.7F) {
                         handleSyncFile(file, initSyncStrategy)
                     }
@@ -127,6 +136,9 @@ internal class DefaultSyncTask @Inject constructor(
                             )
                         }
                     }
+                    // 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)
                     }
@@ -161,12 +173,15 @@ 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}")
         // Should throw if null as it's a mandatory value.
         return syncResponseToReturn!!
     }
 
-    private suspend fun downloadInitSyncResponse(requestParams: Map<String, String>): File {
+    private suspend fun downloadInitSyncResponse(requestParams: Map<String, String>, syncStatisticsData: SyncStatisticsData): File {
         val workingFile = File(workingDir, "initSync.json")
         val status = initialSyncStatusRepository.getStep()
         if (workingFile.exists() && status >= InitialSyncStatus.STEP_DOWNLOADED) {
@@ -181,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) {
@@ -196,6 +211,7 @@ internal class DefaultSyncTask @Inject constructor(
                 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
@@ -239,6 +255,45 @@ internal class DefaultSyncTask @Inject constructor(
         }
     }
 
+    /**
+     * Aggregator to send stat event.
+     */
+    class SyncStatisticsData(
+            val isInitSync: Boolean,
+            val isAfterPause: Boolean
+    ) {
+        val startTime = SystemClock.elapsedRealtime()
+        var requestInitSyncTime = startTime
+        var downloadInitSyncTime = startTime
+        var treatmentSyncTime = startTime
+        var nbOfRooms: Int = 0
+    }
+
+    private fun sendStatistics(data: SyncStatisticsData) {
+        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) {
+        session.dispatchTo(sessionListeners) { session, listener ->
+            listener.onStatisticsEvent(session, statisticEvent)
+        }
+    }
+
     companion object {
         private const val MAX_NUMBER_OF_RETRY_AFTER_TIMEOUT = 50
 

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)

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 */
+                    previousSyncResponseHasToDevice -> 0L /* Force timeout to 0 */
-                    state.let { it is SyncState.Running && it.afterPause } -> 0L /* No timeout after a pause */
+                    afterPause                      -> 0L /* No timeout after a pause */
-                    else                                                   -> DEFAULT_LONG_POOL_TIMEOUT
+                    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)
                 }

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()
     }

vector/src/main/java/im/vector/app/features/analytics/extensions/PerformanceTimerExt.kt

@@ -0,0 +1,51 @@
+/*
+ * 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.toListOfPerformanceTimer(): List<PerformanceTimer> {
+    return when (this) {
+        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.SyncTreatment      ->
+            if (afterPause) {
+                listOf(
+                        PerformanceTimer(
+                                name = PerformanceTimer.Name.StartupIncrementalSync,
+                                timeMs = durationMs,
+                                itemCount = nbOfJoinedRooms
+                        )
+                )
+            } else {
+                // We do not report
+                emptyList()
+            }
+    }
+}

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.toListOfPerformanceTimer
 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<LiveEvent<GlobalError>>()
     val globalErrorLiveData: LiveData<LiveEvent<GlobalError>>
@@ -45,6 +50,12 @@ class SessionListener @Inject constructor() : Session.Listener {
         }
     }
 
+    override fun onStatisticsEvent(session: Session, statisticEvent: StatisticEvent) {
+        statisticEvent.toListOfPerformanceTimer().forEach {
+            analyticsTracker.capture(it)
+        }
+    }
+
     override fun onSessionStopped(session: Session) {
         session.coroutineScope.coroutineContext.cancelChildren()
     }