Add a button that copies what this session costs to draw

A speedometer left of the usage chart, because it is the same kind of
thing about the app that the chart is about the conversation. It copies
rather than opens: a screenful of timings read on the phone is a
screenful nobody can act on, and what it produces is a message to
whoever is looking at the code.

It carries both halves of the question, because "the scroll is laggy"
has two causes and one appearance. From the platform, each frame's cost
split into its phases -- if measuring and drawing are small and the
total is large, the time is going into rasterising and no amount of
doing less work per row will move it. From the app, counts and timings
of the work the transcript actually does: rows composed, replies parsed
on the composing thread rather than ahead of it, runs grouped.

Counts rather than frame times are the point of the second half. This
emulator scrolls at the same 21ms median as the stock Settings app, so
every app-level cost here is under the floor of what it can measure and
no number taken in it says anything about a 120Hz phone. How many times
a row was composed is the same number on any machine, and it is the one
that says whether the work follows what is on screen or everything ever
loaded.

Pressing it empties both, so two presses measure two separate stretches
of scrolling rather than one and then the same one again.

The first reading from the emulator already says something: measure and
layout are 0.0ms at the median, so nothing is being re-measured, and the
cost is 3.9ms of recording the draw against 10.9ms of GPU. It also shows
60 loaded rows composing 177 times across three page loads -- every row
recomposing whenever a page lands -- which is the next thing to look at
if the phone says the work is ours.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
This commit is contained in:
irisandClaude Opus 5 committed 2026-08-31 02:14:15 -04:00
1 parent f0f6d2b099
commit 3e653c4797
9 files changed
+308 -4

No files matched your search

@@ -0,0 +1,103 @@
package com.example.aiapp
import android.content.ClipData
import android.content.ClipboardManager
import android.content.Context
import androidx.core.content.getSystemService
import java.util.concurrent.ConcurrentHashMap
import java.util.concurrent.atomic.AtomicLong
/**
* Counters and timers for the work the transcript does, for the readout behind the debug button.
*
* Here because the emulator cannot answer the question this is for. Its own scroll sits at the same
* frame times as the stock Settings app -- 21ms at the median for both -- so every app-level cost
* is under the floor of what it can measure, and a frame number taken in it says nothing about a
* 120Hz phone. Counts do not have that problem: how many times a row was composed, or a reply
* parsed, is the same number on any machine, and it is the number that says whether the work is
* proportional to what is on screen or to everything ever loaded.
*
* Always on rather than behind a build flag. What is measured is an atomic increment on paths that
* already allocate lists and parse markdown, and a counter that is only compiled into the build
* nobody is holding when it is slow is not an instrument.
*/
object DebugStats {
private val counts = ConcurrentHashMap<String, AtomicLong>()
private val nanos = ConcurrentHashMap<String, AtomicLong>()
private val worst = ConcurrentHashMap<String, AtomicLong>()
private fun at(map: ConcurrentHashMap<String, AtomicLong>, name: String) =
map.computeIfAbsent(name) { AtomicLong() }
fun count(name: String, by: Long = 1) {
at(counts, name).addAndGet(by)
}
/** Records one occurrence of [name] that took [elapsed] nanoseconds. */
fun record(name: String, elapsed: Long) {
count(name)
at(nanos, name).addAndGet(elapsed)
val slot = at(worst, name)
while (true) {
val had = slot.get()
if (elapsed <= had || slot.compareAndSet(had, elapsed)) break
}
}
fun <T> timed(name: String, body: () -> T): T {
val started = System.nanoTime()
try {
return body()
} finally {
record(name, System.nanoTime() - started)
}
}
fun reset() {
counts.clear()
nanos.clear()
worst.clear()
}
/** One line per counter: how many, how long in total, and the worst single one. */
fun lines(): List<String> =
counts.keys.sorted().map { name ->
val n = counts[name]?.get() ?: 0
val total = nanos[name]?.get() ?: 0
if (total == 0L) " $name: $n"
else
" $name: $n, ${ms(total)}ms total, ${ms(total / n.coerceAtLeast(1))}ms mean," +
" ${ms(worst[name]?.get() ?: 0)}ms worst"
}
private fun ms(nanos: Long) = "%.1f".format(nanos / 1_000_000.0)
}
/**
* 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.
*
* Written for somebody to paste into a conversation, so it is plain text with the units on every
* 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<String>, frames: List<String>): String =
buildString {
appendLine("ai-app render report")
appendLine(device)
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) }
}
/** Puts [text] on the clipboard under [label], which is what the system offers as its name. */
fun Context.copyToClipboard(label: String, text: String) {
getSystemService<ClipboardManager>()?.setPrimaryClip(ClipData.newPlainText(label, text))
}
@@ -0,0 +1,138 @@
package com.example.aiapp
import android.app.Activity
import android.content.Context
import android.content.ContextWrapper
import android.os.Build
import android.os.Handler
import android.os.HandlerThread
import android.view.FrameMetrics
import android.view.Window
import androidx.compose.runtime.Composable
import androidx.compose.runtime.DisposableEffect
import androidx.compose.runtime.remember
import androidx.compose.ui.platform.LocalContext
/**
* How long each frame took, and which phase of it, taken from the platform rather than from a frame
* counter of our own.
*
* The point of splitting it up is that "the scroll is laggy" has two completely different causes
* and one appearance. If the layout-and-measure and draw figures are small and the total is large,
* the time is going into rasterising and compositing, and no amount of doing less work per row will
* move it. If they are large, the work per row is the problem and it is ours to fix. Guessing
* between those two is how a day gets spent rewriting the half that was already fast.
*
* The phases are the platform's own: [FrameMetrics] reports each frame's cost in nanoseconds,
* broken down into the parts the UI thread is responsible for -- handling input, running
* animations, measuring and laying out, recording the draw -- and the parts after it.
*/
class FrameStats {
private val total = ArrayList<Long>()
private val layout = ArrayList<Long>()
private val draw = ArrayList<Long>()
private val sync = ArrayList<Long>()
private val issue = ArrayList<Long>()
private val swap = ArrayList<Long>()
private val gpu = ArrayList<Long>()
private var since = System.currentTimeMillis()
@Synchronized
fun add(metrics: FrameMetrics) {
// The first frame after a window opens includes inflating it and is nobody's scroll.
if (metrics.getMetric(FrameMetrics.FIRST_DRAW_FRAME) == 1L) return
if (total.size >= CAP) return
total += metrics.getMetric(FrameMetrics.TOTAL_DURATION)
layout += metrics.getMetric(FrameMetrics.LAYOUT_MEASURE_DURATION)
draw += metrics.getMetric(FrameMetrics.DRAW_DURATION)
sync += metrics.getMetric(FrameMetrics.SYNC_DURATION)
issue += metrics.getMetric(FrameMetrics.COMMAND_ISSUE_DURATION)
swap += metrics.getMetric(FrameMetrics.SWAP_BUFFERS_DURATION)
if (Build.VERSION.SDK_INT >= Build.VERSION_CODES.S) {
gpu += metrics.getMetric(FrameMetrics.GPU_DURATION)
}
}
@Synchronized
fun reset() {
listOf(total, layout, draw, sync, issue, swap, gpu).forEach { it.clear() }
since = System.currentTimeMillis()
}
@Synchronized
fun lines(refreshHz: Float): List<String> {
if (total.isEmpty()) return listOf(" no frames recorded -- scroll first, then press this")
val seconds = (System.currentTimeMillis() - since) / 1000.0
val budget = if (refreshHz > 0) 1000.0 / refreshHz else 16.7
val late = total.count { it / 1_000_000.0 > budget }
return listOf(
" ${total.size} frames over ${"%.1f".format(seconds)}s" +
" at ${"%.0f".format(refreshHz)}Hz (${"%.1f".format(budget)}ms budget)",
" late: $late (${percent(late, total.size)})" +
if (total.size >= CAP) " [capped]" else "",
phase("total ", total),
phase("layout", layout),
phase("draw ", draw),
phase("sync ", sync),
phase("issue ", issue),
phase("swap ", swap),
) + if (gpu.isEmpty()) emptyList() else listOf(phase("gpu ", gpu))
}
private fun phase(name: String, samples: List<Long>): String {
val sorted = samples.sorted()
return " $name p50 ${at(sorted, 50)} p90 ${at(sorted, 90)} p99 ${at(sorted, 99)}"
}
private fun at(sorted: List<Long>, percentile: Int): String {
if (sorted.isEmpty()) return "-"
val index = (sorted.size - 1) * percentile / 100
return "%.1fms".format(sorted[index] / 1_000_000.0)
}
private fun percent(part: Int, whole: Int) = "%.1f%%".format(100.0 * part / whole)
private companion object {
/** Enough for a couple of minutes of scrolling; this is a diagnostic, not a log. */
const val CAP = 20_000
}
}
/**
* Frame timings for as long as this screen is on it.
*
* The listener is handed its own thread because the platform calls it for every frame and the
* documentation is explicit that doing that on the main thread taxes the very thing being measured.
*/
@Composable
fun rememberFrameStats(): FrameStats {
val stats = remember { FrameStats() }
val window = LocalContext.current.activity()?.window
DisposableEffect(window) {
if (window == null) return@DisposableEffect onDispose {}
val thread = HandlerThread("frame-stats").apply { start() }
val listener = Window.OnFrameMetricsAvailableListener { _, metrics, _ ->
stats.add(metrics)
}
window.addOnFrameMetricsAvailableListener(listener, Handler(thread.looper))
onDispose {
window.removeOnFrameMetricsAvailableListener(listener)
thread.quitSafely()
}
}
return stats
}
/** The activity behind a composable's context, which is what owns the window. */
fun Context.activity(): Activity? {
var context: Context? = this
while (context is ContextWrapper) {
if (context is Activity) return context
context = context.baseContext
}
return null
}
/** What the display is actually refreshing at, so "late" is measured against the real budget. */
fun Context.refreshHz(): Float =
@Suppress("DEPRECATION") (activity()?.windowManager?.defaultDisplay?.refreshRate ?: 60f)
@@ -137,7 +137,11 @@ private fun parsedMarkdown(text: String, replies: ParsedReplies): State {
if (parsed.value.first == text) return@LaunchedEffect if (parsed.value.first == text) return@LaunchedEffect
// Not through [replies]: this is a reply still arriving, and every delta would leave // Not through [replies]: this is a reply still arriving, and every delta would leave
// another copy of a message that is about to be superseded. // another copy of a message that is about to be superseded.
parsed.value = text to withContext(Dispatchers.Default) { parseMarkdown(text) } parsed.value =
text to
withContext(Dispatchers.Default) {
DebugStats.timed("markdown reparsed while streaming") { parseMarkdown(text) }
}
} }
return parsed.value.second return parsed.value.second
} }
@@ -166,11 +170,17 @@ class ParsedReplies {
private val parsed = ConcurrentHashMap<String, State>() private val parsed = ConcurrentHashMap<String, State>()
/** The parse of [text] -- the one made ahead, or one made now. */ /** The parse of [text] -- the one made ahead, or one made now. */
fun of(text: String): State = parsed[text] ?: parseMarkdown(text) fun of(text: String): State =
parsed[text]?.also { DebugStats.count("markdown ready") }
?: DebugStats.timed("markdown parsed while composing") { parseMarkdown(text) }
/** Parses whatever is not held yet. Call off the composing thread; that is the whole point. */ /** Parses whatever is not held yet. Call off the composing thread; that is the whole point. */
fun warm(texts: List<String>) { fun warm(texts: List<String>) {
texts.forEach { text -> parsed.computeIfAbsent(text) { parseMarkdown(it) } } texts.forEach { text ->
parsed.computeIfAbsent(text) {
DebugStats.timed("markdown warmed") { parseMarkdown(it) }
}
}
} }
/** Everything these described is gone; see [ParsedReplies]. */ /** Everything these described is gone; see [ParsedReplies]. */
@@ -106,6 +106,14 @@ val BELL_GLYPH = glyph(0xF009A)
*/ */
val USAGE_GLYPH = glyph(0xF201) val USAGE_GLYPH = glyph(0xF201)
/**
* `md-speedometer` -- what this session is costing to draw.
*
* A speedometer rather than a bug, because what it copies is a measurement rather than a fault
* report: it is as useful on a screen that feels fine, where the answer is that nothing is slow.
*/
val SPEED_GLYPH = glyph(0xF04C5)
/** /**
* The size an icon draws at beside a line of text. * The size an icon draws at beside a line of text.
* *
@@ -1,6 +1,8 @@
package com.example.aiapp package com.example.aiapp
import android.os.Build
import android.os.SystemClock import android.os.SystemClock
import android.widget.Toast
import androidx.activity.compose.rememberLauncherForActivityResult import androidx.activity.compose.rememberLauncherForActivityResult
import androidx.activity.result.PickVisualMediaRequest import androidx.activity.result.PickVisualMediaRequest
import androidx.activity.result.contract.ActivityResultContracts import androidx.activity.result.contract.ActivityResultContracts
@@ -1276,6 +1278,7 @@ fun SessionScreen(settings: ServerSettings, summary: SessionSummary, onBack: ()
// One poll for this machine's limits, read by the two things that show them: the bar under // One poll for this machine's limits, read by the two things that show them: the bar under
// the header, and the colour of the button that opens the dialog. // the header, and the colour of the button that opens the dialog.
val usage = rememberSessionUsage(settings, summary.setup) val usage = rememberSessionUsage(settings, summary.setup)
val frames = rememberFrameStats()
var usageOpen by remember { mutableStateOf(false) } var usageOpen by remember { mutableStateOf(false) }
var settingsOpen by remember { mutableStateOf(false) } var settingsOpen by remember { mutableStateOf(false) }
@@ -1320,6 +1323,39 @@ fun SessionScreen(settings: ServerSettings, summary: SessionSummary, onBack: ()
// is no measurement, since blue is the low end of the scale here and would read as // is no measurement, since blue is the low end of the scale here and would read as
// "checked, and fine" about a machine nobody could reach. // "checked, and fine" about a machine nobody could reach.
Row { Row {
// Left of the numbers about the *conversation*, because it is the same kind of
// thing about the *app*: what this session is costing to draw. It copies rather
// than opens, because what it produces is for somewhere else -- a message to
// whoever is looking at the code -- and a screenful of timings read on the phone
// is a screenful nobody can act on.
GlyphButton(
SPEED_GLYPH,
"Copy render timings",
onClick = {
val report =
debugReport(
device =
"device: ${Build.MODEL} (${Build.MANUFACTURER})," +
" Android ${Build.VERSION.RELEASE}",
transcript =
listOf(
" ${items.size} events, ${rows.size} rows loaded",
" content ${listState.contentHeight}px," +
" viewport ${listState.viewport}px," +
" room above ${listState.roomAbove}px",
" ${expandedTools.size} tool calls and" +
" ${expandedGroups.size} groups open",
),
frames = frames.lines(context.refreshHz()),
)
context.copyToClipboard("ai-app render report", report)
// 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()
DebugStats.reset()
Toast.makeText(context, "Copied render report", Toast.LENGTH_SHORT).show()
},
)
GlyphButton( GlyphButton(
USAGE_GLYPH, USAGE_GLYPH,
"Usage", "Usage",
@@ -1396,6 +1432,7 @@ fun SessionScreen(settings: ServerSettings, summary: SessionSummary, onBack: ()
} }
}, },
) { row -> ) { row ->
DebugStats.count("row composed")
Box(Modifier.holdTopEdge(row.key, topEdgeHeld) { grew -> listState.by(grew) }) { Box(Modifier.holdTopEdge(row.key, topEdgeHeld) { grew -> listState.by(grew) }) {
when (row) { when (row) {
is TranscriptRow.Tools -> is TranscriptRow.Tools ->
@@ -96,7 +96,10 @@ sealed class TranscriptRow {
* A single call is left alone: "Called 1 tool" hides a card to say the same thing in more words, * A single call is left alone: "Called 1 tool" hides a card to say the same thing in more words,
* and the run this exists for is the burst of five greps nobody wants to scroll past. * and the run this exists for is the burst of five greps nobody wants to scroll past.
*/ */
fun groupToolRuns(items: List<TranscriptItem>): List<TranscriptRow> { fun groupToolRuns(items: List<TranscriptItem>): List<TranscriptRow> =
DebugStats.timed("grouped tool runs") { groupRuns(items) }
private fun groupRuns(items: List<TranscriptItem>): List<TranscriptRow> {
val rows = mutableListOf<TranscriptRow>() val rows = mutableListOf<TranscriptRow>()
var run = mutableListOf<TranscriptItem.ToolRun>() var run = mutableListOf<TranscriptItem.ToolRun>()
@@ -175,6 +175,10 @@ class TranscriptScroll(internal val scroll: ScrollState) {
val viewport: Int val viewport: Int
get() = scroll.viewportSize get() = scroll.viewportSize
/** How tall everything loaded is, which is what a plain column has to hold laid out at once. */
val contentHeight: Int
get() = scroll.maxValue + scroll.viewportSize
/** Where the reader is now, or null before anything has been laid out. */ /** Where the reader is now, or null before anything has been laid out. */
fun anchor(): ScrollAnchor? { fun anchor(): ScrollAnchor? {
val top = scroll.maxValue - scroll.value val top = scroll.maxValue - scroll.value
Binary file not shown.
+1
View File
@@ -38,6 +38,7 @@ GLYPHS=(
U+F0156 # md-close U+F0156 # md-close
U+F004D # md-arrow_left U+F004D # md-arrow_left
U+F009A # md-bell U+F009A # md-bell
U+F04C5 # md-speedometer
U+F201 # fa-line_chart -- Font Awesome's, asked for by name U+F201 # fa-line_chart -- Font Awesome's, asked for by name
) )