From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by smtp.lore.kernel.org (Postfix) with ESMTP id 58E90C433FE for ; Mon, 16 May 2022 18:14:02 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1343736AbiEPSOA (ORCPT ); Mon, 16 May 2022 14:14:00 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:41290 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1344636AbiEPSN6 (ORCPT ); Mon, 16 May 2022 14:13:58 -0400 Received: from mail-ej1-x635.google.com (mail-ej1-x635.google.com [IPv6:2a00:1450:4864:20::635]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 897B23DA69; Mon, 16 May 2022 11:13:55 -0700 (PDT) Received: by mail-ej1-x635.google.com with SMTP id j6so30195290ejc.13; Mon, 16 May 2022 11:13:55 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20210112; h=message-id:date:mime-version:user-agent:subject:content-language:to :cc:references:from:in-reply-to:content-transfer-encoding; bh=jCwtnCEtWoS4wCjhgbr7CWNZGicJaxfw2KD2HwoiN7Y=; b=ZpDsG84gAHO20eeA/45nqEQP+jYfssQPEG6EJ+xcAQ+4lGfKv+LNKKXd+SkJumRz3i C4SpaCavvJ+qFkHMCgVoeI1Fc8LH5oWO1Sgf1GbvHplcd9Kv3n4kkZzjsUVi8yDowmJt AhaLEznUoGZs3CcLNEG3xs9CLFZOf2wcYLN7paaQ7c9j2ocCVkr9yPU63JSSIx8YxX5R RM/JEVoWf4eB/GRv1WZUTx+dnYFSiDk0+KMu8vsRX0G6lKclc4JcLsHB2b5EJ2Eq59jH jGHefHaOaPGH+CE0R6OHn5tkz+nxVXWQRUA1/phMyFe0q83wjcqBgAhedZjssz10W7F3 NxqA== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20210112; h=x-gm-message-state:message-id:date:mime-version:user-agent:subject :content-language:to:cc:references:from:in-reply-to :content-transfer-encoding; bh=jCwtnCEtWoS4wCjhgbr7CWNZGicJaxfw2KD2HwoiN7Y=; b=dgFT7gQb4U5ST2kS89TU1NwWYARSkGvgBp4VI+zeL9GO66bXGsWDAwdn4QdJwP/Ym8 VvphKCEtQo8sdnWO/xelasj+RZPI9aN1rtmi9el3ZOL6lnNO0xQrcNq4JTGrsyVwgxTg kcR/gldnpUjzVPhUKOxKhRz/JO469yPQ1BkcEDZhT/a0sUKT9EKzK9/oJKmzNnFtFAnd vBFHNl17mIXiqyiGPCu4qhaK77ASCauD/xR6QScIxSKvEbuFTYb8JvGGyIAzRxUF/Dau Dz5LAJEHZrNgL6hQU3Omoq2+stz8ZLYEJip209MbUU+a8mLdeSXxd1ylu6HtqNeCOLca dmQg== X-Gm-Message-State: AOAM532dbL7gxMf+cYTD1C1mPlW2LS9nt+dFD9qzh9zqhs9NswzMB+xE gfybpZB1p0pALyZnHmW7my0isguSuWo= X-Google-Smtp-Source: ABdhPJzQaHtbrzv5AT/9yYAuuoygzwcm04GUa6WVFkn9kftMNYAKDPXLWGTDMMY3HX/Y4UyEy342yQ== X-Received: by 2002:a17:906:dc8f:b0:6f4:e6df:a48d with SMTP id cs15-20020a170906dc8f00b006f4e6dfa48dmr16746939ejc.206.1652724833996; Mon, 16 May 2022 11:13:53 -0700 (PDT) Received: from [192.168.8.198] ([85.255.232.74]) by smtp.gmail.com with ESMTPSA id my35-20020a1709065a6300b006f3ef214dd2sm33950ejc.56.2022.05.16.11.13.52 (version=TLS1_3 cipher=TLS_AES_128_GCM_SHA256 bits=128/128); Mon, 16 May 2022 11:13:53 -0700 (PDT) Message-ID: <152e8d96-28e9-0dda-8782-10690195643b@gmail.com> Date: Mon, 16 May 2022 19:13:05 +0100 MIME-Version: 1.0 User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:91.0) Gecko/20100101 Thunderbird/91.8.1 Subject: Re: [REGRESSION] lxc-stop hang on 5.17.x kernels Content-Language: en-US To: Daniel Harding Cc: regressions@lists.linux.dev, io-uring@vger.kernel.org, linux-kernel@vger.kernel.org, Thorsten Leemhuis , Jens Axboe , Christian Brauner References: <7925e262-e0d4-6791-e43b-d37e9d693414@living180.net> <6ad38ecc-b2a9-f0e9-f7c7-f312a2763f97@kernel.dk> <371c01dd-258c-e428-7428-ff390b664752@kernel.dk> <2436d42c-85ca-d060-6508-350c769804f1@gmail.com> <12a57dd9-4423-a13d-559b-2b1dd2fb0ef3@living180.net> <897dc597-fc0a-34ec-84b8-7e1c4901e0fc@leemhuis.info> <41c86189-0d1f-60f0-ca8e-f80b3ccf5130@gmail.com> <3fc08243-f9e0-9cec-4207-883c55ccff78@living180.net> <13028ff4-3565-f09e-818c-19e5f95fa60f@living180.net> From: Pavel Begunkov In-Reply-To: <13028ff4-3565-f09e-818c-19e5f95fa60f@living180.net> Content-Type: text/plain; charset=UTF-8; format=flowed Content-Transfer-Encoding: 8bit Precedence: bulk List-ID: X-Mailing-List: io-uring@vger.kernel.org On 5/16/22 16:13, Daniel Harding wrote: > On 5/16/22 16:57, Daniel Harding wrote: >> On 5/16/22 16:25, Pavel Begunkov wrote: >>> 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, I had actually just started a draft email with the same theory (although you stated it much more clearly than I could have).  I'm working on debugging the LXC side, but I'm pretty sure the issue is due to LXC using blocking reads and getting stuck exactly as you describe.  If I can confirm this, I'll go ahead and mark this regression as invalid and file an issue with LXC. Thanks for your help and patience. > > Yes, it does appear that was the problem.  The attach POC patch against LXC fixes the hang.  The kernel is working as intended. Daniel, that's great, thanks for confirming! -- Pavel Begunkov