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 9e3b208..dcc85ea 100644 --- a/app/androidApp/src/main/kotlin/com/example/aiapp/DebugStats.kt +++ b/app/androidApp/src/main/kotlin/com/example/aiapp/DebugStats.kt @@ -79,9 +79,44 @@ object DebugStats { " ${ms(worst[name]?.get() ?: 0)}ms worst" } + /** How long everything named [name] took in total, or zero if it never happened. */ + fun nanosOf(name: String): Long = nanos[name]?.get() ?: 0 + private fun ms(nanos: Long) = "%.1f".format(nanos / 1_000_000.0) } +/** + * How much of the frame's draw phase is this app's own work, and how much is not. + * + * The draw phase is where Compose's measurement lands as well as its recording -- the platform + * calls `measureAndLayout()` from `dispatchDraw` -- so "draw is high" has never said which of three + * different things is high. The transcript times its own measure, its own placement and its own + * recording, and this is the subtraction that was otherwise done by hand in a conversation every + * time a report arrived. What is left over is the framework's per-frame bookkeeping after a layout, + * which grows with how many nodes are alive rather than with how many are on screen. + * + * Per frame rather than in total, because the budget it has to fit in is per frame. The recordings + * are not themselves per-frame -- a measurement happens on the frames that need one -- so these are + * shares of an average frame, not a claim about any particular one. + */ +fun drawAccounting(drawNanos: Long, frames: Int): List { + if (frames == 0 || drawNanos == 0L) return emptyList() + val measure = DebugStats.nanosOf("measure: the whole transcript") + val place = DebugStats.nanosOf("place: the whole transcript") + // The rows and blocks record *inside* this one, so adding them too would count them twice. + val record = DebugStats.nanosOf("draw: the whole transcript") + val ours = measure + place + record + val rest = (drawNanos - ours).coerceAtLeast(0) + fun per(n: Long) = "%.2f".format(n / 1_000_000.0 / frames) + return listOf( + " draw phase ${per(drawNanos)}ms per frame, of which:", + " the transcript: ${per(ours)}ms" + + " (measure ${per(measure)}, place ${per(place)}, record ${per(record)})", + " everything else: ${per(rest)}ms" + + " (${if (drawNanos == 0L) "n/a" else "${rest * 100 / drawNanos}%"})", + ) +} + /** * Everything the debug button copies: what the device is, what the transcript is holding, where the * frames went, and what the app did to produce them. @@ -94,6 +129,7 @@ fun debugReport( device: String, transcript: List, frames: List, + accounting: List, crash: String?, ): String = buildString { appendLine("ai-app render report") @@ -112,6 +148,11 @@ fun debugReport( appendLine("frames:") frames.forEach { appendLine(it) } appendLine() + if (accounting.isNotEmpty()) { + appendLine("where the draw phase went:") + accounting.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) } diff --git a/app/androidApp/src/main/kotlin/com/example/aiapp/FrameStats.kt b/app/androidApp/src/main/kotlin/com/example/aiapp/FrameStats.kt index f2c3217..b6dd8b3 100644 --- a/app/androidApp/src/main/kotlin/com/example/aiapp/FrameStats.kt +++ b/app/androidApp/src/main/kotlin/com/example/aiapp/FrameStats.kt @@ -93,6 +93,9 @@ class FrameStats { ) + if (gpu.isEmpty()) emptyList() else listOf(phase("gpu ", gpu)) } + /** How long the frames recorded here spent in their draw phase, and how many there were. */ + @Synchronized fun drawPhase(): Pair = draw.sum() to draw.size + private fun phase(name: String, samples: List): String { val sorted = samples.sorted() return " $name p50 ${at(sorted, 50)} p90 ${at(sorted, 90)} p99 ${at(sorted, 99)}" 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 0b11494..7744b44 100644 --- a/app/androidApp/src/main/kotlin/com/example/aiapp/SessionScreen.kt +++ b/app/androidApp/src/main/kotlin/com/example/aiapp/SessionScreen.kt @@ -1364,6 +1364,10 @@ fun SessionScreen(settings: ServerSettings, summary: SessionSummary, onBack: () " ${expandedGroups.size} groups open", ), frames = frames.lines(context.refreshHz()), + accounting = + frames.drawPhase().let { (nanos, count) -> + drawAccounting(nanos, count) + }, crash = lastCrash(context), ) context.copyToClipboard("ai-app render report", report) 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 fcc4da2..cc1cacc 100644 --- a/app/androidApp/src/main/kotlin/com/example/aiapp/TranscriptScroll.kt +++ b/app/androidApp/src/main/kotlin/com/example/aiapp/TranscriptScroll.kt @@ -152,10 +152,24 @@ class TranscriptScroll(internal val scroll: ScrollState) { // 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) + when { + // The reader's position survived the change, so the window follows it. + at != null -> trackRetained(at) + // It did not, but the window was remapped by name above and still names rows the + // reader was near. That is the better answer than anything the scroll container can + // offer, whose numbers are a layout out of date by the height of whatever just + // arrived. + !retained.isEmpty() -> DebugStats.count("laid out with a lost position") + // Nothing to go on at all -- there were no rows before this. A session opens at its + // newest end, so that is where to build. This branch used to do nothing, on the + // reasoning that a measured scroll position meant there was a position to trust; a + // scroll container that has measured a *different* session still reports one, so the + // window was left empty, the whole transcript composed as a single spacer, and the + // first frame of every session opened was blank. + else -> { + DebugStats.count("window seeded at the newest end") + seedAround(order.lastIndex) + } } } @@ -463,6 +477,23 @@ class TranscriptScroll(internal val scroll: ScrollState) { * changes that order in the same composition that reads this -- so an index from before it can * be past the end. Clamping here rather than at the read sites keeps one answer to it. */ + /** + * The window the list last actually composed rows for. + * + * Not [retained], which is the *intent*. The two came apart the moment the window started being + * recomputed during layout: it is then updated before the frame draws, so a check against it + * passes while the screen is still showing the spacers from the composition before -- and + * [covered] reported zero for a transcript that was visibly flickering. A plain field rather + * than state, because nothing should recompose when it changes; it is a record of what already + * happened. + */ + private var built: IntRange = IntRange.EMPTY + + internal fun building(range: IntRange) { + if (range.isEmpty() && order.isNotEmpty()) DebugStats.count("composed no rows at all") + built = range + } + fun window(count: Int): IntRange { if (count == 0 || retained.isEmpty()) return IntRange.EMPTY val first = retained.first.coerceIn(0, count - 1) @@ -587,32 +618,34 @@ class TranscriptScroll(internal val scroll: ScrollState) { refreshTops() if (order.isEmpty()) return IntRange.EMPTY val margin = (visible * screens).coerceAtLeast(1) - val from = viewportTop - margin - val to = viewportTop + visible + margin - var first = -1 - var last = -1 - var nearest = 0 - var nearestGap = Int.MAX_VALUE - order.forEachIndexed { index, seq -> - val top = tops[index] - val bottom = top + assumed(seq) - if (bottom >= from && top <= to) { - if (first < 0) first = index - last = index - } - val gap = if (bottom < viewportTop) viewportTop - bottom else top - viewportTop - if (gap in 0.. retained.last) - DebugStats.atLeast("window short below, rows", (onScreen.last - retained.last).toLong()) - if (onScreen.first >= retained.first && onScreen.last <= retained.last) + // Against what was composed, not against [retained]; see [built]. + if (onScreen.first >= built.first && onScreen.last <= built.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. + // 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 < built.first) + DebugStats.atLeast("window short above, rows", (built.first - onScreen.first).toLong()) + if (onScreen.last > built.last) + DebugStats.atLeast("window short below, rows", (onScreen.last - built.last).toLong()) + // 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 went stale, including the ways not yet + // found. The paths that are known are fixed at their causes; this stands behind them. retained = minOf(retained.first, onScreen.first)..maxOf(retained.last, onScreen.last) false } @@ -855,6 +886,9 @@ fun TranscriptColumn( // recording accounted for a fortieth of it. Two spacers, because [retained] is a range: the // rows that are not in it are always one run before it and one run after. val window = state.window(rows.size) + // What is being composed, told to the state that has to answer for it later; see + // [TranscriptScroll.building]. + state.building(window) val ahead = if (window.isEmpty()) rows.indices else 0..