Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 2620:137:e000::3:3 as permitted sender) client-ip=2620:137:e000::3:3;
MIME-Version: 1.0
References: <202310172247.b9959bd4-oliver.sang@intel.com>
In-Reply-To: <202310172247.b9959bd4-oliver.sang@intel.com>
From:   Max Kellermann <max.kellermann@ionos.com>
Date:   Wed, 18 Oct 2023 12:21:10 +0200
Message-ID: <CAKPOu+_T8xk4yd2P4KT4j3eMoFqwYmkxqDHaFtv4Hii5-XyPuA@mail.gmail.com>
Subject: Re: [linux-next:master] [drivers/char/mem] 1b057bd800:
 stress-ng.splice.ops_per_sec -99.8% regression
To:     kernel test robot <oliver.sang@intel.com>
Cc:     oe-lkp@lists.linux.dev, lkp@intel.com,
        Linux Memory Management List <linux-mm@kvack.org>,
        Greg Kroah-Hartman <gregkh@linuxfoundation.org>,
        linux-kernel@vger.kernel.org, ying.huang@intel.com,
        feng.tang@intel.com, fengwei.yin@intel.com
Content-Type: text/plain; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable
Precedence: bulk

On Tue, Oct 17, 2023 at 5:07=E2=80=AFPM kernel test robot <oliver.sang@inte=
l.com> wrote:
>     743.57          +334.3%       3229 =C4=85  3%  stress-ng.splice.MB_pe=
r_sec_splice_rate
>   7.46e+08           -99.8%    1373628 =C4=85  3%  stress-ng.splice.ops
>   12433266           -99.8%      22893 =C4=85  3%  stress-ng.splice.ops_p=
er_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) =3D 4
 pipe2([5, 6], 0)                  =3D 0
 fcntl(6, F_SETPIPE_SZ, 65536)     =3D 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) =3D 65536
 splice(5, NULL, 8, NULL, 65536, SPLICE_F_MOVE) =3D 65536
 [...]
 splice(5, [1], 6, [1], 4096, SPLICE_F_MORE) =3D -1 ESPIPE (Illegal seek)
 splice(4, NULL, 6, [1], 65536, SPLICE_F_MOVE) =3D -1 ESPIPE (Illegal seek)
 splice(5, [1], 13, NULL, 65536, SPLICE_F_MORE) =3D -1 ESPIPE (Illegal seek=
)
 splice(4, NULL, 6, NULL, 0, 0)    =3D 0
 splice(4, NULL, 6, NULL, 1,
SPLICE_F_MOVE|SPLICE_F_NONBLOCK|SPLICE_F_MORE|SPLICE_F_GIFT|0xfffffff0)
=3D -1 EINVAL (Invalid argument)
 splice(4, NULL, 6, NULL, 1, 0)    =3D -1 EINVAL (Invalid argument)
 splice(6, [0], 6, [0], 4096, SPLICE_F_MOVE) =3D -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) =3D 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) =3D 4
 pipe2([5, 6], 0)                  =3D 0
 fcntl(6, F_SETPIPE_SZ, 65536)     =3D 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) =3D 65536
 splice(5, NULL, 8, NULL, 65536, SPLICE_F_MOVE) =3D 65536
 [...]
 splice(5, [1], 6, [1], 4096, 0)   =3D -1 ESPIPE (Illegal seek)
 splice(4, NULL, 6, [1], 65536, SPLICE_F_MORE) =3D -1 ESPIPE (Illegal seek)
 splice(5, [1], 13, NULL, 65536, 0) =3D -1 ESPIPE (Illegal seek)
 splice(4, NULL, 6, NULL, 0, SPLICE_F_MOVE|SPLICE_F_MORE) =3D 0
 splice(4, NULL, 6, NULL, 1,
SPLICE_F_MOVE|SPLICE_F_NONBLOCK|SPLICE_F_MORE|SPLICE_F_GIFT|0xfffffff0)
=3D -1 EINVAL (Invalid argument)
 splice(4, NULL, 6, NULL, 1, 0)    =3D 1
 splice(6, [0], 6, [0], 4096, 0)   =3D -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) =3D 61440
 --- SIGALRM {si_signo=3DSIGALRM, si_code=3DSI_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