Messages in this thread | | | From | Max Kellermann <> | Date | Wed, 18 Oct 2023 12:21:10 +0200 | Subject | Re: [linux-next:master] [drivers/char/mem] 1b057bd800: stress-ng.splice.ops_per_sec -99.8% regression |
| |
On Tue, Oct 17, 2023 at 5:07 PM kernel test robot <oliver.sang@intel.com> wrote: > 743.57 +334.3% 3229 ą 3% stress-ng.splice.MB_per_sec_splice_rate > 7.46e+08 -99.8% 1373628 ą 3% stress-ng.splice.ops > 12433266 -99.8% 22893 ą 3% stress-ng.splice.ops_per_sec
I think this might be caused by a bug in stress-ng, leading to blocking pipe writes.
This is how it looks before my patch:
openat(AT_FDCWD, "/dev/zero", O_RDONLY) = 4 pipe2([5, 6], 0) = 0 fcntl(6, F_SETPIPE_SZ, 65536) = 65536 [...] write(6, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 65536) = 65536 splice(5, NULL, 8, NULL, 65536, SPLICE_F_MOVE) = 65536 [...] splice(5, [1], 6, [1], 4096, SPLICE_F_MORE) = -1 ESPIPE (Illegal seek) splice(4, NULL, 6, [1], 65536, SPLICE_F_MOVE) = -1 ESPIPE (Illegal seek) splice(5, [1], 13, NULL, 65536, SPLICE_F_MORE) = -1 ESPIPE (Illegal seek) splice(4, NULL, 6, NULL, 0, 0) = 0 splice(4, NULL, 6, NULL, 1, SPLICE_F_MOVE|SPLICE_F_NONBLOCK|SPLICE_F_MORE|SPLICE_F_GIFT|0xfffffff0) = -1 EINVAL (Invalid argument) splice(4, NULL, 6, NULL, 1, 0) = -1 EINVAL (Invalid argument) splice(6, [0], 6, [0], 4096, SPLICE_F_MOVE) = -1 ESPIPE (Illegal seek) [...] write(6, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 65536) = 65536
Each iteration writes 65536 bytes into the pipe and then reads those 65536 bytes back from the pipe.
After my patch (but "use_splice" disabled manually so the syscalls are the same):
openat(AT_FDCWD, "/dev/zero", O_RDONLY) = 4 pipe2([5, 6], 0) = 0 fcntl(6, F_SETPIPE_SZ, 65536) = 65536 [...] write(6, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 65536) = 65536 splice(5, NULL, 8, NULL, 65536, SPLICE_F_MOVE) = 65536 [...] splice(5, [1], 6, [1], 4096, 0) = -1 ESPIPE (Illegal seek) splice(4, NULL, 6, [1], 65536, SPLICE_F_MORE) = -1 ESPIPE (Illegal seek) splice(5, [1], 13, NULL, 65536, 0) = -1 ESPIPE (Illegal seek) splice(4, NULL, 6, NULL, 0, SPLICE_F_MOVE|SPLICE_F_MORE) = 0 splice(4, NULL, 6, NULL, 1, SPLICE_F_MOVE|SPLICE_F_NONBLOCK|SPLICE_F_MORE|SPLICE_F_GIFT|0xfffffff0) = -1 EINVAL (Invalid argument) splice(4, NULL, 6, NULL, 1, 0) = 1 splice(6, [0], 6, [0], 4096, 0) = -1 ESPIPE (Illegal seek) [...] write(6, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 65536) = 61440 --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---
Just as before, each iteration reads 65536 bytes from the pipe, but it will write an additional byte into the pipe, because the second splice(/dev/zero) did not fail with EINVAL! The next write() blocks because the pipe buffer is already full, eventually killing the process with SIGALRM due to timeout.
Oliver, am I on the right track here? Is this really a bug in stress-ng?
(I still don't get why the throughput increases.)
Max
| |