Re: NFS regression between 5.17 and 5.18

[Chuck Lever III <chuck.lever@oracle.com>]

> On Jun 20, 2022, at 3:46 AM, Thorsten Leemhuis <regressions@leemhuis.info> wrote:
> 
> Dennis, Chuck, I have below issue on the list of tracked regressions.
> What's the status? Has any progress been made? Or is this not really a
> regression and can be ignored?
> 
> Ciao, Thorsten (wearing his 'the Linux kernel's regression tracker' hat)
> 
> P.S.: As the Linux kernel's regression tracker I deal with a lot of
> reports and sometimes miss something important when writing mails like
> this. If that's the case here, don't hesitate to tell me in a public
> reply, it's in everyone's interest to set the public record straight.
> 
> #regzbot poke
> ##regzbot unlink: https://bugzilla.kernel.org/show_bug.cgi?id=215890

The above link points to an Apple trackpad bug.

The bug described all the way at the bottom was the origin problem
report. I believe this is an NFS client issue. We are waiting for
a response from the NFS client maintainers to help Dennis track
this down.


> On 17.05.22 16:02, Chuck Lever III wrote:
>>> On May 17, 2022, at 9:40 AM, Dennis Dalessandro <dennis.dalessandro@cornelisnetworks.com> wrote:
>>> 
>>> On 5/13/22 10:59 AM, Chuck Lever III wrote:
>>>>>> 
>>>>>> Ran a test with -rc6 and this time see a hung task trace on the
>>>>>> console as well
>>>>>> as an NFS RPC error.
>>>>>> 
>>>>>> [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>
>>>>>> 
>>>>>> The call trace shows up again at 245, 368, and 491 seconds. Same
>>>>>> task, same trace.
>>>>>> 
>>>>>> 
>>>>>> 
>>>>>> 
>>>>> 
>>>>> 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.
>>> 
>>> To be fair, I've only seen this one time and have had the performance regression
>>> since -rc1.
>>> 
>>>> 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.
>>> 
>>> I've checked our test code and after 10 minutes it does give up trying to do the
>>> NFS copies and aborts (SIG_INT) the test.
>> 
>> After sleeping on it, I'm fairly certain the stack trace
>> above is a result of a gap in how xprtrdma handles a
>> signaled RPC.
>> 
>> Signal handling in that code is pretty hard to test, so not
>> surprising that there's a lingering bug or two. One idea I
>> had was to add a fault injector in the RPC scheduler to
>> throw signals at random. I think it can be done without
>> perturbing the hot path. Maybe I'll post an RFC patch.
>> 
>> 
>>> So in all my tests and bisect attempts it seems the possibility to hit a slow
>>> NFS operation that hangs for minutes has been possible for quite some time.
>>> However in 5.18 it gets much worse.
>>> 
>>> Any likely places I should add traces to try and find out what's stuck or taking
>>> time?
>> 
>> There's been a lot of churn in that area in recent releases,
>> so I'm not familiar with the existing tracepoints. Maybe
>> Ben or Trond could provide some guidance.
> 

--
Chuck Lever