from_utf8_lossy quietly un-did my zero-copy log parser
logmole already mmaps files of 64 mib and up and parses straight out of the mapping — until one invalid byte turns the whole thing into a heap copy, and only on the files big enough to hurt
i closed the query dsl post promising this one would be about memory-mapping a multi-gigabyte log and parsing records straight out of the mapping, without copying a line. lifetimes, the borrow checker earning its keep, the whole thing.
then i sat down to write it and discovered i’d already done the work. logmole has mmapped large files for months and the record type borrows from the mapping end to end. there was no post in “here’s the thing i already built and it works.”
so i went looking for what it actually costs, pointed it at a one-gigabyte log with three bad bytes in the middle, and watched resident memory go to two gigabytes.
the parts that were already right
the record type is genuinely zero-copy, and it was designed that way from the first commit:
logmole-core/src/record.rs
/// Common representation for a parsed log line.
/// All parsers produce this type.
#[derive(Debug)]
pub struct LogRecord<'a> {
/// Raw line bytes (zero-copy reference to input)
pub raw: &'a [u8],
/// Parsed timestamp (None if not detected)
pub timestamp: Option<DateTime<Utc>>,
/// Log level (None if not detected)
pub level: Option<Level>,
/// Message body
pub message: Option<&'a str>,
/// Structured fields (key-value pairs extracted from the line)
pub fields: HashMap<&'a str, Value<'a>>,
/// Detected source format
pub format: Format,
/// Line number in the source
pub line_number: u64,
}every field that could be a String is a borrow instead. raw is &'a [u8], message is &'a str, and even the field map borrows both its keys and its values. parse forty thousand lines and you have allocated forty thousand LogRecords and zero bytes of string data. that 'a threads back through the parsers, the query evaluator and the analysis passes, which is the part that’s genuinely annoying to write and genuinely worth it.
and the input side maps large files rather than reading them:
logmole-cli/src/input.rs
/// Threshold for using mmap vs reading into memory.
const MMAP_THRESHOLD: u64 = 64 * 1024 * 1024; // 64 MB
pub enum InputSource {
/// Memory-mapped file (for large files).
Mapped { path: PathBuf, mmap: Mmap },
/// In-memory buffer (for small files and stdin).
Buffer { name: String, data: Vec<u8> },
}small files get read into a Vec because the syscall overhead of mapping isn’t worth it. anything of 64 MiB or more gets mapped — the comparison is >=, and the constant is 64 * 1024 * 1024, so it’s mebibytes rather than the round decimal number the name suggests. that is the correct shape and i still think so.
the one line in between
here is how the parser gets at the bytes.
logmole-cli/src/input.rs
/// Get the input as a string slice.
/// Replaces invalid UTF-8 bytes with the replacement character.
pub fn as_str_lossy(&self) -> std::borrow::Cow<'_, str> {
match self {
Self::Mapped { mmap, .. } => String::from_utf8_lossy(mmap.as_ref()),
Self::Buffer { data, .. } => String::from_utf8_lossy(data),
}
}it compiles. the lifetimes are correct. Cow<'_, str> borrows from the mapping, LogRecord<'a> borrows from the Cow, and the borrow checker is satisfied end to end — because it is sound. nothing here is a memory-safety bug and rust has no complaint to make.
read what from_utf8_lossy actually promises ↗
, though:
if our byte slice is invalid UTF-8, then we need to insert the replacement characters, which will change the size of the string, and hence, require a
String. but if it’s already valid UTF-8, we don’t need a new allocation. this return type allows us to handle both cases.
so the return type is a fork in the road, and which branch you take depends on the content of the file, not on anything visible at the call site. valid utf-8 gives you Cow::Borrowed and the zero-copy path everyone designed for. one invalid byte gives you Cow::Owned — a fresh String, containing a copy of the entire input, with U+FFFD where the bad byte was.
the entire input. a four-gigabyte log with one truncated multi-byte character in it becomes a four-gigabyte heap allocation, and the mmap i went to the trouble of adding is now a four-gigabyte thing i am also holding, next to the copy.
logs contain invalid bytes. a truncated write at a rotation boundary, a service that logs a raw byte string, latin-1 leaking in from something old, a container that got killed mid-line. this is not the exotic case. this is tuesday.
measuring it, because i don’t get to just assert this
i wrote the smallest thing that would settle it: map a file, call from_utf8_lossy, report which Cow variant came back and what it cost.
let mmap = unsafe { Mmap::map(&file) }.unwrap();
let t = Instant::now();
let cow = String::from_utf8_lossy(mmap.as_ref());
let elapsed = t.elapsed();
let borrowed = matches!(cow, Cow::Borrowed(_));peak resident memory comes from VmHWM in /proc/self/status, which is the high-water mark the kernel actually observed rather than anything the process reports about itself.
two files, both exactly 1.00 GiB of identical synthetic log lines. the only difference is three bytes at the 90% mark — F0 90 80, a truncated four-byte sequence — in the second one. median of three runs each, warm page cache, on my laptop:
| 1.00 GiB, all valid | 1.00 GiB, three bad bytes | |
|---|---|---|
Cow variant | Borrowed | Owned |
from_utf8_lossy | 1.73 s | 3.46 s |
| peak RSS delta | +1024 MiB | +2048 MiB |
three bytes out of a billion double the time and double the memory. the first cold-cache run was slower for both (5.3 s and 11.5 s) and i’m quoting the warm numbers because the cold ones are mostly measuring my ssd.
the surprise i wasn’t looking for
look at the good column again. Cow::Borrowed — the zero-copy path, working exactly as intended — still cost a full gigabyte of resident memory.
of course it did, once you say it out loud. from_utf8_lossy has to validate, and validating means reading every byte, and reading every byte of a mapping means faulting every page of it into residency. the mapping is lazy right up until something walks it end to end, and then it isn’t lazy at all.
so mmap did not save me a gigabyte of memory here. it never could have, against an operation that touches the whole file.
what it did buy is subtler and worth knowing, because it’s the reason the borrowed column is still hugely better than the owned one even though both look expensive:
- the gigabyte in the
Borrowedcase is clean page-cache memory backed by a file. under memory pressure the kernel can drop those pages instantly and re-read them later. it costs RSS but it’s not really yours. - the extra gigabyte in the
Ownedcase is anonymous heap. it is backed by nothing but swap. the kernel cannot drop it; it can only page it out, and if there’s nowhere to page it, the OOM killer arrives.
two similar-looking numbers with completely different failure behaviour on a box with less RAM than the log file. which is exactly the box you’re on when you reach for a log analyzer in the first place.
it fires precisely where it hurts
the pathology is inverted, and this is the part i’d have taken longest to spot in review.
for a file under 64 MB, InputSource::Buffer already holds a Vec<u8>. an Owned cow there costs one extra copy of something small, on a path that had already copied it once. barely matters.
for a file over 64 MB — the mmap path, the entire reason the threshold exists — an Owned cow copies the whole mapping onto the heap. the optimization defeats itself exactly at the size it was added for, and gets quieter the smaller the file gets. every test i’d have run on a sample log would have looked perfect.
the guard that reads like it covers this
read_file does check for binary content before mapping anything:
logmole-cli/src/input.rs
// Check for binary content (NUL byte in first 512 bytes)
if is_binary(&file)? {
anyhow::bail!("binary file detected, skipping: {}", path.display());
}and it’s a reasonable check. it catches someone pointing the tool at a jpeg. it does nothing whatsoever about a mostly-text log with three bad bytes 900 megabytes in, because it reads five hundred and twelve of them.
i keep finding this shape. the create endpoint that validated OwnerID was a well-formed uuid
had a check sitting next to the field too, and that check made the missing one harder to see, not easier. a guard that addresses a neighbouring concern is worse than no guard, because it satisfies the part of your brain that was going to ask the question.
the fix: stop going through &str at all
the mistake is converting the file to text. nothing needs the file as one enormous &str — the parsers work a line at a time, and LogRecord.raw is already &'a [u8], which means the design was ready for this before i was.
so split on newlines in bytes, and let utf-8 validation be a per-line concern. in sketch — InputSource has no as_bytes() yet, and this deliberately ignores two details that make a real implementation longer than one line: split yields a trailing empty slice on a newline-terminated file, and str::lines strips a \r before the \n while this doesn’t. neither is hard; both are what turns a tidy blog snippet into a function with a test.
pub fn lines(&self) -> impl Iterator<Item = &[u8]> {
self.as_bytes().split(|&b| b == b'\n')
}then, where a line genuinely needs to be text:
match std::str::from_utf8(line) {
Ok(s) => parse(s, line_number),
// one unreadable line is a skipped line and a counter, not a
// gigabyte of heap and a different program.
Err(_) => { malformed += 1; None }
}str::from_utf8 ↗
returns Result<&str, Utf8Error> — a borrow or an error, and never an allocation. the blast radius of a bad byte drops from the entire file to the line it’s on, and the failure becomes something i can report to the user (3 malformed lines skipped) instead of something that silently doubles their memory bill.
be precise about which memory, though, because the previous section applies here too: this does not drop resident memory back to nothing. the scan still walks the mapping, so RSS is still roughly file-sized — just clean, file-backed and evictable. what goes from file-sized to longest-line-sized is the heap, and that’s the number that was going to get the process killed.
it also makes the behaviour honest. from_utf8_lossy was quietly repairing my input — inserting U+FFFD and handing me a line that looks fine and no longer matches what’s on disk. for a tool whose job is telling you what’s in your logs, inventing characters is a worse default than admitting a line is unreadable.
what i rejected: from_utf8_unchecked on the whole mapping. it removes the allocation and the validation pass in one move, and it is unsafe for exactly the reason that matters here — invalid utf-8 in a &str is instant undefined behaviour, and the entire premise of this post is that i cannot predict whether a log file contains invalid utf-8. the one place unsafe is unarguable is the Mmap::map call itself, and even that carries a real caveat i should have written down sooner: if another process truncates the file while it’s mapped, touching the vanished pages is a SIGBUS, which for a tool that runs against live, rotating logs is not a theoretical concern.
lessons learned
Cowis a fork in the road, not a free abstraction.from_utf8_lossyreturningCow<'_, str>means the size of your allocation depends on the contents of the data, decided at runtime, invisible at the call site. any time a return type can be borrowed-or-owned, ask what picks — and whether the expensive branch is the one your real inputs take.- the borrow checker verifies the lifetimes, not the plan. everything here was sound.
'awas correct end to end. rust will happily prove that your borrow of a needless full-file copy is memory-safe, because it is. “it compiles and the lifetimes work” says nothing about where the bytes live. - an mmap only saves memory if you don’t touch the whole thing. validating a gigabyte faults in a gigabyte. what mmap actually bought was clean, evictable pages instead of anonymous heap — which is the difference between slow and OOM under pressure, and worth far more than the RSS number suggests.
- measure the pathological input, not the representative one. the sample logs in my test fixtures are all valid utf-8, so every benchmark i had ran the fast path. the bug lives in a file i’d never thought to construct.
- validate at the granularity you can afford to lose. per-file validation makes one bad byte cost the file. per-line validation makes it cost a line. same check, same correctness, four orders of magnitude difference in blast radius.
next: back to go and the pre-launch audit — four public endpoints that each allocate eight megabytes and peg a core to render a share image, no concurrency cap between them, and a stranger with a for loop. rate limiting caps requests; it does nothing about work.
support
if this saved you an afternoon, coffee is the going rate. no paywall, no tiers, no thank-you video.
$ ko-fi --send coffeeopens ko-fi.com. nothing is loaded from them on this page.