ZFS send hangs sometimes

[rkojedzinszky]

System information

Type	Version/Name
Distribution Name	TrueNAS-CORE/FreeBSD
Distribution Version	13.3
Kernel Version	13.3-RELEASE-p7
Architecture	amd64
OpenZFS Version	2.2.6 + truenas patches

Describe the problem you're observing

TrueNAS is using zettarepl to replicate zfs datasets to remote sites. During a cycle, sometimes, rarely, zfs send hangs. The symptom is that zfs send hangs, not sending anything to its output, is in idle state. I've applied a workaround, a simpe pipe command which reads output from zfs send and passes data through, and this command is reporting that no output is received from zfs send for minutes. Then it kills zfs send. Also, it is reporting that usually only a few thousand bytes are sent by zfs send, not more. Then, simply killing zfs send solves the problem, upon next cycle it will usually send the snapshots completely, without errors.

Must note here that zfs used by TrueNAS contains this PR. I suspect this may be the source of my issue.

I suspect that 6bdc725 may be the source of my issue.

Usually, I receive send errors once in a week or two, cannot reproduce, but I will now give a try without this patch, and see the difference.

Describe how to reproduce the problem

Unfortunately, cannot reproduce.

Include any warning/errors/backtraces from the system logs

[vedadkajtaz]

I'm facing a somehow similar issue.

It occurs only on one out of 7 servers that all run the same OS (FreeBSD 14.1, OpenZFS 2.2.4), and use the same (home-made) zfs replication software.

It is basically a series of zfs send | ssh 'zfs receive'.

The zfs send seldom hangs (roughly once a week), on different datasets being sent.

Killing the piped ssh process does nothing either (which is expected, zfs send doesn't get an EPIPE since it doesn't send anything). Killing the zfs send works, and further iterations are okay, usually for a few days only.

There are no related dmesg messages, the pool is healthy (frequently scrub'd).

I'd be glad to help investigating the issue, but don't know where to look.

[rkojedzinszky]

@vedadkajtaz thanks!

I have to correct myself, zfs-2.2.4 also contains the suspected patch. If you would be able to test openzfs without commit 6bdc725, that would help. I am running 3 boxes now with that reverted, only for a few days, without hanging zfs send. But, I definitely would need more time to declare this as a possible cause.

[rkojedzinszky]

@vedadkajtaz did you have a chance to build zfs userspace with 6bdc725 reverted? Then, that will need some time, but according to your experiments, in a week you'll be able to report some results.

[vedadkajtaz]

@vedadkajtaz did you have a chance to build zfs userspace with 6bdc725 reverted? Then, that will need some time, but according to your experiments, in a week you'll be able to report some results.

Hi, I haven't done anything yet regarding this, possibly/likely next week, sorry.

[rkojedzinszky]

@nabijaczleweli I can report that reverting the mentioned commit caused no zfs send issues on 3 FreeBSD based NAS servers for more than a week now. Can you have a look at the commit?

[nabijaczleweli]

It looked sound back then so it looks sound now. No-one seems to have posted a strace (or backtrace) that would indicate where these hang, that commit basically doesn't touch the actually-sending-stuff thread at all, and all the setup is deterministic AFAICT. This bug hasn't left "oh i see this sometimes". I can't evaluate data you're withholding.

[vedadkajtaz]

I have a hung process (with stock binary, FreeBSD 14.1, OpenZFS 2.2.4) right now.

There is no strace on FreeBSD. truss was not helpful, no system calls whatsoever.
Here's the backtrace from gdb:

(gdb) bt
#0  0x000009ad512dae2c in ?? () from /lib/libthr.so.3
#1  0x000009ad512dfa2e in ?? () from /lib/libthr.so.3
#2  0x000009ad4dbcec83 in ?? () from /lib/libzfs.so.4
#3  0x000009ad4dbd0fbe in ?? () from /lib/libzfs.so.4
#4  0x000009ad4dbbf22a in zfs_iter_snapshots_sorted_v2 () from /lib/libzfs.so.4
#5  0x000009ad4dbd0876 in ?? () from /lib/libzfs.so.4
#6  0x000009ad4dbcc684 in ?? () from /lib/libzfs.so.4
#7  0x000009ad4dbcc1b6 in zfs_send () from /lib/libzfs.so.4
#8  0x000009a527a181f0 in ?? ()
#9  0x000009a527a12010 in ?? ()
#10 0x000009ad4f7b0a6a in __libc_start1 () from /lib/libc.so.7
#11 0x000009a527a1108d in ?? ()

Not super helpful without debugging symbols, but it's obviously stuck in libthr, which seems to indicate @rkojedzinszky is likely right.

[nabijaczleweli]

Would it be a terrible bother to take a backtrace, with symbols, of all the threads, so we don't have to guess what's happening? Attaching the strace-equivalent should in general be easier and tell you in which syscall each thread is stuck, but I don't really know if FreeBSD possesses this ability.

[vedadkajtaz]

I'll rebuild (stock, ie. releng/14.1) binaries with debugging symbols over the next few days, and wait for the next hung.

[rkojedzinszky]

@nabijaczleweli unfortunately, I can only add that since I am running my servers with the mentioned patch reverted, I am not facing with hung zfs processes.

[rkojedzinszky]

@nabijaczleweli I can report now that since I've reverted the mentioned patch, I am not experiencing the hanging issue. @vedadkajtaz what about your setup?

[vedadkajtaz]

It hung this morning, for the first time in a week, this is commit ff3df1211c4a08c36c6ced95eb141a9bb8151e12.

Thread 2 (LWP 252784 of process 16061):
#0  0x000000082a8e26aa in _sigsuspend () from /lib/libc.so.7
#1  0x00000008289a1fb6 in ?? () from /lib/libthr.so.3
#2  0x000000082a858a65 in pause () from /lib/libc.so.7
#3  0x0000000822ead7c9 in send_progress_thread (arg=0x820d26f20) at lib/libzfs/libzfs_sendrecv.c:1010
#4  0x0000000828998b05 in ?? () from /lib/libthr.so.3
#5  0x0000000000000000 in ?? ()
Backtrace stopped: Cannot access memory at address 0x82ec22000

Thread 1 (LWP 100935 of process 16061):
#0  0x0000000828995e2c in ?? () from /lib/libthr.so.3
#1  0x000000082899aa2e in ?? () from /lib/libthr.so.3
#2  0x0000000822eada3f in send_progress_thread_exit (hdl=0xb6dbd03c000, ptid=0xb6dbd012700, oldmask=oldmask@entry=0x820d26e10) at lib/libzfs/libzfs_sendrecv.c:1066
#3  0x0000000822eb0357 in dump_snapshot (zhp=0xb6dbd05a500, arg=arg@entry=0x820d28b28) at lib/libzfs/libzfs_sendrecv.c:1283
#4  0x0000000822ea014a in zfs_iter_snapshots_sorted_v2 (zhp=zhp@entry=0xb6dbd05a000, flags=flags@entry=0, callback=0x822eaff20 <dump_snapshot>, data=data@entry=0x820d28b28, min_txg=8867784, max_txg=8869382) at lib/libzfs/libzfs_iter.c:352
#5  0x0000000822eafd24 in dump_filesystem (zhp=0xb6dbd05a000, sdd=0x820d28b28) at lib/libzfs/libzfs_sendrecv.c:1356
#6  0x0000000822eaec89 in dump_filesystems (rzhp=0xb6dbd012700, rzhp@entry=0xb6dbd05a000, sdd=0x2, sdd@entry=0x820d28b28) at lib/libzfs/libzfs_sendrecv.c:1424
#7  0x0000000822eae403 in zfs_send_cb_impl (zhp=0xb6dbd05a000, fromsnap=<optimized out>, tosnap=0xb6dbd01040b "zpair-02749186397145403432-kenny-674d4ac4-18805166", flags=0x820d29350, outfd=1, filter_func=0x0, cb_arg=0x820d29330, debugnvp=0x0) at lib/libzfs/libzfs_sendrecv.c:2498
#8  0x0000000822eac26e in zfs_send_cb (outfd=0, arg=<optimized out>) at lib/libzfs/libzfs_sendrecv.c:2551
#9  0x0000000822eac237 in zfs_send (zhp=zhp@entry=0xb6dbd05a000, fromsnap=fromsnap@entry=0xb6dbd0190c0 "zpair-02749186397145403432-kenny-674d2ea4-74205ab9", tosnap=tosnap@entry=0xb6dbd01040b "zpair-02749186397145403432-kenny-674d4ac4-18805166", flags=0x0, flags@entry=0x820d29350, outfd=0, outfd@entry=1, filter_func=0x0, cb_arg=0x820d29330, debugnvp=0x0) at lib/libzfs/libzfs_sendrecv.c:2569
#10 0x0000000000215754 in zfs_do_send (argc=<optimized out>, argv=<optimized out>) at cmd/zfs/zfs_main.c:5099
#11 0x000000000020fd18 in main (argc=6, argv=0x820d294b0) at cmd/zfs/zfs_main.c:9249