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:     Olga Kornievskaia <aglo@umich.edu>
CC:     Timo Rothenpieler <timo@rothenpieler.org>,
        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/TYHEFmapbOyaAgAAHBQCAAB6ZgIABlTwAgAArPQCAACy3AIAA0KWSgAAkhACAAB9zAIABZJ0AgAACxwCAAANsgIAADTqAgAAgBICAAAOaAA==
Date:   Fri, 19 Feb 2021 20:55:58 +0000
Message-ID: <1A329051-FD97-4200-AB48-B3DAE7AA9D21@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>
 <CAN-5tyHq-1SM8o-qpeF-_UGd0a74ky8Atcam=gY9HqUrMhfp_g@mail.gmail.com>
In-Reply-To: <CAN-5tyHq-1SM8o-qpeF-_UGd0a74ky8Atcam=gY9HqUrMhfp_g@mail.gmail.com>
Accept-Language: en-US
Content-Language: en-US
Content-Type: text/plain; charset="us-ascii"
Content-ID: <E14E7957EF5FB84A9CB1C7D576519C47@namprd10.prod.outlook.com>
Content-Transfer-Encoding: quoted-printable
MIME-Version: 1.0
X-MS-Exchange-CrossTenant-Network-Message-Id: e3eeddc9-7bea-4f69-f843-08d8d518c244
X-MS-Exchange-CrossTenant-originalarrivaltime: 19 Feb 2021 20:55:58.6593
 (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: Qslz7C/kUJnxZUdrQ/DbTR6G340my/ZzwfiV9WGu0IARVeNyWOpRp3Z5CQKapYqJ/T9KkIsXPABvyzSBkaqDyA==
X-MS-Exchange-Transport-CrossTenantHeadersStamped: SJ0PR10MB4814
X-Proofpoint-Virus-Version: vendor=nai engine=6200 definitions=9900 signatures=668683
X-Proofpoint-Spam-Details: rule=notspam policy=default score=0 malwarescore=0 spamscore=0 mlxscore=0
 phishscore=0 adultscore=0 bulkscore=0 mlxlogscore=999 suspectscore=0
 classifier=spam adjust=0 reason=mlx scancount=1 engine=8.12.0-2009150000
 definitions=main-2102190167
X-Proofpoint-Virus-Version: vendor=nai engine=6200 definitions=9900 signatures=668683
X-Proofpoint-Spam-Details: rule=notspam policy=default score=0 lowpriorityscore=0 suspectscore=0
 impostorscore=0 priorityscore=1501 clxscore=1015 spamscore=0 mlxscore=0
 phishscore=0 malwarescore=0 bulkscore=0 adultscore=0 mlxlogscore=999
 classifier=spam adjust=0 reason=mlx scancount=1 engine=8.12.0-2009150000
 definitions=main-2102190168
Precedence: bulk
List-ID: <linux-nfs.vger.kernel.org>
X-Mailing-List: linux-nfs@vger.kernel.org


> On Feb 19, 2021, at 3:43 PM, Olga Kornievskaia <aglo@umich.edu> wrote:
>=20
> On Fri, Feb 19, 2021 at 1:48 PM Chuck Lever <chuck.lever@oracle.com> wrot=
e:
>>=20
>>=20
>>=20
>>> 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.
>>=20
>> Thanks, Timo.
>>=20
>> The first CB_OFFLOAD callback succeeds:
>>=20
>> 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)
>>=20
>> 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
>>=20
>>=20
>> About 305 seconds later, the autodisconnect timer fires. I'm not sure if=
 this is the backchannel transport, but it looks suspicious:
>>=20
>> 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
>>=20
>>=20
>> The next CB_OFFLOAD callback fails because the xprt has been marked "dis=
connected" and the request's NOCONNECT flag is set.
>>=20
>> 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)
>>=20
>> 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
>>=20
>>=20
>> Perhaps RPC clients for NFSv4.1+ callback should be created with
>> the RPC_CLNT_CREATE_NO_IDLE_TIMEOUT flag.
>=20
> Do you know if this callback behavior is new? The same problem would
> exist with delegation recalls.

Delegation recall would be affected, but that wouldn't cause an
indefinite hang. The server should eventually revoke the delegation
and life would continue.

Also, the server should be setting the CALLBACK_DOWN sequence status
flag in its replies. If the client isn't sending any other traffic
while waiting for the copy to complete, it probably wouldn't notice
the problem.

Is the client renewing its lease while the copy is ongoing? That
would be an opportunity for the server to signal the loss of
backchannel connectivity.

Again, in the long term, the copy mechanism needs to be prepared for
the contingency that the callback channel is lost while copy
operations are pending.

There's plenty to investigate and confirm here.


--
Chuck Lever