perf(queue): stop serializing every delivery on one mutex, and prune the tombstones nobody removed - #147
Merged
Merged
Conversation
Manager.DeleteMessage took the manager's single write lock and held it across three file operations: read the metadata, read the entire message body, then write a tombstone and unlink two files. Every completed delivery in the server queued behind that one lock. Measured on a 52,000-message queue with 20 workers configured: the LMTP operation itself took 33ms at the median, yet only 0.9 workers were ever busy, the queue drained at 11 messages a second, and every container sat under 7% CPU. Nineteen workers were blocked on a mutex held across disk reads — not on the network, not on Dovecot, not on ClamAV. Turning ClamAV off changed nothing, and delivering to a sink fifty times faster than Dovecot changed nothing, because the constraint was here the whole time. Deletes of different messages touch different files and different rows and have never needed to exclude each other. Deletes of the same message do. So the hot path now takes a read lock plus a per-id lock, and FlushQueue and Stop keep the write lock so they still exclude deletes entirely. The storage backend's own per-id lock and durable tombstone ordering are untouched beneath it. MoveMessage gets the same treatment, since a deferral has no reason to block a delivery completing on another message. messageLocks is a value rather than a pointer so a Manager built as a struct literal — the tests do this — cannot nil-panic on the delivery path, and its entries are reference-counted and dropped on release: a map keyed by message id that only grows is the same shape as the tombstone leak this queue already had. Measured after: 200 concurrent deletes went from 34.8ms to 10.5ms, and draining a 13,005-message queue gave 46.2/s average and 106/s peak — against 28.8/s and 94.6/s on a queue a third the size before the change. Correctness is covered by tests that fail on the old behaviour: the same message deleted from twelve goroutines succeeds exactly once, different messages do not serialize, and the lock map returns to empty.
Profiling the delivery path found what four rounds of black-box measurement could not. A drain with no inbound traffic had 19 goroutines runnable inside atomicWriteReaderAt and 73% of CPU in syscalls: the delivery path was writing files, not delivering. Behind it, /app/queue/tmp held 418,462 consumed-enqueue tombstones totalling 793MB, and nothing had ever removed them — the same unbounded growth the sqlite and postgres backends had, on the backend that was missed. Cleanup now prunes them on their own age bound, independently of whether any message expired, because they outnumber live messages by orders of magnitude. The message body stays in the tombstone. Removing it would halve the write on every delivery, and TestNewTombstoneRemainsReadableByOldBinaries exists to stop exactly that: a binary rolled back to a build predating ContentHash reads only the body, and an empty one would make it treat every retry as a conflict and start refusing mail. That is a deployment decision about rollback range, not a performance tweak, so it is left alone and the cost is written down where the next person will find it. Pruning bounds the rollback window as a side effect. Two bugs of my own along the way, both caught by testing rather than reading. The first pruner swallowed the unlink error, so a failure to delete counted as success — the exact pattern this session has been removing elsewhere. The second was subtler: os.DirEntry.Info() resolves its lstat against the process working directory, and these directories are opened with openat and wrapped by os.NewFile, so every stat failed and every entry was silently skipped. It now stats relative to the descriptor, like the rest of this file. Also adds net/http/pprof to the metrics listener behind ELEMTA_PPROF=1, off by default: that port binds 0.0.0.0 in the shipped compose and pprof serves goroutine stacks and a CPU profiler to anyone who can reach it. And drops the queue sweep interval from 10s to 1s. It is pickup latency, not throughput — gaps of exactly 10,005ms were measured between claim cycles, which is a message sitting in the queue doing nothing.
golangci-lint's unused check does not count test usage, so messageLocks.held read as dead code. The test is in-package and can take the mutex and read the map itself, which is one fewer method to keep honest. Caught by CI rather than locally: the full gate ran before this file existed, and adding code after it is exactly when a green local run stops meaning anything.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Delivery throughput was capped by two things inside the queue, not by the
network, the scanners or the mailbox server. Turning ClamAV off changed
nothing. Delivering to a sink fifty times faster than Dovecot changed nothing.
Both of those were the right experiments and both came back negative, which is
what finally pointed inward.
One mutex, held across disk I/O
Manager.DeleteMessagetook the manager's single write lock and held it whilereading the message metadata, reading the entire message body, and writing a
tombstone plus unlinking two files. Every completed delivery in the server
queued behind it.
Measured on a 52,000-message queue with 20 workers configured:
Nineteen workers blocked on a lock, on an idle machine.
Deletes of different messages touch different files and have never needed to
exclude each other; deletes of the same message do. The hot path now takes a
read lock plus a per-message-id lock.
FlushQueueandStopkeep the writelock and still exclude deletes entirely, and the storage backend's own per-id
lock and durable tombstone ordering are untouched beneath it.
MoveMessagegets the same treatment — a deferral has no reason to block a delivery
completing on another message.
200 concurrent deletes: 34.8ms → 10.5ms.
452,502 tombstones, 885MB, never pruned
Profiling a drain with no inbound traffic showed 19 goroutines runnable inside
atomicWriteReaderAtand 73% of CPU in syscalls — the delivery path waswriting files.
/app/queue/tmpheld 452,502 consumed-enqueue markers totalling885MB, and nothing had ever removed them. The same unbounded growth the sqlite
and postgres backends had; this is the backend that was missed.
Cleanupnow prunes them on their own age bound, independent of messageexpiry, because they outnumber live messages by orders of magnitude.
The message body stays in the tombstone, and that is deliberate. Removing it
would roughly halve the write on every delivery — it is the single biggest
remaining cost — but
TestNewTombstoneRemainsReadableByOldBinariesprotects areal failure: a binary rolled back to a build predating
ContentHashreads onlythat field, and an empty body would make it treat every retry as a conflict and
start refusing mail. That is a deployment decision about rollback range, not a
performance tweak, so the cost is written down rather than taken.
Also
net/http/pprofon the metrics listener behindELEMTA_PPROF=1, off bydefault — that port binds 0.0.0.0 and pprof serves goroutine stacks and a
CPU profiler to anyone who can reach it.
exactly 10,005ms were measured between claim cycles, which is a queued
message doing nothing.
Two bugs of mine, caught by testing rather than reading
The first pruner swallowed the unlink error, so failing to delete counted as
success. The second was subtler:
os.DirEntry.Info()resolves its lstat againstthe process working directory, and these directories are opened with
openatand wrapped by
os.NewFile, so every stat failed and every entry was silentlyskipped. It now stats relative to the descriptor, like the rest of that file.
Verified
Whole
internal/queuepackage green under-race. The same message deletedfrom twelve goroutines succeeds exactly once; 200 different messages do not
serialize; the lock map returns to empty; a stale tombstone is pruned while a
fresh one survives. Live: peak throughput 104/s → 136/s.