blog

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.

columnrawcompressed
variables39.3 MB2.23 MB
timestamps (delta varint)386 KB242 KB
attribute dictionary4.74 MB205 KB
template table48 KB
attribute refs326 KB35 KB
template ids318 KB26 KB
service317 KB21 KB
severity317 KB978 B
raw fallback bodies2.1 KB15 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:

stagescopedunscoped
first working version, full decode207 ms383 ms
+ column-selective scans, parallel chunking39.7 ms36.9 ms
+ sharded compaction10.9 ms14.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.

 agenterrOpenObserve
storage, all-in9.4 B/record10.9 B/record
scoped search10.9 ms37.0 ms
unscoped search14.8 ms34.4 ms
aggregate by service0.17 ms20.3 ms
ingest79k logs/s, fsync-acked213k 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.

Run it in one command.

$ docker run ghcr.io/agenterr/agenterr