headroom/deploy/beacon/test-rollup.mjs
Tejas Chopra e0870ef931
feat(beacon): hourly R2 compaction, per-strategy savings, and a stack that reports (#2853)
Three beacon changes bundled because they are one story: the corpus got
too
slow to query, and then too coarse to answer the question it was
collected for.

## 1. Hourly compaction (`deploy/beacon`)

The beacon writes one ~1 KB object per heartbeat — **64,987 on
2026-08-06** and
climbing. A full analysis `pull` was ~100k HTTPS round trips for 95 MB:
minutes
of pure per-object latency. Listing the bucket alone took 88 seconds.

Moving the query server-side does not help — R2 SQL reads only Iceberg
tables,
and a pile of tiny files is the pathological case for every query
engine.
Compaction is the fix, and it is Iceberg's own answer to the same
problem.

An hourly cron collapses each **complete** hour of `sessions/` into one
`rollup/dt=…/hh=…/data.ndjson`, keeping the highest-`seq` heartbeat per
`(install, session)`.

| measured on `dt=2026-08-06/hh=14` | before | after |
|---|---|---|
| objects | 3,938 | **1** |
| rows | 3,938 | **1,061** |
| analysis `pull` | minutes | **seconds** |

Hourly rather than daily because every R2 binding call is a subrequest:
a day
is ~65k, an hour is ~4k. Newest-first, so a backlog drains from the
present
backwards and live data never starves behind it; a failing hour is
logged and
skipped rather than blocking every older hour behind it. **Raw objects
are
never deleted**, so any rollup is rebuildable by deleting it.

Backfill runs to the **oldest surviving raw day**, not a fixed window. A
fixed
lookback strands everything older than it the moment analysis stops
reading
`sessions/`: the raw objects are still there, but nothing would ever
compact
them, so they disappear from every report. `oldestRawDay()` finds that
floor in
one delimited LIST, and the rollup listing starts from it — so the work
is
bounded by retention rather than by total history.

Three failure modes the tests pin down, because each one is silent:

- A **failed `get`** is transient, so the hour throws and writes
nothing. A
rollup is built once and trusted forever, so a short read would quietly
  become the permanent record.
- A **corrupt record** loses only itself. This Worker wrote that content
with
`JSON.stringify`; it will never become valid, so blocking on it strands
the
  hour instead of the record.
- An **empty hour** writes an `empty` marker. Without one the hour stays
  "missing" and is re-listed on every run forever.

`test-rollup.mjs` asserts the Worker's dedup picks exactly the same rows
as the
analysis-side `QUALIFY`. If those two ever disagree the reports go
quietly
wrong rather than loudly broken, which is why that check exists. Its
stub
paginates at 3 keys so the list cursor loop — load-bearing at the real
~4,000
objects/hour — runs in every case.

## 2. Per-strategy savings (`compression.by_strategy`)

`compression.transforms` counts *invocations*, which cannot distinguish
a
compressor that saved 60% from one that ran constantly and saved
nothing. The
fleet's top transform by count contributes an unknown share of
`tokens.saved`.

It is worse than that in practice. Transform labels are slugged with
`split(":", 1)[0]`, so every `router:<strategy>:<detail>` label
collapses into a
single `router` bucket. On 2026-08-08 that bucket held **19.1 M of the
day's
transform counts, across 8,528 of 9,616 sessions** — the compressors
that do
most of the work are indistinguishable from each other, by name as well
as by
yield:

| transform | n | sessions |
|---|---|---|
| `router` | 19,108,118 | 8,528 |
| `anthropic` | 688,124 | 4,734 |
| `output_shaper` | 548,017 | 1,120 |

No question about which strategy is earning its keep can be answered
from that,
which is what this field is for.

The measurement already existed. `PrometheusMetrics.record_compression`
is the
configured `CompressionObserver` and already accumulates
`tokens_saved_by_strategy` on the hot path — the numbers just never left
the
process. This forwards from that one chokepoint rather than adding a
second
observer and a second measurement pass. The paths that have **no**
observer
configured (MCP server, LangGraph, Strands hooks, the transform
pipeline) get
`BeaconCompressionObserver` passed directly.

Compression runs on the executor thread *before* that request's outcome
reaches
`record()`, so events are **staged** into module state and drained by
the next
outcome. Staging is what makes two things true at once:

- The first turn of a session still reports its numbers — otherwise
every
session's opening turn, and any session short enough to be one turn,
would
  report nothing.
- A compression event **never opens a session**. An abandoned request
would
otherwise emit a phantom `turns=0` row with all-zero tokens, inflating
fleet
  session and install counts.

Staging takes a dedicated mutex the request path never touches, so the
fan-out
stays off the aggregator's lock and `record_compression` keeps its
"synchronous + lock-free" contract.

```json
"by_strategy": [
  {"strategy": "code_aware",    "n": 1, "tokens_in":  800, "tokens_out": 800},
  {"strategy": "smart_crusher", "n": 2, "tokens_in": 1500, "tokens_out": 700}
]
```

A **list of records, sorted by strategy** — not an object keyed by
strategy.
Keyed shapes change type as keys accumulate: DuckDB infers a STRUCT
under ~24
keys and a MAP over it, so the analysis query breaks on the day the
fleet
picks up a 25th strategy. Sorted so heartbeats are byte-comparable.

**These do not sum to `tokens.saved`,** and the field comment says so:
strategies compose (the router routes, a strategy runs inside it) so the
same
text is measured more than once. A row means "of what this strategy was
handed,
it removed this much" — a per-strategy yield, not a share of the total.
A
strategy that saved nothing still appears; dropping it would make every
strategy look effective.

## 3. `headroom.stack`

`resource_attributes()` was called with no arguments at its one call
site, so
`headroom.stack` was absent from **all 24,040 sessions** in the corpus
while
`detect_stack` sat unused — dead code on both ends of a wire nobody
connected.
The fleet was unsegmentable by agent, which is the question the corpus
is asked
most often.

Environment detection alone is not enough. It answers `wrap_claude` only
under
`headroom wrap`; every install that points an agent at a persistent
proxy — the
common deployment — reports `proxy`, which segments nothing. The
per-request
`X-Headroom-Stack` slugs are the only signal that names the harness
there, so
`record_stack()` stages them the same way and feeds `detect_stack`'s
`by_stack`
branch:

```
9x wrap_claude, 1x wrap_cursor -> wrap_claude   (dominant harness wins)
5x wrap_claude, 5x wrap_cursor -> mixed
no per-request signal          -> proxy         (environment fallback)
junk slug                      -> dropped before staging
```

## Privacy

The strategy string is slugged through the same `_safe_slug` as skip
reasons
and capped at `MAX_STRATEGIES`, because the observer protocol takes a
free
string and an extension could otherwise invent keys per request. Stack
slugs
are normalized and capped the same way.

**Deliberately not collected:** the tool names in
`smart_crush:<count>:<names>`.
Those are user-defined MCP identifiers and can name internal tooling
(`acme_deploy_prod`). They stay stripped by the existing `split(":",
1)[0]`,
and this PR does not widen it. No new key was needed in `worker.js` —
`by_strategy` nests under the already-allowlisted `compression`, and
`headroom.stack` was already in `ALLOWED_RESOURCE`.

Nothing here deletes or rewrites existing data: the Worker only ever
writes,
`sessions/` is never pruned by it, and readers merge old and new shapes
with
`union_by_name`, so pre-change heartbeats keep reading with the new
fields null.

## Verification

- `python -m headroom.telemetry.session` — self-check covers staging,
the
no-phantom-session case, drain exhaustiveness, a 0%-yield strategy
staying
visible, the cardinality cap, slug safety, and dominant/mixed/junk stack
  resolution
- `node test-rollup.mjs /tmp/hr` — 3,938 real corpus objects → 1,061
sessions
in 1 object, plus the pagination, partial-read, corrupt-record,
empty-hour
  and `oldestRawDay` cases
- 51 passing in `test_compression_observability`,
`test_prometheus_obs_counters`,
  `test_telemetry_context`, `test_compression_strategy_outcomes`
- Consumer side exists and is checked: `beacon.sh by_strategy` in
  headroom-beacon-stats reads the field end to end (sessions, installs,
invocations, tokens in/out, yield %), verified against a synthetic
parquet for
the cases that matter — aggregation across installs, a 0%-yield strategy
staying visible, pre-field sessions dropping out rather than erroring.
It is
guarded on the column, so it prints an instruction instead of a binder
error
  until a release carrying this PR reaches the fleet.
- Deployed and running against the live corpus on the `5 * * * *`
trigger

🤖 Generated with [Claude Code](https://claude.com/claude-code)

---------

Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
2026-08-09 15:42:12 -07:00

214 lines
8.1 KiB
JavaScript

/**
* Self-check for scheduled()'s hourly compaction. node test-rollup.mjs [dir]
*
* The one thing that must never drift: rollupHour() and the QUALIFY in
* headroom-beacon-stats/beacon.sh have to agree on which heartbeat wins. If
* they disagree the reports get quietly wrong rather than loudly broken, so
* this asserts the JS picks exactly the max-seq row per (install, session).
*
* Point it at a directory of real beacon objects to check against the corpus:
* aws s3 sync s3://headroom-telemetry/sessions/dt=.../hh=.../ /tmp/hr/ ...
* node test-rollup.mjs /tmp/hr
* With no argument it runs on a small fixture and needs no network.
*/
import { readdirSync, readFileSync } from 'node:fs';
import assert from 'node:assert/strict';
import { oldestRawDay, rollupHour } from './worker.js';
// R2 returns at most 1000 keys per list page, so on a real hour (~4,000
// objects) the cursor loop in rollupHour is load-bearing. The stub paginates at
// a deliberately tiny size so that loop is exercised by every case below: with
// a single-page stub, a regression that dropped the cursor would still print
// "ok" while silently rolling up only the first page of every hour.
const PAGE = 3;
/** The slice of the R2 binding rollupHour uses, backed by a plain object. */
function stubBucket(files, { failKeys = new Set() } = {}) {
const written = {};
const reads = [];
return {
written,
reads,
list: async ({ prefix, cursor, delimiter }) => {
const keys = Object.keys(files)
.filter((k) => k.startsWith(prefix))
.sort();
if (delimiter) {
const seen = new Set();
for (const k of keys) {
const cut = k.indexOf(delimiter, prefix.length);
if (cut >= 0) seen.add(k.slice(0, cut + 1));
}
return { objects: [], delimitedPrefixes: [...seen], truncated: false };
}
const start = cursor ? keys.indexOf(cursor) : 0;
const page = keys.slice(start, start + PAGE);
const next = start + PAGE;
return {
objects: page.map((key) => ({ key })),
truncated: next < keys.length,
cursor: next < keys.length ? keys[next] : undefined,
};
},
get: async (key) => {
reads.push(key);
if (failKeys.has(key)) throw new Error(`simulated R2 failure: ${key}`);
if (!(key in files)) return null;
return { text: async () => files[key] };
},
put: async (key, body) => {
written[key] = body;
},
};
}
const beacon = (install, id, seq) =>
JSON.stringify({ resource: { 'headroom.install_id': install }, session: { id, seq } });
const PART = 'dt=2026-08-06/hh=14';
/** Run rollupHour against a stub bucket and decode whatever it wrote. */
async function run(files, opts = {}) {
const CORPUS = stubBucket(files, opts);
const spend = { read: 0 };
let threw = null;
let out = null;
try {
out = await rollupHour({ CORPUS }, PART, spend);
} catch (err) {
threw = err;
}
const body = CORPUS.written[`rollup/${PART}/data.ndjson`];
return {
threw,
spend,
wrote: out ? out.wrote : 0,
empty: `rollup/${PART}/empty` in CORPUS.written,
keys: Object.keys(CORPUS.written),
rows: body ? body.split('\n').map((l) => JSON.parse(l)) : [],
};
}
// 1. Highest seq wins, out-of-order input, one row per (install, session).
// More objects than PAGE, so the list cursor loop runs.
{
const files = {
[`sessions/${PART}/a.json`]: [beacon('i1', 's1', 3), beacon('i1', 's2', 1)].join('\n'),
[`sessions/${PART}/b.json`]: beacon('i1', 's1', 9),
[`sessions/${PART}/c.json`]: beacon('i1', 's1', 7),
// Same session id under a different install must not collapse together.
[`sessions/${PART}/d.json`]: beacon('i2', 's1', 2),
[`sessions/${PART}/e.json`]: beacon('i1', 's1', 5),
};
const { rows, spend, threw } = await run(files);
assert.equal(threw, null);
// 5 objects at PAGE=3 is two pages: proves the cursor loop, which is
// load-bearing at the real ~4,000 objects/hour.
assert.ok(Object.keys(files).length > PAGE, 'fixture must span pages');
assert.equal(spend.read, 5, 'reads every object across every page');
assert.equal(rows.length, 3, 'one row per (install, session)');
const seq = Object.fromEntries(
rows.map((r) => [`${r.resource['headroom.install_id']} ${r.session.id}`, r.session.seq])
);
assert.deepEqual(seq, { 'i1 s1': 9, 'i1 s2': 1, 'i2 s1': 2 });
}
// 2. An unparseable record loses only itself. Content this Worker wrote with
// JSON.stringify never becomes valid later, so blocking the hour on it would
// strand the hour rather than one record.
{
const files = {
[`sessions/${PART}/a.json`]: '{ this is not json',
[`sessions/${PART}/b.json`]: `\n${beacon('i1', 's1', 4)}\n`,
};
const { rows, threw } = await run(files);
assert.equal(threw, null, 'corrupt content does not abandon the hour');
assert.deepEqual(rows.map((r) => r.session.seq), [4], 'survives a corrupt object');
}
// 3. A failed get is transient, so the hour must NOT be written — a rollup is
// built once and then trusted forever, so a short read would silently become
// the permanent record.
{
const files = {
[`sessions/${PART}/a.json`]: beacon('i1', 's1', 1),
[`sessions/${PART}/b.json`]: beacon('i1', 's2', 1),
};
const { threw, keys } = await run(files, {
failKeys: new Set([`sessions/${PART}/b.json`]),
});
assert.ok(threw, 'a failed get throws so the hour is retried');
assert.deepEqual(keys, [], 'nothing written on a partial read');
}
// 4. Spend is reported even when the hour throws. Charging a flat guess instead
// lets a run that failed late overshoot the subrequest ceiling.
{
const files = Object.fromEntries(
Array.from({ length: 7 }, (_, i) => [`sessions/${PART}/o${i}.json`, beacon('i1', `s${i}`, 1)])
);
const { threw, spend } = await run(files, {
failKeys: new Set([`sessions/${PART}/o6.json`]),
});
assert.ok(threw);
assert.equal(spend.read, 7, 'caller sees real spend, not a guess');
}
// 5. An empty hour writes a marker, not a zero-byte NDJSON. Without it the hour
// stays "missing" and is re-listed on every run forever.
{
const { rows, empty, keys } = await run({});
assert.deepEqual(rows, []);
assert.ok(empty, 'empty hour leaves a marker');
assert.ok(
keys.every((k) => !k.endsWith('.ndjson')),
'no zero-byte ndjson for readers to special-case'
);
}
// 6. oldestRawDay floors the backfill. A fixed lookback window silently strands
// every hour older than it once analysis stopped reading sessions/.
{
const CORPUS = stubBucket({
'sessions/dt=2026-08-03/hh=01/a.json': beacon('i1', 's1', 1),
'sessions/dt=2026-08-06/hh=14/b.json': beacon('i1', 's2', 1),
'sessions/dt=2026-08-07/hh=00/c.json': beacon('i1', 's3', 1),
});
assert.equal(await oldestRawDay({ CORPUS }), '2026-08-03');
assert.equal(await oldestRawDay({ CORPUS: stubBucket({}) }), null, 'empty bucket -> null');
}
// 7. Against real objects, if a directory was given: same answer as the QUALIFY
// in beacon.sh, which is `count(DISTINCT install||session)` rows, each
// carrying that pair's max seq.
const dir = process.argv[2];
if (dir) {
const files = {};
for (const f of readdirSync(dir).filter((f) => f.endsWith('.json'))) {
files[`sessions/${PART}/${f}`] = readFileSync(`${dir}/${f}`, 'utf8');
}
const { rows, spend, threw } = await run(files);
assert.equal(threw, null);
const expected = new Map();
for (const text of Object.values(files)) {
for (const line of text.split('\n')) {
if (!line.trim()) continue;
const r = JSON.parse(line);
const k = `${r.resource?.['headroom.install_id']} ${r.session?.id}`;
expected.set(k, Math.max(expected.get(k) ?? -1, r.session?.seq ?? 0));
}
}
assert.equal(spend.read, Object.keys(files).length);
assert.equal(rows.length, expected.size, 'row count matches DISTINCT sessions');
for (const r of rows) {
const k = `${r.resource['headroom.install_id']} ${r.session.id}`;
assert.equal(r.session.seq, expected.get(k), `max seq for ${k}`);
}
console.log(
`real corpus: ${spend.read} objects -> ${rows.length} sessions in 1 object` +
` (${Math.ceil(spend.read / PAGE)} list pages)`
);
}
console.log('ok');