Nine bytes per log record
·9 min read
A search for record returned zero results. The string appeared 166 times in the
last day of logs.
Agenterr stored log bodies in SQLite with an FTS5 index. FTS5's unicode61 tokenizer
treats an ANSI escape sequence as word characters, so a colorized GORM line like \x1b[35;1mrecord not found tokenized as 1mrecord, not record. Every colorized log in the corpus was invisible to the thing whose entire
job is finding logs.
For a tool an agent calls, a false zero is the worst failure we can ship. An agent asks "is this error happening in production", gets back nothing, and confidently reports that the bug is fixed. A slow answer is an annoyance. A wrong answer poisons everything downstream of it.
Stripping ANSI at ingest would have closed that specific hole in an afternoon. We went looking at what else the row store was costing us first, and the answer was large enough to change the plan.
481 bytes to store a log line
Measured on a real production day: agenterr was using about 481 bytes per record all-in — uncompressed row-store SQLite plus the FTS index that was lying to us. Running OpenObserve on the same box for comparison put it near 106. We were holding 3.7x fewer records and still using more disk in absolute terms.
Search was worse than the storage. One unscoped multi-word query pegged the container at its half-core cap for minutes and never returned.
The thing we already knew and kept throwing away
Agenterr groups errors into issues by fingerprinting them. To do that it already computes, for every line, which parts are structure and which parts vary. That is the entire product. Then it took that knowledge, discarded it, and wrote the full line to a row store as if it had never seen a log before.
Log lines are overwhelmingly repeated structure. A service emits the same twenty phrasings a million times with different ids and durations in the holes. Storing the phrasing once and the holes per record is the CLP idea — Compressed Log Processing — and it beats running zstd over raw text by a wide margin, because zstd has to rediscover the structure inside every window.
So a log stopped being a string and became this:
body GET /api/v1/orders/8821 200 in 14.2ms template GET /api/v1/orders/<*> <*> in <*>ms variables ["8821", "200", "14.2"] stored (template_id=17, vars, ts)
The template text is written once, ever. Extraction uses a Drain-style prefix tree, and it is lossless: every record is reconstructed byte-for-byte and compared at ingest before it is acknowledged. Anything that fails to template — genuinely unique lines, multiline dumps — falls back to raw storage rather than being mangled to fit.
What that does to the bytes
Here is the column breakdown from a real day: 317,229 logs across twelve services, from a production box.
| column | raw | compressed |
|---|---|---|
| variables | 39.3 MB | 2.23 MB |
| timestamps (delta varint) | 386 KB | 242 KB |
| attribute dictionary | 4.74 MB | 205 KB |
| template table | — | 48 KB |
| attribute refs | 326 KB | 35 KB |
| template ids | 318 KB | 26 KB |
| service | 317 KB | 21 KB |
| severity | 317 KB | 978 B |
| raw fallback bodies | 2.1 KB | 15 B |
The whole day compresses to 2.80 MB. That is 8.8 bytes per record for the log data, and 9.4 once the metadata database and segment overhead are counted.
Two numbers surprised us. The corpus needed 189 templates — for a twelve-service day, with a 99.3% templating rate and 0.7% falling back to raw. We had budgeted for thousands and braced for template explosion on the noisy services. The busiest service, about 71% of all volume, turned out to be the most regular.
The second: attribute interning. 4.74 MB of repeated JSON attributes collapsed to a 205 KB dictionary plus 35 KB of references. Roughly 0.76 bytes per record for structured metadata that was previously being written out in full, every time.
Severity is the one that makes the point. 317,229 severity values, one per log, stored in 978 bytes.
Why search got faster instead of slower
Compressed columnar storage usually trades read speed for size. It did the opposite here, and the reason is that templates are a search index that costs nothing extra to keep.
A substring query runs template-first. Match it against a few thousand template strings — that is microseconds — and you immediately know which segments can possibly contain a hit. Everything else is skipped without decompressing a byte. Only the segments whose templates matched get decoded, and only the columns the query actually touches.
There was no free lunch in the first cut. Getting from correct to fast took three passes:
| stage | scoped | unscoped |
|---|---|---|
| first working version, full decode | 207 ms | 383 ms |
| + column-selective scans, parallel chunking | 39.7 ms | 36.9 ms |
| + sharded compaction | 10.9 ms | 14.8 ms |
The last row is the one worth stealing. Compaction merges the small segments a five-minute flush interval produces, and the obvious way to write it makes one big segment per bucket. Sharding that output instead means a parallel scan divides the decompression floor across cores rather than serializing on a single blob. Same data, same compression, a quarter of the latency.
Against OpenObserve, on identical data
The caveats belong before the table, not in a footnote under it.
OpenObserve caches query results, which flatters repeated queries by roughly 4x. The harness
pins use_cache=false for both systems, because a benchmark that measures a cache
hit measures nothing. And OpenObserve ingests substantially faster than we do — it acknowledges
writes before they are durable, while agenterr fsyncs before acking. That is a real difference in
guarantees, so those two numbers are not comparing the same operation.
Also worth stating plainly: the ~106 bytes/record we measured for OpenObserve on the trial box is not the number below. In a controlled head-to-head on identical data it came in at 10.9. We report the controlled number, which is much less flattering to us.
| agenterr | OpenObserve | |
|---|---|---|
| storage, all-in | 9.4 B/record | 10.9 B/record |
| scoped search | 10.9 ms | 37.0 ms |
| unscoped search | 14.8 ms | 34.4 ms |
| aggregate by service | 0.17 ms | 20.3 ms |
| ingest | 79k logs/s, fsync-acked | 213k logs/s, async-acked |
On storage we match them. On queries we are ahead, and the aggregate figure is a different mechanism rather than a better one — those come from precomputed hourly rollups instead of a scan, so it is 0.17 ms against a real query. Comparing them is only fair in the sense that both answer the same question for a user.
What we gave up
Search is substring matching over the reconstructed body. There is no tokenizer and no full-text index, so it finds exact substrings and will not do stemmed or fuzzy matching. For "is this error in production right now" that is the correct trade, and it is the reason the original ANSI bug cannot recur — there is no tokenizer left to mangle anything.
We also shipped v0.2.0 with no migrator. The engine change was total enough that carrying v0.1 data forward was not worth the weeks, so v0.2.0 starts fresh. That was the right call for a project with the user count we had at the time, and it is a debt we owe the next version.
Reproduce it
The harness is in the repo, along with the full methodology, the corpus shape, and every gate threshold:
$ make bench-vs-o2
The complete report lives in docs/superpowers/specs. Agenterr itself is on GitHub, AGPL-3.0, and self-hosting is free and unlimited.