Received-SPF: pass (google.com: domain of linux-nfs+bounces-188-linux.lists.archive=gmail.com@vger.kernel.org designates 139.178.88.99 as permitted sender) client-ip=139.178.88.99;
Date: Thu, 30 Nov 2023 14:36:32 +0700
From: Bagas Sanjaya <bagasdotme@gmail.com>
To: "Sukruth Sridharan (he/him)" <susridharan@purestorage.com>,
	Linux Network File System <linux-nfs@vger.kernel.org>,
	Linux RDMA <linux-rdma@vger.kernel.org>
Cc: Chuck Lever <chuck.lever@oracle.com>, Jeff Layton <jlayton@kernel.org>,
	Neil Brown <neilb@suse.de>, Olga Kornievskaia <kolga@netapp.com>,
	Dai Ngo <Dai.Ngo@oracle.com>, Tom Talpey <tom@talpey.com>,
	Saeed Mahameed <saeedm@nvidia.com>,
	Leon Romanovsky <leonro@nvidia.com>
Subject: Re: Hung task panic as part of NFS RDMA Disconnect due to possible
 bug on 6.2.0-34-generic client
Message-ID: <ZWg7gGnvVOYjIhx1@archie.me>
References: <CAMyEAb9XbL55taNXD_MrTxJz62s6ByDWiK8m1Nxj1_G3pg-M6A@mail.gmail.com>
Precedence: bulk
MIME-Version: 1.0
Content-Type: multipart/signed; micalg=pgp-sha512;
	protocol="application/pgp-signature"; boundary="Bj68ANcoh+ILJN6F"
Content-Disposition: inline
In-Reply-To: <CAMyEAb9XbL55taNXD_MrTxJz62s6ByDWiK8m1Nxj1_G3pg-M6A@mail.gmail.com>


--Bj68ANcoh+ILJN6F
Content-Type: text/plain; charset=utf-8
Content-Disposition: inline
Content-Transfer-Encoding: quoted-printable

On Thu, Nov 30, 2023 at 10:52:59AM +0530, Sukruth Sridharan (he/him) wrote:
> I notice the following hung task panic on 6.2.0-34 kernel during RDMA dis=
connect
>=20
> [Wed Nov  1 08:03:54 2023] INFO: task kworker/u16:5:2274646 blocked
> for more than 120 seconds.
> [Wed Nov  1 08:03:55 2023]       Tainted: G        W  OE
> 6.2.0-34-generic #34-Ubuntu
> [Wed Nov  1 08:03:55 2023] "echo 0 >
> /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [Wed Nov  1 08:03:55 2023] task:kworker/u16:5   state:D stack:0
> pid:2274646 ppid:2      flags:0x00004000
> [Wed Nov  1 08:03:55 2023] Workqueue: xprtiod xprt_autoclose [sunrpc]
> [Wed Nov  1 08:03:55 2023] Call Trace:
> [Wed Nov  1 08:03:55 2023]  <TASK>
> [Wed Nov  1 08:03:55 2023]  __schedule+0x2aa/0x610
> [Wed Nov  1 08:03:55 2023]  schedule+0x63/0x110
> [Wed Nov  1 08:03:55 2023]  schedule_timeout+0x157/0x170
> [Wed Nov  1 08:03:55 2023]  wait_for_completion+0x88/0x150
> [Wed Nov  1 08:03:55 2023]  rpcrdma_xprt_disconnect+0x33f/0x350 [rpcrdma]
> [Wed Nov  1 08:03:55 2023]  xprt_rdma_close+0x12/0x40 [rpcrdma]
> [Wed Nov  1 08:03:55 2023]  xprt_autoclose+0x5c/0x120 [sunrpc]
> [Wed Nov  1 08:03:55 2023]  process_one_work+0x225/0x430
> [Wed Nov  1 08:03:55 2023]  worker_thread+0x50/0x3e0
> [Wed Nov  1 08:03:55 2023]  ? __pfx_worker_thread+0x10/0x10
> [Wed Nov  1 08:03:55 2023]  kthread+0xe9/0x110
> [Wed Nov  1 08:03:55 2023]  ? __pfx_kthread+0x10/0x10
> [Wed Nov  1 08:03:55 2023]  ret_from_fork+0x2c/0x50
> [Wed Nov  1 08:03:55 2023]  </TASK>
>=20
> The flow which induced the bug is as follows:
> 1. Client initiates connection
> 2. Server hands off the response to the first RPC on the connection to
> the NIC (Mellanox ConnectX-5)
> 3. NIC tries to send the response around 6 times and fails the response w=
ith RNR
> 4. Client issues disconnect (possibly because it didn't receive a respons=
e)
> 5. Server cleans up the connection state
> 6. Client runs into the above panic as part of disconnect while draining =
the IOs
>=20
> It looks like re_receiving is set only in rpcrdma_post_recvs, and the
> reason why it wouldn't be reset is if memory-region allocation code
> fails.
> That is possible if disconnect on the client somehow blocks allocation.
>=20
> void rpcrdma_post_recvs(struct rpcrdma_xprt *r_xprt, int needed, bool tem=
p)
> {
>         // ... (some initialization code)
>=20
>     if (atomic_inc_return(&ep->re_receiving) > 1)
>         goto out;
>=20
>         // ... (some allocation code)
>=20
>     if (!wr) // <<<<<<<<<<<<<<<<<< PROBLEM HERE >>>>>>>>>>>>>>>>>>>
>         goto out;
>=20
>         // ... (post recv code, and some error handling)
>=20
>     if (atomic_dec_return(&ep->re_receiving) > 0)
>         complete(&ep->re_done);
>=20
> out:
>     trace_xprtrdma_post_recvs(r_xprt, count);
>     ep->re_receive_count +=3D count;
>     return;
> }
>=20
> static void rpcrdma_xprt_drain(struct rpcrdma_xprt *r_xprt)
> {
>     struct rpcrdma_ep *ep =3D r_xprt->rx_ep;
>     struct rdma_cm_id *id =3D ep->re_id;
>=20
>     /* Wait for rpcrdma_post_recvs() to leave its critical
>      * section.
>      */
>     if (atomic_inc_return(&ep->re_receiving) > 1) //
> <<<<<<<<<<<<<<<<<<< This is not reset, so wait gets stuck
> >>>>>>>>>>>>>>>>>
>         wait_for_completion(&ep->re_done);
>=20
>     /* Flush Receives, then wait for deferred Reply work
>      * to complete.
>      */
>     ib_drain_rq(id->qp);
>=20
>     /* Deferred Reply processing might have scheduled
>      * local invalidations.
>      */
>     ib_drain_sq(id->qp);
>=20
>     rpcrdma_ep_put(ep);
> }
>=20
> Can you help conclude if the above theory around the bug being in the
> client code is right? If not, can you help with steps/data points
> required to debug this further?
>=20

Can you verify that the bug still occurs with latest vanilla kernel
(currently v6.7-rc3)?

Thanks.

--=20
An old man doll... just what I always wanted! - Clara

--Bj68ANcoh+ILJN6F
Content-Type: application/pgp-signature; name="signature.asc"

-----BEGIN PGP SIGNATURE-----

iHUEABYKAB0WIQSSYQ6Cy7oyFNCHrUH2uYlJVVFOowUCZWg7ewAKCRD2uYlJVVFO
o2LoAQD/DycCySM1guMz6DbpdVpzp3oHU+m/0FMWHT5Vu0QIJQEAv1BMp5IzPAne
zyv7DbEj1tZecHdsHzqVgA6taXIhvAU=
=yVp9
-----END PGP SIGNATURE-----

--Bj68ANcoh+ILJN6F--