chadtmiller.com/knotless
git that lives in your Atmosphere account
1
10
A long poll is never slow, in the request log or the usage stats
crates/knotless/src/telemetry.rs+24−1
| @@ -477,6 +477,8 @@ pub struct Served<'a> { | ||
pub trace: &'a str, | ||
/// Why it failed, for a 5xx. | ||
pub cause: Option<&'a str>, | ||
/// Whether it waits on purpose, as a long poll does, so is never slow. | ||
pub waits: bool, | ||
} | ||
| ||
/// Logs a request served and counts it: at error if it failed on this | ||
| @@ -484,7 +486,7 @@ pub struct Served<'a> { | ||
pub fn served(r: &Served) { | ||
let ms = millis(r.took); | ||
let failed = r.status >= 500; | ||
let slow = slow(r.took); | ||
let slow = slow(r.took) && !r.waits; | ||
let route = r.route.unwrap_or("fallback"); | ||
let key = (route.to_string(), r.method.to_string(), r.status); | ||
record(|s| { | ||
| @@ -887,6 +889,26 @@ mod tests { | ||
assert_eq!(stats.call("new", "200", 1, false, false), "other"); | ||
} | ||
| ||
/// A long poll is never slow, however long it waits. | ||
#[test] | ||
fn long_polls_are_not_slow() { | ||
let lines = logged(|| { | ||
served(&Served { | ||
route: Some("/xrpc/x.awaitWrites"), | ||
method: "GET", | ||
path: "/xrpc/x.awaitWrites", | ||
agent: None, | ||
status: 200, | ||
bytes: None, | ||
took: Duration::from_secs(25), | ||
trace: "t", | ||
cause: None, | ||
waits: true, | ||
}); | ||
}); | ||
assert_eq!(lines[0]["level"], "INFO"); | ||
} | ||
| ||
#[test] | ||
fn served_and_summarized() { | ||
let lines = logged(|| { | ||
| @@ -907,6 +929,7 @@ mod tests { | ||
took: Duration::from_millis(ms), | ||
trace: "t", | ||
cause: (status >= 500).then_some("PDS down"), | ||
waits: false, | ||
}); | ||
} | ||
assert_eq!(looked("avatars", Some(1)), Some(1)); | ||
crates/knotless-serve/src/telemetry.rs+16−1
| @@ -40,6 +40,19 @@ pub fn observed(routes: Router) -> Router { | ||
.layer(axum::middleware::from_fn(observe)) | ||
} | ||
| ||
/// The routes that wait on purpose before they answer, for something to | ||
/// happen or a while to pass: long polls, never slow however long they | ||
/// take. | ||
const WAITS: [&str; 2] = [ | ||
"/xrpc/dev.knotless.awaitSpaceWrites", | ||
"/xrpc/dev.knotless.getDelegation", | ||
]; | ||
| ||
/// Whether `route` is one of [`WAITS`]. | ||
pub fn waits(route: Option<&str>) -> bool { | ||
route.is_some_and(|r| WAITS.contains(&r)) | ||
} | ||
| ||
async fn matched(req: Request, next: Next) -> Response { | ||
let path = req.extensions().get::<MatchedPath>(); | ||
if let (Some(route), Some(path)) = (req.extensions().get::<Route>(), path) { | ||
| @@ -64,8 +77,9 @@ async fn observe(mut req: Request, next: Next) -> Response { | ||
res.headers_mut().insert("x-trace-id", id); | ||
let cause = res.extensions().get::<Cause>(); | ||
let bytes = axum::body::HttpBody::size_hint(res.body()).exact(); | ||
let matched = route.0.get().map(String::as_str); | ||
telemetry::served(&telemetry::Served { | ||
route: route.0.get().map(String::as_str), | ||
route: matched, | ||
method: &method, | ||
path: &path, | ||
agent: agent.as_deref(), | ||
| @@ -74,6 +88,7 @@ async fn observe(mut req: Request, next: Next) -> Response { | ||
took: started.elapsed(), | ||
trace: &trace, | ||
cause: cause.map(|c| c.0.as_str()), | ||
waits: waits(matched), | ||
}); | ||
res | ||
} | ||
crates/knotless-serve/src/usage.rs+17−2
| @@ -199,6 +199,8 @@ impl Usage { | ||
let Some((surface, route)) = surface(route, path) else { | ||
return; | ||
}; | ||
// A long poll's wait is what it is for, not what anyone waited on. | ||
let slow = u64::from(!crate::telemetry::waits(Some(route.as_str()))); | ||
let key = Key { | ||
hour: hour(SystemTime::now()), | ||
surface, | ||
| @@ -212,8 +214,8 @@ impl Usage { | ||
let tally = pending.entry(key).or_default(); | ||
tally.n += 1; | ||
tally.ms += ms; | ||
tally.over_half += u64::from(ms > 500); | ||
tally.over_two += u64::from(ms > 2000); | ||
tally.over_half += u64::from(ms > 500) * slow; | ||
tally.over_two += u64::from(ms > 2000) * slow; | ||
} | ||
| ||
/// Writes the requests counted; folds the days gone by into their | ||
| @@ -1027,6 +1029,19 @@ mod tests { | ||
assert_eq!(&routes[100..], ["/slow", "/xrpc/dev.knotless.inviteToOrg"]); | ||
} | ||
| ||
/// A long poll is counted, but never as slow: it waits on purpose. | ||
#[test] | ||
fn long_polls_are_not_slow() { | ||
let dir = tempfile::tempdir().unwrap(); | ||
let usage = Usage::open(&dir.path().join("usage.db")).unwrap(); | ||
let route = "/xrpc/dev.knotless.awaitSpaceWrites"; | ||
let waited = Duration::from_secs(25); | ||
usage.tally(Some(route), route, "GET", 200, "cli", waited); | ||
let pending = usage.pending.lock().unwrap(); | ||
let tally = pending.values().next().unwrap(); | ||
assert_eq!((tally.n, tally.over_half, tally.over_two), (1, 0, 0)); | ||
} | ||
| ||
#[test] | ||
fn counts_folds_and_reads() { | ||
let dir = tempfile::tempdir().unwrap(); | ||
deploy/README.md+5−3
| @@ -272,7 +272,8 @@ So it answers, among others: | ||
fetched most, and which CLI versions are still about. | ||
- **The gateway**: how many who delegate to it go on to push. | ||
- **Health**: which routes fail or are slow, and a deploy that made | ||
either worse, day against day; and the hours it happened in. | ||
either worse, day against day; and the hours it happened in. A long | ||
poll is never counted slow. | ||
| ||
What it does not count: | ||
| ||
| @@ -649,8 +650,9 @@ What serve logs: | ||
query), `http.request.method`, `user_agent.original` (the client as it | ||
names itself), `http.response.status_code`, | ||
`http.response.body.size` when known, `duration_ms` and `trace_id`, at | ||
info; at warn when over `KNOTLESS_SLOW_MS` (1000), at error for a 5xx | ||
with its `error`, and `/healthz` at debug. The answer carries the trace | ||
info; at warn when over `KNOTLESS_SLOW_MS` (1000), unless it is a long | ||
poll (`awaitSpaceWrites`, `getDelegation`), which waits on purpose; at | ||
error for a 5xx with its `error`, and `/healthz` at debug. The answer carries the trace | ||
as `x-trace-id`; the pages hand it back on their XRPC calls, so a | ||
page and the data it drew share one. | ||
- `outgoing`, each call made, to a PDS, the PLC directory, Bluesky's CDN | ||
docs/observability.md+2−1
| @@ -15,7 +15,8 @@ to read it is in [deploy/README.md](../deploy/README.md#logs). | ||
with its route, path, status, size, duration and trace, as Stripe's | ||
canonical log lines are [1]: a question about traffic is a jq filter | ||
over one kind of line, not a join across many. Slow ones (over | ||
`KNOTLESS_SLOW_MS`, 1000) are at warn, 5xx at error with the cause. | ||
`KNOTLESS_SLOW_MS`, 1000) are at warn, but for long polls, which wait | ||
on purpose; 5xx at error with the cause. | ||
- **A line for each call made**, to a PDS, the PLC directory, Bluesky or | ||
a handle's host, from the one place every call goes through | ||
(`knotless::telemetry::send`): host, path, XRPC method, status, error, | ||