[TMP] Update timeline debugging

And clean up some debugging that's probably not needed anymore

Change-Id: I3b154280487f02479f7c40b543da43ca39e9e2e3
This commit is contained in:
SpiritCroc 2022-03-15 10:08:08 +01:00
parent f8971a9ba1
commit c214c2233f
3 changed files with 24 additions and 21 deletions

View file

@ -299,7 +299,7 @@ internal class DefaultTimeline(private val roomId: String,
Timber.v("Post snapshot of ${snapshot.size} events") Timber.v("Post snapshot of ${snapshot.size} events")
// Async debugging to not slow down things too much // Async debugging to not slow down things too much
timelineScope.launch(coroutineDispatchers.computation) { timelineScope.launch(coroutineDispatchers.computation) {
checkTimelineConsistency("DefaultTimeline.postSnapshot", snapshot) { msg -> checkTimelineConsistency("DefaultTimeline.postSnapshot", snapshot, verbose = false) { msg ->
timelineScope.launch(coroutineDispatchers.main) { timelineScope.launch(coroutineDispatchers.main) {
StaticScSdkHelper.scSdkPreferenceProvider?.annoyDevelopersWithToast(msg) StaticScSdkHelper.scSdkPreferenceProvider?.annoyDevelopersWithToast(msg)
} }
@ -393,8 +393,8 @@ internal class DefaultTimeline(private val roomId: String,
} }
} }
fun checkTimelineConsistency(location: String, events: List<TimelineEvent>, sendToastFunction: (String) -> Unit = {}) { fun checkTimelineConsistency(location: String, events: List<TimelineEvent>, verbose: Boolean = true, sendToastFunction: (String) -> Unit = {}) {
Timber.i("Check timeline consistency from $location for ${events.size} events, from ${events.firstOrNull()?.eventId} to ${events.lastOrNull()?.eventId}") // 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 { try {
var potentialIssues = 0 var potentialIssues = 0
// Note that the "previous" event is actually newer than the currently looked at event, // Note that the "previous" event is actually newer than the currently looked at event,
@ -427,7 +427,9 @@ fun checkTimelineConsistency(location: String, events: List<TimelineEvent>, send
if (toastMsg.isNotEmpty()) { if (toastMsg.isNotEmpty()) {
sendToastFunction(toastMsg.substring(0, toastMsg.length-1)) 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) { } catch (t: Throwable) {
Timber.e("Failed check timeline consistency from $location", t) Timber.e("Failed check timeline consistency from $location", t)
} }

View file

@ -64,13 +64,14 @@ internal class TimelineChunk(private val chunkEntity: ChunkEntity,
private val isLastBackward = AtomicBoolean(chunkEntity.isLastBackward) private val isLastBackward = AtomicBoolean(chunkEntity.isLastBackward)
private var prevChunkLatch: CompletableDeferred<Unit>? = null private var prevChunkLatch: CompletableDeferred<Unit>? = null
private var nextChunkLatch: CompletableDeferred<Unit>? = null private var nextChunkLatch: CompletableDeferred<Unit>? = null
private val dbgId = chunkEntity.identifier()
private val chunkObjectListener = RealmObjectChangeListener<ChunkEntity> { _, changeSet -> private val chunkObjectListener = RealmObjectChangeListener<ChunkEntity> { _, changeSet ->
if (changeSet == null) return@RealmObjectChangeListener if (changeSet == null) return@RealmObjectChangeListener
if (changeSet.isDeleted.orFalse()) { if (changeSet.isDeleted.orFalse()) {
return@RealmObjectChangeListener 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)) { if (changeSet.isFieldChanged(ChunkEntityFields.IS_LAST_FORWARD)) {
isLastForward.set(chunkEntity.isLastForward) isLastForward.set(chunkEntity.isLastForward)
} }
@ -79,10 +80,12 @@ internal class TimelineChunk(private val chunkEntity: ChunkEntity,
} }
if (changeSet.isFieldChanged(ChunkEntityFields.NEXT_CHUNK.`$`)) { if (changeSet.isFieldChanged(ChunkEntityFields.NEXT_CHUNK.`$`)) {
nextChunk = createTimelineChunk(chunkEntity.nextChunk) nextChunk = createTimelineChunk(chunkEntity.nextChunk)
Timber.i("TimelineChunk.$dbgId set next to ${nextChunk?.dbgId}")
nextChunkLatch?.complete(Unit) nextChunkLatch?.complete(Unit)
} }
if (changeSet.isFieldChanged(ChunkEntityFields.PREV_CHUNK.`$`)) { if (changeSet.isFieldChanged(ChunkEntityFields.PREV_CHUNK.`$`)) {
prevChunk = createTimelineChunk(chunkEntity.prevChunk) prevChunk = createTimelineChunk(chunkEntity.prevChunk)
Timber.i("TimelineChunk.$dbgId set prev to ${prevChunk?.dbgId}")
prevChunkLatch?.complete(Unit) prevChunkLatch?.complete(Unit)
} }
} }
@ -101,6 +104,7 @@ internal class TimelineChunk(private val chunkEntity: ChunkEntity,
private var prevChunk: TimelineChunk? = null private var prevChunk: TimelineChunk? = null
init { init {
Timber.i("TimelineChunk.init.$dbgId prev ${chunkEntity.prevChunk?.identifier()} next ${chunkEntity.nextChunk?.identifier()}")
timelineEventEntities.addChangeListener(timelineEventsChangeListener) timelineEventEntities.addChangeListener(timelineEventsChangeListener)
chunkEntity.addChangeListener(chunkObjectListener) chunkEntity.addChangeListener(chunkObjectListener)
} }
@ -119,7 +123,7 @@ internal class TimelineChunk(private val chunkEntity: ChunkEntity,
val nextEvents = nextChunk?.builtItems(includesNext = true, includesPrev = false).orEmpty() val nextEvents = nextChunk?.builtItems(includesNext = true, includesPrev = false).orEmpty()
deepBuiltItems.addAll(nextEvents) deepBuiltItems.addAll(nextEvents)
} }
checkTimelineConsistency("TimelineChunk.builtItems", builtEvents) checkTimelineConsistency("TimelineChunk.builtItems.$dbgId", builtEvents, verbose = false)
deepBuiltItems.addAll(builtEvents) deepBuiltItems.addAll(builtEvents)
if (includesPrev) { if (includesPrev) {
val prevEvents = prevChunk?.builtItems(includesNext = false, includesPrev = true).orEmpty() 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 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) { return if (offsetCount == 0) {
LoadMoreResult.SUCCESS LoadMoreResult.SUCCESS
} else if (direction == Timeline.Direction.FORWARDS && isLastForward.get()) { } 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 // Update the relation of existing event
builtEvents.getOrNull(builtIndex)?.let { te -> 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) val rebuiltEvent = builder(te)
builtEvents[builtIndex] = rebuiltEvent!! builtEvents[builtIndex] = rebuiltEvent!!
true true
@ -289,7 +295,6 @@ internal class TimelineChunk(private val chunkEntity: ChunkEntity,
* whether or not we reached the end/root message * whether or not we reached the end/root message
*/ */
private fun loadFromStorage(count: Int, direction: Timeline.Direction): LoadedFromStorage { private fun loadFromStorage(count: Int, direction: Timeline.Direction): LoadedFromStorage {
Timber.i("TimelineChunk.loadFromStorage() start")
val displayIndex = getNextDisplayIndex(direction) ?: return LoadedFromStorage() val displayIndex = getNextDisplayIndex(direction) ?: return LoadedFromStorage()
val baseQuery = timelineEventEntities.where() val baseQuery = timelineEventEntities.where()
@ -298,18 +303,18 @@ internal class TimelineChunk(private val chunkEntity: ChunkEntity,
.findAll() .findAll()
.orEmpty() .orEmpty()
val builtTimelineEvents = timelineEvents.map { it.buildAndDecryptIfNeeded() } 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 // Disabled due to the new fallback
// if(!lightweightSettingsStorage.areThreadMessagesEnabled()) { // if(!lightweightSettingsStorage.areThreadMessagesEnabled()) {
// fetchRootThreadEventsIfNeeded(timelineEvents) // fetchRootThreadEventsIfNeeded(timelineEvents)
// } // }
if (direction == Timeline.Direction.FORWARDS) { if (direction == Timeline.Direction.FORWARDS) {
builtEventsIndexes.entries.forEach { it.setValue(it.value + timelineEvents.size) } 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 { } 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<TimelineEvent>() val extraCheck = mutableListOf<TimelineEvent>()
//timelineEvents //timelineEvents
@ -328,12 +333,10 @@ internal class TimelineChunk(private val chunkEntity: ChunkEntity,
} }
extraCheck.add(timelineEvent) extraCheck.add(timelineEvent)
} }
checkTimelineConsistency("TimelineChunk.loadFromStorage-extra-check", extraCheck) checkTimelineConsistency("TimelineChunk.loadFromStorage-extra-check.$dbgId", extraCheck)
return LoadedFromStorage( return LoadedFromStorage(
threadReachedEnd = threadReachedEnd(timelineEvents), threadReachedEnd = threadReachedEnd(timelineEvents),
numberOfEvents = timelineEvents.size).also { numberOfEvents = timelineEvents.size)
Timber.i("TimelineChunk.loadFromStorage() end")
}
} }
/** /**
@ -442,7 +445,6 @@ internal class TimelineChunk(private val chunkEntity: ChunkEntity,
* *
*/ */
private fun handleDatabaseChangeSet(results: RealmResults<TimelineEventEntity>, changeSet: OrderedCollectionChangeSet) { private fun handleDatabaseChangeSet(results: RealmResults<TimelineEventEntity>, changeSet: OrderedCollectionChangeSet) {
Timber.i("TimelineChunk.handleDatabaseChangeSet() start")
val insertions = changeSet.insertionRanges val insertions = changeSet.insertionRanges
for (range in insertions) { for (range in insertions) {
val newItems = results val newItems = results
@ -454,7 +456,7 @@ internal class TimelineChunk(private val chunkEntity: ChunkEntity,
isLastBackward.set(true) isLastBackward.set(true)
} }
val correctedIndex = range.startIndex + index 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) builtEvents.add(correctedIndex, timelineEvent)
builtEventsIndexes[timelineEvent.eventId] = correctedIndex builtEventsIndexes[timelineEvent.eventId] = correctedIndex
} }
@ -465,7 +467,7 @@ internal class TimelineChunk(private val chunkEntity: ChunkEntity,
val updatedEntity = results[modificationIndex] ?: continue val updatedEntity = results[modificationIndex] ?: continue
val displayIndex = builtEventsIndexes.getOrDefault(updatedEntity.eventId, null) val displayIndex = builtEventsIndexes.getOrDefault(updatedEntity.eventId, null)
if (displayIndex == 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 continue
} }
try { try {
@ -475,7 +477,6 @@ internal class TimelineChunk(private val chunkEntity: ChunkEntity,
} }
} }
} }
Timber.i("TimelineChunk.handleDatabaseChangeSet() end")
if (insertions.isNotEmpty() || modifications.isNotEmpty()) { if (insertions.isNotEmpty() || modifications.isNotEmpty()) {
onBuiltEvents(true) onBuiltEvents(true)
} }

View file

@ -65,7 +65,7 @@ internal class TokenChunkEventPersistor @Inject constructor(
direction: PaginationDirection): Result { direction: PaginationDirection): Result {
monarchy monarchy
.awaitTransaction { realm -> .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 nextToken: String?
val prevToken: String? val prevToken: String?