diff --git a/app/androidApp/src/main/kotlin/com/example/aiapp/CrashLog.kt b/app/androidApp/src/main/kotlin/com/example/aiapp/CrashLog.kt new file mode 100644 index 0000000..a174267 --- /dev/null +++ b/app/androidApp/src/main/kotlin/com/example/aiapp/CrashLog.kt @@ -0,0 +1,66 @@ +package com.example.aiapp + +import android.content.Context +import java.io.File +import java.io.PrintWriter +import java.io.StringWriter +import java.text.SimpleDateFormat +import java.util.Date +import java.util.Locale + +/** + * The last crash, kept so the debug button can hand it over. + * + * The alternative is asking somebody to reproduce a crash with the phone plugged into a computer + * and `logcat` running, which is the one thing nobody has set up at the moment it happens -- and a + * crash report that arrives a day later, without the stack, is a guess. This costs one file write + * on a process that is already dying, and it turns "it crashes when I open that chat" into the + * frame it crashed in. + * + * Kept until it is read rather than cleared on the next launch: the app restarts before anybody can + * ask about it, so a log that lives for one session is a log that is never read. + */ +private const val CRASH_FILE = "last-crash.txt" + +/** + * How much of a stack is kept. + * + * This is pasted into a conversation, so it has a budget like any other output written for a + * reader. The top of a stack is what identifies a crash and the bottom is framework plumbing, so + * what gets cut is the part nobody reads. + */ +private const val CRASH_LIMIT = 4000 + +/** + * Records uncaught exceptions, then lets the platform do what it was going to do. + * + * Chained rather than replacing: the default handler is what shows the "app has stopped" dialog and + * ends the process, and an app that swallows that instead sits there in an unknown state. This only + * adds a witness. + */ +fun installCrashLog(context: Context) { + val app = context.applicationContext + val previous = Thread.getDefaultUncaughtExceptionHandler() + Thread.setDefaultUncaughtExceptionHandler { thread, error -> + runCatching { File(app.filesDir, CRASH_FILE).writeText(describe(thread, error)) } + previous?.uncaughtException(thread, error) + } +} + +private fun describe(thread: Thread, error: Throwable): String { + val when_ = SimpleDateFormat("yyyy-MM-dd HH:mm:ss", Locale.US).format(Date()) + val stack = StringWriter().also { error.printStackTrace(PrintWriter(it)) }.toString() + val kept = + if (stack.length <= CRASH_LIMIT) stack + else stack.take(CRASH_LIMIT) + "\n ... ${stack.length - CRASH_LIMIT} more characters" + return "$when_ on thread ${thread.name}\n$kept" +} + +/** The last crash, or null if there has not been one since it was last read. */ +fun lastCrash(context: Context): String? = + File(context.applicationContext.filesDir, CRASH_FILE).takeIf { it.exists() }?.readText() + +/** Forgets the last crash, once somebody has taken a copy of it. */ +fun clearCrash(context: Context) { + File(context.applicationContext.filesDir, CRASH_FILE).delete() +} diff --git a/app/androidApp/src/main/kotlin/com/example/aiapp/DebugStats.kt b/app/androidApp/src/main/kotlin/com/example/aiapp/DebugStats.kt index 145b1a5..9e3b208 100644 --- a/app/androidApp/src/main/kotlin/com/example/aiapp/DebugStats.kt +++ b/app/androidApp/src/main/kotlin/com/example/aiapp/DebugStats.kt @@ -90,21 +90,32 @@ object DebugStats { * number -- a report whose reader has to ask what the columns mean costs another round trip, and * the whole point of it is to save one. */ -fun debugReport(device: String, transcript: List, frames: List): String = - buildString { - appendLine("ai-app render report") - appendLine(device) +fun debugReport( + device: String, + transcript: List, + frames: List, + crash: String?, +): String = buildString { + appendLine("ai-app render report") + appendLine(device) + appendLine() + // First, because a crash outranks every timing below it and the reader should not have to + // scroll past two screens of counters to find out the app fell over. + if (crash != null) { + appendLine("last crash:") + crash.trimEnd().lines().forEach { appendLine(" $it") } appendLine() - appendLine("transcript:") - transcript.forEach { appendLine(it) } - appendLine() - appendLine("frames:") - frames.forEach { appendLine(it) } - appendLine() - appendLine("work since this was last copied:") - val work = DebugStats.lines() - if (work.isEmpty()) appendLine(" nothing recorded") else work.forEach { appendLine(it) } } + appendLine("transcript:") + transcript.forEach { appendLine(it) } + appendLine() + appendLine("frames:") + frames.forEach { appendLine(it) } + appendLine() + appendLine("work since this was last copied:") + val work = DebugStats.lines() + if (work.isEmpty()) appendLine(" nothing recorded") else work.forEach { appendLine(it) } +} /** Puts [text] on the clipboard under [label], which is what the system offers as its name. */ fun Context.copyToClipboard(label: String, text: String) { diff --git a/app/androidApp/src/main/kotlin/com/example/aiapp/MainActivity.kt b/app/androidApp/src/main/kotlin/com/example/aiapp/MainActivity.kt index 2f8a037..fc86104 100644 --- a/app/androidApp/src/main/kotlin/com/example/aiapp/MainActivity.kt +++ b/app/androidApp/src/main/kotlin/com/example/aiapp/MainActivity.kt @@ -54,6 +54,9 @@ class MainActivity : ComponentActivity() { override fun onCreate(savedInstanceState: Bundle?) { super.onCreate(savedInstanceState) + // Before anything else that could throw, so the first crash of a launch is caught too. + installCrashLog(this) + // Transparent status bar on every version; the Surface below paints // through underneath it and content insets itself. Same reasoning // as dev-updater's MainActivity. diff --git a/app/androidApp/src/main/kotlin/com/example/aiapp/SessionScreen.kt b/app/androidApp/src/main/kotlin/com/example/aiapp/SessionScreen.kt index ea69f15..0b11494 100644 --- a/app/androidApp/src/main/kotlin/com/example/aiapp/SessionScreen.kt +++ b/app/androidApp/src/main/kotlin/com/example/aiapp/SessionScreen.kt @@ -2,6 +2,7 @@ package com.example.aiapp import android.os.Build import android.os.SystemClock +import android.util.Log import android.widget.Toast import androidx.activity.compose.rememberLauncherForActivityResult import androidx.activity.result.PickVisualMediaRequest @@ -1363,8 +1364,17 @@ fun SessionScreen(settings: ServerSettings, summary: SessionSummary, onBack: () " ${expandedGroups.size} groups open", ), frames = frames.lines(context.refreshHz()), + crash = lastCrash(context), ) context.copyToClipboard("ai-app render report", report) + // Also to the log, so a session driving the app over adb can read the + // same report the button copies. The clipboard is not reachable from a + // shell, and a counter nobody can check from here is a counter that only + // gets checked by asking Iris to press a button and paste. + Log.i("ai-app", report) + // Only once it is somewhere it can be read from, so a copy that never + // happened does not throw the stack away with it. + clearCrash(context) // Emptied by the copy, so pressing it twice measures two separate stretches // of scrolling rather than one and then the same one again. frames.reset() diff --git a/app/androidApp/src/main/kotlin/com/example/aiapp/TranscriptScroll.kt b/app/androidApp/src/main/kotlin/com/example/aiapp/TranscriptScroll.kt index 89b1d93..069221e 100644 --- a/app/androidApp/src/main/kotlin/com/example/aiapp/TranscriptScroll.kt +++ b/app/androidApp/src/main/kotlin/com/example/aiapp/TranscriptScroll.kt @@ -10,18 +10,17 @@ import androidx.compose.foundation.layout.Spacer import androidx.compose.foundation.layout.fillMaxWidth import androidx.compose.foundation.layout.height import androidx.compose.foundation.layout.padding -import androidx.compose.foundation.rememberScrollState import androidx.compose.foundation.verticalScroll import androidx.compose.runtime.Composable import androidx.compose.runtime.LaunchedEffect import androidx.compose.runtime.Stable import androidx.compose.runtime.getValue import androidx.compose.runtime.key -import androidx.compose.runtime.mutableIntStateOf import androidx.compose.runtime.mutableStateOf import androidx.compose.runtime.remember import androidx.compose.runtime.setValue import androidx.compose.runtime.snapshotFlow +import androidx.compose.runtime.snapshots.Snapshot import androidx.compose.runtime.withFrameNanos import androidx.compose.ui.Alignment import androidx.compose.ui.Modifier @@ -34,6 +33,7 @@ import androidx.compose.ui.layout.onPlaced import androidx.compose.ui.layout.onSizeChanged import androidx.compose.ui.platform.LocalDensity import androidx.compose.ui.platform.LocalLayoutDirection +import androidx.compose.ui.platform.LocalWindowInfo import androidx.compose.ui.unit.Dp import androidx.compose.ui.unit.dp @@ -91,18 +91,35 @@ class TranscriptScroll(internal val scroll: ScrollState) { private var rowIndex = HashMap() private var topsStale = true - /** How many rows the list is drawing, so the window notices one arriving. */ - var rowCount: Int by mutableIntStateOf(0) - private set - - internal fun laidOut(order: List, spacing: Int, padTop: Int) { + internal fun laidOut(order: List, spacing: Int, padTop: Int, screen: Int) { + // The window is a range of indices, and an index means nothing across a change to the + // order. A page of older history is *prepended*, so every row moves down by the size of the + // page and the window then names rows nowhere near the reader -- the transcript blanks + // until the next frame recomputes it, which is the flicker on loading history. Held by seq + // across the rebuild, the window still names the rows it named before. + val heldFirst = if (retained.isEmpty()) null else this.order.getOrNull(retained.first) + val heldLast = if (retained.isEmpty()) null else this.order.getOrNull(retained.last) + // Where the reader is, named by a row rather than by a pixel, because the pixels are about + // to be a layout out of date. A page of older history is added above the viewport, and the + // scroll container does not know it exists until it has measured it -- so `maxValue` still + // describes the shorter transcript, and a window computed from it is wrong by the whole + // height of the page that just arrived. Measured on the emulator as a blank frame on every + // page loaded. A row keeps its identity across the change; its offset does not. + val was = if (scroll.maxValue > 0) anchor() else null this.order = order - rowCount = order.size this.spacing = spacing this.padTop = padTop + this.screen = screen rowIndex = HashMap(order.size) order.forEachIndexed { index, seq -> rowIndex[seq] = index } topsStale = true + val first = heldFirst?.let { rowIndex[it] } + val last = heldLast?.let { rowIndex[it] } + retained = + if (first != null && last != null && first <= last) first..last else IntRange.EMPTY + // Whatever it was walking towards was named in the old indices too. + target = retained + growing = false // Something has to be built before the first frame, or the first frame is blank. The window // is worked out from the scroll position, and there is no scroll position until this has // been laid out once -- so on the composition that introduces the rows, every one of them @@ -110,9 +127,52 @@ class TranscriptScroll(internal val scroll: ScrollState) { // reader sees it flicker before the real window arrives a frame later. The newest end is // the right guess because that is where the transcript opens; [restore] seeds the other // case, where the reader is being put back somewhere else entirely. - if (retained.isEmpty() && order.isNotEmpty()) seedAround(order.lastIndex) + // Recomputed here, in the composition that introduces the rows, rather than a frame later + // when the snapshot of the scroll position next runs: a message arriving does not move the + // view, so there is nothing for the scroll flow to notice, and the frame that first draws + // the new row would draw a spacer where it goes -- a gap between the last message and the + // box it was typed in. + // + // Except before the scroll container has measured any content, where the position it + // reports is not a position. `maxValue` is zero then, which reads as the reader being at + // the oldest end of the conversation, and a window computed from it lands a whole + // transcript away from where the session is about to open. Measured on the emulator as one + // blank frame on every session opened. The newest end is the right guess there, because it + // is where a session opens; a restore overrides it in [restore], which knows better. + // + // The test is what the *scroll container* knows, not whether there was a window before. + // Those two come apart in the case that matters: a regroup during streaming can retire the + // rows the window was named after, and answering "no window, so seed the newest end" puts a + // reader who was up in the history back at rows they were nowhere near. + if (order.isEmpty()) return + // Only when the reader's position survived the change. If it did not -- the row they were + // looking at was folded into another by a regroup, which happens whenever a page boundary + // moves -- then the window is left exactly where the remap above put it, on the same rows + // by name. The tempting fallback, the scroll container's own pixels, is the one answer + // known to be wrong here: it is a layout out of date, by the height of the page that just + // arrived, and using it put the window a whole page away from the reader. + val at = was?.let { a -> rowHolding(a.seq)?.let { tops[it] + a.offset } } + if (at != null) trackRetained(at) + else if (scroll.maxValue == 0) { + DebugStats.count("window seeded at the newest end") + seedAround(order.lastIndex) + } } + /** The window's height, for the frames before the scroll container has measured one. */ + private var screen = 0 + + /** + * How tall to treat the visible area as. + * + * The scroll container's own measurement once there is one, and the window's height before + * that. There is a first composition in which rows exist and no layout has happened, and + * answering it with zero there builds a window of nothing -- so the transcript draws blank for + * a frame, which is the flicker when a session opens. + */ + private val visible: Int + get() = scroll.viewportSize.takeIf { it > 0 } ?: screen + /** * Builds a screenful of rows around [index], for the frames before there is a window. * @@ -123,7 +183,7 @@ class TranscriptScroll(internal val scroll: ScrollState) { */ private fun seedAround(index: Int) { if (order.isEmpty()) return - val budget = (scroll.viewportSize * SEED_SCREENS).coerceAtLeast(ROW_GUESS) + val budget = (visible * SEED_SCREENS).coerceAtLeast(ROW_GUESS) var first = index.coerceIn(0, order.lastIndex) var last = first var built = assumed(order[first]) @@ -133,7 +193,13 @@ class TranscriptScroll(internal val scroll: ScrollState) { if (last < order.lastIndex) built += assumed(order[++last]) if (built < budget && first > 0) built += assumed(order[--first]) } - retained = first..last + // In rows as well as in pixels, for the same reason the window is; see `trackRetained`. + // Nothing has been measured at all when this runs, so the pixel budget is being spent + // against a guess at every row's height. + retained = + (first - RETAIN_NOW_ROWS).coerceAtLeast(0)..(last + RETAIN_NOW_ROWS).coerceAtMost( + order.lastIndex + ) } internal fun height(seq: Long, height: Int) { @@ -246,6 +312,7 @@ class TranscriptScroll(internal val scroll: ScrollState) { val rowTop = topOf(anchor.seq) ?: return scroll.dispatchRawDelta((scroll.maxValue - rowTop - anchor.offset - scroll.value).toFloat()) pending = null + DebugStats.count("restored position applied") // The jump lands somewhere the window was not computed for, and this is the last chance // before the frame that draws. It cannot build anything by itself -- writing state during // placement only schedules a recomposition -- which is why [restore] seeds the destination @@ -253,6 +320,24 @@ class TranscriptScroll(internal val scroll: ScrollState) { trackRetained() } + /** + * The row that *holds* [seq], which is not always the row that starts with it. + * + * Rows are groups: a run of tool calls folds into one, two halves of a reply become one + * message, and which way they fold changes when a page boundary moves. So a seq recorded as a + * row's name a moment ago can be in the middle of a different row now, and a lookup by name + * alone answers null for a reader who has not gone anywhere. + */ + private fun rowHolding(seq: Long): Int? { + refreshTops() + var found: Int? = null + for ((index, start) in order.withIndex()) { + if (start > seq) break + found = index + } + return found + } + /** Where a row's top edge sits inside the content, or null if it has not been measured. */ private fun topOf(seq: Long): Int? { var y = padTop @@ -406,32 +491,57 @@ class TranscriptScroll(internal val scroll: ScrollState) { return growing } - internal fun trackRetained() { - // Before the comparison, not after it. Rows arriving is the case this exists to catch and - // it does not move the view: a message sent lands at the newest end, and if the range is - // not recomputed the new row is outside it and stands in as a spacer of its guessed height - // -- a screen of blank between the last message and the box it was typed in. The version - // it is compared against is only bumped by this call, so asking first meant never noticing. - refreshTops() - val viewportTop = scroll.maxValue - scroll.value - val step = (scroll.viewportSize * RETAIN_STEP_SCREENS).coerceAtLeast(1) - val moved = viewportTop - rangeAt - if (retained.isEmpty() || topsVersion != rangeVersion || moved > step || moved < -step) { - target = retainedRange(viewportTop, RETAIN_SCREENS) - // Whatever is on screen goes up in this frame whatever else happens -- amortising is - // for the margin that is being read *towards*, never for the part being looked at. - val visible = retainedRange(viewportTop, 1) - retained = - if (retained.isEmpty()) visible - else - minOf(retained.first, visible.first).coerceAtLeast(target.first)..maxOf( - retained.last, - visible.last, - ) - .coerceAtMost(target.last) - growing = retained != target + internal fun trackRetained(from: Int? = null) = + // Without subscribing whoever called it to the scroll position. This runs from the + // composition that lays the rows out as well as from the flow that watches scrolling, and + // a composition that reads `scroll.value` recomposes on every frame of every fling -- the + // O(rows)-per-frame mistake this whole file exists to undo, arriving by the back door. + Snapshot.withoutReadObservation { + refreshTops() + // [from] when the caller knows better than the scroll container does; see `laidOut`. + val viewportTop = from ?: (scroll.maxValue - scroll.value) + // The outer bound moves lazily, because every row reads the window and moving it + // recomposes all of them -- affordable every couple of screens, and not at every row + // boundary a fling crosses. + val step = (visible * RETAIN_STEP_SCREENS).coerceAtLeast(1) + val moved = viewportTop - rangeAt + if (target.isEmpty() || topsVersion != rangeVersion || moved > step || moved < -step) { + rangeAt = viewportTop + rangeVersion = topsVersion + target = retainedRange(viewportTop, RETAIN_SCREENS) + } + // What is near the screen, every frame rather than only when the bound moves. This is + // the half that cannot be lazy and the half that was: a fling crosses a screen in a + // frame or two, so a window last widened two screens ago has already been outrun and + // the row arriving at the edge is drawn as the spacer it still is. Standing rows up a + // few at a time made it worse rather than causing it -- after a seed or a restore the + // built window is a couple of screens wide and grows two rows a frame, which a fling + // beats easily. Cheap enough to do always: one scan of the row list, and the write + // below is skipped when the answer has not changed, so nothing recomposes. + // Widened by a fixed number of rows as well as by screens, because a screen is a + // number of pixels and the rows it covers are only *estimated* until they have been + // measured -- and nothing has been measured on the frame a session opens, which is + // where this matters. Rows shorter than the running average make a two-screen window + // cover fewer rows than the screen actually shows, and the reader sees the difference + // as blank. + val screens = retainedRange(viewportTop, RETAIN_NOW_SCREENS) + val near = + (screens.first - RETAIN_NOW_ROWS).coerceAtLeast(0)..(screens.last + RETAIN_NOW_ROWS) + .coerceAtMost(order.lastIndex) + val first = if (retained.isEmpty()) near.first else minOf(retained.first, near.first) + val last = if (retained.isEmpty()) near.last else maxOf(retained.last, near.last) + // Clamped to the bound, but never past what is on screen: the bound is allowed to be a + // couple of screens out of date and this is not. + val next = + minOf(first.coerceAtLeast(target.first), near.first)..maxOf( + last.coerceAtMost(target.last), + near.last, + ) + if (next != retained) { + retained = next + growing = retained != target + } } - } /** * Which rows stay built, as a range of indices rather than a test each row makes for itself. @@ -445,9 +555,9 @@ class TranscriptScroll(internal val scroll: ScrollState) { private fun retainedRange(viewportTop: Int, screens: Int): IntRange { refreshTops() if (order.isEmpty()) return IntRange.EMPTY - val margin = (scroll.viewportSize * screens).coerceAtLeast(1) + val margin = (visible * screens).coerceAtLeast(1) val from = viewportTop - margin - val to = viewportTop + scroll.viewportSize + margin + val to = viewportTop + visible + margin var first = -1 var last = -1 var nearest = 0 @@ -469,11 +579,46 @@ class TranscriptScroll(internal val scroll: ScrollState) { first = nearest last = nearest } - rangeAt = viewportTop - rangeVersion = topsVersion return first..last } + /** + * Whether what is on screen is actually built, asked at the moment of drawing. + * + * This is the flicker, made countable. Every way the window can be stale looks the same to a + * reader -- a band of blank where a message should be, for one frame -- and "it still flickers + * sometimes" is not something a fix can be tested against. Drawing is the one place that knows + * both what is being shown and what was built, so the check belongs here even though the state + * is not this function's own. + * + * O(rows), which is affordable only because it runs when the transcript is *recorded* rather + * than when it is placed -- measured on a Pixel 9 Pro XL as 48 times in 42 seconds of reading, + * against 2204 placements. Without read observation, or asking the question would make the + * answer wrong: a scroll position read while drawing invalidates that drawing every frame. + */ + internal fun covered(): Boolean = Snapshot.withoutReadObservation { + if (order.isEmpty()) return@withoutReadObservation true + refreshTops() + val onScreen = retainedRange(scroll.maxValue - scroll.value, 0) + // Which way it fell short, and by how much, so a failure that survives this says what it + // is rather than only that it happened. + if (onScreen.first < retained.first) + DebugStats.atLeast( + "window short above, rows", + (retained.first - onScreen.first).toLong(), + ) + if (onScreen.last > retained.last) + DebugStats.atLeast("window short below, rows", (onScreen.last - retained.last).toLong()) + if (onScreen.first >= retained.first && onScreen.last <= retained.last) + return@withoutReadObservation true + // Repaired as well as reported. This cannot rescue the frame being drawn -- building a row + // needs a composition and that is the next frame at the earliest -- but it bounds the + // damage to one frame however the window got stale, including the ways not yet found. The + // paths that are known are fixed at their causes; this is what stands behind them. + retained = minOf(retained.first, onScreen.first)..maxOf(retained.last, onScreen.last) + false + } + private var rangeAt = Int.MIN_VALUE private var rangeVersion = -1 private var topsVersion = 0 @@ -514,6 +659,7 @@ class TranscriptScroll(internal val scroll: ScrollState) { // so the rows it would build arrive a frame after the frame that ungates drawing, and the // reader is shown the place they were put back to as blank spacer before it fills in. // Seeded here it is built by the composition that the jump is measured in. + DebugStats.count("window seeded around a restored position") rowIndex[anchor.seq]?.let { seedAround(it) } } @@ -536,7 +682,10 @@ class TranscriptScroll(internal val scroll: ScrollState) { @Composable fun rememberTranscriptScroll(key: Any?): TranscriptScroll { - val scroll = rememberScrollState() + // Keyed like the state that wraps it. `rememberScrollState()` is not, so a second session + // opened without leaving the screen would inherit the first one's offset -- and, worse for the + // window, its `maxValue`, which is the number everything here decides from. + val scroll = remember(key) { ScrollState(0) } return remember(key) { TranscriptScroll(scroll) } } @@ -562,20 +711,23 @@ fun TranscriptColumn( val layoutDirection = LocalLayoutDirection.current // The order and the gaps, so a row's position can be added up from heights when one is wanted. // Recomputed only when the rows change, which is what keeps every frame free of it. - remember(rows, spacing, contentPadding, density) { + // The window's own height, for the frames before the scroll container has measured one; see + // [TranscriptScroll.visible]. + val screen = LocalWindowInfo.current.containerSize.height + remember(rows, spacing, contentPadding, density, screen) { state.laidOut( rows.map { it.startSeq }, with(density) { spacing.roundToPx() }, with(density) { contentPadding.calculateTopPadding().roundToPx() }, + screen, ) layoutDirection } // One evaluation of the window a frame, for the whole list; see [TranscriptScroll.retained]. - // The row count is in here because a row arriving is the one case that does not move the view: - // without it a sent message falls outside the window and stands in as a spacer, which is a - // screen of blank between the last message and the box it was typed in. + // Scrolling only -- rows arriving is handled by `laidOut` above, in the composition that + // introduces them, because a frame later is a frame with a spacer where the new row goes. LaunchedEffect(state) { - snapshotFlow { Triple(state.scroll.value, state.scroll.maxValue, state.rowCount) } + snapshotFlow { state.scroll.value to state.scroll.maxValue } .collect { state.trackRetained() } } // Walks the window towards its target a few rows a frame; see [TranscriptScroll.standUpSome]. @@ -622,6 +774,16 @@ fun TranscriptColumn( val placing = System.nanoTime() // From the bottom, because that is the end the conversation hangs from. placeable.place(0, height - placeable.height) + // Here, because this is the moment both halves of the question are current: + // the rows have just been measured, so their heights are this layout's, and + // the scroll container has just been measured, so its position is too. Every + // other place it was called from could be right about one and stale about the + // other -- a row growing when it is finally built moves every position after + // it and moves nothing the scroll flow can see, so a window last worked out + // from a scroll no longer describes the rows it names. It writes only when the + // answer changes, so a frame where nothing moved costs one scan and no + // recomposition. + state.trackRetained() DebugStats.record("place: the whole transcript", System.nanoTime() - placing) } } @@ -639,6 +801,8 @@ fun TranscriptColumn( val started = System.nanoTime() drawContent() DebugStats.record("draw: the whole transcript", System.nanoTime() - started) + // The flicker, counted rather than described; see [TranscriptScroll.covered]. + if (!state.covered()) DebugStats.count("drew a row that was not built") } .pointerInput(Unit) { awaitEachGesture { @@ -731,9 +895,20 @@ private fun RetainedRow( /** How far either side of the screen a row stays built; see [TranscriptScroll.retains]. */ private const val RETAIN_SCREENS = 8 -/** How far the view moves before the retained range is worked out again; see `trackRetained`. */ +/** How far the view moves before the outer bound is worked out again; see `trackRetained`. */ private const val RETAIN_STEP_SCREENS = 2 +/** + * How much either side of the screen is built at once rather than a few rows at a time. + * + * Has to exceed what a fling covers between two of those recomputations, or the reader reaches a + * row before it has been built. Two screens, against a bound that moves every two. + */ +private const val RETAIN_NOW_SCREENS = 2 + +/** The same margin counted in rows, for when no height is known yet; see `trackRetained`. */ +private const val RETAIN_NOW_ROWS = 6 + /** * How many rows may be laid out in one frame while the window is catching up; see `standUpSome`. */ diff --git a/app/trace-draw.sh b/app/trace-draw.sh new file mode 100755 index 0000000..248b347 --- /dev/null +++ b/app/trace-draw.sh @@ -0,0 +1,129 @@ +#!/usr/bin/env bash +# What a scrolling frame is actually spending its time in, by name. +# +# The app's own counters can time the code we wrote, and they showed that almost none of the frame +# is that code -- roughly a fortieth of the draw phase. The rest is inside the framework, which +# already brackets its own work with trace sections (measure, layout, draw, the position-callback +# dispatch, the per-node rect bookkeeping, semantics). This turns those on, drives a fling, and adds +# up what each section cost, so "the other eighty percent" gets a name instead of a hypothesis. +# +# atrace's text output rather than perfetto's protobuf on purpose: this needs no trace_processor +# build, and the question here is which sections dominate, which the text format answers directly. +# +# The absolute milliseconds from an emulator are worthless -- it renders in software, and its stock +# apps miss frames as badly as ours do. The *ranking* is what transfers, which is what this prints. +set -euo pipefail + +app=com.example.aiapp +secs=6 +swipes=12 +out=/tmp/ai-app-trace.txt +top=25 +# Empty means whatever `adb` picks by itself, which in this checkout is its own emulator. A phone +# needs naming, and a phone is the only place these numbers mean anything -- see the note at the +# foot of this file. +serial=() + +while [ $# -gt 0 ]; do + case "$1" in + -t) secs=$2; shift 2 ;; + -n) swipes=$2; shift 2 ;; + -o) out=$2; shift 2 ;; + --top) top=$2; shift 2 ;; + -s) serial=(-s "$2"); shift 2 ;; + -h|--help) + echo "usage: $0 [-s serial] [-t seconds] [-n swipes] [-o file] [--top n]" + exit 0 ;; + *) echo "$0: unknown argument $1" >&2; exit 2 ;; + esac +done + +if ! adb "${serial[@]}" shell pidof "$app" >/dev/null 2>&1; then + echo "$0: $app is not running -- open a session in it first" >&2 + exit 1 +fi +pid=$(adb "${serial[@]}" shell pidof "$app" | tr -d '\r') + +# `view` carries Compose's measure/layout/draw and the View system's own; `gfx` carries the render +# thread and the frame boundaries. Buffer sized for a few seconds of a busy main thread: a fling +# emits a great many sections and a full buffer silently drops the end of the trace. +# +# A blocking capture with the gestures alongside it, rather than atrace's own --async_start / +# --async_dump pair: measured on this emulator, the asynchronous form returns a buffer of +# `entries-in-buffer: 0/0` however long it runs, and an empty trace reads exactly like an app that +# emitted no sections. Blocking, the same categories fill it immediately. +# +# `-a` is the flag the whole thing turns on. Without it atrace records only what the system emits, +# and every section Compose writes -- measure, layout, recomposition -- comes from `android.os.Trace` +# inside the app process, which stays switched off. The result looks like a successful capture and +# answers the question with the framework's half of the frame, which is not the half being asked +# about. +adb "${serial[@]}" shell atrace -a "$app" -b 65536 -t "$secs" -c view gfx input 2>/dev/null | tr -d '\r' >"$out" & +capture=$! + +for _ in $(seq "$swipes"); do + adb "${serial[@]}" shell input swipe 540 1800 540 700 80 >/dev/null 2>&1 +done +wait "$capture" + +if ! grep -q tracing_mark_write "$out"; then + echo "$0: the trace holds no sections; another capture may hold the ftrace buffer" >&2 + exit 1 +fi + +python3 - "$out" "$pid" "$top" <<'PY' +import collections, re, sys + +path, pid, top = sys.argv[1], sys.argv[2], int(sys.argv[3]) +# ftrace text: "- () [cpu] flags : tracing_mark_write: B||" +mark = re.compile(r"^\s*\S+-(\d+)\s+\(\s*(\d+|-+)\)[^:]*?\s+(\d+\.\d+):\s+tracing_mark_write:\s+(.*)$") +stacks = collections.defaultdict(list) +total = collections.Counter() +count = collections.Counter() +worst = collections.Counter() +frames = 0 + +for line in open(path, errors="replace"): + m = mark.match(line) + if not m: + continue + tid, owner, ts, body = m.group(1), m.group(2), float(m.group(3)), m.group(4) + parts = body.split("|") + if parts[0] == "B" and len(parts) >= 3: + if parts[1] != pid: + continue + stacks[tid].append((parts[2], ts)) + elif parts[0] == "E": + if not stacks[tid]: + continue + name, began = stacks[tid].pop() + ms = (ts - began) * 1000.0 + total[name] += ms + count[name] += 1 + worst[name] = max(worst[name], ms) + if name.startswith("Choreographer#doFrame"): + frames += 1 + +if not total: + print("no sections for pid " + pid + " -- was the app in the foreground?") + raise SystemExit(1) + +print(f"{frames} frames traced, {sum(count.values())} sections") +print() +print(f"{'section':<44}{'calls':>7}{'total ms':>10}{'mean':>8}{'worst':>8}") +for name, ms in total.most_common(top): + n = count[name] + label = name if len(name) <= 43 else name[:40] + "..." + print(f"{label:<44}{n:>7}{ms:>10.1f}{ms/n:>8.2f}{worst[name]:>8.1f}") +left = len(total) - top +if left > 0: + print(f"... {left} more sections not shown (--top to raise the limit)") +PY + +# A note on where to run this. +# +# Not here. Measured on this checkout's emulator, a scrolling frame is 15ms of `Drawing` of which +# 10ms is `dequeueBuffer` and `postAndWait` -- the main thread blocked on the buffer queue, because +# the emulator renders in software -- while Compose's own `AndroidOwner:draw` is 0.40ms. The +# ranking that comes out is the ranking of the emulator's graphics stack, and it says nothing about +# a phone whose whole draw phase is 3.6ms. Point it at the device the numbers came from.