Analytics: report performance event about sync request

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

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

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

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<LiveEvent<GlobalError>>()
     val globalErrorLiveData: LiveData<LiveEvent<GlobalError>>
@@ -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()
     }