Report what a reply spent reading its prompt, and pin the clock right

`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 <noreply@anthropic.com>
This commit is contained in:
iris-aiandClaude Opus 5 committed 2026-09-19 15:57:56 -04:00
1 parent b660905098
commit 369b8f7e52
14 files changed
+135 -42

No files matched your search

+5
View File
@@ -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,
})
);
}
+5
View File
@@ -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!(
+13
View File
@@ -438,6 +438,17 @@ pub enum Event {
/// times those were.
#[serde(default, skip_serializing_if = "Option::is_none")]
tokens_per_second: Option<f64>,
/// 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<u64>,
},
/// 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)
+2
View File
@@ -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();
});
+9
View File
@@ -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<std::time::Instant>| {
@@ -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);
+1
View File
@@ -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(),