Received: by 2002:a5d:925a:0:0:0:0:0 with SMTP id e26csp1220434iol; Sun, 12 Jun 2022 09:21:28 -0700 (PDT) X-Google-Smtp-Source: ABdhPJwG7f2kaNfqb8j5uytA9edE9BFLGYgaOb6fEd0fl5BUCoUr40ws7RtYOEGF+XlCIT9BUCY6 X-Received: by 2002:a17:90a:e2c2:b0:1ea:788a:e951 with SMTP id fr2-20020a17090ae2c200b001ea788ae951mr11163022pjb.155.1655050887799; Sun, 12 Jun 2022 09:21:27 -0700 (PDT) ARC-Seal: i=1; a=rsa-sha256; t=1655050887; cv=none; d=google.com; s=arc-20160816; b=tSauJpFjHSnHJwWPyPGFE0l8Swvj/eWZNAiK50lCIezuE6B/hNxNCebFgXt811m64q IXrTyQmeRnCrS+m6WCTFMndrBp/b1kFn9ve1o+UIxS8T+TrpcKHjV0Y0ic3BjqDU1JO2 YSuOg9jH6F/2AxXjOh+kJAchQ6ZJt6zHnwK83PmygNGfc+Zl+iuc7kt85TDOiYO+deUF NOPc3z2u0YGNV9G4kBnbeUA7KrxH0Vu2qAr3MFMDM3205MHnQP/j2Ol8wK5VwtkopU8/ GzaV3/l71HX8iOAcke697PdkDl1fpSkTfm4qqTCpeh5DKMbG1nw47PTXgJuQx4YsrnXk FBpw== ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=arc-20160816; h=list-id:precedence:in-reply-to:content-transfer-encoding :content-disposition:mime-version:references:reply-to:message-id :subject:cc:to:from:date:dkim-signature; bh=YQ004PkuSTWwNW0u6q+20kdz46iZJIoemlex3cbnEf4=; b=x5ADX7Ez2tvOEpcd7aZwAGh7R633m3oVR+UC+mlEB9M1x9Xv5GMc4BA3VZimAIzZNR iAUDGJIutzxTLYurt6QkxOlaf3tSa8LXFvImNm1GbsBlLNtdj8ZfhUbcvvFINcAt5OTI Hyr21Ry7tl43cqEjGou5kR+UT24BjZfhU+QKRdjbSifSW82i2StNHz+PF5mZKF5wCydC qjkYDs4w53jMqzE2NBiaMZ+YirP8dja4idfRk14QZvTem/s9Ac1+hYWewoBdAed3ddzP uXcKjHN8RsFf2BRAo+XxQA9M51mq5oxWSYSzzVBIOs9TIHGEZRhfVvrhYVe5mxvOMA3f GOng== ARC-Authentication-Results: i=1; mx.google.com; dkim=pass header.i=@kernel.org header.s=k20201202 header.b=mBaqaTy+; spf=pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 2620:137:e000::1:20 as permitted sender) smtp.mailfrom=linux-kernel-owner@vger.kernel.org; dmarc=pass (p=NONE sp=NONE dis=NONE) header.from=kernel.org Return-Path: Received: from out1.vger.email (out1.vger.email. [2620:137:e000::1:20]) by mx.google.com with ESMTP id f37-20020a635565000000b00405024dd5b6si6520592pgm.405.2022.06.12.09.21.16; Sun, 12 Jun 2022 09:21:27 -0700 (PDT) Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 2620:137:e000::1:20 as permitted sender) client-ip=2620:137:e000::1:20; Authentication-Results: mx.google.com; dkim=pass header.i=@kernel.org header.s=k20201202 header.b=mBaqaTy+; spf=pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 2620:137:e000::1:20 as permitted sender) smtp.mailfrom=linux-kernel-owner@vger.kernel.org; dmarc=pass (p=NONE sp=NONE dis=NONE) header.from=kernel.org Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S233587AbiFLNgf (ORCPT + 99 others); Sun, 12 Jun 2022 09:36:35 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:43248 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S229912AbiFLNge (ORCPT ); Sun, 12 Jun 2022 09:36:34 -0400 Received: from dfw.source.kernel.org (dfw.source.kernel.org [139.178.84.217]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 5C5F84A93C; Sun, 12 Jun 2022 06:36:33 -0700 (PDT) Received: from smtp.kernel.org (relay.kernel.org [52.25.139.140]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by dfw.source.kernel.org (Postfix) with ESMTPS id D6C4060EE7; Sun, 12 Jun 2022 13:36:32 +0000 (UTC) Received: by smtp.kernel.org (Postfix) with ESMTPSA id 3AAA1C34115; Sun, 12 Jun 2022 13:36:32 +0000 (UTC) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/simple; d=kernel.org; s=k20201202; t=1655040992; bh=pWDwNcvIidrGgS4/pNO+FanuGaNPZuY1PMIGuVsnnuI=; h=Date:From:To:Cc:Subject:Reply-To:References:In-Reply-To:From; b=mBaqaTy+6bZ/qIqt08BuELqII8vPRHwyHUSf15JwTVIBZsoKT9hj9SQIpAaXuUO+b ylim/3pWOunTvONVlhhnTqpuRDe1sP+coV171k0/iaR8tmr7PNKKUeAyRzo9jyu9FJ ZsIL98lerhiU0y8aWD7mFtnZ2eCQM4iTDrpqYt3noBLHwdvE7a+rXS/rhHYGrr5a++ ANGmA330da6bmiZpXN8eyWYyHkoRLV3o4rmIRhR7i9lIX+AUJ1r4eKSym2qOaf14df lmaFBiLPkSL/4oXD/F3mfFOYdYylXtv4t8QDPoL9W+Si1NOfMt1ccNXTi+AEfMpbSR 09Qza2sMU8hoQ== Received: by paulmck-ThinkPad-P17-Gen-1.home (Postfix, from userid 1000) id D26265C02F9; Sun, 12 Jun 2022 06:36:31 -0700 (PDT) Date: Sun, 12 Jun 2022 06:36:31 -0700 From: "Paul E. McKenney" To: "zhangfei.gao@foxmail.com" Cc: Zhangfei Gao , "linux-kernel@vger.kernel.org" , rcu@vger.kernel.org, Lai Jiangshan , Josh Triplett , Mathieu Desnoyers , Matthew Wilcox , Shameerali Kolothum Thodi Subject: Re: Commit 282d8998e997 (srcu: Prevent expedited GPs and blocking readers from consuming CPU) cause qemu boot slow Message-ID: <20220612133631.GQ1790663@paulmck-ThinkPad-P17-Gen-1> Reply-To: paulmck@kernel.org References: <20615615-0013-5adc-584f-2b1d5c03ebfc@linaro.org> <20220611165956.GO1790663@paulmck-ThinkPad-P17-Gen-1> MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Disposition: inline Content-Transfer-Encoding: 8bit In-Reply-To: X-Spam-Status: No, score=-8.3 required=5.0 tests=BAYES_00,DKIMWL_WL_HIGH, DKIM_SIGNED,DKIM_VALID,DKIM_VALID_AU,DKIM_VALID_EF,RCVD_IN_DNSWL_HI, SPF_HELO_NONE,SPF_PASS,T_SCC_BODY_TEXT_LINE autolearn=ham autolearn_force=no version=3.4.6 X-Spam-Checker-Version: SpamAssassin 3.4.6 (2021-04-09) on lindbergh.monkeyblade.net Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On Sun, Jun 12, 2022 at 03:40:30PM +0800, zhangfei.gao@foxmail.com wrote: > Hi, Paul > > On 2022/6/12 上午12:59, Paul E. McKenney wrote: > > On Sun, Jun 12, 2022 at 12:32:59AM +0800, Zhangfei Gao wrote: > > > Hi, Paul > > > > > > When verifying qemu with acpi rmr feature on v5.19-rc1, the guest kernel > > > stuck for several minutes. > > Stuck for several minutes but then continues normally? Or stuck for > > several minutes before you kill qemu? > > qemu boot stuck for several minutes, then guest can bootup normally, just > slower. > > > > And I have to ask... What happened without the ACPI RMR feature? > If no ACPI, qemu boot quickly without stuck. > build/aarch64-softmmu/qemu-system-aarch64 -machine > virt,gic-version=3,iommu=smmuv3 \ > -enable-kvm -cpu host -m 1024 \ > -kernel Image -initrd mini-rootfs.cpio.gz -nographic -append \ > "rdinit=init console=ttyAMA0 earlycon=pl011,0x9000000 kpti=off" > > Adding acpi=force & -bios QEMU_EFI.fd, qemu boot stuck for several minutes. > > By the way, my hardware platform is aarch64. Thank you for the information! The problem is excessive delay rather than a hang, and it is configuration-dependent. Good to know! > Only change this can solve the stuck issue. > > --- a/kernel/rcu/srcutree.c > +++ b/kernel/rcu/srcutree.c > @@ -524,6 +524,10 @@ static unsigned long srcu_get_delay(struct srcu_struct > *ssp) >  { >         unsigned long jbase = SRCU_INTERVAL; > > +       if (ULONG_CMP_LT(READ_ONCE(ssp->srcu_gp_seq), > READ_ONCE(ssp->srcu_gp_seq_needed_exp))) > +               return 0; > +       return SRCU_INTERVAL; I am glad that you have a workaround for this problem, but this change would re-introduce the problem that commit 282d8998e997 ("srcu: Prevent expedited GPs and blocking readers from consuming CPU") was intended to fix. For one example, your change can prevent kernel live patching from applying a patch. So something else is needed. Does changing the value of SRCU_MAX_INTERVAL to (say) 3 decrease the delay significantly? (This is not a fix, either, but instead a debug check.) Your change always returns zero if another SRCU grace period is needed. Let's look at the callers of srcu_get_delay(): o cleanup_srcu_struct() uses it to check whether there is an expedited grace period pending, leaking the srcu_struct if so. This should not affect boot delay. (Unless you are invoking init_srcu_struct() and cleanup_srcu_struct() really really often.) o srcu_gp_end() uses it to determine whether or not to allow a one-jiffy delay before invoking callbacks at the end of a grace period. o srcu_funnel_gp_start() uses it to determine whether or not to allow a one-jiffy delay before starting the process of checking for the end of an SRCU grace period. o try_check_zero() uses it to add an additional short delay (instead of a long delay) between checks of reader state. o process_srcu() uses it to calculate the long delay between checks of reader state. These add one-jiffy delays, except for process_srcu(), which adds a delay of up to 10 jiffies. Even given HZ=100 (as opposed to the HZ=1000 that I normally use), this requires thousands of such delays to add up to the several minutes that you are seeing. (In theory, the delays could also be due to SRCU readers, except that in that case adjusting timeouts in the grace-period processing would not make things go faster.) So, does acpi=force & -bios QEMU_EFI.fd add SRCU grace periods? If so, it would be very good make sure that this code is using SRCU efficiently. One way to check would be to put a printk() into synchronize_srcu(), though maintaining a counter and printing (say) every 1000th invocation might be easier on the console output. > > > And on 5.18, there is no such problem. > > > > > > After revert this patch, the issue solved. > > > Commit 282d8998e997 (srcu: Prevent expedited GPs and blocking readers from > > > consuming CPU) > > > > > > > > > qemu cmd: > > > build/aarch64-softmmu/qemu-system-aarch64 -machine > > > virt,gic-version=3,iommu=smmuv3 \ > > > -enable-kvm -cpu host -m 1024 \ > > > -kernel Image -initrd mini-rootfs.cpio.gz -nographic -append \ > > > "rdinit=init console=ttyAMA0 earlycon=pl011,0x9000000 kpti=off acpi=force" \ > > > -bios QEMU_EFI.fd > > > > > > log: > > > InstallProtocolInterface: 5B1B31A1-9562-11D2-8E3F-00A0C969723B 7AA4D040 > > > add-symbol-file /home/linaro/work/edk2/Build/ArmVirtQemu-AARCH64/DEBUG_GCC48/AARCH64/NetworkPkg/IScsiDxe/IScsiDxe/DEBUG/IScsiDxe.dll > > > 0x75459000 > > > Loading driver at 0x00075458000 EntryPoint=0x00075459058 IScsiDxe.efi > > > InstallProtocolInterface: BC62157E-3E33-4FEC-9920-2D3B36D750DF 7AA4DE98 > > > ProtectUefiImageCommon - 0x7AA4D040 > > >   - 0x0000000075458000 - 0x000000000003F000 > > > SetUefiImageMemoryAttributes - 0x0000000075458000 - 0x0000000000001000 > > > (0x0000000000004008) > > > SetUefiImageMemoryAttributes - 0x0000000075459000 - 0x000000000003B000 > > > (0x0000000000020008) > > > SetUefiImageMemoryAttributes - 0x0000000075494000 - 0x0000000000003000 > > > (0x0000000000004008) > > > InstallProtocolInterface: 18A031AB-B443-4D1A-A5C0-0C09261E9F71 754952C8 > > > InstallProtocolInterface: 107A772C-D5E1-11D4-9A46-0090273FC14D 75495358 > > > InstallProtocolInterface: 6A7A5CFF-E8D9-4F70-BADA-75AB3025CE14 75495370 > > > InstallProtocolInterface: 18A031AB-B443-4D1A-A5C0-0C09261E9F71 754952F8 > > > InstallProtocolInterface: 107A772C-D5E1-11D4-9A46-0090273FC14D 75495358 > > > InstallProtocolInterface: 6A7A5CFF-E8D9-4F70-BADA-75AB3025CE14 75495370 > > > InstallProtocolInterface: 59324945-EC44-4C0D-B1CD-9DB139DF070C 75495348 > > > InstallProtocolInterface: 09576E91-6D3F-11D2-8E39-00A0C969723B 754953E8 > > > InstallProtocolInterface: 330D4706-F2A0-4E4F-A369-B66FA8D54385 7AA4D728 > > > > > > > > > Not sure it is either reported or solved. > > This is the first I have heard of it, so thank you for reporting it. > > > > Do you have a way of collecting something sysrq-t output? > Do you mean "echo t > /proc/sysrq-trigger", > There are too much output and kernel dump can not stop. OK. What other tools do you have to work out what is happening during temporary hangs such as this one? The question to be answered: "Is there usually at least one task waiting in synchronize_srcu() during these hangs, and if so, which srcu_struct is passed to those synchronize_srcu() calls?" Thanx, Paul