Re: [linux-next:master] [drivers/char/mem] 1b057bd800: stress-ng.splice.ops_per_sec -99.8% regression

[Max Kellermann]

On Tue, Oct 17, 2023 at 5:07 PM kernel test robot <oliver.sang@xxxxxxxxx> 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