From 369b8f7e523582ec126c9d92e9e34f8c79a3c932 Mon Sep 17 00:00:00 2001 From: iris-ai <4+iris-ai@noreply.localhost> Date: Sat, 19 Sep 2026 15:57:56 -0400 Subject: [PATCH] Report what a reply spent reading its prompt, and pin the clock right MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `UsageDelta` gains `prefillMs`, llama-server's own `timings.prompt_ms`, so the footer under a finished reply is "read 9.5s · 50.3 tok/s · 3:00 PM". Prefill is the half of a turn that was invisible and is often the larger: measured on the 0.6B here, 1m 4s for the first turn after a model loads against 22ms for the next, whose prompt the server still had cached. The clock moves to the end of the line. Everything in front of it is a provider's own measurement, so a session on another provider has fewer of them or none, and a reader who has learned where the time is should not have to find it again because the model changed. The costs grow leftwards into the space instead, and a test asserts every shape of the line ends with the same thing. Verified on the emulator against a real llama session: three replies reading "read 1m 4s · 193 tok/s · 3:54 PM", "read 25ms · 308 tok/s · 3:54 PM" and "read 22ms · 194 tok/s · 3:54 PM", with the clock in one column. Co-Authored-By: Claude Opus 5 --- AGENTS.md | 8 ++-- PLAN.md | 37 ++++++++++------- .../main/kotlin/com/example/aiapp/Events.kt | 7 ++++ .../kotlin/com/example/aiapp/ReplyFooter.kt | 40 ++++++++++++++----- .../kotlin/com/example/aiapp/SessionScreen.kt | 3 +- .../com/example/aiapp/TranscriptItems.kt | 8 +++- .../com/example/aiapp/TranscriptUnits.kt | 2 + .../kotlin/com/example/aiapp/ThinkingTest.kt | 37 +++++++++++------ server/src/session/claude/translate.rs | 5 +++ server/src/session/codex/translate.rs | 5 +++ server/src/session/driver.rs | 13 ++++++ server/src/session/echo.rs | 2 + server/src/session/llama/mod.rs | 9 +++++ server/src/session/transcript.rs | 1 + 14 files changed, 135 insertions(+), 42 deletions(-) diff --git a/AGENTS.md b/AGENTS.md index 2d3fea2..4ef5492 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -67,9 +67,11 @@ Module-by-module intent is in PLAN.md's "Backend layout". the span the *driver* measured, and the phone draws a card that spins while the block is open and says "Thought for 12.4s" once it is not. The reasoning is deliberately not part of the next prompt (`conversation` ignores it), and - `timings.predicted_per_second` off the same stream becomes `UsageDelta`'s - `tokensPerSecond`, which is the "149 tok/s" under a finished reply — nothing - else here measures one, so every other driver sends `None`. + `timings.predicted_per_second` and `timings.prompt_ms` off the same stream + become `UsageDelta`'s `tokensPerSecond` and `prefillMs`, which is the + "read 9.5s · 50.3 tok/s · 3:00 PM" under a finished reply — nothing else here + measures either, so every other driver sends `None`, and the clock is last so + that it does not move when a provider reports fewer of them. **A turn's wait has two halves and says which** (2026-09-19): `SessionStatus::Loading` is the model coming off disk and `SessionStatus::Reading` is `llama-server` processing the prompt -- emitted diff --git a/PLAN.md b/PLAN.md index 14ac2b4..325b4de 100644 --- a/PLAN.md +++ b/PLAN.md @@ -169,13 +169,17 @@ seq N", so there is no separate history path to drift from the live one. waiting for itself and will speak again with nobody having typed anything. Reporting it as idle sent a "finished" notification at the one moment that was untrue. -- `UsageDelta { tokens, context, tokensPerSecond }` — what a turn cost, how - much the model was holding when it ended, and how fast it was generated. - `tokensPerSecond` (2026-09-19) is the provider's own measurement or nothing: - llama.cpp reports `timings.predicted_per_second`, and the coding CLIs report - no such figure, so dividing what this server watched a reply arrive over - would count the network, the tool calls and the reader's own permission - answers as generation. The phone draws it under the reply it measured. `context` is prompt plus both cache figures, +- `UsageDelta { tokens, context, tokensPerSecond, prefillMs }` — what a turn + cost, how much the model was holding when it ended, how fast it was + generated, and how long the provider spent reading the prompt first. The last + two (2026-09-19) are the provider's own measurements or nothing: llama.cpp + reports `timings.predicted_per_second` and `timings.prompt_ms`, and the + coding CLIs report neither, so dividing what this server watched a reply + arrive over would count the network, the tool calls and the reader's own + permission answers as generation. The phone draws both under the reply they + measured. `prefillMs` is small on a turn whose prompt the server still had + cached -- 22ms against 64s for the first turn after a model loads, measured + on the 0.6B -- which is a fact about the turn rather than a missing figure. `context` is prompt plus both cache figures, taken from the **last assistant message** rather than the turn's `result`: measured 2026-08-30 against CLI 2.1.237, the result adds a turn's messages up, so its cache read of 40,211 was the same conversation counted twice. @@ -1275,14 +1279,17 @@ dev-updater (Kotlin 2.4.x, CMP 1.11.x, JDK 21). the model stopped to think in the middle of it. A block cut by a page boundary is welded like a reply is (`healSplitThinking`), since the half with no ending would otherwise spin for the rest of the conversation. - - **A finished reply carries a line under it saying when it was sent and, - where the provider measured one, how fast it was generated** (2026-09-19) - — "3:00 PM · 149 tok/s", small and set back, right-aligned because it - closes the message rather than opening one. The time is the transcript's - own timestamp, so every device draws the same one; the rate is the - provider's own figure or nothing at all. It is a list unit of its own - (`ReplyFoot`), because a settled reply *is* its blocks and there is no - row left to hang it on. + - **A finished reply carries a line under it saying what it cost to produce + and when it was sent** (2026-09-19) — "read 9.5s · 50.3 tok/s · 3:00 PM", + small and set back, right-aligned because it closes the message rather + than opening one. **The clock is last**, so it sits against the right edge + whatever else is on the line: the measurements in front of it belong to + the provider, and a reader who has learned where the time is should not + have to find it again because the session is on a different one. The time + is the transcript's own timestamp, so every device draws the same one; the + costs are the provider's own figures or nothing at all. It is a list unit + of its own (`ReplyFoot`), because a settled reply *is* its blocks and + there is no row left to hang it on. - **Anything that is a note *about* the conversation rather than a turn in it is closed by default** — a tool call, a peer message, a memory note, a thinking block. diff --git a/app/androidApp/src/main/kotlin/com/example/aiapp/Events.kt b/app/androidApp/src/main/kotlin/com/example/aiapp/Events.kt index 8ac2551..a300a0c 100644 --- a/app/androidApp/src/main/kotlin/com/example/aiapp/Events.kt +++ b/app/androidApp/src/main/kotlin/com/example/aiapp/Events.kt @@ -185,6 +185,12 @@ sealed class SessionEvent { * over includes the network and whatever the server was doing between tokens. */ val tokensPerSecond: Double? = null, + /** + * How long the provider spent reading the prompt before it began answering; null where + * nothing measured it. The same rule as [tokensPerSecond]: the provider's own figure, or + * nothing at all. + */ + val prefillMs: Long? = null, ) : SessionEvent() /** How much context this session's model has, which is what [UsageDelta.context] is out of. */ @@ -328,6 +334,7 @@ fun parseSeqEvent(json: String): SeqEvent { body.getLong("tokens"), if (body.has("context")) body.getLong("context") else null, if (body.has("tokensPerSecond")) body.getDouble("tokensPerSecond") else null, + if (body.has("prefillMs")) body.getLong("prefillMs") else null, ) "compacted" -> SessionEvent.Compacted( diff --git a/app/androidApp/src/main/kotlin/com/example/aiapp/ReplyFooter.kt b/app/androidApp/src/main/kotlin/com/example/aiapp/ReplyFooter.kt index 90c75c3..7a68575 100644 --- a/app/androidApp/src/main/kotlin/com/example/aiapp/ReplyFooter.kt +++ b/app/androidApp/src/main/kotlin/com/example/aiapp/ReplyFooter.kt @@ -13,7 +13,7 @@ import java.time.format.FormatStyle import java.util.Locale /** - * The line under a finished reply: when it was sent, and how fast it was generated. + * The line under a finished reply: what it cost to produce, and when it was sent. * * Small and set back, in the tone the session's own subtitle takes: it is about the message rather * than part of it, and at the reply's own size it would read as the last thing the model said. @@ -22,8 +22,13 @@ import java.util.Locale * left edge is reading what was said, and this is where that ends. */ @Composable -fun ReplyFooter(ts: Double, tokensPerSecond: Double?, modifier: Modifier = Modifier) { - val text = replyFooterText(ts, tokensPerSecond, ZoneId.systemDefault()) ?: return +fun ReplyFooter( + ts: Double, + tokensPerSecond: Double?, + prefillMs: Long?, + modifier: Modifier = Modifier, +) { + val text = replyFooterText(ts, tokensPerSecond, prefillMs, ZoneId.systemDefault()) ?: return Text( text, style = MaterialTheme.typography.labelSmall, @@ -34,17 +39,28 @@ fun ReplyFooter(ts: Double, tokensPerSecond: Double?, modifier: Modifier = Modif } /** - * What the footer says, or null when there is nothing to say. + * What the footer says, or null when there is nothing to say: "read 9.5s · 50.3 tok/s · 3:00 PM". * * Split out so the wording is testable without a screen, and [zone] is a parameter for the same * reason [limitSummary] takes one: a test has to say the same thing wherever it runs. * - * A rate is drawn only where the provider measured one. Most do not -- a coding CLI reports what a - * turn cost and never how long the model spent -- and the time this app watched a reply arrive over - * is not the same quantity: it counts the network, the pauses between tokens and whatever the - * server was doing in them. So the line is the time alone rather than a plausible figure beside it. + * **The time is last, and so sits against the right edge whatever else is on the line.** The + * measurements in front of it are the provider's, so a session on another provider has fewer of + * them or none -- and a reader who has learned where the clock is should not have to find it again + * because the model changed. The costs grow leftwards into the space instead. + * + * Those measurements are drawn only where the provider made them. Most do not -- a coding CLI + * reports what a turn cost and never how long the model spent on it -- and the time this app + * watched a reply arrive over is a different quantity: it counts the network, the pauses between + * tokens and whatever else the machine was doing. So the line is the clock alone rather than a + * plausible figure beside it. */ -fun replyFooterText(ts: Double, tokensPerSecond: Double?, zone: ZoneId): String? { +fun replyFooterText( + ts: Double, + tokensPerSecond: Double?, + prefillMs: Long?, + zone: ZoneId, +): String? { val at = if (ts <= 0.0) null else @@ -65,5 +81,9 @@ fun replyFooterText(ts: Double, tokensPerSecond: Double?, zone: ZoneId): String? if (it >= 100) String.format(Locale.getDefault(), "%.0f tok/s", it) else String.format(Locale.getDefault(), "%.1f tok/s", it) } - return listOfNotNull(at, rate).joinToString(" · ").ifEmpty { null } + // Named "read" rather than given a unit alone, because a second figure in seconds beside a + // rate is unreadable otherwise -- and it is the same word the status row uses while it is + // happening, so the wait and the figure for it are one vocabulary. + val read = prefillMs?.takeIf { it > 0 }?.let { "read ${formatMillis(it)}" } + return listOfNotNull(read, rate, at).joinToString(" · ").ifEmpty { null } } 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 458be8b..93affc7 100644 --- a/app/androidApp/src/main/kotlin/com/example/aiapp/SessionScreen.kt +++ b/app/androidApp/src/main/kotlin/com/example/aiapp/SessionScreen.kt @@ -1710,7 +1710,7 @@ fun SessionScreen( when (unit) { is TranscriptUnit.Block -> MarkdownPiece(unit.text, unit.piece, replies) is TranscriptUnit.ReplyFoot -> - ReplyFooter(unit.ts, unit.tokensPerSecond) + ReplyFooter(unit.ts, unit.tokensPerSecond, unit.prefillMs) is TranscriptUnit.PeerHead -> PeerHeadRow( unit.item, @@ -1823,6 +1823,7 @@ fun SessionScreen( ReplyFooter( item.ts, item.tokensPerSecond, + item.prefillMs, ) } } diff --git a/app/androidApp/src/main/kotlin/com/example/aiapp/TranscriptItems.kt b/app/androidApp/src/main/kotlin/com/example/aiapp/TranscriptItems.kt index 42c6772..9ce2b20 100644 --- a/app/androidApp/src/main/kotlin/com/example/aiapp/TranscriptItems.kt +++ b/app/androidApp/src/main/kotlin/com/example/aiapp/TranscriptItems.kt @@ -80,6 +80,8 @@ sealed class TranscriptItem { * known until the reply is over. */ val tokensPerSecond: Double? = null, + /** How long the provider spent reading the prompt, where it measured that. */ + val prefillMs: Long? = null, ) : TranscriptItem() /** @@ -633,7 +635,11 @@ fun foldEvent(items: List, entry: SeqEvent): List when (val last = items.lastOrNull()) { is TranscriptItem.AssistantMsg -> - items.dropLast(1) + last.copy(tokensPerSecond = event.tokensPerSecond) + items.dropLast(1) + + last.copy( + tokensPerSecond = event.tokensPerSecond, + prefillMs = event.prefillMs, + ) else -> items } is SessionEvent.ContextWindow -> items diff --git a/app/androidApp/src/main/kotlin/com/example/aiapp/TranscriptUnits.kt b/app/androidApp/src/main/kotlin/com/example/aiapp/TranscriptUnits.kt index 80a88b9..770d465 100644 --- a/app/androidApp/src/main/kotlin/com/example/aiapp/TranscriptUnits.kt +++ b/app/androidApp/src/main/kotlin/com/example/aiapp/TranscriptUnits.kt @@ -142,6 +142,7 @@ sealed class TranscriptUnit { override val ordinal: Int, val ts: Double, val tokensPerSecond: Double?, + val prefillMs: Long?, override val gap: Dp, ) : TranscriptUnit() { override val key: Any @@ -265,6 +266,7 @@ fun transcriptUnits( ordinal, item.ts, item.tokensPerSecond, + item.prefillMs, gap(FOOT_SPACING), ) } else { diff --git a/app/androidApp/src/test/kotlin/com/example/aiapp/ThinkingTest.kt b/app/androidApp/src/test/kotlin/com/example/aiapp/ThinkingTest.kt index fb77f69..dd967a4 100644 --- a/app/androidApp/src/test/kotlin/com/example/aiapp/ThinkingTest.kt +++ b/app/androidApp/src/test/kotlin/com/example/aiapp/ThinkingTest.kt @@ -14,6 +14,7 @@ import kotlin.test.assertTrue * generation speed has no figure -- neither may borrow one. */ class ThinkingTest { + private val utc = ZoneId.of("UTC") private var seq = 0L private fun fold(items: List, event: SessionEvent, ts: Double = 1.0) = @@ -77,29 +78,41 @@ class ThinkingTest { } @Test - fun `a reply carries when it was sent and what it was generated at`() { + fun `a reply carries when it was sent and what it cost to produce`() { val items = fold(emptyList(), SessionEvent.AssistantText("Done."), ts = 1_788_609_600.0).let { - fold(it, SessionEvent.UsageDelta(42, 100, 18.37)) + fold(it, SessionEvent.UsageDelta(42, 100, 18.37, 9_489)) } val reply = items.filterIsInstance().single() assertEquals(1_788_609_600.0, reply.ts) assertEquals(18.37, reply.tokensPerSecond) + assertEquals(9_489, reply.prefillMs) - val footer = replyFooterText(reply.ts, reply.tokensPerSecond, ZoneId.of("UTC")) + val footer = replyFooterText(reply.ts, reply.tokensPerSecond, reply.prefillMs, utc) // The clock reading rather than the whole string: the platform's own short-time format // differs by JDK and locale, which is the point of asking it for one. - assertTrue(footer!!.contains("12:00"), footer) - assertTrue(footer.endsWith("18.4 tok/s"), footer) + assertTrue(footer!!.startsWith("read 9.5s · 18.4 tok/s · "), footer) + assertTrue(footer.contains("12:00"), footer) } @Test - fun `a provider that measures no speed gets a footer of the time alone`() { - val footer = replyFooterText(1_788_609_600.0, null, ZoneId.of("UTC")) - assertTrue(footer!!.contains("12:00"), footer) - assertTrue(!footer.contains("tok/s"), footer) - // And a reply with neither has no line at all rather than an empty one. - assertNull(replyFooterText(0.0, null, ZoneId.of("UTC"))) + fun `the clock stays at the end however much the provider measured`() { + // What a provider that measures nothing leaves: the time, and nothing in front of it. + val bare = replyFooterText(1_788_609_600.0, null, null, utc) + assertTrue(bare!!.contains("12:00"), bare) + assertTrue(!bare.contains("tok/s") && !bare.contains("read"), bare) + // Every shape ends with the same thing, which is the whole point of the order: the clock + // does not move because the session is on a provider that measures more or less. + val shapes = + listOf( + bare, + replyFooterText(1_788_609_600.0, 18.37, null, utc)!!, + replyFooterText(1_788_609_600.0, null, 9_489, utc)!!, + replyFooterText(1_788_609_600.0, 18.37, 9_489, utc)!!, + ) + assertEquals(1, shapes.map { it.substringAfterLast("· ") }.distinct().size, "$shapes") + // A reply with nothing to say has no line at all rather than an empty one. + assertNull(replyFooterText(0.0, null, null, utc)) } @Test @@ -130,7 +143,7 @@ class ThinkingTest { SessionEvent.AssistantText("Reading it."), SessionEvent.ToolStart("t1", "Read", "{}"), SessionEvent.ToolEnd("t1", "done"), - SessionEvent.UsageDelta(42, 100, 18.0), + SessionEvent.UsageDelta(42, 100, 18.0, 500), ) assertNull(items.filterIsInstance().single().tokensPerSecond) } diff --git a/server/src/session/claude/translate.rs b/server/src/session/claude/translate.rs index 06f646f..bfc6575 100644 --- a/server/src/session/claude/translate.rs +++ b/server/src/session/claude/translate.rs @@ -429,6 +429,7 @@ impl Translator { tokens, context, tokens_per_second: None, + prefill_ms: None, }); } // A level snapshot is authoritative at a turn boundary. In @@ -2554,6 +2555,7 @@ mod tests { tokens: 182, context: None, tokens_per_second: None, + prefill_ms: None, }, Event::Status { state: SessionStatus::Idle @@ -2597,6 +2599,7 @@ mod tests { tokens: 7, context: None, tokens_per_second: None, + prefill_ms: None, }, Event::Status { state: SessionStatus::Idle @@ -2651,6 +2654,7 @@ mod tests { tokens: 173, context: Some(26_131), tokens_per_second: None, + prefill_ms: None, }) ); @@ -2668,6 +2672,7 @@ mod tests { tokens: 13, context: None, tokens_per_second: None, + prefill_ms: None, }) ); } diff --git a/server/src/session/codex/translate.rs b/server/src/session/codex/translate.rs index b9ab353..80c0b2b 100644 --- a/server/src/session/codex/translate.rs +++ b/server/src/session/codex/translate.rs @@ -230,6 +230,7 @@ impl Translator { // Cached input is a subset of this figure, not an additional count. context: last.get("inputTokens").and_then(Value::as_u64), tokens_per_second: None, + prefill_ms: None, }) .into_iter() .collect() @@ -247,6 +248,7 @@ impl Translator { tokens: input.unwrap_or(0) + output.unwrap_or(0), context: input, tokens_per_second: None, + prefill_ms: None, }); } } @@ -939,6 +941,7 @@ mod tests { tokens: 18, context: Some(13), tokens_per_second: None, + prefill_ms: None, } ); assert!(translator.completed()); @@ -1162,6 +1165,7 @@ mod tests { tokens: 42, context: Some(39), tokens_per_second: None, + prefill_ms: None, }] ); assert_eq!( @@ -1172,6 +1176,7 @@ mod tests { tokens: 65, context: Some(61), tokens_per_second: None, + prefill_ms: None, }] ); assert_eq!( diff --git a/server/src/session/driver.rs b/server/src/session/driver.rs index bde16d3..76fa676 100644 --- a/server/src/session/driver.rs +++ b/server/src/session/driver.rs @@ -438,6 +438,17 @@ pub enum Event { /// times those were. #[serde(default, skip_serializing_if = "Option::is_none")] tokens_per_second: Option, + /// How long the provider spent reading the prompt before it began + /// answering -- see [`SessionStatus::Reading`], which is this while it + /// is happening. + /// + /// The provider's own measurement or nothing, for the same reason + /// `tokens_per_second` above is: the wait this server watched also + /// contains the request and whatever else the machine was doing. It is worth reporting because it is the larger half of a + /// turn on a long conversation -- 22 seconds against 3 of generation, + /// measured on a 14,000-token prompt. + #[serde(default, skip_serializing_if = "Option::is_none")] + prefill_ms: Option, }, /// A compaction that finished, and how much context it recovered. /// @@ -904,6 +915,7 @@ mod tests { tokens: 12, context: Some(30_100), tokens_per_second: None, + prefill_ms: None, } ), Some(30_100) @@ -944,6 +956,7 @@ mod tests { tokens: 12, context: None, tokens_per_second: None, + prefill_ms: None, } ), Some(30_100) diff --git a/server/src/session/echo.rs b/server/src/session/echo.rs index 390d31c..a83a563 100644 --- a/server/src/session/echo.rs +++ b/server/src/session/echo.rs @@ -894,6 +894,8 @@ impl EchoDriver { tokens_per_second: Some(streaming.elapsed().as_secs_f64()) .filter(|elapsed| *elapsed > 0.0) .map(|elapsed| words as f64 / elapsed), + // Nothing to read: this driver has no prompt to process. + prefill_ms: None, }); finish(); }); diff --git a/server/src/session/llama/mod.rs b/server/src/session/llama/mod.rs index 625b6d2..9963fa7 100644 --- a/server/src/session/llama/mod.rs +++ b/server/src/session/llama/mod.rs @@ -1640,6 +1640,10 @@ fn generate( // divided out of the wall time here, which would count the request, the // prompt processing and this loop's own scheduling as generation. let mut per_second = None; + // What it spent reading the prompt, the same way: `prompt_ms` is the + // server's own account of prompt processing, and a prompt it had cached is + // a small number rather than a missing one. + let mut prefill = None; // Closes the open block, which is anything the model says that is not more // working: the first word of the reply, or a tool call. let done_thinking = |thinking: &mut Option| { @@ -1678,6 +1682,9 @@ fn generate( { per_second = Some(rate); } + if let Some(ms) = chunk.pointer("/timings/prompt_ms").and_then(Value::as_f64) { + prefill = Some(ms.round() as u64); + } let Some(delta) = chunk.pointer("/choices/0/delta") else { continue; }; @@ -1723,6 +1730,7 @@ fn generate( tokens, context, tokens_per_second: per_second, + prefill_ms: prefill, }); } // A call whose name never arrived is not a call. It happens when a stream @@ -1967,6 +1975,7 @@ mod tests { tokens: 12, context: Some(12), tokens_per_second: None, + prefill_ms: None, }, ]); let messages = conversation(&path); diff --git a/server/src/session/transcript.rs b/server/src/session/transcript.rs index 7485ada..a211299 100644 --- a/server/src/session/transcript.rs +++ b/server/src/session/transcript.rs @@ -997,6 +997,7 @@ mod tests { tokens: 42, context: Some(42), tokens_per_second: None, + prefill_ms: None, }, Event::AuthenticationRequired { message: "sign in again".into(),