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>,
        Olga Kornievskaia <aglo@umich.edu>
CC:     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/TYHEFmapbOyaAgAAHBQCAAB6ZgIABlTwAgAArPQCAACy3AIAA0KWSgAAkhACAAB9zAIABZJ0AgAACxwCAAANsgIAADTqA
Date:   Fri, 19 Feb 2021 18:48:30 +0000
Message-ID: <E4BAC726-2FFA-47A8-A1B6-F0D2848ABB98@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>
In-Reply-To: <19c74710-bf35-6412-dd06-071331419ab5@rothenpieler.org>
Accept-Language: en-US
Content-Language: en-US
Content-Type: text/plain; charset="us-ascii"
Content-ID: <75A73CDAA780F74FA0F91F17E107996E@namprd10.prod.outlook.com>
Content-Transfer-Encoding: quoted-printable
MIME-Version: 1.0
X-MS-Exchange-CrossTenant-Network-Message-Id: d2783e78-113f-4156-56af-08d8d506f35f
X-MS-Exchange-CrossTenant-originalarrivaltime: 19 Feb 2021 18:48:30.1531
 (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: xbxrPK4bnJgFXzTNb7loBymGjt9SFSWkur4WpWEd95e29PL7B0ZSYXUBMoHXzekINS+vHM/bIClpcJFQUyGh0Q==
X-MS-Exchange-Transport-CrossTenantHeadersStamped: BY5PR10MB4147
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-2102190146
X-Proofpoint-Virus-Version: vendor=nai engine=6200 definitions=9900 signatures=668683
X-Proofpoint-Spam-Details: rule=notspam policy=default score=0 spamscore=0 priorityscore=1501
 lowpriorityscore=0 bulkscore=0 impostorscore=0 mlxlogscore=999
 adultscore=0 malwarescore=0 phishscore=0 clxscore=1015 mlxscore=0
 suspectscore=0 classifier=spam adjust=0 reason=mlx scancount=1
 engine=8.12.0-2009150000 definitions=main-2102190146
Precedence: bulk
List-ID: <linux-nfs.vger.kernel.org>
X-Mailing-List: linux-nfs@vger.kernel.org


> On Feb 19, 2021, at 1:01 PM, Timo Rothenpieler <timo@rothenpieler.org> wr=
ote:
>=20
> On 19.02.2021 18:48, Chuck Lever wrote:
>>> On Feb 19, 2021, at 12:38 PM, Olga Kornievskaia <aglo@umich.edu> wrote:
>>>=20
>>> On Thu, Feb 18, 2021 at 3:22 PM Timo Rothenpieler <timo@rothenpieler.or=
g> wrote:
>>>>=20
>>>> On 18.02.2021 19:30, Olga Kornievskaia wrote:
>>>>> Thank you for getting tracepoints from a busy server but can you get
>>>>> more? As suspected, the server is having issues sending the callback.
>>>>> 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 as
>>>> NFS server from an ext4 mount, the other is the same client as before.
>>>> 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 attac=
hed.
>>>>=20
>>>> Another observation made due to this: unmount and re-mounting the NFS
>>>> share also gets it back into working condition for a while, no reboot
>>>> necessary.
>>>> During this trace, I got "lucky", and after just 5 minutes of waiting,
>>>> it got stuck.
>>>>=20
>>>> Before that, I had a run of mount + trying to copy every 5 minutes whe=
re
>>>> it ran for 45 minutes without getting stuck. At which point I decided =
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 copy
>>> 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 nfs=
d 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 602eb64=
5:daa037ae procedure=3DCB_OFFLOAD
2076155.216704: rpc_request:          task:57746@6 nfs4_cbv1 CB_OFFLOAD (as=
ync)

2076155.216975: rpc_stats_latency:    task:57746@6 xid=3D0xff9faaf9 nfs4_cb=
v1 CB_OFFLOAD backlog=3D33 rtt=3D195 execute=3D282
2076155.216977: nfsd_cb_done:         addr=3D10.110.10.252:0 client 602eb64=
5:daa037ae status=3D0


About 305 seconds later, the autodisconnect timer fires. I'm not sure if th=
is is the backchannel transport, but it looks suspicious:

2076460.314954: xprt_disconnect_auto: peer=3D[10.110.10.252]:0 state=3DLOCK=
ED|CONNECTED|BOUND
2076460.314957: xprt_disconnect_done: peer=3D[10.110.10.252]:0 state=3DLOCK=
ED|CONNECTED|BOUND


The next CB_OFFLOAD callback fails because the xprt has been marked "discon=
nected" and the request's NOCONNECT flag is set.

2076465.200136: nfsd_cb_work:         addr=3D10.110.10.252:0 client 602eb64=
5:daa037ae procedure=3DCB_OFFLOAD
2076465.200151: rpc_request:          task:57752@6 nfs4_cbv1 CB_OFFLOAD (as=
ync)

2076465.200168: rpc_task_run_action:  task:57752@6 flags=3DASYNC|DYNAMIC|SO=
FT|NOCONNECT runstate=3DRUNNING|ACTIVE status=3D0 action=3Dcall_encode
2076465.200173: rpc_task_run_action:  task:57752@6 flags=3DASYNC|DYNAMIC|SO=
FT|NOCONNECT runstate=3DRUNNING|ACTIVE|NEED_XMIT|NEED_RECV status=3D0 actio=
n=3Dcall_connect
2076465.200174: rpc_call_rpcerror:    task:57752@6 tk_status=3D-107 rpc_sta=
tus=3D-107
2076465.200174: rpc_task_run_action:  task:57752@6 flags=3DASYNC|DYNAMIC|SO=
FT|NOCONNECT runstate=3DRUNNING|ACTIVE|NEED_XMIT|NEED_RECV status=3D-107 ac=
tion=3Drpc_exit_task
2076465.200179: nfsd_cb_done:         addr=3D10.110.10.252:0 client 602eb64=
5:daa037ae status=3D-107
2076465.200180: nfsd_cb_state:        addr=3D10.110.10.252:0 client 602eb64=
5:daa037ae state=3DFAULT


Perhaps RPC clients for NFSv4.1+ callback should be created with
the RPC_CLNT_CREATE_NO_IDLE_TIMEOUT flag.


--
Chuck Lever