Received-SPF: pass (google.com: domain of linux-nfs-owner@vger.kernel.org designates 2620:137:e000::1:18 as permitted sender) client-ip=2620:137:e000::1:18;
From:   Chuck Lever III <chuck.lever@oracle.com>
To:     Trond Myklebust <trondmy@hammerspace.com>
CC:     Olga Kornievskaia <aglo@umich.edu>,
        "dennis.dalessandro@cornelisnetworks.com" 
        <dennis.dalessandro@cornelisnetworks.com>,
        Linux NFS Mailing List <linux-nfs@vger.kernel.org>
Subject: Re: NFS regression between 5.17 and 5.18
Thread-Topic: NFS regression between 5.17 and 5.18
Thread-Index: AQHYWwCixuCyjj49XkSuf+bm0GIRX60Faq4AgAAMfoCAAERPAIAAApwAgAEchwCAAAwEAIAK/HiAgAroagCAABmggIAAGOOA
Date:   Fri, 13 May 2022 14:59:18 +0000
Message-ID: <9D98FE64-80FB-43B7-9B1C-D177F32D2814@oracle.com>
References: <979544aa-a7b1-ab22-678f-5ac19f03e17a@cornelisnetworks.com>
 <8E8485F8-F56F-4A93-85AC-44BD8436DF6A@oracle.com>
 <9d814666-6e95-e331-62a7-ec36fe1ca062@cornelisnetworks.com>
 <04edca2f-d54f-4c52-9877-978bf48208fb@cornelisnetworks.com>
 <ca84dc10f073284c9219808bb521201f246cf558.camel@hammerspace.com>
 <bb2c7dec-dc34-6a14-044d-b6487c9e1018@cornelisnetworks.com>
 <A04B2E88-9F29-4CF7-8ACB-1308100F1478@oracle.com>
 <46beb079-fb43-a9c1-d9a0-9b66d5a36163@cornelisnetworks.com>
 <9d3055f2-f751-71f4-1fc0-927817a07d99@cornelisnetworks.com>
 <b2691e39ec13cd2b0d4f5e844f4474c8b82a13c8.camel@hammerspace.com>
In-Reply-To: <b2691e39ec13cd2b0d4f5e844f4474c8b82a13c8.camel@hammerspace.com>
Accept-Language: en-US
Content-Language: en-US
x-ms-exchange-antispam-messagedata-chunkcount: 1
x-ms-exchange-antispam-messagedata-0: =?us-ascii?Q?px8xJls5c91vQy2KBygc93lQb8UyozuPym38mNtJ1zGRgWj2QFYBeefNxgMw?=
 =?us-ascii?Q?im9wHnTmkNOS8x1P4jlJo2uvgPH1pSnE6CNTJn4RsU+Kyc9/s9KJxIxFn6YB?=
 =?us-ascii?Q?jiK+qnTEg2K7BlResprm74dbVg6/kl4rhJP1rj03SCLu1wEKvhwdNi+u9QAs?=
 =?us-ascii?Q?BGLGhR0aGvUNdEv16MzPywJ+AcjxvSiBgNAekDUMvnqSNrPueCz0xwPKEbuH?=
 =?us-ascii?Q?i01KueS2SVmNREDioC3vMjiTDjaqjZL1zUsF7f14EL6LzVKKFrL1DZEYvk2C?=
 =?us-ascii?Q?ATm+RVr+lgJf9GuLRGYs8xvqtTaYNkHamfaojfZuxwRmP05cUqk9Grut1rz5?=
 =?us-ascii?Q?Wdx+cQPvlxmTvPOAvM6VmQ5CJsj2Mc9qbI5fiXjyZ9sf9NEwa6fupEwGRUH0?=
 =?us-ascii?Q?qvIx5XcqY0WFyJXkSh2gOmUpMoPdoQlKsIsmkeoWItHz4NFi32fzoB3AaOZp?=
 =?us-ascii?Q?N7w9vA6W60fces0yB6QchN42E4VvH6Huhe7pjPmTiFMlK2G+QE4BSbLcM7Bw?=
 =?us-ascii?Q?9HZb9HRCdfjB9uxOhrv/e6hGWRTkaZ1pZ/o1m0ervaxs6UNDI/z+CEIwKOTq?=
 =?us-ascii?Q?hg4VislVbrnnfmI3bBs9aemNDUEyYutqer73sX3qUs+ylZwHMNDgXeEEkGmB?=
 =?us-ascii?Q?6iJFaVaQcC6NKZ4+624mndsPzJkmNS0yXf55FGqeSl8nT//jTJ64GO42KxUO?=
 =?us-ascii?Q?yTTKomgsvYrx+H5ayZ/n2Vv4CZkOoiLrlgLlIBeNdU1dAbLK39kbDvUrokBG?=
 =?us-ascii?Q?h/vypb/+hAn3spxOqd3ctRIFUfe7pQDpbUQ1IfMyXC0TvzFK8kbZCHmxG98M?=
 =?us-ascii?Q?rSwCoqD67OlB95+8+FCI3PfFN8u3UNUwycu7mMmwU6oOM1GzLeEg5BZF1mm3?=
 =?us-ascii?Q?3yIo24K0i40Si/r+WQvGwHK9KsVDIoXspxCpBitzf5VqEpKLy7JBYf0yRWoA?=
 =?us-ascii?Q?NIPUrE4E5/iSP1V4oF29JVxYPYtES3OUCn44UU/mVLGeWPFeKVRRX38hVbed?=
 =?us-ascii?Q?jFtAe4jUL8WCodK1ZfOcFUiul+AWPz3VkZmx+qNVf2DSDnOlBxXQdzHgO+Wx?=
 =?us-ascii?Q?vh9rMKZmkN6lv2BxQ2RCAL1BOwIwiK28sUtUWmJ8esEidpMKO6k7PvnfEt5l?=
 =?us-ascii?Q?fCUjEHSpWiEnsxJBKiukSCKZg+o0gsowFDFD0yxrOktNPq0gofdROKkKMaAv?=
 =?us-ascii?Q?b29Fk6Uw1DGZkOwykh1JsKrFK0VphJO9tXwwWWb0VNLhrC7u5Nab6ywA9j1l?=
 =?us-ascii?Q?Y78CZioCCYD5vgu0LhSqUXg5ZM4Etyaw4fMWNFBDHGBwlGgTsDoIXokz0LHt?=
 =?us-ascii?Q?6Ujdkg017nwgC7XIvGL89rNmMeIEP15A43OP3bM0ho4s79XoYU5rNmG3MxUT?=
 =?us-ascii?Q?AaLfISlaaiZK1FXtLw9CsU78T7yaIei4MRctZ62xCSCit+tvjwYomu5Sr83g?=
 =?us-ascii?Q?G8TRfko5nustRSxPTI+XHe9TrRiDuWkoqKv2OBngzIEf3wkfzBFZFO4EfWzj?=
 =?us-ascii?Q?NOJmfbxxVaOFmoVK60AlguaXnluaIMXWzmax6KDaP8vpaathCmUsgT4O7wRS?=
 =?us-ascii?Q?6wihmHbYsPYiCx50awdt3EwWBohorLK9v5gwt2m7MYEugEpGfCvbzCFsY0BJ?=
 =?us-ascii?Q?yn4YjsUIzHUCXyp3hxLZVJLuVJOQRp0vV/EsCMr921uSAchMqg8QgXiaX9u7?=
 =?us-ascii?Q?LznquxCc0by7gFOPNAbT8j9E0HZPBKcDi6RhfD8Gnbby8EjQNut0pfqUhSyq?=
 =?us-ascii?Q?VJe5xmR/qLDVLZupDm4ftqYJXBLS0bw=3D?=
Content-Type: text/plain; charset="us-ascii"
Content-ID: <44EAF79DD0D05F47976887710281D184@namprd10.prod.outlook.com>
Content-Transfer-Encoding: quoted-printable
MIME-Version: 1.0
X-OriginatorOrg: oracle.com
X-MS-Exchange-CrossTenant-AuthAs: Internal
X-MS-Exchange-CrossTenant-AuthSource: BN0PR10MB5128.namprd10.prod.outlook.com
X-MS-Exchange-CrossTenant-Network-Message-Id: 6c987144-a4a1-4828-123a-08da34f127e6
X-MS-Exchange-CrossTenant-originalarrivaltime: 13 May 2022 14:59:18.7029
 (UTC)
X-MS-Exchange-CrossTenant-fromentityheader: Hosted
X-MS-Exchange-CrossTenant-id: 4e2c6054-71cb-48f1-bd6c-3a9705aca71b
X-MS-Exchange-CrossTenant-mailboxtype: HOSTED
X-MS-Exchange-CrossTenant-userprincipalname: X0ZYtRp5StOdkMG5MAcqWwgq9E3bY/hi8YPRuGD8+Hvpd92suPI4YU6itxHYHTIWvrb+cqV6qkeN8uT6Z1r3lQ==
X-MS-Exchange-Transport-CrossTenantHeadersStamped: BN0PR10MB5173
X-Proofpoint-Virus-Version: vendor=fsecure engine=2.50.10434:6.0.486,18.0.858
 definitions=2022-05-13_04:2022-05-13,2022-05-13 signatures=0
X-Proofpoint-Spam-Details: rule=notspam policy=default score=0 mlxlogscore=999 adultscore=0
 spamscore=0 phishscore=0 suspectscore=0 mlxscore=0 bulkscore=0
 malwarescore=0 classifier=spam adjust=0 reason=mlx scancount=1
 engine=8.12.0-2202240000 definitions=main-2205130066
X-Proofpoint-ORIG-GUID: yr7ucLd_2NcCyC9mpkZbrm1AdeHlyk2I
X-Proofpoint-GUID: yr7ucLd_2NcCyC9mpkZbrm1AdeHlyk2I
X-Spam-Status: No, score=-2.0 required=5.0 tests=BAYES_00,DKIM_SIGNED,
	DKIM_VALID,DKIM_VALID_AU,HEADER_FROM_DIFFERENT_DOMAINS,
	MAILING_LIST_MULTI,RDNS_NONE,SPF_HELO_NONE,T_SCC_BODY_TEXT_LINE
	autolearn=no autolearn_force=no version=3.4.6
X-Spam-Checker-Version: SpamAssassin 3.4.6 (2021-04-09) on
	lindbergh.monkeyblade.net
Precedence: bulk
List-ID: <linux-nfs.vger.kernel.org>
X-Mailing-List: linux-nfs@vger.kernel.org


> On May 13, 2022, at 9:30 AM, Trond Myklebust <trondmy@hammerspace.com> wr=
ote:
>=20
> On Fri, 2022-05-13 at 07:58 -0400, Dennis Dalessandro wrote:
>> On 5/6/22 9:24 AM, Dennis Dalessandro wrote:
>>> On 4/29/22 9:37 AM, Chuck Lever III wrote:
>>>>=20
>>>>=20
>>>>> On Apr 29, 2022, at 8:54 AM, Dennis Dalessandro
>>>>> <dennis.dalessandro@cornelisnetworks.com> wrote:
>>>>>=20
>>>>> On 4/28/22 3:56 PM, Trond Myklebust wrote:
>>>>>> On Thu, 2022-04-28 at 15:47 -0400, Dennis Dalessandro wrote:
>>>>>>> On 4/28/22 11:42 AM, Dennis Dalessandro wrote:
>>>>>>>> On 4/28/22 10:57 AM, Chuck Lever III wrote:
>>>>>>>>>> On Apr 28, 2022, at 9:05 AM, Dennis Dalessandro
>>>>>>>>>> <dennis.dalessandro@cornelisnetworks.com> wrote:
>>>>>>>>>>=20
>>>>>>>>>> Hi NFS folks,
>>>>>>>>>>=20
>>>>>>>>>> I've noticed a pretty nasty regression in our NFS
>>>>>>>>>> capability
>>>>>>>>>> between 5.17 and
>>>>>>>>>> 5.18-rc1. I've tried to bisect but not having any
>>>>>>>>>> luck. The
>>>>>>>>>> problem I'm seeing
>>>>>>>>>> is it takes 3 minutes to copy a file from NFS to the
>>>>>>>>>> local
>>>>>>>>>> disk. When it should
>>>>>>>>>> take less than half a second, which it did up through
>>>>>>>>>> 5.17.
>>>>>>>>>>=20
>>>>>>>>>> It doesn't seem to be network related, but can't rule
>>>>>>>>>> that out
>>>>>>>>>> completely.
>>>>>>>>>>=20
>>>>>>>>>> I tried to bisect but the problem can be
>>>>>>>>>> intermittent. Some
>>>>>>>>>> runs I'll see a
>>>>>>>>>> problem in 3 out of 100 cycles, sometimes 0 out of
>>>>>>>>>> 100.
>>>>>>>>>> Sometimes I'll see it
>>>>>>>>>> 100 out of 100.
>>>>>>>>>=20
>>>>>>>>> It's not clear from your problem report whether the
>>>>>>>>> problem
>>>>>>>>> appears
>>>>>>>>> when it's the server running v5.18-rc or the client.
>>>>>>>>=20
>>>>>>>> That's because I don't know which it is. I'll do a quick
>>>>>>>> test and
>>>>>>>> find out. I
>>>>>>>> was testing the same kernel across both nodes.
>>>>>>>=20
>>>>>>> Looks like it is the client.
>>>>>>>=20
>>>>>>> server  client  result
>>>>>>> ------  ------  ------
>>>>>>> 5.17    5.17    Pass
>>>>>>> 5.17    5.18    Fail
>>>>>>> 5.18    5.18    Fail
>>>>>>> 5.18    5.17    Pass
>>>>>>>=20
>>>>>>> Is there a patch for the client issue you mentioned that I
>>>>>>> could try?
>>>>>>>=20
>>>>>>> -Denny
>>>>>>=20
>>>>>> Try this one
>>>>>=20
>>>>> Thanks for the patch. Unfortunately it doesn't seem to solve
>>>>> the issue, still
>>>>> see intermittent hangs. I applied it on top of -rc4:
>>>>>=20
>>>>> copy /mnt/nfs_test/run_nfs_test.junk to
>>>>> /dev/shm/run_nfs_test.tmp...
>>>>>=20
>>>>> real    2m6.072s
>>>>> user    0m0.002s
>>>>> sys     0m0.263s
>>>>> Done
>>>>>=20
>>>>> While it was hung I checked the mem usage on the machine:
>>>>>=20
>>>>> # free -h
>>>>>              total        used        free      shared=20
>>>>> buff/cache   available
>>>>> Mem:           62Gi       871Mi        61Gi       342Mi     =20
>>>>> 889Mi        61Gi
>>>>> Swap:         4.0Gi          0B       4.0Gi
>>>>>=20
>>>>> Doesn't appear to be under memory pressure.
>>>>=20
>>>> Hi, since you know now that it is the client, perhaps a bisect
>>>> would be more successful?
>>>=20
>>> I've been testing all week. I pulled the nfs-rdma tree that was
>>> sent to Linus
>>> for 5.18 and tested. I see the problem on pretty much all the
>>> patches. However
>>> it's the frequency that it hits which changes.
>>>=20
>>> I'll see 1-5 cycles out of 2500 where the copy takes minutes up to:
>>> "NFS: Convert readdir page cache to use a cookie based index"
>>>=20
>>> After this I start seeing it around 10 times in 500 and by the last
>>> patch 10
>>> times in less than 100.
>>>=20
>>> Is there any kind of tracing/debugging I could turn on to get more
>>> insight on
>>> what is taking so long when it does go bad?
>>>=20
>>=20
>> Ran a test with -rc6 and this time see a hung task trace on the
>> console as well
>> as an NFS RPC error.
>>=20
>> [32719.991175] nfs: RPC call returned error 512
>> .
>> .
>> .
>> [32933.285126] INFO: task kworker/u145:23:886141 blocked for more
>> than 122 seconds.
>> [32933.293543]       Tainted: G S                5.18.0-rc6 #1
>> [32933.299869] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
>> disables this
>> message.
>> [32933.308740] task:kworker/u145:23 state:D stack:    0 pid:886141
>> ppid:     2
>> flags:0x00004000
>> [32933.318321] Workqueue: rpciod rpc_async_schedule [sunrpc]
>> [32933.324524] Call Trace:
>> [32933.327347]  <TASK>
>> [32933.329785]  __schedule+0x3dd/0x970
>> [32933.333783]  schedule+0x41/0xa0
>> [32933.337388]  xprt_request_dequeue_xprt+0xd1/0x140 [sunrpc]
>> [32933.343639]  ? prepare_to_wait+0xd0/0xd0
>> [32933.348123]  ? rpc_destroy_wait_queue+0x10/0x10 [sunrpc]
>> [32933.354183]  xprt_release+0x26/0x140 [sunrpc]
>> [32933.359168]  ? rpc_destroy_wait_queue+0x10/0x10 [sunrpc]
>> [32933.365225]  rpc_release_resources_task+0xe/0x50 [sunrpc]
>> [32933.371381]  __rpc_execute+0x2c5/0x4e0 [sunrpc]
>> [32933.376564]  ? __switch_to_asm+0x42/0x70
>> [32933.381046]  ? finish_task_switch+0xb2/0x2c0
>> [32933.385918]  rpc_async_schedule+0x29/0x40 [sunrpc]
>> [32933.391391]  process_one_work+0x1c8/0x390
>> [32933.395975]  worker_thread+0x30/0x360
>> [32933.400162]  ? process_one_work+0x390/0x390
>> [32933.404931]  kthread+0xd9/0x100
>> [32933.408536]  ? kthread_complete_and_exit+0x20/0x20
>> [32933.413984]  ret_from_fork+0x22/0x30
>> [32933.418074]  </TASK>
>>=20
>> The call trace shows up again at 245, 368, and 491 seconds. Same
>> task, same trace.
>>=20
>>=20
>>=20
>>=20
>=20
> That's very helpful. The above trace suggests that the RDMA code is
> leaking a call to xprt_unpin_rqst().

IMHO this is unlikely to be related to the performance
regression -- none of this code has changed in the past 5
kernel releases. Could be a different issue, though.

As is often the case in these situations, the INFO trace
above happens long after the issue that caused the missing
unpin. So... unless Dennis has a reproducer that can trigger
the issue frequently, I don't think there's much that can
be extracted from that.

Also "nfs: RPC call returned error 512" suggests someone
hit ^C at some point. It's always possible that the
xprt_rdma_free() path is missing an unpin. But again,
that's not likely to be related to performance.


> From what I can see, rpcrdma_reply_handler() will always call
> xprt_pin_rqst(), and that call is required to be matched by a call to
> xprt_unpin_rqst() before the handler exits. However those calls to
> xprt_unpin_rqst() appear to be scattered around the code, and it is not
> at all obvious that the requirement is being fulfilled.

I don't think unpin is required before rpcrdma_reply_handler()
exits. It /is/ required after xprt_complete_rqst(), and
sometimes that call has to be deferred until the NIC is
fully done with the RPC's buffers. The NIC is often not
finished with the buffers in the Receive completion handler.


> Chuck, why does that code need to be so complex?

The overall goal is that the upper layer cannot be awoken
until the NIC has finished with the RPC's header and
payload buffers. These buffers are treated differently
depending on how the send path chose to marshal the RPC.

And, all of these are hot paths, so it's important to
ensure that we are waiting/context-switching as
infrequently as possible. We wake the upper layer waiter
during an RDMA completion to reduce context switching.
The first completion does not always mean there's nothing
left for the NIC to do.

Ignoring the server backchannel, there is a single unpin
in the "complete without error" case in
rpcrdma_complete_rqst().

There are three call sites for rpcrdma_complete_rqst:

1. rpcrdma_reply_done - called when no explicit invalidation
is needed and the Receive completion fired after the Send
completion.

2. rpcrdma_sendctx_done - called when no explicit invalidation
is needed and the Send completion fired after the Receive
completion.

3. frwr_wc_localinv_done - called when explicit invalidation
was needed and that invalidation has completed. SQ ordering
guarantees that the Send has also completed at this point,
so a separate wait for Send completion is not needed.

These are the points when the NIC has finished with all of
the memory resources associated with an RPC, so that's
when it is safe to wake the waiter and unpin the RPC.

--
Chuck Lever