Mirror Stream sync is ~2.9× slower when a Consumer cold-scans the mirror during catch-up

[cyqsign]

Problem statement

With a JetStream Mirror Stream that has to sync a large sparse backlog
from its source, running a DeliverAll "cold-scan" Consumer on the mirror at
the same time makes the mirror catch-up ~2.9× slower than without the
Consumer.

Is this expected contention (a cold scanner competing with the mirror write
thread over the file store / block cache), or is there something in the mirror
path that is unnecessarily serialized behind consumer reads?

Setup

Single node, Hub + LeafNode as two separate nats-server processes (both
JetStream, domains hub and leaf), mirror on the LeafNode.

  Hub nats-server            LeafNode nats-server
  domain: hub                domain: leaf
  ┌──────────────┐           ┌───────────────────────┐
  │ Stream A     │◄──leafnode──►  Mirror Stream B    │
  │  (source)    │              (external $JS.hub.API)│
  └──────────────┘               │  + DeliverAll cold- │
                                 │    scan Consumer    │
                                 └─────────────────────┘

Environment where it was measured:

• nats-server v2.14.2
• CentOS 7 (kernel 3.10.0-957.27.2.el7)
• File storage, Replicas: 1

Source stream A: MaxMsgsPerSubject: 1 (KV semantics), AllowAtomicPublish,
AllowRollup, AllowDirect, Storage: File.
Mirror B: same retention/storage, AllowRollup + AllowDirect , mirroring A via external API prefix
$JS.hub.API.

A clean buildable reproduction package accompanies it (see the zip).
nats-mirror-consumer-perf-repro.zip

The data shape (why the stream is "sparse")

A KV subject space with hot-key write skew produces a stream with a huge seq
span and few live messages:

• keys = 1 000 000 subjects written once (cold floor, seq 1..1M);
  FirstSeq stays pinned at 1.
• hot-keys = 300 000: overwrites only touch the top segment of the key space.
• prewarm = 3 000 000: overwrites published as fast as possible. Each
  overwrite appends a seq but, with MaxMsgsPerSubject: 1, removes the
  subject's previous message — so live Msgs stays ≈ 1 M while LastSeq grows
  to ≈ 4 M.

Result: span ≈ 4 000 000, holes ≈ 3 000 000, hole ratio ≈ 75%. Every
message retrieval must skip through ~3 dead seqs on average.

Reproduction

nats-mirror-consumer-perf-repro -prewarm 3000000 -keys 1000000 -hot-keys 300000

The program drives both nats-server processes itself (external processes,
kept running after exit; next run kills + wipes data for a fresh state) and:

1. Generates the sparse backlog on A and lets B fully catch up once.
2. Step 3 (baseline): deletes + recreates B, measures time for B to sync
   A's whole sparse backlog from scratch, no Consumer.
3. Step 4: deletes + recreates B again and runs a DeliverAll cold-scan
   Consumer (AckNone, ephemeral, empty filter subject, re-scans head→tail in a
   loop) while B syncs; measures the sync time again.

The sync time is measured by LastSeq growth of the mirror until lag reaches
0 — so the difference is purely the Consumer's presence.

Results

	Mirror sync time	Min ingest rate
Step 3 — no Consumer	14.201 s	64 217 seq/s
Step 4 — with cold-scan Consumer	41.003 s	23 080 seq/s
Delta	+26.802 s (2.89×)	down 64%

Data integrity verified after both runs: mirror message counts match the
source and lag returns to 0, so both steps synced the same data.

questions

• The cold-scan Consumer and the mirror write thread share the same file store
  and block cache. The scan repeatedly walks
  LoadNextMsg → firstMatching over large stretches of holes while holding
  fs.mu (RLock over long spans) and pulling cold blocks into cache.

Questions for nats-server maintainers:

1. Is this magnitude of slowdown (2.9× on a 75%-sparse stream) expected given
   lock/block-cache contention, or is there a known inefficiency in the mirror
   pull-consumer path when it competes with reads?
2. Are there server-side settings that would reduce this contention (e.g.
   memory-cache / store options, consumer tuning, or mirror-specific settings)?

I can provide any additional measurements on request. @derekcollison @MauriceVanVeen

[gitsult4n]

This is very likely lock serialization, and the sparse/hole structure of this backlog is what makes it worse — though I want to flag upfront that this is a strong, code-grounded hypothesis rather than something I've isolated with a profiler, and it may be compounding with (not replacing) the disk/block-cache contention you already suspected. Both the mirror's write path and the cold-scan consumer's read path take the same single, whole-store fileStore.mu (sync.RWMutex), and the hole structure of this data roughly doubles the writer's lock acquisitions compared to what a dense mirror backlog would cost. That doubling is real and directly demonstrable in the code below; whether it alone accounts for the full 2.9x (versus, say, cold block reloads lengthening individual critical sections) is the part I can't prove from source reading alone.

The lock

// server/filestore.go:174-177
type fileStore struct {
	srv         *Server
	mu          sync.RWMutex
	state       StreamState
	...

One RWMutex guards the whole store: block list, state, everything. Every read of "what's next" and every write goes through it.

The read side: one RLock per delivered message

LoadNextMsg is what a plain (unfiltered) pull consumer calls once per delivered message:

// server/consumer.go:4884-4887
} else {
	// No filter here.
	sm, sseq, err = o.mset.store.LoadNextMsg(_EMPTY_, false, fseq, &pmsg.StoreMsg)
}

// server/filestore.go:9151-9157
func (fs *fileStore) LoadNextMsg(filter string, wc bool, start uint64, sm *StoreMsg) (*StoreMsg, uint64, error) {
	if fs.isClosed() {
		return nil, 0, ErrStoreClosed
	}
	fs.mu.RLock()
	defer fs.mu.RUnlock()
	...

For a DeliverAll, no-filter, cold-scan consumer this fires at roughly the same rate as messages are delivered — i.e. close to the mirror's own ingest rate. Note the lock is held for the whole call, including the loop that walks fs.blks — so a single LoadNextMsg invocation that has to step over several holes-only blocks holds fs.mu.RLock() for the entire multi-block walk, not just one block.

The write side: two Locks per live message, not one

Every normal mirrored message is persisted through StoreMsg/StoreRawMsg, which take the same lock — the comment even says so:

// server/filestore.go:5127-5129
// Store stores a message. We hold the main filestore lock for any write operation.
func (fs *fileStore) StoreMsg(subj string, hdr, msg []byte, ttl int64) (uint64, int64, error) {
	fs.mu.Lock()

But this stream isn't just receiving live messages — it's sparse. MaxMsgsPerSubject: 1 on the source means most historical seqs for hot keys are already gone by the time the mirror's internal consumer walks the source, so the sseq the mirror receives jumps ahead of the last one it processed:

// server/stream.go:3217-3227
// If the deliver sequence matches then the upstream stream has expired or deleted messages.
if dseq == mset.mirror.dseq+1 {
	if err := mset.skipMsgs(mset.mirror.sseq+1, sseq-1); err != nil {
		...
	}
	mset.mirror.dseq++
	mset.mirror.sseq = sseq
}

skipMsgs, for a non-clustered stream (Replicas: 1, as in the repro), calls store.SkipMsgs directly to backfill that gap so the mirror's local sequence numbering still matches the source's:

// server/stream.go:3345-3348
if node == nil {
	if err := store.SkipMsgs(start, end-start+1); err != nil {
		return err
	}

// server/filestore.go:5238-5240
func (fs *fileStore) SkipMsgs(seq uint64, num uint64) error {
	fs.mu.Lock()
	defer fs.mu.Unlock()

So for every live message that arrives after a gap, B does two exclusive fs.mu.Lock() acquisitions — one for SkipMsgs to fill the gap, one for StoreMsg/StoreRawMsg to persist the message — where a dense mirror backlog would only need one. At a ~75% hole ratio with ~3 dead seqs per live one on average, that's close to a 2x increase in exclusive-lock acquisitions on the write side alone, layered directly against the consumer's near-1:1 RLock traffic on the read side. Go's sync.RWMutex is writer-preferring: once a Lock() call is queued, subsequent RLock() calls queue behind it too — so more frequent writer locks mean the reader gets starved out more often, and vice versa.

Where I'd push back on my own reasoning: I don't think it's safe to assume these critical sections are uniformly short. firstMatching (the per-block scan LoadNextMsg calls) takes mb.mu.Lock() and, if the block's cache isn't loaded, calls loadMsgsWithLock() (filestore.go:8413) — a disk-backed cache populate — while holding that lock. Your harness's continuousConsumer restarts a full head-to-tail scan every round (its own code comment says as much: "mimics ... a full cold scan"), which is exactly the access pattern that would evict the blocks near the mirror's actively-written tail from cache between rounds. If that's happening, some fraction of these lock holds are not cheap in-memory pointer-chasing but actual disk reads gated behind a lock — meaning lock-acquisition count and disk/page-cache pressure are probably not independent, competing explanations here, but two views of the same mechanism. Message-count parity between your two runs (which you confirmed) rules out logical data-shape differences, but it doesn't rule out one run doing more physical re-reads of the same blocks than the other.

Answering the two questions directly

1. I don't think this is simply "expected" disk/block-cache contention in the sense of being an unavoidable cost of the workload — it's at least partly a design property of the current single coarse-grained fileStore.mu, which serializes every write anywhere in the store against every read anywhere in the store, regardless of which blocks are actually touched. That serialization is real and doubles in frequency here because of the sparse mirror backlog (SkipMsgs + StoreMsg per live message vs. just StoreMsg). Whether the remaining gap between "2x more lock acquisitions" and "2.9x slower wall-clock" is fully explained by that alone, or partly by cold-block reloads happening inside those same locks, I can't say for certain without a mutex/CPU profile (go tool pprof with block/mutex profiling enabled on the server) from an actual run — that would be the concrete way to settle it.
2. There's no FileStoreConfig/stream/consumer setting that narrows this lock's scope — BlockSize, cache/sync options, etc. don't change what StoreMsg, StoreRawMsg, SkipMsg, SkipMsgs, and LoadNextMsg lock. One concrete, testable mitigation: the SkipMsgs half of the extra write-lock traffic exists only to backfill the historical hole structure during initial catch-up — it has nothing to do with steady-state traffic (new keys don't need artificial gap-fills). If you gate starting the cold-scan consumer on the mirror's lag reaching 0 (poll STREAM.INFO for the mirror's lag/active state) instead of running it concurrently with the initial sync, you should remove the doubling effect during catch-up entirely; the consumer would then only contend with the single per-message StoreMsg/StoreRawMsg lock that any live mirror traffic causes. Worth confirming with a repeat measurement rather than assuming it fully closes the gap, given the uncertainty above about cache-driven lock hold time.

One thing in your own harness worth flagging: continuousConsumer (main.go:942-963 in the repro zip) creates a brand-new ephemeral consumer via CreateOrUpdateConsumer on every scan round with no explicit name, relying only on InactiveThreshold: 30s to reap the old ones. Each of those creations does its own I/O and locking (writing consumer assignment state) on top of the LoadNextMsg contention you're trying to isolate. If you want a cleaner measurement of pure read-vs-write lock contention, reuse a single long-lived consumer across rounds instead of recreating it every time the scan hits EOF — and if you're able to, a mutex-profile capture from both the "no consumer" and "with consumer" runs would directly show whether it's acquisition count, hold time, or both.