zfs send -v adds extra delay

[psy0rz]

System information

Type	Version/Name
Distribution Name	Ubuntu
Distribution Version	20.04
Linux Kernel	5.9.10-050910-generic
Architecture	x86_64
ZFS Version	2.0.1-0york0~20.04
SPL Version	2.0.1-0york0~20.04

Describe the problem you're observing

If i use the -v option of zfs send, it takes longer for the command to exit. (using it on an empty dataset)

Describe how to reproduce the problem

root@ws1:/home/psy/zfs_autobackup# zfs create rpool/test1
root@ws1:/home/psy/zfs_autobackup# zfs snapshot rpool/test1@a
root@ws1:/home/psy/zfs_autobackup# time zfs send rpool/test1@a >/dev/null

real	0m0,008s
user	0m0,006s
sys	0m0,000s
root@ws1:/home/psy/zfs_autobackup# time zfs send -v rpool/test1@a >/dev/null
full send of rpool/test1@a estimated size is 42.6K
total estimated size is 42.6K

real	0m1,007s
user	0m0,000s
sys	0m0,009s

I did some tests and it seems the problem didnt exist in 0.8.x.

You can imagine this delay is hugely annoying if you have a lot of small snapshots, or do regression testing like I was doing when i noticed it.

strace of last part:

write(2, "total estimated size is 42.6K\n", 30total estimated size is 42.6K
) = 30
clone(child_stack=0x7fc119baff30, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTIDstrace: Process 270173 attached
, parent_tid=[270173], tls=0x7fc119bb2700, child_tidptr=0x7fc119bb29d0) = 270173
[pid 270173] set_robust_list(0x7fc119bb29e0, 24 <unfinished ...>
[pid 270171] ioctl(5, _IOC(_IOC_NONE, 0x5a, 0x40, 0) <unfinished ...>
[pid 270173] <... set_robust_list resumed>) = 0
[pid 270173] clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=1, tv_nsec=0},  <unfinished ...>
[pid 270171] <... ioctl resumed>, 0x7ffef130d0e0) = 0
[pid 270171] futex(0x7fc119bb29d0, FUTEX_WAIT, 270173, NULL

********* 1 second delay here ***********

 <unfinished ...>
[pid 270173] <... clock_nanosleep resumed>0x7fc119bafda0) = 0

[pid 270173] ioctl(3, _IOC(_IOC_NONE, 0x5a, 0x3e, 0), 0x7fc119bac7e0) = -1 ENOENT (No such file or directory)
[pid 270173] madvise(0x7fc1193b2000, 8359936, MADV_DONTNEED) = 0
[pid 270173] exit(0)                    = ?
[pid 270171] <... futex resumed>)       = 0
[pid 270173] +++ exited with 0 +++
ioctl(3, _IOC(_IOC_NONE, 0x5a, 0x3f, 0), 0x7ffef130deb0) = -1 EPERM (Operation not permitted)
close(3)                                = 0
close(4)                                = 0
close(5)                                = 0
exit_group(0)                           = ?
+++ exited with 0 +++

[psy0rz]

Ping..can someone triage this already? Its a pretty annoying bug and making things really slow in https://github.com/psy0rz/zfs_autobackup

Copy paste this and notice how the zfs send takes a whole second instead of almost 0.

zfs create rpool/test1
zfs snapshot rpool/test1@a
time zfs send -v rpool/test1@a >/dev/null

[stale]

This issue has been automatically marked as "stale" because it has not had any activity for a while. It will be closed in 90 days if no further activity occurs. Thank you for your contributions.

[psy0rz]

stale bot! we meet again!

but beholdddd:

ws1# uname -a
Linux ws1 5.14.15-051415-generic #202111011158-Ubuntu SMP Mon Nov 1 12:17:41 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux
ws1# zfs version
zfs-2.1.2-0york1~20.04
zfs-kmod-2.1.2-0york1~20.04
ws1# FS=rpool/test; zfs create $FS; zfs snapshot $FS@a; time zfs send $FS@a >/tmp/test.dump; time zfs send -v $FS@a >/tmp/test.dump
zfs send $FS@a > /tmp/test.dump  0.00s user 0.00s system 75% cpu 0.006 total
full send of rpool/test@a estimated size is 46.6K
total estimated size is 46.6K
zfs send -v $FS@a > /tmp/test.dump  0.00s user 0.01s system 0% cpu 1.005 total

(both times should be approx 0, but the one where i use the verbose option is stretched to the next whole second by this bug)

So the problem still persists with 2.1.2 and a fairly new kernel. ( zfs send to > /dev/null was not supported with this kernel)

@ahrens could you perhaps take the literal second it takes to triage this bug? :)

This is the one liner:

FS=rpool/test; zfs create $FS; zfs snapshot $FS@a; time zfs send $FS@a >/tmp/test.dump; time zfs send -v $FS@a >/tmp/test.dump

Or should i create a pull-request for a regression test for this, so someone HAS to fix it? :P

[behlendorf]

The cause of the delay here is the progress reporting which is enabled with the -v option. The send_progress_thread() sleeps unconditionally for one second between reporting intervals, this means the thread won't promptly detect the completed send and exit causing the additional delay.

One nicer way to handle this would be to use pthread_cond_timedwait() in send_progress_thread() to sleep, this way we could signal the progress thread to exit immediately. This is the same approach taken by zpool_do_wait().

[psy0rz]

the problem didnt seem to exist in 0.8.x, maybe you can check how it was implemented there?

[nabijaczleweli]

#13284