Received-SPF: pass (google.com: domain of linux-nfs-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) client-ip=23.128.96.18;
From:   Chuck Lever III <chuck.lever@oracle.com>
To:     Timo Rothenpieler <timo@rothenpieler.org>
CC:     Linux NFS Mailing List <linux-nfs@vger.kernel.org>,
        linux-rdma <linux-rdma@vger.kernel.org>
Subject: Re: Spurious instability with NFSoRDMA under moderate load
Thread-Topic: Spurious instability with NFSoRDMA under moderate load
Thread-Index: AQHXSnp8j8N6G2OhyUK9Nr2RtJxnoarn3hgAgAATb4CANuhZgIBOXZcAgAAVhICAADVLgA==
Date:   Tue, 10 Aug 2021 17:17:38 +0000
Message-ID: <4BA2A532-9063-4893-AF53-E1DAB06095CC@oracle.com>
References: <4da3b074-a6be-d83f-ccd4-b151557066aa@rothenpieler.org>
 <72ECF9E1-1F6E-44AF-850C-536BED898DDD@oracle.com>
 <e12c24fd-beaf-31ce-cb49-36ad32bd22b3@rothenpieler.org>
 <daae674a-84d4-de36-336d-693dc582e3ef@rothenpieler.org>
 <9355de20-921c-69e0-e5a4-733b64e125e1@rothenpieler.org>
 <a28b403e-42cf-3189-a4db-86d20da1b7aa@rothenpieler.org>
In-Reply-To: <a28b403e-42cf-3189-a4db-86d20da1b7aa@rothenpieler.org>
Accept-Language: en-US
Content-Language: en-US
x-ms-exchange-antispam-messagedata-chunkcount: 1
x-ms-exchange-antispam-messagedata-0: =?us-ascii?Q?GmTZTH+DejPs4RDOe7QWQljSObydHEipzoDO/nXo1HMnMwADTWdc3OGWHGrp?=
 =?us-ascii?Q?lHP/u8glDJ9Q/XAci4ueAGY/nQ9OTP6Joi1O3uyvZo+QAVZMayGZJ5dha/J0?=
 =?us-ascii?Q?qz5zCYMITYSOBOfb/xmkjRGFpRwl7Uwh1+6zU9xBaXjH/lrZRJeW4im3EWEW?=
 =?us-ascii?Q?Yk0woQGXAeUx0XS7TbGVTOP0DmVkyBNVer9E9XWB/PZjEy+wb5yTxO0DEPWf?=
 =?us-ascii?Q?CUQ+aG1fb+yyKvvFXMIlCdoEpTNKbIDhKoWkmoq04eZv3ee5caDKhaASYPhs?=
 =?us-ascii?Q?3cJBqNRiPuJBJGFnvhLpRf5YVQhZKbPWxajUSeofs6OWol3lZNcBO1OEcWN2?=
 =?us-ascii?Q?E+KzPuXJezhQwhi4GKdHbrqVIdZfEtW1LSlk5hjDXgamH4n6XVgM02TAuGN8?=
 =?us-ascii?Q?c3QrHs3W+6iEQ+/dwBbzLn19dk+c2J+IuKCg9SCKJEc49Jog2s2yk68Mp/mo?=
 =?us-ascii?Q?GeeF7Yr9rfgjaOu0BJtn60nc/HdPCHJpEMLRZXUKEeWSQYbuEBvUzKk26k44?=
 =?us-ascii?Q?ZJvAxDyXQ5ueqx3GbpkLUvHcPwlBykI0jirkMyTDKTj8cml9697vtwriAjEI?=
 =?us-ascii?Q?3deSq8T16kJDBzJ2gFf3gDdcOfSQf8je+fJpX21nbdMRYZNMTUsBG2aI+k4s?=
 =?us-ascii?Q?oXwZSrs8mywcRXi8iFgfs5cuzFRbvpG8s3NLDFYS7lzRvVLYG/9TmcKUrcnx?=
 =?us-ascii?Q?MwwZ5Q19oGriL0gqsKRN1lGDiBLeCxVTmi0Bw0I303vQHN3XNN0bY3xvQtv1?=
 =?us-ascii?Q?vJ//JMnuckVA497MU45jv+0XoXyHT03wiP2ulQJa2FGrBh1UY/hHZmRKOOyp?=
 =?us-ascii?Q?YobZ7E3PKV0v6/iaCo1A52McFCOgVeuAfN4i9O4PhinxZWo01w4HIT/b96iA?=
 =?us-ascii?Q?HqTZxAhozi2fLHio6hZJtvE72D8JfxG1ZdFtqL46avqlSYHIgzkSYoiF8fzj?=
 =?us-ascii?Q?tJxLh8+AXgyPa2WaNIV73bQ0yqK2taREblRJNPonoT9tkB7Q+X/wexipC8I/?=
 =?us-ascii?Q?RDgxTq1ku5wuXoRAUSCIioAOZOT/Zz6nHwJ1ZZLpAsrl6cLGHu2EzYQSf5xl?=
 =?us-ascii?Q?L9T64lT3vbW1Z7+0ezP2n4x491RmXi3juzBnQoTPDq5AmWnIZN22SDiZ87xD?=
 =?us-ascii?Q?WAr4KyE/jR/N5qF/qeuSCPK1Mih0ogomDddZQ66mmQkQL1TyiVJVp9613qlz?=
 =?us-ascii?Q?m8TSKr9QipzuXvxn35ZaFEdHE0Mk7I/Mp2wZQbWMD6cJgr+OuLFWd5DoPRfs?=
 =?us-ascii?Q?OkKvBssMVEv5EpIHP5t7aylDsgYpzSlaJR9vNAPkxe42CEy2Kvy+7FYfUVC3?=
 =?us-ascii?Q?46VJy6GmnqJqhsF9ehYuhC6+z2B8uaHhoI7UOzqOAIjUqw=3D=3D?=
x-ms-exchange-transport-forked: True
Content-Type: text/plain; charset="us-ascii"
Content-ID: <26C42073A9ACD14CAE6B76BD15EADD2B@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: SJ0PR10MB4688.namprd10.prod.outlook.com
X-MS-Exchange-CrossTenant-Network-Message-Id: 696bbe9c-6c87-4d7e-3b05-08d95c22c0cb
X-MS-Exchange-CrossTenant-originalarrivaltime: 10 Aug 2021 17:17:38.1658
 (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: u5G35oRBP5rQPSSzEAvMHx6O804CDzzOQhTmyOEVLdaG9QSIObtlHHB4P9h5CcPZjzFyo9IZbMRcuGchRaMAUg==
X-MS-Exchange-Transport-CrossTenantHeadersStamped: BY5PR10MB4212
X-Proofpoint-Virus-Version: vendor=nai engine=6200 definitions=10072 signatures=668682
X-Proofpoint-Spam-Details: rule=notspam policy=default score=0 mlxlogscore=999 mlxscore=0
 suspectscore=0 malwarescore=0 phishscore=0 adultscore=0 spamscore=0
 bulkscore=0 classifier=spam adjust=0 reason=mlx scancount=1
 engine=8.12.0-2107140000 definitions=main-2108100112
X-Proofpoint-ORIG-GUID: Cv2li_9tJ-356Wu3Axbnj_LybP3pr7wm
X-Proofpoint-GUID: Cv2li_9tJ-356Wu3Axbnj_LybP3pr7wm
Precedence: bulk
List-ID: <linux-nfs.vger.kernel.org>
X-Mailing-List: linux-nfs@vger.kernel.org


> On Aug 10, 2021, at 10:06 AM, Timo Rothenpieler <timo@rothenpieler.org> w=
rote:
>=20
> On 10.08.2021 14:49, Timo Rothenpieler wrote:
>> Ok, so this just happened again for the first time since upgrading to 5.=
12.
>> Exact same thing, except this time no error cqe was dumped simultaneousl=
y (It still appeared in dmesg, but over a week before the issue showed up).=
 So I'll assume it's unrelated to this issue.
>> I had no issues while running 5.12.12 and below. Recently (14 days ago o=
r so) updated to 5.12.19, and now it's happening again.
>> Unfortunately, with how rarely this issue happens, this can either be a =
regression between those two versions, or it was still present all along an=
d just never triggered for several months.
>> Makes me wonder if this is somehow related to the problem described in "=
NFS server regression in kernel 5.13 (tested w/ 5.13.9)". But the pattern o=
f the issue does not look all that similar, given that for me, the hangs ne=
ver recover, and I have RDMA in the mix.
>=20
> Here's some trace and debug data I collected while it was in a state wher=
e everything using copy_range would get stuck.
> The file(s) in question is named "tmp-copy-*", with a bunch of numbers at=
 the end.
>=20
> This also seems to be entirely a client side issue, since other NFS clien=
ts on the same server work just fine the whole time, and a reboot of that o=
ne affected client makes it work normally again, without touching the serve=
r.
>=20
> In this instance right now, I was even unable to cleanly reboot the clien=
t machine, since it got completely stuck, seemingly unable to unmount the N=
FS shares, getting stuck the same way other operations would.
>=20
> What confuses me the most is that while it is in this messed up state, it=
 generally still works fine, and it's only a few very specific operations (=
only one I know of for sure is copy_range) get stuck.
> The processes also aren't unkillable. a SIGTERM or SIGKILL will end them,=
 and also flushes NFS. Captured that in the dmesg_output2.

What I see in this data is that the server is reporting

   SEQ4_STATUS_CB_PATH_DOWN

and the client is attempting to recover (repeatedly) using
BIND_CONN_TO_SESSION. But apparently the recovery didn't
actually work, because the server continues to report a
callback path problem.

[1712389.125641] nfs41_handle_sequence_flag_errors: "10.110.10.200" (client=
 ID 6765f8600a675814) flags=3D0x00000001
[1712389.129264] nfs4_bind_conn_to_session: bind_conn_to_session was succes=
sful for server 10.110.10.200!

[1712389.171953] nfs41_handle_sequence_flag_errors: "10.110.10.200" (client=
 ID 6765f8600a675814) flags=3D0x00000001
[1712389.178361] nfs4_bind_conn_to_session: bind_conn_to_session was succes=
sful for server 10.110.10.200!

[1712389.195606] nfs41_handle_sequence_flag_errors: "10.110.10.200" (client=
 ID 6765f8600a675814) flags=3D0x00000001
[1712389.203891] nfs4_bind_conn_to_session: bind_conn_to_session was succes=
sful for server 10.110.10.200!

I guess it's time to switch to tracing on the server side
to see if you can nail down why the server's callback
requests are failing. On your NFS server, run:

 # trace-cmd record -e nfsd -e sunrpc -e rpcgss -e rpcrdma

at roughly the same point during your test that you captured
the previous client-side trace.

--
Chuck Lever