From c214c2233f5a586d5bf740f6cffae6611d98362b Mon Sep 17 00:00:00 2001 From: SpiritCroc Date: Tue, 15 Mar 2022 10:08:08 +0100 Subject: [PATCH] [TMP] Update timeline debugging And clean up some debugging that's probably not needed anymore Change-Id: I3b154280487f02479f7c40b543da43ca39e9e2e3 --- .../session/room/timeline/DefaultTimeline.kt | 10 +++--- .../session/room/timeline/TimelineChunk.kt | 33 ++++++++++--------- .../room/timeline/TokenChunkEventPersistor.kt | 2 +- 3 files changed, 24 insertions(+), 21 deletions(-) diff --git a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/room/timeline/DefaultTimeline.kt b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/room/timeline/DefaultTimeline.kt index 5ff7282b01..8895c6f11a 100644 --- a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/room/timeline/DefaultTimeline.kt +++ b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/room/timeline/DefaultTimeline.kt @@ -299,7 +299,7 @@ internal class DefaultTimeline(private val roomId: String, Timber.v("Post snapshot of ${snapshot.size} events") // Async debugging to not slow down things too much timelineScope.launch(coroutineDispatchers.computation) { - checkTimelineConsistency("DefaultTimeline.postSnapshot", snapshot) { msg -> + checkTimelineConsistency("DefaultTimeline.postSnapshot", snapshot, verbose = false) { msg -> timelineScope.launch(coroutineDispatchers.main) { StaticScSdkHelper.scSdkPreferenceProvider?.annoyDevelopersWithToast(msg) } @@ -393,8 +393,8 @@ internal class DefaultTimeline(private val roomId: String, } } -fun checkTimelineConsistency(location: String, events: List, sendToastFunction: (String) -> Unit = {}) { - Timber.i("Check timeline consistency from $location for ${events.size} events, from ${events.firstOrNull()?.eventId} to ${events.lastOrNull()?.eventId}") +fun checkTimelineConsistency(location: String, events: List, verbose: Boolean = true, sendToastFunction: (String) -> Unit = {}) { + // Set verbose = false if this is a much repeated check and not close to the likely issue source -> in this case, we only want to complain about actually found issues try { var potentialIssues = 0 // Note that the "previous" event is actually newer than the currently looked at event, @@ -427,7 +427,9 @@ fun checkTimelineConsistency(location: String, events: List, send if (toastMsg.isNotEmpty()) { sendToastFunction(toastMsg.substring(0, toastMsg.length-1)) } - Timber.i("Done check timeline consistency from $location, found $potentialIssues possible issues") + if (verbose || potentialIssues > 0) { + Timber.i("Check timeline consistency from $location for ${events.size} events from ${events.firstOrNull()?.eventId} to ${events.lastOrNull()?.eventId}, found $potentialIssues possible issues") + } } catch (t: Throwable) { Timber.e("Failed check timeline consistency from $location", t) } diff --git a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/room/timeline/TimelineChunk.kt b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/room/timeline/TimelineChunk.kt index b1dee12865..fe2e31bf61 100644 --- a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/room/timeline/TimelineChunk.kt +++ b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/room/timeline/TimelineChunk.kt @@ -64,13 +64,14 @@ internal class TimelineChunk(private val chunkEntity: ChunkEntity, private val isLastBackward = AtomicBoolean(chunkEntity.isLastBackward) private var prevChunkLatch: CompletableDeferred? = null private var nextChunkLatch: CompletableDeferred? = null + private val dbgId = chunkEntity.identifier() private val chunkObjectListener = RealmObjectChangeListener { _, changeSet -> if (changeSet == null) return@RealmObjectChangeListener if (changeSet.isDeleted.orFalse()) { return@RealmObjectChangeListener } - Timber.v("on chunk (${chunkEntity.identifier()}) changed: ${changeSet.changedFields?.joinToString(",")}") + Timber.v("on chunk $dbgId changed: ${changeSet.changedFields?.joinToString(",")}") if (changeSet.isFieldChanged(ChunkEntityFields.IS_LAST_FORWARD)) { isLastForward.set(chunkEntity.isLastForward) } @@ -79,10 +80,12 @@ internal class TimelineChunk(private val chunkEntity: ChunkEntity, } if (changeSet.isFieldChanged(ChunkEntityFields.NEXT_CHUNK.`$`)) { nextChunk = createTimelineChunk(chunkEntity.nextChunk) + Timber.i("TimelineChunk.$dbgId set next to ${nextChunk?.dbgId}") nextChunkLatch?.complete(Unit) } if (changeSet.isFieldChanged(ChunkEntityFields.PREV_CHUNK.`$`)) { prevChunk = createTimelineChunk(chunkEntity.prevChunk) + Timber.i("TimelineChunk.$dbgId set prev to ${prevChunk?.dbgId}") prevChunkLatch?.complete(Unit) } } @@ -101,6 +104,7 @@ internal class TimelineChunk(private val chunkEntity: ChunkEntity, private var prevChunk: TimelineChunk? = null init { + Timber.i("TimelineChunk.init.$dbgId prev ${chunkEntity.prevChunk?.identifier()} next ${chunkEntity.nextChunk?.identifier()}") timelineEventEntities.addChangeListener(timelineEventsChangeListener) chunkEntity.addChangeListener(chunkObjectListener) } @@ -119,7 +123,7 @@ internal class TimelineChunk(private val chunkEntity: ChunkEntity, val nextEvents = nextChunk?.builtItems(includesNext = true, includesPrev = false).orEmpty() deepBuiltItems.addAll(nextEvents) } - checkTimelineConsistency("TimelineChunk.builtItems", builtEvents) + checkTimelineConsistency("TimelineChunk.builtItems.$dbgId", builtEvents, verbose = false) deepBuiltItems.addAll(builtEvents) if (includesPrev) { val prevEvents = prevChunk?.builtItems(includesNext = false, includesPrev = true).orEmpty() @@ -145,6 +149,8 @@ internal class TimelineChunk(private val chunkEntity: ChunkEntity, val offsetCount = count - loadFromStorage.numberOfEvents + Timber.i("TimelineChunk.loadMore.$dbgId: $direction, count = $count, loaded = ${loadFromStorage.numberOfEvents}, offsetCount = $offsetCount, builtEvents = ${builtEvents.size}, available = ${timelineEventEntities.size}") + return if (offsetCount == 0) { LoadMoreResult.SUCCESS } else if (direction == Timeline.Direction.FORWARDS && isLastForward.get()) { @@ -259,7 +265,7 @@ internal class TimelineChunk(private val chunkEntity: ChunkEntity, } // Update the relation of existing event builtEvents.getOrNull(builtIndex)?.let { te -> - Timber.i("TimelineChunk.rebuildEvent $eventId at $builtIndex, which was ${te.eventId}") + Timber.i("TimelineChunk.rebuildEvent.$dbgId $eventId at $builtIndex, which was ${te.eventId}") val rebuiltEvent = builder(te) builtEvents[builtIndex] = rebuiltEvent!! true @@ -289,7 +295,6 @@ internal class TimelineChunk(private val chunkEntity: ChunkEntity, * whether or not we reached the end/root message */ private fun loadFromStorage(count: Int, direction: Timeline.Direction): LoadedFromStorage { - Timber.i("TimelineChunk.loadFromStorage() start") val displayIndex = getNextDisplayIndex(direction) ?: return LoadedFromStorage() val baseQuery = timelineEventEntities.where() @@ -298,18 +303,18 @@ internal class TimelineChunk(private val chunkEntity: ChunkEntity, .findAll() .orEmpty() val builtTimelineEvents = timelineEvents.map { it.buildAndDecryptIfNeeded() } - checkTimelineConsistency("TimelineChunk.loadFromStorage-raw-query", builtTimelineEvents) + checkTimelineConsistency("TimelineChunk.loadFromStorage-raw-query.$dbgId", builtTimelineEvents) - if (timelineEvents.isEmpty()) return LoadedFromStorage().also { Timber.i("TimelineChunk.loadFromStorage() empty abort") } + if (timelineEvents.isEmpty()) return LoadedFromStorage() // Disabled due to the new fallback // if(!lightweightSettingsStorage.areThreadMessagesEnabled()) { // fetchRootThreadEventsIfNeeded(timelineEvents) // } if (direction == Timeline.Direction.FORWARDS) { builtEventsIndexes.entries.forEach { it.setValue(it.value + timelineEvents.size) } - Timber.i("TimelineChunk.loadFromStorage: insert ${timelineEvents.size} items forwards at start, old size: ${builtEvents.size}") + Timber.i("TimelineChunk.loadFromStorage.$dbgId: insert ${timelineEvents.size} items forwards at start, old size: ${builtEvents.size}") } else { - Timber.i("TimelineChunk.loadFromStorage: insert ${timelineEvents.size} items backwards at end, old size: ${builtEvents.size}") + Timber.i("TimelineChunk.loadFromStorage.$dbgId: insert ${timelineEvents.size} items backwards at end, old size: ${builtEvents.size}") } val extraCheck = mutableListOf() //timelineEvents @@ -328,12 +333,10 @@ internal class TimelineChunk(private val chunkEntity: ChunkEntity, } extraCheck.add(timelineEvent) } - checkTimelineConsistency("TimelineChunk.loadFromStorage-extra-check", extraCheck) + checkTimelineConsistency("TimelineChunk.loadFromStorage-extra-check.$dbgId", extraCheck) return LoadedFromStorage( threadReachedEnd = threadReachedEnd(timelineEvents), - numberOfEvents = timelineEvents.size).also { - Timber.i("TimelineChunk.loadFromStorage() end") - } + numberOfEvents = timelineEvents.size) } /** @@ -442,7 +445,6 @@ internal class TimelineChunk(private val chunkEntity: ChunkEntity, * */ private fun handleDatabaseChangeSet(results: RealmResults, changeSet: OrderedCollectionChangeSet) { - Timber.i("TimelineChunk.handleDatabaseChangeSet() start") val insertions = changeSet.insertionRanges for (range in insertions) { val newItems = results @@ -454,7 +456,7 @@ internal class TimelineChunk(private val chunkEntity: ChunkEntity, isLastBackward.set(true) } val correctedIndex = range.startIndex + index - Timber.i("TimelineChunk.handleDatabaseChangeSet: insert ${timelineEvent.eventId} at $correctedIndex (${range.startIndex} + $index)") + Timber.i("TimelineChunk.handleDatabaseChangeSet.$dbgId: insert ${timelineEvent.eventId} at $correctedIndex (${range.startIndex} + $index)") builtEvents.add(correctedIndex, timelineEvent) builtEventsIndexes[timelineEvent.eventId] = correctedIndex } @@ -465,7 +467,7 @@ internal class TimelineChunk(private val chunkEntity: ChunkEntity, val updatedEntity = results[modificationIndex] ?: continue val displayIndex = builtEventsIndexes.getOrDefault(updatedEntity.eventId, null) if (displayIndex == null) { - Timber.w("TimelineChunk.handleDatabaseChangeSet: skip modification for ${updatedEntity.eventId} at $modificationIndex, not found in chunk") + Timber.w("TimelineChunk.handleDatabaseChangeSet.$dbgId: skip modification for ${updatedEntity.eventId} at $modificationIndex, not found in chunk") continue } try { @@ -475,7 +477,6 @@ internal class TimelineChunk(private val chunkEntity: ChunkEntity, } } } - Timber.i("TimelineChunk.handleDatabaseChangeSet() end") if (insertions.isNotEmpty() || modifications.isNotEmpty()) { onBuiltEvents(true) } diff --git a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/room/timeline/TokenChunkEventPersistor.kt b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/room/timeline/TokenChunkEventPersistor.kt index 6607e71bd9..c97547c55b 100644 --- a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/room/timeline/TokenChunkEventPersistor.kt +++ b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/room/timeline/TokenChunkEventPersistor.kt @@ -65,7 +65,7 @@ internal class TokenChunkEventPersistor @Inject constructor( direction: PaginationDirection): Result { monarchy .awaitTransaction { realm -> - Timber.v("Start persisting ${receivedChunk.events.size} events in $roomId towards $direction") + Timber.i("Start persisting ${receivedChunk.events.size} events in $roomId towards $direction | first ${receivedChunk.events.firstOrNull()?.eventId} last ${receivedChunk.events.lastOrNull()?.eventId}") val nextToken: String? val prevToken: String?