Adds logging message to hunt down some slow screens

2025-04-23 17:15:21 -04:00
parent ca8faa062f
commit 802e04445d
9 changed files with 126 additions and 109 deletions
@@ -27,6 +27,7 @@ import android.os.Debug
 import android.util.Log
 import androidx.core.content.getSystemService
 import com.vitorpamplona.amethyst.model.LocalCache
+import kotlin.time.DurationUnit
 import kotlin.time.measureTimedValue

 val isDebug = BuildConfig.DEBUG || BuildConfig.BUILD_TYPE == "benchmark"
@@ -151,19 +152,19 @@ inline fun <T> logTime(
 ): T =
    if (isDebug) {
        val (result, elapsed) = measureTimedValue(block)
-        Log.d("DEBUG-TIME", "$elapsed: $debugMessage")
+        Log.d("DEBUG-TIME", "${elapsed.toString(DurationUnit.MILLISECONDS, 3).padStart(12)}: $debugMessage")
        result
    } else {
        block()
    }

 inline fun <T> logTime(
-    debugMessage: (T) -> Unit,
+    debugMessage: (T) -> String,
    block: () -> T,
 ): T =
    if (isDebug) {
        val (result, elapsed) = measureTimedValue(block)
-        Log.d("DEBUG-TIME", "$elapsed: ${debugMessage(result)}")
+        Log.d("DEBUG-TIME", "${elapsed.toString(DurationUnit.MILLISECONDS, 3).padStart(12)}: ${debugMessage(result)}")
        result
    } else {
        block()
@@ -20,7 +20,7 @@
 */
 package com.vitorpamplona.amethyst.ui.dal

-import kotlin.time.measureTimedValue
+import com.vitorpamplona.amethyst.logTime

 abstract class AdditiveFeedFilter<T> : FeedFilter<T>() {
    abstract fun applyFilter(collection: Set<T>): Set<T>
@@ -30,20 +30,16 @@ abstract class AdditiveFeedFilter<T> : FeedFilter<T>() {
    open fun updateListWith(
        oldList: List<T>,
        newItems: Set<T>,
-    ): List<T> {
-        val (feed, elapsed) =
-            measureTimedValue {
-                val newItemsToBeAdded = applyFilter(newItems)
-                if (newItemsToBeAdded.isNotEmpty()) {
-                    val newList = oldList.toSet() + newItemsToBeAdded
-                    sort(newList).take(limit())
-                } else {
-                    oldList
-                }
+    ): List<T> =
+        logTime(
+            debugMessage = { "${this.javaClass.simpleName} AdditiveFeedFilter updating ${newItems.size} new items to ${it.size} items" },
+        ) {
+            val newItemsToBeAdded = applyFilter(newItems)
+            if (newItemsToBeAdded.isNotEmpty()) {
+                val newList = oldList.toSet() + newItemsToBeAdded
+                sort(newList).take(limit())
+            } else {
+                oldList
            }
-
-        // Log.d("Time", "${this.javaClass.simpleName} Additive Feed in $elapsed with ${feed.size}
-        // objects")
-        return feed
-    }
+        }
 }
@@ -20,14 +20,15 @@
 */
 package com.vitorpamplona.amethyst.ui.dal

-import android.util.Log
-import kotlin.time.measureTimedValue
+import com.vitorpamplona.amethyst.logTime

 abstract class FeedFilter<T> {
    fun loadTop(): List<T> {
-        val (feed, elapsed) = measureTimedValue { feed() }
-
-        Log.d("Time", "${this.javaClass.simpleName} Full Feed in $elapsed with ${feed.size} objects")
+        val feed =
+            logTime(
+                debugMessage = { "${this.javaClass.simpleName} FeedFilter returning ${it.size} objects" },
+                block = ::feed,
+            )
        return feed.take(limit())
    }

@@ -55,6 +55,7 @@ import androidx.lifecycle.map
 import com.vitorpamplona.amethyst.Amethyst
 import com.vitorpamplona.amethyst.R
 import com.vitorpamplona.amethyst.commons.compose.produceCachedStateAsync
+import com.vitorpamplona.amethyst.logTime
 import com.vitorpamplona.amethyst.model.AddressableNote
 import com.vitorpamplona.amethyst.model.Channel
 import com.vitorpamplona.amethyst.model.FeatureSetType
@@ -223,33 +224,37 @@ fun NoteCompose(
    accountViewModel: AccountViewModel,
    nav: INav,
 ) {
-    WatchNoteEvent(
-        baseNote = baseNote,
-        accountViewModel = accountViewModel,
-        modifier,
+    logTime(
+        debugMessage = { "NoteCompose " + externalLinkForNote(baseNote) },
    ) {
-        CheckHiddenFeedWatchBlockAndReport(
-            note = baseNote,
-            modifier = modifier,
-            ignoreAllBlocksAndReports = isHiddenFeed,
-            showHiddenWarning = isQuotedNote || isBoostedNote,
+        WatchNoteEvent(
+            baseNote = baseNote,
            accountViewModel = accountViewModel,
-            nav = nav,
-        ) { canPreview ->
-            AcceptableNote(
-                baseNote = baseNote,
+            modifier,
+        ) {
+            CheckHiddenFeedWatchBlockAndReport(
+                note = baseNote,
                modifier = modifier,
-                routeForLastRead = routeForLastRead,
-                isBoostedNote = isBoostedNote,
-                isQuotedNote = isQuotedNote,
-                unPackReply = unPackReply,
-                makeItShort = makeItShort,
-                canPreview = canPreview,
-                quotesLeft = quotesLeft,
-                parentBackgroundColor = parentBackgroundColor,
+                ignoreAllBlocksAndReports = isHiddenFeed,
+                showHiddenWarning = isQuotedNote || isBoostedNote,
                accountViewModel = accountViewModel,
                nav = nav,
-            )
+            ) { canPreview ->
+                AcceptableNote(
+                    baseNote = baseNote,
+                    modifier = modifier,
+                    routeForLastRead = routeForLastRead,
+                    isBoostedNote = isBoostedNote,
+                    isQuotedNote = isQuotedNote,
+                    unPackReply = unPackReply,
+                    makeItShort = makeItShort,
+                    canPreview = canPreview,
+                    quotesLeft = quotesLeft,
+                    parentBackgroundColor = parentBackgroundColor,
+                    accountViewModel = accountViewModel,
+                    nav = nav,
+                )
+            }
        }
    }
 }
@@ -40,6 +40,8 @@ import com.vitorpamplona.amethyst.R
 import com.vitorpamplona.amethyst.collectSuccessfulOperations
 import com.vitorpamplona.amethyst.commons.compose.GenericBaseCache
 import com.vitorpamplona.amethyst.commons.compose.GenericBaseCacheAsync
+import com.vitorpamplona.amethyst.isDebug
+import com.vitorpamplona.amethyst.logTime
 import com.vitorpamplona.amethyst.model.Account
 import com.vitorpamplona.amethyst.model.AccountSettings
 import com.vitorpamplona.amethyst.model.AddressableNote
@@ -1339,13 +1341,17 @@ class AccountViewModel(
                feedStates.init()
                // awaits for init to finish before starting to capture new events.
                LocalCache.live.newEventBundles.collect { newNotes ->
-                    Log.d(
-                        "Rendering Metrics",
-                        "Update feeds ${this@AccountViewModel} for ${account.userProfile().toBestDisplayName()} with ${newNotes.size} new notes",
-                    )
-                    feedStates.updateFeedsWith(newNotes)
-                    upgradeAttestations()
-                    precomputeNewEvents(newNotes)
+                    if (isDebug) {
+                        Log.d(
+                            "Rendering Metrics",
+                            "Update feeds ${this@AccountViewModel} for ${account.userProfile().toBestDisplayName()} with ${newNotes.size} new notes",
+                        )
+                    }
+                    logTime("AccountViewModel newEventBundle Update with ${newNotes.size} new notes") {
+                        feedStates.updateFeedsWith(newNotes)
+                        upgradeAttestations()
+                        precomputeNewEvents(newNotes)
+                    }
                }
            }
    }
@@ -42,6 +42,7 @@ import androidx.compose.ui.Alignment.Companion.CenterStart
 import androidx.compose.ui.Modifier
 import androidx.compose.ui.graphics.Color
 import androidx.compose.ui.unit.dp
+import com.vitorpamplona.amethyst.logTime
 import com.vitorpamplona.amethyst.model.FeatureSetType
 import com.vitorpamplona.amethyst.model.Note
 import com.vitorpamplona.amethyst.ui.navigation.INav
@@ -59,6 +60,7 @@ import com.vitorpamplona.amethyst.ui.note.ZapReaction
 import com.vitorpamplona.amethyst.ui.note.creators.zapsplits.DisplayZapSplits
 import com.vitorpamplona.amethyst.ui.note.elements.DisplayLocation
 import com.vitorpamplona.amethyst.ui.note.elements.DisplayPoW
+import com.vitorpamplona.amethyst.ui.note.externalLinkForNote
 import com.vitorpamplona.amethyst.ui.screen.loggedIn.AccountViewModel
 import com.vitorpamplona.amethyst.ui.screen.loggedIn.chats.feed.layouts.ChatBubbleLayout
 import com.vitorpamplona.amethyst.ui.screen.loggedIn.chats.feed.types.RenderChangeChannelMetadataNote
@@ -97,25 +99,29 @@ fun ChatroomMessageCompose(
    onWantsToReply: (Note) -> Unit,
    onWantsToEditDraft: (Note) -> Unit,
 ) {
-    WatchNoteEvent(baseNote = baseNote, accountViewModel = accountViewModel) {
-        WatchBlockAndReport(
-            note = baseNote,
-            showHiddenWarning = false,
-            modifier = Modifier.fillMaxWidth(),
-            accountViewModel = accountViewModel,
-            nav = nav,
-        ) { canPreview ->
-            NormalChatNote(
-                baseNote,
-                routeForLastRead,
-                innerQuote,
-                canPreview,
-                parentBackgroundColor,
-                accountViewModel,
-                nav,
-                onWantsToReply,
-                onWantsToEditDraft,
-            )
+    logTime(
+        debugMessage = { "ChatroomMessageCompose " + externalLinkForNote(baseNote) },
+    ) {
+        WatchNoteEvent(baseNote = baseNote, accountViewModel = accountViewModel) {
+            WatchBlockAndReport(
+                note = baseNote,
+                showHiddenWarning = false,
+                modifier = Modifier.fillMaxWidth(),
+                accountViewModel = accountViewModel,
+                nav = nav,
+            ) { canPreview ->
+                NormalChatNote(
+                    baseNote,
+                    routeForLastRead,
+                    innerQuote,
+                    canPreview,
+                    parentBackgroundColor,
+                    accountViewModel,
+                    nav,
+                    onWantsToReply,
+                    onWantsToEditDraft,
+                )
+            }
        }
    }
 }
@@ -53,6 +53,7 @@ import androidx.compose.ui.unit.dp
 import androidx.compose.ui.unit.sp
 import androidx.lifecycle.compose.collectAsStateWithLifecycle
 import com.vitorpamplona.amethyst.R
+import com.vitorpamplona.amethyst.logTime
 import com.vitorpamplona.amethyst.model.Channel
 import com.vitorpamplona.amethyst.model.FeatureSetType
 import com.vitorpamplona.amethyst.model.Note
@@ -70,6 +71,8 @@ import com.vitorpamplona.amethyst.ui.note.LoadChannel
 import com.vitorpamplona.amethyst.ui.note.LoadDecryptedContentOrNull
 import com.vitorpamplona.amethyst.ui.note.NonClickableUserPictures
 import com.vitorpamplona.amethyst.ui.note.ObserveDraftEvent
+import com.vitorpamplona.amethyst.ui.note.elements.TimeAgo
+import com.vitorpamplona.amethyst.ui.note.externalLinkForNote
 import com.vitorpamplona.amethyst.ui.note.timeAgo
 import com.vitorpamplona.amethyst.ui.screen.loggedIn.AccountViewModel
 import com.vitorpamplona.amethyst.ui.screen.loggedIn.chats.privateDM.header.RoomNameDisplay
@@ -91,14 +94,18 @@ fun ChatroomHeaderCompose(
    accountViewModel: AccountViewModel,
    nav: INav,
 ) {
-    if (baseNote.event != null) {
-        ChatroomComposeChannelOrUser(baseNote, accountViewModel, nav)
-    } else {
-        val hasEvent by observeNoteHasEvent(baseNote)
-        if (hasEvent) {
+    logTime(
+        debugMessage = { "ChatroomHeaderCompose " + externalLinkForNote(baseNote) },
+    ) {
+        if (baseNote.event != null) {
            ChatroomComposeChannelOrUser(baseNote, accountViewModel, nav)
        } else {
-            BlankNote()
+            val hasEvent by observeNoteHasEvent(baseNote)
+            if (hasEvent) {
+                ChatroomComposeChannelOrUser(baseNote, accountViewModel, nav)
+            } else {
+                BlankNote()
+            }
        }
    }
 }
@@ -25,6 +25,7 @@ import androidx.compose.runtime.Immutable
 import androidx.compose.runtime.MutableState
 import androidx.compose.runtime.Stable
 import androidx.compose.runtime.mutableStateOf
+import com.vitorpamplona.amethyst.logTime
 import com.vitorpamplona.amethyst.model.Account
 import com.vitorpamplona.amethyst.model.LocalCache
 import com.vitorpamplona.amethyst.model.Note
@@ -57,7 +58,6 @@ import kotlinx.coroutines.launch
 import java.time.Instant
 import java.time.ZoneId
 import java.time.format.DateTimeFormatter
-import kotlin.time.measureTimedValue

@Stable
 class CardFeedContentState(
@@ -363,8 +363,7 @@ class CardFeedContentState(
        bundler.invalidate(ignoreIfDoing) {
            // adds the time to perform the refresh into this delay
            // holding off new updates in case of heavy refresh routines.
-            val (value, elapsed) = measureTimedValue { refreshSuspended() }
-            Log.d("Time", "${this.javaClass.simpleName} Card update $elapsed")
+            logTime("${this.javaClass.simpleName} Card update") { refreshSuspended() }
        }
    }

@@ -373,12 +372,10 @@ class CardFeedContentState(
        bundler.invalidate(ignoreIfDoing) {
            // adds the time to perform the refresh into this delay
            // holding off new updates in case of heavy refresh routines.
-            val (value, elapsed) =
-                measureTimedValue {
-                    refreshSuspended()
-                    sendToTop()
-                }
-            Log.d("Time", "${this.javaClass.simpleName} Card update $elapsed")
+            logTime("${this.javaClass.simpleName} Card update") {
+                refreshSuspended()
+                sendToTop()
+            }
        }
    }

@@ -388,12 +385,10 @@ class CardFeedContentState(
            bundler.invalidate(false) {
                // adds the time to perform the refresh into this delay
                // holding off new updates in case of heavy refresh routines.
-                val (value, elapsed) =
-                    measureTimedValue {
-                        refreshSuspended()
-                        sendToTop()
-                    }
-                Log.d("Time", "${this.javaClass.simpleName} Card update $elapsed")
+                logTime("${this.javaClass.simpleName} Card update: checkKeysInvalidateDataAndSendToTop") {
+                    refreshSuspended()
+                    sendToTop()
+                }
            }
        }
    }
@@ -401,16 +396,11 @@ class CardFeedContentState(
    fun invalidateInsertData(newItems: Set<Note>) {
        bundlerInsert.invalidateList(newItems) {
            val newObjects = it.flatten().toSet()
-            val (value, elapsed) =
-                measureTimedValue {
-                    if (newObjects.isNotEmpty()) {
-                        refreshFromOldState(newObjects)
-                    }
+            logTime("${this.javaClass.simpleName} Card additive receiving ${newObjects.size} items into ${it.size} items") {
+                if (newObjects.isNotEmpty()) {
+                    refreshFromOldState(newObjects)
                }
-            Log.d(
-                "Time",
-                "${this.javaClass.simpleName} Card additive update $elapsed. ${newObjects.size}",
-            )
+            }
        }
    }

@@ -44,6 +44,7 @@ import androidx.compose.ui.graphics.Color
 import androidx.lifecycle.compose.collectAsStateWithLifecycle
 import com.vitorpamplona.amethyst.BuildConfig
 import com.vitorpamplona.amethyst.R
+import com.vitorpamplona.amethyst.logTime
 import com.vitorpamplona.amethyst.ui.actions.CrossfadeIfEnabled
 import com.vitorpamplona.amethyst.ui.components.LoadNote
 import com.vitorpamplona.amethyst.ui.feeds.FeedError
@@ -176,13 +177,17 @@ private fun FeedLoaded(
            contentType = { _, item -> item.javaClass.simpleName },
        ) { _, item ->
            Row(Modifier.fillMaxWidth().animateItemPlacement()) {
-                RenderCardItem(
-                    item,
-                    routeForLastRead,
-                    showHidden = items.showHidden,
-                    accountViewModel,
-                    nav,
-                )
+                logTime(
+                    debugMessage = { "CardFeedView $item" },
+                ) {
+                    RenderCardItem(
+                        item,
+                        routeForLastRead,
+                        showHidden = items.showHidden,
+                        accountViewModel,
+                        nav,
+                    )
+                }
            }
            HorizontalDivider(
                thickness = DividerThickness,