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 <chuck.lever@oracle.com>
To:     Timo Rothenpieler <timo@rothenpieler.org>
CC:     Olga Kornievskaia <aglo@umich.edu>,
        linux-rdma <linux-rdma@vger.kernel.org>,
        Linux NFS Mailing List <linux-nfs@vger.kernel.org>
Subject: Re: copy_file_range() infinitely hangs on NFSv4.2 over RDMA
Thread-Topic: copy_file_range() infinitely hangs on NFSv4.2 over RDMA
Thread-Index: AQHXAoMfawdRzWrgDkSpe5/TYHEFmapbOyaAgAAHBQCAAB6ZgIABlTwAgAArPQCAACy3AIAA0KWSgAAkhACAAB9zAIABZJ0AgAACxwCAAANsgIAADTqAgAG4DICAAVrpgA==
Date:   Sun, 21 Feb 2021 17:45:09 +0000
Message-ID: <5196DB85-0629-4FF4-9DD4-D5019AD94527@oracle.com>
References: <57f67888-160f-891c-6217-69e174d7e42b@rothenpieler.org>
 <CAN-5tyE4OyNOZRXGnyONcdGsHaRAF39LSE5416Kj964m-+_C2A@mail.gmail.com>
 <81cb9aef-c10d-f11c-42c0-5144ee2608bc@rothenpieler.org>
 <0e49471c-e640-a331-c7b4-4e0a49a7a967@rothenpieler.org>
 <CAN-5tyG9Ly9tqKxguFNhg_PGXCxE2=Zn6LQPLY59twdVkD3Auw@mail.gmail.com>
 <51a8caa7-52c2-8155-10a7-1e8d21866924@rothenpieler.org>
 <CAN-5tyFT4+kkqk6E0Jxe-vMYm7q5mHyTeq0Ht7AEYasA30ZaGw@mail.gmail.com>
 <3f946e6b-6872-641c-8828-35ddd5c8fed0@rothenpieler.org>
 <e89ab742-7984-6a2c-2f01-402283ba6e89@rothenpieler.org>
 <CAN-5tyGhyh0ZF77voaN4TNgMt+jSUG0PMp-KixfTvgUhDdhDUQ@mail.gmail.com>
 <def12560-2481-b17d-5a42-7236edbd5392@rothenpieler.org>
 <CAN-5tyHLRn4HEs9R291N6Y=boOvQ9-qvKfJzA8Khkqie2kVVWQ@mail.gmail.com>
 <6478B738-0C33-46DC-B711-B0BF7069FD82@oracle.com>
 <19c74710-bf35-6412-dd06-071331419ab5@rothenpieler.org>
 <E4BAC726-2FFA-47A8-A1B6-F0D2848ABB98@oracle.com>
 <14ca46ac-6b3f-5e51-e4f6-bf4d5dc9933b@rothenpieler.org>
In-Reply-To: <14ca46ac-6b3f-5e51-e4f6-bf4d5dc9933b@rothenpieler.org>
Accept-Language: en-US
Content-Language: en-US
Content-Type: text/plain; charset="us-ascii"
Content-ID: <191D7EB11D1188428FF847F3044B54B1@namprd10.prod.outlook.com>
Content-Transfer-Encoding: quoted-printable
MIME-Version: 1.0
X-MS-Exchange-CrossTenant-Network-Message-Id: cd2ecc88-e92d-456e-c19f-08d8d6906eaa
X-MS-Exchange-CrossTenant-originalarrivaltime: 21 Feb 2021 17:45:09.2308
 (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: q/2ZlB1/aC/ZdHFcbTNE5YAbQn/Ti+UYChKsnpI2/OLsbzWCTNPydn+nJ5/yH1TlFjfIfzR7nS8XB9GlwbXMRg==
X-MS-Exchange-Transport-CrossTenantHeadersStamped: BY5PR10MB4051
X-Proofpoint-Virus-Version: vendor=nai engine=6200 definitions=9902 signatures=668683
X-Proofpoint-Spam-Details: rule=notspam policy=default score=0 spamscore=0 suspectscore=0
 malwarescore=0 mlxlogscore=999 adultscore=0 bulkscore=0 mlxscore=0
 phishscore=0 classifier=spam adjust=0 reason=mlx scancount=1
 engine=8.12.0-2009150000 definitions=main-2102210179
X-Proofpoint-Virus-Version: vendor=nai engine=6200 definitions=9902 signatures=668683
X-Proofpoint-Spam-Details: rule=notspam policy=default score=0 impostorscore=0 phishscore=0
 mlxlogscore=999 malwarescore=0 clxscore=1015 suspectscore=0
 lowpriorityscore=0 bulkscore=0 adultscore=0 priorityscore=1501 mlxscore=0
 spamscore=0 classifier=spam adjust=0 reason=mlx scancount=1
 engine=8.12.0-2009150000 definitions=main-2102210180
Precedence: bulk
List-ID: <linux-nfs.vger.kernel.org>
X-Mailing-List: linux-nfs@vger.kernel.org


> On Feb 20, 2021, at 4:03 PM, Timo Rothenpieler <timo@rothenpieler.org> wr=
ote:
>=20
> On 19.02.2021 19:48, Chuck Lever wrote:
>>> On Feb 19, 2021, at 1:01 PM, Timo Rothenpieler <timo@rothenpieler.org> =
wrote:
>>>=20
>>> On 19.02.2021 18:48, Chuck Lever wrote:
>>>>> On Feb 19, 2021, at 12:38 PM, Olga Kornievskaia <aglo@umich.edu> wrot=
e:
>>>>>=20
>>>>> On Thu, Feb 18, 2021 at 3:22 PM Timo Rothenpieler <timo@rothenpieler.=
org> wrote:
>>>>>>=20
>>>>>> On 18.02.2021 19:30, Olga Kornievskaia wrote:
>>>>>>> Thank you for getting tracepoints from a busy server but can you ge=
t
>>>>>>> more? As suspected, the server is having issues sending the callbac=
k.
>>>>>>> I'm not sure why. Any chance to turn on the server's sunrpc
>>>>>>> tracespoints, probably both sunrpc and rdmas tracepoints, I wonder =
if
>>>>>>> we can any more info about why it's failing?
>>>>>>=20
>>>>>> I isolated out two of the machines on that cluster now, one acting a=
s
>>>>>> NFS server from an ext4 mount, the other is the same client as befor=
e.
>>>>>> That way I managed to capture a trace and ibdump of an entire cycle:
>>>>>> mount + successful copy + 5 minutes later a copy that got stuck
>>>>>>=20
>>>>>> Next to no noise happened during those traces, you can find them att=
ached.
>>>>>>=20
>>>>>> Another observation made due to this: unmount and re-mounting the NF=
S
>>>>>> share also gets it back into working condition for a while, no reboo=
t
>>>>>> necessary.
>>>>>> During this trace, I got "lucky", and after just 5 minutes of waitin=
g,
>>>>>> it got stuck.
>>>>>>=20
>>>>>> Before that, I had a run of mount + trying to copy every 5 minutes w=
here
>>>>>> it ran for 45 minutes without getting stuck. At which point I decide=
d to
>>>>>> remount once more.
>>>>>=20
>>>>> Timo, thank you for gathering the debug info.
>>>>>=20
>>>>> Chuck, I need your help. Why would the server lose a callback channel=
?
>>>>>=20
>>>>>           <...>-1461944 [001] 2076465.200151: rpc_request:
>>>>> task:57752@6 nfs4_cbv1 CB_OFFLOAD (async)
>>>>>           <...>-1461944 [001] 2076465.200151: rpc_task_run_action:
>>>>> task:57752@6 flags=3DASYNC|DYNAMIC|SOFT|NOCONNECT
>>>>> runstate=3DRUNNING|ACTIVE status=3D0 action=3Dcall_reserve
>>>>>           <...>-1461944 [001] 2076465.200154: xprt_reserve:
>>>>> task:57752@6 xid=3D0x00a0aaf9
>>>>>           <...>-1461944 [001] 2076465.200155: rpc_task_run_action:
>>>>> task:57752@6 flags=3DASYNC|DYNAMIC|SOFT|NOCONNECT
>>>>> runstate=3DRUNNING|ACTIVE status=3D0 action=3Dcall_reserveresult
>>>>>           <...>-1461944 [001] 2076465.200156: rpc_task_run_action:
>>>>> task:57752@6 flags=3DASYNC|DYNAMIC|SOFT|NOCONNECT
>>>>> runstate=3DRUNNING|ACTIVE status=3D0 action=3Dcall_refresh
>>>>>           <...>-1461944 [001] 2076465.200163: rpc_task_run_action:
>>>>> task:57752@6 flags=3DASYNC|DYNAMIC|SOFT|NOCONNECT
>>>>> runstate=3DRUNNING|ACTIVE status=3D0 action=3Dcall_refreshresult
>>>>>           <...>-1461944 [001] 2076465.200163: rpc_task_run_action:
>>>>> task:57752@6 flags=3DASYNC|DYNAMIC|SOFT|NOCONNECT
>>>>> runstate=3DRUNNING|ACTIVE status=3D0 action=3Dcall_allocate
>>>>>           <...>-1461944 [001] 2076465.200168: rpc_buf_alloc:
>>>>> task:57752@6 callsize=3D548 recvsize=3D104 status=3D0
>>>>>           <...>-1461944 [001] 2076465.200168: rpc_task_run_action:
>>>>> task:57752@6 flags=3DASYNC|DYNAMIC|SOFT|NOCONNECT
>>>>> runstate=3DRUNNING|ACTIVE status=3D0 action=3Dcall_encode
>>>>>           <...>-1461944 [001] 2076465.200173: rpc_task_run_action:
>>>>> task:57752@6 flags=3DASYNC|DYNAMIC|SOFT|NOCONNECT
>>>>> runstate=3DRUNNING|ACTIVE|NEED_XMIT|NEED_RECV status=3D0
>>>>> action=3Dcall_connect
>>>>>           <...>-1461944 [001] 2076465.200174: rpc_call_rpcerror:
>>>>> task:57752@6 tk_status=3D-107 rpc_status=3D-107
>>>>>           <...>-1461944 [001] 2076465.200174: rpc_task_run_action:
>>>>> task:57752@6 flags=3DASYNC|DYNAMIC|SOFT|NOCONNECT
>>>>> runstate=3DRUNNING|ACTIVE|NEED_XMIT|NEED_RECV status=3D-107
>>>>> action=3Drpc_exit_task
>>>>>=20
>>>>> It's reporting ENOTCON. I'm not really sure if this is related to cop=
y
>>>>> offload but more perhaps doing callbacks over RDMA/IB.
>>>> If the client is awaiting a COPY notification callback, I can see why
>>>> a lost CB channel would cause the client to wait indefinitely.
>>>> The copy mechanism has to deal with this contingency... Perhaps the
>>>> server could force a disconnect so that the client and server have an
>>>> opportunity to re-establish the callback channel. <shrug>
>>>> In any event, the trace log above shows nothing more than "hey, it's
>>>> not working." Are there any rpcrdma trace events we can look at to
>>>> determine why the backchannel is getting lost?
>>>=20
>>> The trace log attached to my previous mail has it enabled, along with n=
fsd and sunrpc.
>>> I'm attaching the two files again here.
>> Thanks, Timo.
>> The first CB_OFFLOAD callback succeeds:
>> 2076155.216687: nfsd_cb_work:         addr=3D10.110.10.252:0 client 602e=
b645:daa037ae procedure=3DCB_OFFLOAD
>> 2076155.216704: rpc_request:          task:57746@6 nfs4_cbv1 CB_OFFLOAD =
(async)
>> 2076155.216975: rpc_stats_latency:    task:57746@6 xid=3D0xff9faaf9 nfs4=
_cbv1 CB_OFFLOAD backlog=3D33 rtt=3D195 execute=3D282
>> 2076155.216977: nfsd_cb_done:         addr=3D10.110.10.252:0 client 602e=
b645:daa037ae status=3D0
>> About 305 seconds later, the autodisconnect timer fires. I'm not sure if=
 this is the backchannel transport, but it looks suspicious:
>> 2076460.314954: xprt_disconnect_auto: peer=3D[10.110.10.252]:0 state=3DL=
OCKED|CONNECTED|BOUND
>> 2076460.314957: xprt_disconnect_done: peer=3D[10.110.10.252]:0 state=3DL=
OCKED|CONNECTED|BOUND
>> The next CB_OFFLOAD callback fails because the xprt has been marked "dis=
connected" and the request's NOCONNECT flag is set.
>> 2076465.200136: nfsd_cb_work:         addr=3D10.110.10.252:0 client 602e=
b645:daa037ae procedure=3DCB_OFFLOAD
>> 2076465.200151: rpc_request:          task:57752@6 nfs4_cbv1 CB_OFFLOAD =
(async)
>> 2076465.200168: rpc_task_run_action:  task:57752@6 flags=3DASYNC|DYNAMIC=
|SOFT|NOCONNECT runstate=3DRUNNING|ACTIVE status=3D0 action=3Dcall_encode
>> 2076465.200173: rpc_task_run_action:  task:57752@6 flags=3DASYNC|DYNAMIC=
|SOFT|NOCONNECT runstate=3DRUNNING|ACTIVE|NEED_XMIT|NEED_RECV status=3D0 ac=
tion=3Dcall_connect
>> 2076465.200174: rpc_call_rpcerror:    task:57752@6 tk_status=3D-107 rpc_=
status=3D-107
>> 2076465.200174: rpc_task_run_action:  task:57752@6 flags=3DASYNC|DYNAMIC=
|SOFT|NOCONNECT runstate=3DRUNNING|ACTIVE|NEED_XMIT|NEED_RECV status=3D-107=
 action=3Drpc_exit_task
>> 2076465.200179: nfsd_cb_done:         addr=3D10.110.10.252:0 client 602e=
b645:daa037ae status=3D-107
>> 2076465.200180: nfsd_cb_state:        addr=3D10.110.10.252:0 client 602e=
b645:daa037ae state=3DFAULT
>> Perhaps RPC clients for NFSv4.1+ callback should be created with
>> the RPC_CLNT_CREATE_NO_IDLE_TIMEOUT flag.
>=20
> I added that flag to the callback client creation flags, and so far after=
 a few hours of uptime, copying still works.

It seems like a good thing to do in any event (barring any other observatio=
ns).
Can you send a patch for review?


> Can't say anything about that being the appropriate fix for the issue at =
hand, as I lack the necessary insight into the NFS code, but I'll leave it =
running like that for now and observe.
>=20
> Can also gladly test any other patches.
>=20
>=20
> Thanks,
> Timo

--
Chuck Lever