storage: disk stall detector does not fire on dmsetup suspend

[erikgrinaker]

#94240 added a roachtest that measures pMax latency during a leaseholder disk stall. The expectation was that the disk stall detector would fire after 20 seconds and restart the node, but this never happened. The disk was confirmed to be stalled by running touch /mnt/data1/foo && sync, and the relevant cluster settings were confirmed to use the defaults.

Repro:

# Set up a simple linear mapping (pass-through) of the underlying block device and mount it.
$ sudo umount /mnt/data1
$ echo "0 $(sudo blockdev --getsz /dev/nvme0n1) linear /dev/nvme0n1 0" | sudo dmsetup create data1
$ sudo mount /dev/mapper/data1 /mnt/data1

# Start CRDB.
$ roachprod start foo

# Suspend IO.
$ sudo dmsetup suspend --noflush --nolockfs data1

# Resume IO.
$ sudo dmsetup resume --noflush --nolockfs data1

Or alternatively just run the failover/non-system/disk-stall roachtest, and inspect e.g. n4 once it's stalled:

$ roachtest run failover/non-system/disk-stall --debug-always

Jira issue: CRDB-22860

[jbowens]

Crashing the process when a stall is detected happens here, within a callback on a Pebble EventListener:

cockroach/pkg/storage/pebble.go

Lines 1062 to 1079 in 6af6c6d

	DiskSlow: func(info pebble.DiskSlowInfo) {
	maxSyncDuration := MaxSyncDuration.Get(&p.settings.SV)
	fatalOnExceeded := MaxSyncDurationFatalOnExceeded.Get(&p.settings.SV)
	if info.Duration.Seconds() >= maxSyncDuration.Seconds() {
	atomic.AddInt64(&p.diskStallCount, 1)
	// Note that the below log messages go to the main cockroach log, not
	// the pebble-specific log.
	if fatalOnExceeded {
	log.Fatalf(ctx, "disk stall detected: pebble unable to write to %s in %.2f seconds",
	info.Path, redact.Safe(info.Duration.Seconds()))
	} else {
	log.Errorf(ctx, "disk stall detected: pebble unable to write to %s in %.2f seconds",
	info.Path, redact.Safe(info.Duration.Seconds()))
	}
	return
	}
	atomic.AddInt64(&p.diskSlowCount, 1)
	},

The EventListener installed on Pebble wraps two event listeners, the default logging one and the crashing one:

cockroach/pkg/storage/pebble.go

Lines 985 to 991 in 6af6c6d

	el := pebble.TeeEventListener(
	pebble.MakeLoggingEventListener(pebbleLogger{
	ctx: logCtx,
	depth: 2, // skip over the EventListener stack frame
	}),
	p.makeMetricEtcEventListener(ctx),
	)

. The crashing one is installed second. I don't see any reason why the EventListener.DiskSlow invocation wouldn't get stuck in the logging event listener's attempt to write the event to the log file.

[sumeerbhola]

We could just reverse the order, right? If it is a crashing event, then we don't mind that the Pebble logs miss that event.

[petermattis]

Does the charybdefs-based disk-stall roachtest only stall the store directory and not the logging directory?

[jbowens]

Yeah, I'm going to try to grab a stack trace from the above roachtest during the stall to confirm.

Does the charybdefs-based disk-stall roachtest only stall the store directory and not the logging directory?

Looks like it

	c.Run(ctx, n, "sudo charybdefs {store-dir}/faulty -oallow_other,modules=subdir,subdir={store-dir}/real")

[sean-]

Repro:

1. Create a 3x AZ cluster w/ 3x nodes per AZ.
2. Move the crdb process into a cgroup
3. Determine the device names of the stores mounted on each crdb node (e.g., lsblk)
4. Run any KV workload that spreads the work across all three nodes (50/50 read/write)
5. On one (or all nodes) in one of the AZs, run the following:

DEVICE_NAMES="data1|data2"
disklist=$(lsblk|egrep -i "${DEVICE_NAMES}"|awk '{print $1}')

i=1;
for diskname in $disklist
do
echo "`lsblk -np /dev/${diskname}|awk '{print $2}'` $i" > /sys/fs/cgroup/blkio/blkio.throttle.write_bps_device;
echo "`lsblk -np /dev/${diskname}|awk '{print $2}'` $i" > /sys/fs/cgroup/blkio/blkio.throttle.read_bps_device;
done



i=1;
for diskname in $disklist
do
echo "`lsblk -np /dev/${diskname}|awk '{print $2}'` $i" > /sys/fs/cgroup/blkio/blkio.throttle.write_iops_device;
echo "`lsblk -np /dev/${diskname}|awk '{print $2}'` $i" > /sys/fs/cgroup/blkio/blkio.throttle.read_iops_device;
done

[jbowens]

We could just reverse the order, right?

I think we also might need to run DiskSlow handlers in a separate goroutine. Otherwise, it seems like a stalled log write could halt the goroutine that's responsible for monitoring a file's writes. The first 'DiskSlow' event for a non-fatal duration may never return.

[petermattis]

Does the charybdefs-based disk-stall roachtest only stall the store directory and not the logging directory?

Looks like it

But later on it configures the logging dir as either faulty/logs or real/logs. That roachtest tests the matrix of stalled logging dir and stalled store dir. See registerDiskStalledDetection.

[jbowens]

But later on it configures the logging dir as either faulty/logs or real/logs. That roachtest tests the matrix of stalled logging dir and stalled store dir. See registerDiskStalledDetection.

Ah, thanks—maybe this explains it. If charybdefs only delays syscalls for 50ms, we'll eventually return and crash the process.

	// NB: charybdefs' delay nemesis introduces 50ms per syscall. It would
	// be nicer to introduce a longer delay, but this works.
	tooShortSync := 40 * time.Millisecond

[sean-]

@jbowens : that's another good idea: potentially call runtime.LockOSThread for the go routine handling DiskSlow so its underlying sys thread can't be preempted for other work that will be caught up in the disk stall.

[jbowens]

Grabbing stack traces from the running node, there's a different or additional issue. When we open a new WAL, we call (vfs.FS).Create or (vfs.FS).ReuseForWrite to obtain a file handle for our new WAL. Since the VFS passed into Options.FS is wrapped with disk health checking, this file handle has disk-health checking.

But before we begin using the new WAL, we wrap it with vfs.NewSyncingFile to add periodic syncing to reduce latency spikes. The syncing file performs I/O outside the vfs.File interface (eg, Fdatasync), and this I/O needs to be timed. So the syncing file does a contortion to check if the file that it's wrapping is a disk-health checking file and wrap the operation with the timing if so: https://github.com/cockroachdb/pebble/blob/4199154043c56ed233b670d28114561073009c50/vfs/syncing_file.go#L62-L71

But in the time since disk-health checking was added we've accumulated additional VFS middleware, and the disk-health checking VFS is not the top of the stack. This leaves these non-vfs.File I/O ops untimed.

goroutine 96 [syscall, 21 minutes]:
syscall.Syscall(0x46f65f?, 0x476351?, 0xc001531b11?, 0xc0027e0d80?)
	GOROOT/src/syscall/syscall_linux.go:68 +0x27
golang.org/x/sys/unix.Fdatasync(0x46f9a7?)
	golang.org/x/sys/unix/external/org_golang_x_sys/unix/zsyscall_linux.go:712 +0x30
github.com/cockroachdb/pebble/vfs.(*syncingFile).syncFdatasync.func1()
	github.com/cockroachdb/pebble/vfs/external/com_github_cockroachdb_pebble/vfs/syncing_file_linux.go:63 +0x2a
github.com/cockroachdb/pebble/vfs.NewSyncingFile.func1(0x1080c0f?)
	github.com/cockroachdb/pebble/vfs/external/com_github_cockroachdb_pebble/vfs/syncing_file.go:73 +0x1a
github.com/cockroachdb/pebble/vfs.(*syncingFile).syncFdatasync(0xc001cb9e00)
	github.com/cockroachdb/pebble/vfs/external/com_github_cockroachdb_pebble/vfs/syncing_file_linux.go:62 +0x9c
github.com/cockroachdb/pebble/vfs.(*syncingFile).Sync(0x4f2c97?)
	github.com/cockroachdb/pebble/vfs/external/com_github_cockroachdb_pebble/vfs/syncing_file.go:136 +0x46
github.com/cockroachdb/pebble/record.(*LogWriter).syncWithLatency(0xc0001dc500)
	github.com/cockroachdb/pebble/record/external/com_github_cockroachdb_pebble/record/log_writer.go:545 +0x43
github.com/cockroachdb/pebble/record.(*LogWriter).flushPending(0xc0001dc500, {0xc001531b11, 0x220, 0x4f7}, {0xc001066000, 0x0, 0x4fdec6?}, 0x16e, 0x16d)
	github.com/cockroachdb/pebble/record/external/com_github_cockroachdb_pebble/record/log_writer.go:532 +0x1dc
github.com/cockroachdb/pebble/record.(*LogWriter).flushLoop(0xc0001dc500, {0x4ecce60, 0xae7af58})
	github.com/cockroachdb/pebble/record/external/com_github_cockroachdb_pebble/record/log_writer.go:466 +0x358
runtime/pprof.Do({0x6c413f8?, 0xc000128000?}, {{0xc000080880?, 0xa159a74074462db8?, 0x67f6ce90e736b243?}}, 0xc0012237c0)
	GOROOT/src/runtime/pprof/runtime.go:40 +0xa3
github.com/cockroachdb/pebble/record.NewLogWriter.func2()
	github.com/cockroachdb/pebble/record/external/com_github_cockroachdb_pebble/record/log_writer.go:351 +0x5c
created by github.com/cockroachdb/pebble/record.NewLogWriter
	github.com/cockroachdb/pebble/record/external/com_github_cockroachdb_pebble/record/log_writer.go:350 +0x456

The interface assertion contortion here is way too brittle, and I think we should elevate what we need up to the vfs.File interface like we did in cockroachdb/pebble#2262.

[petermattis]

@jbowens : that's another good idea: potentially call runtime.LockOSThread for the go routine handling DiskSlow so its underlying sys thread can't be preempted for other work that will be caught up in the disk stall.

If I'm understanding this suggestion correctly, it is trying to solve for ensuring that the goroutine watching for stalled disk IOPs has a runnable thread. Do we have any evidence that is a problem? The Go runtime would have a serious bug if there is a scenario where a runnable goroutine is not run for a significant period of time. As @jbowens is discovering, I suspect we simply have other more basic bugs in the stalled IOPs detection.

[bobvawter]

I did some reductionist testing yesterday to look at the go runtime's behavior if you have many goroutines doing IO and then you starve it out. In the limit, the 1.19 runtime will allow only 10,000 OS threads for executing (blocked) syscalls and then panic once it hits the limit. I was never able to break the HTTP service with blocked disk IO because, as I understand it, the epoll loop has a dedicated OS thread that proceeds to dispatch into the rest of the runtime.

stall.tgz

[erikgrinaker]

@jbowens Can we close this out now? The motivating benchmark is now showing disk stalls handled correctly: https://roachperf.crdb.dev/?filter=&view=failover%2Fnon-system%2Fdisk-stall&tab=gce.

[jbowens]

Yeah, let's close it out.