Messages in this thread | | | Date | Mon, 16 May 2022 14:25:49 +0100 | Subject | Re: [REGRESSION] lxc-stop hang on 5.17.x kernels | From | Pavel Begunkov <> |
| |
On 5/16/22 13:12, Pavel Begunkov wrote: > On 5/15/22 19:34, Daniel Harding wrote: >> On 5/15/22 11:20, Thorsten Leemhuis wrote: >>> On 04.05.22 08:54, Daniel Harding wrote: >>>> On 5/3/22 17:14, Pavel Begunkov wrote: >>>>> On 5/3/22 08:37, Daniel Harding wrote: >>>>>> [Resend with a smaller trace] >>>>>> On 5/3/22 02:14, Pavel Begunkov wrote: >>>>>>> On 5/2/22 19:49, Daniel Harding wrote: >>>>>>>> On 5/2/22 20:40, Pavel Begunkov wrote: >>>>>>>>> On 5/2/22 18:00, Jens Axboe wrote: >>>>>>>>>> On 5/2/22 7:59 AM, Jens Axboe wrote: >>>>>>>>>>> On 5/2/22 7:36 AM, Daniel Harding wrote: >>>>>>>>>>>> On 5/2/22 16:26, Jens Axboe wrote: >>>>>>>>>>>>> On 5/2/22 7:17 AM, Daniel Harding wrote: >>>>>>>>>>>>>> I use lxc-4.0.12 on Gentoo, built with io-uring support >>>>>>>>>>>>>> (--enable-liburing), targeting liburing-2.1. My kernel >>>>>>>>>>>>>> config is a >>>>>>>>>>>>>> very lightly modified version of Fedora's generic kernel >>>>>>>>>>>>>> config. After >>>>>>>>>>>>>> moving from the 5.16.x series to the 5.17.x kernel series, I >>>>>>>>>>>>>> started >>>>>>>>>>>>>> noticed frequent hangs in lxc-stop. It doesn't happen 100% >>>>>>>>>>>>>> of the >>>>>>>>>>>>>> time, but definitely more than 50% of the time. Bisecting >>>>>>>>>>>>>> narrowed >>>>>>>>>>>>>> down the issue to commit >>>>>>>>>>>>>> aa43477b040251f451db0d844073ac00a8ab66ee: >>>>>>>>>>>>>> io_uring: poll rework. Testing indicates the problem is still >>>>>>>>>>>>>> present >>>>>>>>>>>>>> in 5.18-rc5. Unfortunately I do not have the expertise with the >>>>>>>>>>>>>> codebases of either lxc or io-uring to try to debug the problem >>>>>>>>>>>>>> further on my own, but I can easily apply patches to any of the >>>>>>>>>>>>>> involved components (lxc, liburing, kernel) and rebuild for >>>>>>>>>>>>>> testing or >>>>>>>>>>>>>> validation. I am also happy to provide any further >>>>>>>>>>>>>> information that >>>>>>>>>>>>>> would be helpful with reproducing or debugging the problem. >>>>>>>>>>>>> Do you have a recipe to reproduce the hang? That would make it >>>>>>>>>>>>> significantly easier to figure out. >>>>>>>>>>>> I can reproduce it with just the following: >>>>>>>>>>>> >>>>>>>>>>>> sudo lxc-create --n lxc-test --template download --bdev >>>>>>>>>>>> dir --dir /var/lib/lxc/lxc-test/rootfs -- -d ubuntu -r bionic >>>>>>>>>>>> -a amd64 >>>>>>>>>>>> sudo lxc-start -n lxc-test >>>>>>>>>>>> sudo lxc-stop -n lxc-test >>>>>>>>>>>> >>>>>>>>>>>> The lxc-stop command never exits and the container continues >>>>>>>>>>>> running. >>>>>>>>>>>> If that isn't sufficient to reproduce, please let me know. >>>>>>>>>>> Thanks, that's useful! I'm at a conference this week and hence have >>>>>>>>>>> limited amount of time to debug, hopefully Pavel has time to >>>>>>>>>>> take a look >>>>>>>>>>> at this. >>>>>>>>>> Didn't manage to reproduce. Can you try, on both the good and bad >>>>>>>>>> kernel, to do: >>>>>>>>> Same here, it doesn't reproduce for me >>>>>>>> OK, sorry it wasn't something simple. >>>>>>>>> # echo 1 > /sys/kernel/debug/tracing/events/io_uring/enable >>>>>>>>>> run lxc-stop >>>>>>>>>> >>>>>>>>>> # cp /sys/kernel/debug/tracing/trace ~/iou-trace >>>>>>>>>> >>>>>>>>>> so we can see what's going on? Looking at the source, lxc is just >>>>>>>>>> using >>>>>>>>>> plain POLL_ADD, so I'm guessing it's not getting a notification >>>>>>>>>> when it >>>>>>>>>> expects to, or it's POLL_REMOVE not doing its job. If we have a >>>>>>>>>> trace >>>>>>>>>> from both a working and broken kernel, that might shed some light >>>>>>>>>> on it. >>>>>>>> It's late in my timezone, but I'll try to work on getting those >>>>>>>> traces tomorrow. >>>>>>> I think I got it, I've attached a trace. >>>>>>> >>>>>>> What's interesting is that it issues a multi shot poll but I don't >>>>>>> see any kind of cancellation, neither cancel requests nor task/ring >>>>>>> exit. Perhaps have to go look at lxc to see how it's supposed >>>>>>> to work >>>>>> Yes, that looks exactly like my bad trace. I've attached good trace >>>>>> (captured with linux-5.16.19) and a bad trace (captured with >>>>>> linux-5.17.5). These are the differences I noticed with just a >>>>>> visual scan: >>>>>> >>>>>> * Both traces have three io_uring_submit_sqe calls at the very >>>>>> beginning, but in the good trace, there are further >>>>>> io_uring_submit_sqe calls throughout the trace, while in the bad >>>>>> trace, there are none. >>>>>> * The good trace uses a mask of c3 for io_uring_task_add much more >>>>>> often than the bad trace: the bad trace uses a mask of c3 only for >>>>>> the very last call to io_uring_task_add, but a mask of 41 for the >>>>>> other calls. >>>>>> * In the good trace, many of the io_uring_complete calls have a >>>>>> result of 195, while in the bad trace, they all have a result of 1. >>>>>> >>>>>> I don't know whether any of those things are significant or not, but >>>>>> that's what jumped out at me. >>>>>> >>>>>> I have also attached a copy of the script I used to generate the >>>>>> traces. If there is anything further I can to do help debug, please >>>>>> let me know. >>>>> Good observations! thanks for traces. >>>>> >>>>> It sounds like multi-shot poll requests were getting downgraded >>>>> to one-shot, which is a valid behaviour and was so because we >>>>> didn't fully support some cases. If that's the reason, than >>>>> the userspace/lxc is misusing the ABI. At least, that's the >>>>> working hypothesis for now, need to check lxc. >>>> So, I looked at the lxc source code, and it appears to at least try to >>>> handle the case of multi-shot being downgraded to one-shot. I don't >>>> know enough to know if the code is actually correct however: >>>> >>>> https://github.com/lxc/lxc/blob/7e37cc96bb94175a8e351025d26cc35dc2d10543/src/lxc/mainloop.c#L165-L189 >>>> https://github.com/lxc/lxc/blob/7e37cc96bb94175a8e351025d26cc35dc2d10543/src/lxc/mainloop.c#L254 >>>> https://github.com/lxc/lxc/blob/7e37cc96bb94175a8e351025d26cc35dc2d10543/src/lxc/mainloop.c#L288-L290 >>> Hi, this is your Linux kernel regression tracker. Nothing happened here >>> for round about ten days now afaics; or did the discussion continue >>> somewhere else. >>> >>> From what I gathered from this discussion is seems the root cause might >>> be in LXC, but it was exposed by kernel change. That makes it sill a >>> kernel regression that should be fixed; or is there a strong reason why >>> we should let this one slip? >> >> No, there hasn't been any discussion since the email you replied to. I've done a bit more testing on my end, but without anything conclusive. The one thing I can say is that my testing shows that LXC does correctly handle multi-shot poll requests which were being downgraded to one-shot in 5.16.x kernels, which I think invalidates Pavel's theory. In 5.17.x kernels, those same poll requests are no longer being downgraded to one-shot requests, and thus under 5.17.x LXC is no longer re-arming those poll requests (but also shouldn't need to, according to what is being returned by the kernel). I don't know if this change in kernel behavior is related to the hang, or if it is just a side effect of other io-uring changes that made it into 5.17. Nothing in the LXC's usage of io-uring seems obviously incorrect to me, but I am far from an expert. I also did some work toward creating a simpler reproducer, without success (I was able to get a simple program using io-uring running, >> but never could get it to hang). ISTM that this is still a kernel regression, unless someone can point out a definite fault in the way LXC is using io-uring. > > Haven't had time to debug it. Apparently LXC is stuck on > read(2) terminal fd. Not yet clear what is the reason.
How it was with oneshots:
1: kernel: poll fires, add a CQE 2: kernel: remove poll 3: userspace: get CQE 4: userspace: read(terminal_fd); 5: userspace: add new poll 6: goto 1)
What might happen and actually happens with multishot:
1: kernel: poll fires, add CQE1 2: kernel: poll fires again, add CQE2 3: userspace: get CQE1 4: userspace: read(terminal_fd); // reads all data, for both CQE1 and CQE2 5: userspace: get CQE2 6: userspace: read(terminal_fd); // nothing to read, hangs here
It should be the read in lxc_terminal_ptx_io().
IMHO, it's not a regression but a not perfect feature API and/or an API misuse.
Cc: Christian Brauner
Christian, in case you may have some input on the LXC side of things. Daniel reported an LXC problem when it uses io_uring multishot poll requests. Before aa43477b04025 ("io_uring: poll rework"), multishot poll requests for tty/pty and some other files were always downgraded to oneshots, which had been fixed by the commit and exposed the problem. I hope the example above explains it, but please let me know if it needs more details
-- Pavel Begunkov
| |