On 20.06.22 16:11, Chuck Lever III wrote: > > >> On Jun 20, 2022, at 3:46 AM, Thorsten Leemhuis <regressions@xxxxxxxxxxxxx> 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. Yeah, I know, sorry, should have mentioned: either I or my bot did something stupid and associated that report with this regression, that's why I deassociated it with the "unlink" command. > 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. Many thx for the status update. Can anything be done to speed things up? This is taken quite a long time already -- way longer that outlined in "Prioritize work on fixing regressions" here: https://docs.kernel.org/process/handling-regressions.html Ciao, Thorsten >> On 17.05.22 16:02, Chuck Lever III wrote: >>>> On May 17, 2022, at 9:40 AM, Dennis Dalessandro <dennis.dalessandro@xxxxxxxxxxxxxxxxxxxx> 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 > > > >
