linux-kernel - Re: [linux-next:master] [drivers/char/mem] 1b057bd800: stress-ng.splice.ops_per

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Date:   Wed, 18 Oct 2023 12:21:10 +0200
From:   Max Kellermann <max.kellermann@...os.com>
To:     kernel test robot <oliver.sang@...el.com>
Cc:     oe-lkp@...ts.linux.dev, lkp@...el.com,
        Linux Memory Management List <linux-mm@...ck.org>,
        Greg Kroah-Hartman <gregkh@...uxfoundation.org>,
        linux-kernel@...r.kernel.org, ying.huang@...el.com,
        feng.tang@...el.com, fengwei.yin@...el.com
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@...el.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