SEEK_HOLE loop & forced syncing causes never-ending delay in grep

[StefanEnspired]

System information

Type	Version/Name
Distribution Name	Fedora
Distribution Version	37
Kernel Version	6.1.11-200.fc37.x86_64
Architecture	x86_64
OpenZFS Version	2.1.8

Describe the problem you're observing

When I have a log-generating program and want to run grep on its output, it never finishes.

Describe how to reproduce the problem

A reproducer is this log generator in go, which can easily be used to trigger this condition. When I pipe its output into a file and run grep on it while it’s running, grep cannot run until the generator is stopped. I can reproduce this inside a plain Fedora 37 VM with 4 GB of memory, a completely empty pool on an empty virtual disk. Setting zfs_dmu_offset_next_sync=0 eliminates this problem. It was introduced in #12724

Mailing list link: https://zfsonlinux.topicbox.com/groups/zfs-discuss/T696e33a9741edf03/reading-buffered-data-causes-io-storm

package main

import (
	"fmt"
	"math/rand"
	"time"
)

func main() {
	seq := make([]uint64, 20)
	var number int
	for {
		for i := 0; i < 19; i++ {
			seq[i] = seq[i+1]
		}
		seq[19] = rand.Uint64()
		number++
		fmt.Printf("{\"level\":\"debug\",\"log\":\"Sequence %v\",\"number\":%d,\"my-time\":\"%v\"}\n", seq, number, time.Now())
		time.Sleep(time.Millisecond)
	}
}

[rincebrain]

In theory, that PR is supposed to avoid that by the caller holding the rangelock, according to the comment, so it shouldn't get dirtied again and never return, assuming that's what transpires.

A trivial workaround, assuming that's what happens, would be to make it refuse to go through that codepath twice so it falls back to the tunable off behavior in that case, and just says no holes. An alternate behavior would be to assume it's good enough once synced once, but I guess that depends on the semantics anyone might expect from that.

@behlendorf any ideas why this might not be doing what the comment expects?

[jknepher]

In case it is helpful, I experience the same problem, and have for a while. I have trained myself to always use cat/tail | grep rather than directly using grep on any active log file, as that works fine.
x86_64
Linux 5.10.52-gentoo
zfs-kmod-2.1.99-943_g045aeabce

[devZer0]

@rincebrain ,for me this looks very different from #14594

if there is a correlation here, it can be easily tested

• disable atime or enable relatime and retry
• check if it still happens with 2.1.4

[behlendorf]

The dn_struct_rwlock locking in dmu_offset_next() is supposed to protect against a concurrent dirtying update. But it seems pretty clear from the reproducer there's an update happening outside that lock. PR #13368 may help, but it'll depend on exactly what is being dirtied and where. This change also still needs some work.

[devZer0]

@rincebrain ,for me this looks very different from #14594

if there is a correlation here, it can be easily tested

* disable atime or enable relatime and retry
* check if it still happens with 2.1.4

i was wrong with this, apparently Setting zfs_dmu_offset_next_sync=0 eliminates my problem, too

[dbavatar]

We his this too on kernel 5.15, after pulling latest zfs turned zfs_dmu_offset_next_sync on by default. I remember that zfs_holey() fn was very iffy. Would be nice if someone is smart enough to get that data from in-memory state without causing a txg_sync.