db: investigate elevated batch commit tail latencies

[jbowens]

The following graphs are from one particular instance of this, but we've seen it across several test clusters including the 23.1 test cluster.

Internal discussion: https://cockroachlabs.slack.com/archives/C057ULDSKC0/p1686947338066129?thread_ts=1686924156.296339&cid=C057ULDSKC0

[jbowens]

(Potentially) related to:

• db: pipeline WAL rotation #2540
• cache: investigate mutex contention with TPCC #1997

Also, ingests can be disruptive to batch commit tail latencies, although it is definitely not the only factor because we've seen elevated batch commit tail latencies in the absence of ingests.:

• db: concurrent ingests may result in lengthy spin loop #2487
• db: improve ingested flushable flushing logic #2266
• db: reduce Ingest I/O with manifest+db locks #2112

[jbowens]

As far as I can tell, there are two primary sources of tail latency:

1. There's contention on d.commit.mu. Some batch commits block on acquiring d.commit.mu for 90ms:

slow batch commit: ‹(TotDur: 93.940495ms, SemaWait: 206ns, WALQueueWait: 0s, MemtblStall: 0s, L0Stall: 0s, WALRot: 0s, CommitWait: 489.115µs, MemtblApply: 10.924µs, Publish: 489.572µs, CommitMu: 93.436399ms, WALWrite: 1.094µs, DBMu: 124ns, PendingEnqueue: 308ns, RoomForWrite: 376ns, MemtblRot: 0s, MemtblPrep: 219ns)›

This seems to be driven by slow DB.makeRoomForWrite calls, which tend to be dominated by the memtable rotation:

slow make room for write: ‹(TotDur: 191.177358ms, SemaWait: 336ns, WALQueueWait: 0s, MemtblStall: 0s, L0Stall: 0s, WALRot: 607.996µs, CommitWait: 48ns, MemtblApply: 4.215µs, Publish: 797ns, CommitMu: 88ns, WALWrite: 2.49µs, DBMu: 91ns, PendingEnqueue: 227ns, RoomForWrite: 191.165895ms, MemtblRot: 190.55501ms, MemtblPrep: 347ns)›

I believe we're seeing contention on the table cache mutexes while reserving space for the memtables: #1997. These long memtable rotations keep DB.commit.mu locked throughout.

2. Once a batch has been applied to the memtable, we need to wait for a) the fsync to complete, if applicable, and b) for the sequence number to be published.

slow batch commit: ‹(TotDur: 80.033189ms, SemaWait: 233ns, WALQueueWait: 0s, MemtblStall: 0s, L0Stall: 0s, WALRot: 0s, CommitWait: 80.027419ms, MemtblApply: 2.887µs, Publish: 80.027626ms, CommitMu: 343ns, WALWrite: 441ns, DBMu: 32ns, PendingEnqueue: 126ns, RoomForWrite: 284ns, MemtblRot: 0s, MemtblPrep: 170ns)›

I tried to look at whether this might be solely due to the fsync by setting kv.raft_log.disable_synchronization_unsafe = true and found some batches still wait tens of milliseconds:

I230621 21:34:35.452617 1048 3@pebble/db.go:881 ⋮ [n2,s2,pebble] 5426  vslow batch commit: ‹(TotDur: 57.603998ms, SemaWait: 172ns, WALQueueWait: 0s, MemtblStall: 0s, L0Stall: 0s, WALRot: 0s, CommitWait: 57.596621ms, MemtblApply: 5.669µs, Publish: 57.596777ms, CommitMu: 72ns, WALWrite: 196ns, DBMu: 38ns, PendingEnqueue: 119ns, RoomForWrite: 183ns, MemtblRot: 0s, MemtblPrep: 99ns)›

I wonder if there's contention on the visible sequence number?:

		// We're responsible for publishing the sequence number for batch t, but
		// another concurrent goroutine might sneak in and publish the sequence
		// number for a subsequent batch. That's ok as all we're guaranteeing is
		// that the sequence number ratchets up.
		for {
			curSeqNum := p.env.visibleSeqNum.Load()
			newSeqNum := t.SeqNum() + uint64(t.Count())
			if newSeqNum <= curSeqNum {
				// t's sequence number has already been published.
				break
			}
			if p.env.visibleSeqNum.CompareAndSwap(curSeqNum, newSeqNum) {
				// We successfully published t's sequence number.
				break
			}
		}

[jbowens]

I played with a few tweaks looking to understand and reduce the tail latencies, including avoiding acquiring DB.mu in order to gain a reference to the mutable memtable: b77606f...a891d5d

It can be difficult to see past the noise, especially in the presence of write stalls which can spike log commit latency dramatically or on process start. The below graph uses a MIN aggregator to see past the spikes. It shows these changes do help in the very tail, but are more muted at p99.

For comparison, the WAL latency: