The previous post was about uploads into Garage. This one is about reading back out of it, and it's a better story, because the answer had nothing to do with Garage at all.
The workload: a small log viewer that points DuckDB at a bucket of
vector-written JSON — about 6,600 objects averaging 1.4 KB, 28 MB total —
and materializes them into a local DuckDB table. The Garage node is a 1 vCPU,
512 MB VM on the LAN, roughly 1–2 ms round-trip away.
Ingest took 132 seconds to move 28 MB across a fast LAN. That's absurd, and the path from there to 12.3s ran through one real optimisation that wasn't the problem, and three wrong theories about the server.
A note on provenance: this post was written by an AI, and the investigation
behind it was too. The hypotheses, the probe scripts, the tcpdump and
iostat analysis, and the kernel-source check that settled the last question
were all done in a Claude Code session. I ran
the commands against my own hardware, decided what to try next, and reviewed
the result. Every number here is a real measurement from that work rather than
an illustration — including the two spots where the AI stated a confident wrong
conclusion and only reading the kernel source sorted it out.
The view was built with read_json_auto(..., union_by_name=true). With
union_by_name, DuckDB has to open every object to union their schemas
before a single row materializes — then logs_mat scans them all again. Two
full passes over 6,600 objects.
Declaring the columns explicitly dropped view binding from 0.41s to 0.12s locally, and over S3 it deleted an entire pass. Real win. Ingest went from an estimated ~263s to 132.9s.
But 132.9s ÷ 6,596 files is ~20 ms per file — essentially serial, one round-trip at a time, on a link with a 1–2 ms RTT. Something else was wrong.
The symptom was distinctive: long pauses between groups of file accesses,
with htop on the Garage box showing nothing much. I had three theories, all
about the server: metadata fsync on a slow disk, a degraded node making reads
wait on a quorum timeout, or the single core simply being saturated by
signature verification. iostat -x 1 from the VM during a run killed all three
at once:
| metric | value |
|---|---|
r_await / w_await |
p95 10.7 ms / 9.0 ms |
util |
p50 0%, p95 34% |
steal |
0.00 everywhere |
| fully idle intervals | 120 of 170 (71%) |
Not disk-bound. Not iowait. No noisy neighbour. During the pauses the box was doing nothing at all — under 5% CPU, zero disk reads. If requests were arriving and Garage were slow to answer, there would be CPU or disk to see. There wasn't.
An idle server plus a stalled client means the requests aren't arriving.
tcpdump -ttt settles it-ttt prints the delta between packets, which turns "where does the time go"
into a sort. 87,000 packets, 222.8s span:
capture span : 222.8s
connection attempts (SYNs) : 7409 -> 33 new connections/sec
distinct connections : 6245
genuine SYN retransmits : 365
backoff pattern : 155x 1s, 89x 2s, 64x 4s, 57x 8s
That backoff ladder — 1s, 2s, 4s, 8s — is textbook TCP SYN retransmission. Only 155 connections out of 6,245 ever entered it, which is 2.5%; the other rows are those same connections climbing the ladder. That's the part worth sitting with. A 2.5% failure rate sounds like a rounding error, but each connection that hit it lost up to 15 seconds, and the total is 1,068 connection-seconds — divided by ~8 concurrent DuckDB workers, ~133s of wall clock. The ingest time was the retry time, almost exactly.
It also explains the idle server: a dropped SYN never reaches the application, so there's no CPU or disk work to observe on the other end.
Two things fall out of that capture, and they're independent problems:
threads of 8, 4, and 2 alike.dmesg on the VM had the answer waiting: nf_conntrack: table full, dropping
packet.
conntrack — the kernel's connection
tracking, and the conntrack-tools userspace that inspects it — keeps an entry
per connection, and holds it after close for
nf_conntrack_tcp_timeout_time_wait. So the sustainable rate of new
connections is just table size ÷ timeout. On this VM nf_conntrack_max was
4096.
Worth a picture, because two different numbers are easy to conflate — and conflating them is exactly what makes the failure confusing. Every packet crossing a tracked path gets hashed into a bucket, and the entry it finds (or creates) lives in a chain hanging off that bucket:
packet arrives
│
▼
┌───────────────────────────────────┐
│ 5-tuple │
│ proto · src ip:port · dst ip:port │
└───────────────────────────────────┘
│
hash(5-tuple)
│
▼
nf_conntrack_buckets = 8192 ← one list head per bucket
┌────────┐
│ 0 │──▶ ( empty )
├────────┤
│ 1 │──▶ [ 10.5.5.15:47436 → 10.5.5.14:3900 ESTABLISHED ]
├────────┤
│ 2 │──▶ [ …:38484 → …:3900 TIME_WAIT ]──▶ [ …:39002 TIME_WAIT ]
├────────┤ └─ collisions chain off one bucket ─┘
│ … │
├────────┤
│ 8191 │──▶ ( empty )
└────────┘
live entries ..... nf_conntrack_count ~300 bytes each
hard cap ......... nf_conntrack_max count == max ⇒ packet DROPPED
chain depth ...... count ÷ buckets what hashsize buys you
So hashsize and max do unrelated jobs: buckets decide how fast a lookup
is, max decides how many connections exist at all. Only the second one can
drop your traffic. Getting them confused is why I spent a while tuning the
harmless one.
The other half is that an entry outlives the connection:
SYN ──▶ NEW ──▶ ESTABLISHED ──▶ FIN ──▶ TIME_WAIT ──▶ slot freed
│
└─ held 120s by default,
long after the socket is gone
That's the whole bug in one line. A closed connection keeps its slot for two minutes by default, so the table's real currency isn't connections — it's connections per second. Which is why a box with nothing to do can still be out of table.
Nothing on the box set that 4096. It's what the kernel chose at boot, and the
arithmetic is worth walking through, because I talked myself out of the right
answer twice before going to the source. nf_conntrack sizes its hash table
from RAM when the module loads: buckets are RAM ÷ 16384 ÷ 8, which on 512 MB
gives 4,091, rounded up to 4096. Then it sets the cap from that:
/* net/netfilter/nf_conntrack_core.c, v5.15 */
max_factor = 1;
/* … */
nf_conntrack_max = max_factor * nf_conntrack_htable_size;
One allowed entry per bucket. On this kernel nf_conntrack_max simply is the
bucket count.
That factor used to be 4, and the change is what makes a small VM fragile. The machine running DuckDB is on 5.10, where the old rule still applies — 12 GB of RAM, 65,536 buckets, cap 262,144, a clean 4:1. Somewhere between 5.10 and 5.15 upstream tightened the default to 1:1, trading cap headroom for short hash chains. On a big host nobody notices. On this one it's the difference between 16384 and 4096, and 4096 is exactly where the workload lives.
It's far too small for the job either way. 4096 entries at a 120s TIME_WAIT is a ceiling of 34 new connections per second — for a machine whose whole job is answering S3 requests over short-lived connections. It's the kind of limit that never announces itself: nothing is slow until something opens connections in bulk, and then the failure surfaces as a network problem, several layers away from the file that caused it. That's most of why it took so long to find.
sudo conntrack -S prices the damage. It prints per-CPU counters for the
tracking layer itself:
$ sudo conntrack -S
cpu=0 found=0 invalid=6 insert=0 insert_failed=0 drop=5937 early_drop=77
error=2 search_restart=284734
Two things to notice. First, there's exactly one line — conntrack -S reports
per-CPU, so a single cpu=0 is its own quiet reminder of what this box is.
Second, 5,937 dropped packets against insert_failed=0. I'd expected the
opposite, and the distinction is worth knowing: insert_failed counts a
collision on insert, while a table that is simply full drops the packet
earlier and lands in drop. early_drop=77 is the kernel evicting unassured
entries — connections it hasn't yet seen traffic on in both directions — to
make room for a new one, which is about as direct an "I'm out of table" signal
as the kernel gives you. So drop
climbing while insert_failed stays flat is exactly the shape of a table at
its cap.
Those counters are cumulative since boot, so sample them either side of a single run rather than reading absolutes — a few dozen per ingest is noise, thousands is the ceiling.
The cheapest knob first, because it costs no memory. These connections are short-lived and already closed while conntrack is still holding them, so the timeout is mostly waste:
sysctl -w net.netfilter.nf_conntrack_tcp_timeout_time_wait=30
Ingest went 132.9s → 45.1s, a 2.9x speedup from one number. The ratio to watch, though, is the connection rate, not the clock: 120s ÷ 30s is 4x more headroom, and the observed rate went up almost exactly 4x. Wall clock improved less than that because the later run also had ~10k more rows to ingest — as throughput it's 3.2x. The two runs make the point together:
| run | max | TIME_WAIT | ceiling = max/TW | observed rate |
|---|---|---|---|---|
| before | 4096 | 120s | 34 conn/s | 33 conn/s |
| after | 4096 | 30s | 137 conn/s | 142 conn/s |
Both land within a few percent of their ceiling. The ingest was never running as fast as Garage allowed — it was running exactly as fast as conntrack could recycle entries, in both configurations. Which means the timeout was never the real fix, just a bigger allowance. That's when the arithmetic stopped being a theory.
And sure enough, conntrack -S was still incrementing, and the ingest still had visible
pauses. To see whether the table was still the binding constraint I skipped the
tooling entirely and used a while loop on the VM, printing the live count
once a second while an ingest ran:
while :; do
echo "$(date +%T) $(cat /proc/sys/net/netfilter/nf_conntrack_count)"
sleep 1
done
Run that in one pane and the ingest in another, and the shape of the problem is just there, a second at a time:
20:53:34 525
20:53:35 525
20:53:36 525
20:53:37 525
20:53:38 525
20:53:39 530
20:53:40 952
20:53:41 1678
20:53:42 2807
20:53:44 3936
20:53:45 4096
20:53:46 4096
20:53:47 4096
20:53:48 4096
20:53:49 4096
20:53:50 4096
20:53:51 4096
20:53:52 4096
20:53:53 4096
20:53:54 4096
20:53:55 4096
Five seconds of baseline at 525 — background traffic, nothing to do with us —
while the DuckDB session installs httpfs and creates its secret. Then view
binding starts, a connection is opened per object, and it goes vertical:
530 → 3,936 in five seconds, roughly a thousand new tracked connections per
second from a statement that hasn't returned a single row yet.
And then 4096, and it stops dead. Not hovering near the cap, not wobbling a few
entries either side — pinned to the exact value of nf_conntrack_max for
eleven consecutive samples while the ingest is still running. Real demand never
levels off that precisely. That's a table with nowhere left to put an entry.
Every SYN arriving during those eleven seconds was dropped, and the client
spent them working through the 1/2/4/8s backoff.
The shortened TIME_WAIT hadn't fixed that. It had let the table churn faster,
so the run got to the same wall sooner and sat there just as hard.
Raising the table itself removed the ceiling entirely:
sysctl -w net.netfilter.nf_conntrack_max=65536
Ingest: 12.3 seconds. Local-disk ingest of the same data is 3.0s, so this is now within ~4x of local over the network — that remainder is per-object fetch cost, not a bug.
Worth doing the memory arithmetic before you copy that line, though, because this is a 512 MB box: conntrack entries run about 300 bytes, so 65,536 of them is ~20 MB of kernel memory that Garage no longer gets to use.
So I benchmarked my way back down afterwards and settled on 32768. At 12.3s
the ingest opens ~7,000 connections in twelve seconds — around 570 per second,
which at a 30s TIME_WAIT is a working set near 17,000 entries. 32768 covers
that with room to spare at half the memory, and repeated runs at 32768 held the
same time as 65536, which is the only evidence I actually trust here. The honest
caveat is that 17,000 is an average, and the packet capture showed 5-second
bursts running about 3x the mean; on paper a bad enough burst could still brush
the cap. It hasn't yet, but that's the number I watch rather than assume.
Measure your own peak — the while loop above is the whole tool — instead of
inheriting mine.
One loose end either way: raising max without touching hashsize leaves the
table with the number of buckets it booted with. Chain depth is occupancy ÷
buckets, so check what you actually have before guessing at the cost:
sysctl net.netfilter.nf_conntrack_buckets
At a ~17,000 working set, 1024 buckets would mean 16-deep chains and a slower
lookup on every packet; 4096 buckets is a much less interesting 4. hashsize
isn't a sysctl — it's a module parameter, written through sysfs on a running
kernel:
echo 8192 > /sys/module/nf_conntrack/parameters/hashsize
max/4 is the guidance you'll find everywhere, which is where 8192 comes from —
but note it's advice from the era when the kernel's own default was 4:1. A 5.15
kernel picks 1:1, so matching hashsize to max is what upstream now considers
correct, and buckets are only 8 bytes each: 32768 of them is 256 KB. I kept 8192
because ~17,000 entries over 8192 buckets is barely 2 deep, but there's no real
argument for the memory saving.
| change | time |
|---|---|
baseline (read_json_auto, two passes) |
~263s (est.) |
| declared columns — one pass | 132.9s |
TIME_WAIT 120s → 30s |
45.1s |
nf_conntrack_max 4096 → 65536 |
12.3s |
"Slow server" primes you to look at compute. I spent the middle of this in
iostat and htop for no better reason than that's where the phrase points.
Neither tool can show you a packet that was dropped before the application ever
heard about it — the whole failure happened below the layer I was watching.
A small machine isn't slow — its defaults are. This is the part I'll actually carry forward. Nothing about 1 vCPU and 512 MB says "132 seconds to read 28 MB." The box was idle the whole time. What was slow was a table the kernel sized down because the box is small, and a newer kernel sizes it down harder: 4:1 became 1:1 between 5.10 and 5.15, so the same 512 MB VM that used to get 16384 entries now gets 4096. Small hosts inherit conservative defaults from every layer, and the defaults compound. Twenty megabytes of kernel memory — 4% of this VM's RAM — bought a 10x speedup, which is not a trade you'd ever get on a big machine, because on a big machine it's already made for you. So this is going on the list I run through when I set up a low-end box, next to swap and journald limits: check what the kernel derived from the RAM it found, and decide whether that's what I actually want.
An idle server during a stall is a strong signal, not a confusing one. It narrows things to "the request never arrived," which is a much smaller search space than "the server is slow."
tcpdump -ttt deserves to be reached for sooner. It attributes the gap:
after the request and before the response means the server; after the response
and before the next request means the client. No guessing.
Lowering concurrency is a mitigation that can make things more fragile. I
set DuckDB's threads to 4 for remote sources to reduce the connection rate
(the total is fixed at one per object). It helped — but a later capture showed
one drop burst taking out all four workers simultaneously and stalling the
pipeline dead for 25 of 49 seconds. With 8 workers, losing 4 leaves 4 running.
Fix the capacity, then raise the concurrency back.
sysctl -w doesn't survive a reboot. There's now a 10x speedup resting on
two kernel settings, and if they silently revert the regression will look like
witchcraft:
printf 'net.netfilter.nf_conntrack_max = 32768\nnet.netfilter.nf_conntrack_tcp_timeout_time_wait = 30\n' \
| sudo tee /etc/sysctl.d/99-conntrack.conf
echo 'options nf_conntrack hashsize=8192' | sudo tee /etc/modprobe.d/nf_conntrack.conf
Note that the three settings live in two different files, because hashsize is
a module parameter — the sysfs write above only holds until the module is
reloaded.
I'm happy with this. Twelve seconds is good enough — this is a homelab log viewer, not a service with an SLO, and I'd rather have the understanding than the last few seconds.
The nicest part is what htop shows now. Back at the start, the whole
motivating oddity was an idle server during a 132-second run: nothing to see,
because the requests weren't arriving. During a 12-second ingest today, Garage
sits at 70–90% of the CPU. The box is finally working — it's doing
signature verification and block serving flat out, which is exactly what it
should be doing when a client asks it for 6,600 objects as fast as it can.
That's a real result on its own: the bottleneck moved from a kernel table back to honest compute. And it tells me what the next step is — that's a single core at 90%, so scaling the VM up is now a change that should actually buy something, where before it would have bought nothing at all. That's the experiment I'll run next.
The other honest conclusion: none of this would have happened with fewer, larger objects. 28 MB in ~10 objects instead of 6,596 means ~10 connections, and the connection storm, the conntrack overflow, and the 20 ms per request all disappear together. Tuning the kernel was the right immediate fix. Compaction is the one that removes the problem — and that's for the next post.