diff --git a/app/androidApp/src/main/kotlin/com/example/aiapp/DebugStats.kt b/app/androidApp/src/main/kotlin/com/example/aiapp/DebugStats.kt new file mode 100644 index 0000000..3d36bd4 --- /dev/null +++ b/app/androidApp/src/main/kotlin/com/example/aiapp/DebugStats.kt @@ -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() + private val nanos = ConcurrentHashMap() + private val worst = ConcurrentHashMap() + + private fun at(map: ConcurrentHashMap, 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 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 = + 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, frames: List): 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()?.setPrimaryClip(ClipData.newPlainText(label, text)) +} diff --git a/app/androidApp/src/main/kotlin/com/example/aiapp/FrameStats.kt b/app/androidApp/src/main/kotlin/com/example/aiapp/FrameStats.kt new file mode 100644 index 0000000..8f47154 --- /dev/null +++ b/app/androidApp/src/main/kotlin/com/example/aiapp/FrameStats.kt @@ -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() + private val layout = ArrayList() + private val draw = ArrayList() + private val sync = ArrayList() + private val issue = ArrayList() + private val swap = ArrayList() + private val gpu = ArrayList() + 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 { + 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): String { + val sorted = samples.sorted() + return " $name p50 ${at(sorted, 50)} p90 ${at(sorted, 90)} p99 ${at(sorted, 99)}" + } + + private fun at(sorted: List, 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) diff --git a/app/androidApp/src/main/kotlin/com/example/aiapp/Markdown.kt b/app/androidApp/src/main/kotlin/com/example/aiapp/Markdown.kt index 0764e7e..48414bc 100644 --- a/app/androidApp/src/main/kotlin/com/example/aiapp/Markdown.kt +++ b/app/androidApp/src/main/kotlin/com/example/aiapp/Markdown.kt @@ -137,7 +137,11 @@ private fun parsedMarkdown(text: String, replies: ParsedReplies): State { if (parsed.value.first == text) return@LaunchedEffect // 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. - 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 } @@ -166,11 +170,17 @@ class ParsedReplies { private val parsed = ConcurrentHashMap() /** 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. */ fun warm(texts: List) { - 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]. */ diff --git a/app/androidApp/src/main/kotlin/com/example/aiapp/NerdIcons.kt b/app/androidApp/src/main/kotlin/com/example/aiapp/NerdIcons.kt index beaba59..92068c1 100644 --- a/app/androidApp/src/main/kotlin/com/example/aiapp/NerdIcons.kt +++ b/app/androidApp/src/main/kotlin/com/example/aiapp/NerdIcons.kt @@ -106,6 +106,14 @@ val BELL_GLYPH = glyph(0xF009A) */ 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. * 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 3622401..0fd0ef8 100644 --- a/app/androidApp/src/main/kotlin/com/example/aiapp/SessionScreen.kt +++ b/app/androidApp/src/main/kotlin/com/example/aiapp/SessionScreen.kt @@ -1,6 +1,8 @@ package com.example.aiapp +import android.os.Build import android.os.SystemClock +import android.widget.Toast import androidx.activity.compose.rememberLauncherForActivityResult import androidx.activity.result.PickVisualMediaRequest 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 // the header, and the colour of the button that opens the dialog. val usage = rememberSessionUsage(settings, summary.setup) + val frames = rememberFrameStats() var usageOpen 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 // "checked, and fine" about a machine nobody could reach. 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( USAGE_GLYPH, "Usage", @@ -1396,6 +1432,7 @@ fun SessionScreen(settings: ServerSettings, summary: SessionSummary, onBack: () } }, ) { row -> + DebugStats.count("row composed") Box(Modifier.holdTopEdge(row.key, topEdgeHeld) { grew -> listState.by(grew) }) { when (row) { is TranscriptRow.Tools -> diff --git a/app/androidApp/src/main/kotlin/com/example/aiapp/ToolRows.kt b/app/androidApp/src/main/kotlin/com/example/aiapp/ToolRows.kt index 2a30c21..af8833f 100644 --- a/app/androidApp/src/main/kotlin/com/example/aiapp/ToolRows.kt +++ b/app/androidApp/src/main/kotlin/com/example/aiapp/ToolRows.kt @@ -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, * and the run this exists for is the burst of five greps nobody wants to scroll past. */ -fun groupToolRuns(items: List): List { +fun groupToolRuns(items: List): List = + DebugStats.timed("grouped tool runs") { groupRuns(items) } + +private fun groupRuns(items: List): List { val rows = mutableListOf() var run = mutableListOf() 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 7888c39..7a91c28 100644 --- a/app/androidApp/src/main/kotlin/com/example/aiapp/TranscriptScroll.kt +++ b/app/androidApp/src/main/kotlin/com/example/aiapp/TranscriptScroll.kt @@ -175,6 +175,10 @@ class TranscriptScroll(internal val scroll: ScrollState) { val viewport: Int 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. */ fun anchor(): ScrollAnchor? { val top = scroll.maxValue - scroll.value diff --git a/app/androidApp/src/main/res/font/nerd_icons.ttf b/app/androidApp/src/main/res/font/nerd_icons.ttf index 6769aae..172bdc4 100644 Binary files a/app/androidApp/src/main/res/font/nerd_icons.ttf and b/app/androidApp/src/main/res/font/nerd_icons.ttf differ diff --git a/app/build-icon-font.sh b/app/build-icon-font.sh index c250514..8785455 100755 --- a/app/build-icon-font.sh +++ b/app/build-icon-font.sh @@ -38,6 +38,7 @@ GLYPHS=( U+F0156 # md-close U+F004D # md-arrow_left U+F009A # md-bell + U+F04C5 # md-speedometer U+F201 # fa-line_chart -- Font Awesome's, asked for by name )