Received-SPF: pass (google.com: domain of linux-kernel+bounces-102881-linux.lists.archive=gmail.com@vger.kernel.org designates 2604:1380:45e3:2400::1 as permitted sender) client-ip=2604:1380:45e3:2400::1;
Feedback-ID: iad51458e:Fastmail
Date: Wed, 13 Mar 2024 23:33:01 -0700
From: Boqun Feng <boqun.feng@gmail.com>
To: Florian Fainelli <f.fainelli@gmail.com>
Cc: Frederic Weisbecker <frederic@kernel.org>,
	"Russell King (Oracle)" <linux@armlinux.org.uk>,
	Joel Fernandes <joel@joelfernandes.org>,
	Anna-Maria Behnsen <anna-maria@linutronix.de>,
	Linus Torvalds <torvalds@linux-foundation.org>,
	linux-kernel@vger.kernel.org, kernel-team@meta.com,
	paulmck@kernel.org, mingo@kernel.org, tglx@linutronix.de,
	rcu@vger.kernel.org, neeraj.upadhyay@amd.com, urezki@gmail.com,
	qiang.zhang1211@gmail.com, bigeasy@linutronix.de,
	chenzhongjin@huawei.com, yangjihong1@huawei.com,
	rostedt@goodmis.org, Justin Chen <justin.chen@broadcom.com>
Subject: Re: Unexplained long boot delays [Was Re: [GIT PULL] RCU changes for
 v6.9]
Message-ID: <ZfKaHQXdYCKrT3Yr@Boquns-Mac-mini.home>
References: <c5f9c640-4c06-495e-9c7e-0c208b914fa7@gmail.com>
 <CAHk-=wgP=9JxdOJ5oYtVO5yM6pFi5+3FPxfCQa4ezpagJuXq3g@mail.gmail.com>
 <ZfDptafiK0jns050@boqun-archlinux>
 <CAEXW_YRvz8xf-6hpwpYqS=YNa-xkn4CsuJzELJxOH_2FP+6ptQ@mail.gmail.com>
 <2fb110ed-ba04-4320-9ef0-8766c9df5578@gmail.com>
 <ZfIh33YAYkLaDeAS@shell.armlinux.org.uk>
 <533151c9-afb5-453b-8014-9fbe7c3b26c2@gmail.com>
 <ZfIuRMo8oKbR08Af@lothringen>
 <f4a2a18c-1c81-4857-a3a0-d049ec5c79b3@gmail.com>
 <ZfKHKtt4ar6HyRKu@Boquns-Mac-mini.home>
Precedence: bulk
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <ZfKHKtt4ar6HyRKu@Boquns-Mac-mini.home>

On Wed, Mar 13, 2024 at 10:12:10PM -0700, Boqun Feng wrote:
> On Wed, Mar 13, 2024 at 08:44:07PM -0700, Florian Fainelli wrote:
> > 
> > 
> > On 3/13/2024 3:52 PM, Frederic Weisbecker wrote:
> > > On Wed, Mar 13, 2024 at 03:04:26PM -0700, Florian Fainelli wrote:
> > > > On 3/13/24 14:59, Russell King (Oracle) wrote:
> > > > > On Wed, Mar 13, 2024 at 02:30:43PM -0700, Florian Fainelli wrote:
> > > > > > I will try to provide multiple answers for the sake of everyone having the
> > > > > > same context. Responding to Linus' specifically and his suggestion to use
> > > > > > "initcall_debug", this is what it gave me:
> > > > > > 
> > > > > > [    6.970669] ata1: SATA link down (SStatus 0 SControl 300)
> > > > > > [  166.136366] probe of unimac-mdio-0:01 returned 0 after 159216218 usecs
> > > > > > [  166.142931] unimac-mdio unimac-mdio.0: Broadcom UniMAC MDIO bus
> > > > > > [  166.148900] probe of unimac-mdio.0 returned 0 after 159243553 usecs
> > > > > > [  166.155820] probe of f0480000.ethernet returned 0 after 159258794 usecs
> > > > > > [  166.166427] ehci-brcm f0b00300.ehci_v2: EHCI Host Controller
> > > > > > 
> > > > > > Also got another occurrence happening resuming from suspend to DRAM with:
> > > > > > 
> > > > > > [   22.570667] brcmstb-dpfe 9932000.dpfe-cpu: PM: calling
> > > > > > platform_pm_resume+0x0/0x54 @ 1574, parent: rdb
> > > > > > [  181.643809] brcmstb-dpfe 9932000.dpfe-cpu: PM:
> > > > > > platform_pm_resume+0x0/0x54 returned 0 after 159073134 usecs
> > > > > > 
> > > > > > and also with the PCIe root complex driver:
> > > > > > 
> > > > > > [   18.266279] brcm-pcie f0460000.pcie: PM: calling
> > > > > > brcm_pcie_resume_noirq+0x0/0x164 @ 1597, parent: platform
> > > > > > [  177.457219] brcm-pcie f0460000.pcie: clkreq-mode set to default
> > > > > > [  177.457225] brcm-pcie f0460000.pcie: link up, 2.5 GT/s PCIe x1 (!SSC)
> > > > > > [  177.457231] brcm-pcie f0460000.pcie: PM: brcm_pcie_resume_noirq+0x0/0x164
> > > > > > returned 0 after 159190939 usecs
> > > > > > [  177.457257] pcieport 0000:00:00.0: PM: calling
> > > > > > pci_pm_resume_noirq+0x0/0x160 @ 33, parent: pci0000:00
> > > > > > 
> > > > > > Surprisingly those drivers are consistently reproducing the failures I am
> > > > > > seeing so at least this gave me a clue as to where the problem is.
> > > > > > 
> > > > > > There were no changes to drivers/net/ethernet/broadcom/genet/, the two
> > > > > > changes done to drivers/net/mdio/mdio-bcm-unimac.c are correct, especially
> > > > > > the read_poll_timeout() conversion is correct, we properly break out of the
> > > > > > loop. The initial delay looked like a good culprit for a little while, but
> > > > > > it is not used on the affected platforms because instead we provide a
> > > > > > callback and we have an interrupt to signal the completion of a MDIO
> > > > > > operation, therefore unimac_mdio_poll() is not used at all. Finally
> > > > > > drivers/memory/brcmstb_dpfe.c also received a single change which is not
> > > > > > functional here (.remove function change do return void).
> > > > > > 
> > > > > > I went back to a manual bisection and this time I believe that I have a more
> > > > > > plausible candidate with:
> > > > > > 
> > > > > > 7ee988770326fca440472200c3eb58935fe712f6 ("timers: Implement the
> > > > > > hierarchical pull model")
> > > > > 
> > > > > I haven't understood the code there yet, and how it would interact with
> > > > > arch code, but one thing that immediately jumps out to me is this:
> > > > > 
> > > > > "    As long as a CPU is busy it expires both local and global timers. When a
> > > > >       CPU goes idle it arms for the first expiring local timer."
> > > > > 
> > > > > So are local timers "armed" when they are enqueued while the cpu is
> > > > > "busy" during initialisation, and will they expire, and will that
> > > > > expiry be delivered in a timely manner?
> > > > > 
> > > > > If not, this commit is basically broken, and would be the cause of the
> > > > > issue you are seeing. For the mdio case, we're talking about 2ms
> > > > > polling. For the dpfe case, it looks like we're talking about 1ms
> > > > > sleeps. I'm guessing that these end up being local timers.
> > > > > 
> > > > > Looking at pcie-brcmstb, there's a 100ms msleep(), and then a polling
> > > > > for link up every 5ms - if the link was down and we msleep(5) I wonder
> > > > > if that's triggering the same issue.
> > > > > 
> > > > > Why that would manifest itself on 32-bit but not 64-bit Arm, I can't
> > > > > say. I would imagine that the same hardware timer driver is being used
> > > > > (may be worth checking DT.) The same should be true for the interrupt
> > > > > driver as well. There's been no changes in that code.
> > > > 
> > > > I just had it happen with ARM64 I was plagued by:
> > > > 
> > > > https://lore.kernel.org/lkml/87wmqrjg8n.fsf@somnus/T/
> > > > 
> > > > and my earlier bisections somehow did not have ARM64 fail, so I thought it
> > > > was immune but it fails with about the same failure rate as ARM 32-bit.
> > > 
> > > Can you please boot with:
> > > 
> > >      trace_event=timer_migration,timer_start,timer_expire_entry,timer_cancel
> > > 
> > > And add the following and give us the resulting output in dmesg?
> > 
> > Here are two logs from two different systems that exposed the problem on
> > boot:
> > 
> 
> I found a pattern here, maybe related.
> 
> > https://gist.github.com/ffainelli/f0834c52ef6320c9216d879ca29a4b81
> 
> 	[  163.244130] kworker/-31        3D.... 44007us : timer_start: timer=b089b886 function=delayed_work_timer_fn expires=4294672340 [timeout=5000] bucket_expiry=4294672384 cpu =3 idx=192 flags=D|I
> 
> ^^^ this timer was supposed to expired after around 5000 jiffies (i.e. 5
> second, since HZ=1000), but it expired way late (160 seconds later).
> 

Hmm.. this is more a noise since it's a deferreable timer...

> 	[  163.261034] kworker/-31        3d.... 44012us : timer_start: timer=394b309f function=delayed_work_timer_fn expires=4294787991 [timeout=120651] bucket_expiry=4294791168 c pu=3 idx=277 flags=I
> 	...
> 	[  221.630578]   <idle>-0         1..s.. 3287405us : timer_expire_entry: timer=7e541f87 function=process_timeout now=4294670584 baseclk=4294670584
> 	[  221.643475]   <idle>-0         0d.s.. 162361292us : timer_cancel: timer=95703ccd
> 	[  221.650896]   <idle>-0         0..s.. 162361292us : timer_expire_entry: timer=95703ccd function=process_timeout now=4294829657 baseclk=4294670587
> 

but here:

	[  221.555265] kworker/-44        0d.... 3279414us : timer_start: timer=95703ccd function=process_timeout expires=4294670586 [timeout=10] bucket_expiry=4294670587 cpu=0 idx =59 flags=

this is a normal timer.

	[  221.571298] rcu_sche-15        3d.... 3279417us : timer_start: timer=7e541f87 function=process_timeout expires=4294670579 [timeout=3] bucket_expiry=4294670580 cpu=3 idx= 52 flags=
	[  221.587241]   <idle>-0         1d.s.. 3283405us : timer_cancel: timer=7e541f87
	[  221.594488]   <idle>-0         1..s.. 3283407us : timer_expire_entry: timer=7e541f87 function=process_timeout now=4294670580 baseclk=4294670580
	[  221.607388] rcu_sche-15        3d.... 3283416us : timer_start: timer=7e541f87 function=process_timeout expires=4294670583 [timeout=3] bucket_expiry=4294670584 cpu=3 idx= 56 flags=
	[  221.623331]   <idle>-0         1d.s.. 3287404us : timer_cancel: timer=7e541f87
	[  221.630578]   <idle>-0         1..s.. 3287405us : timer_expire_entry: timer=7e541f87 function=process_timeout now=4294670584 baseclk=4294670584
	[  221.643475]   <idle>-0         0d.s.. 162361292us : timer_cancel: timer=95703ccd
	[  221.650896]   <idle>-0         0..s.. 162361292us : timer_expire_entry: timer=95703ccd function=process_timeout now=4294829657 baseclk=4294670587

which got fired here.

	[  221.663967]   <idle>-0         0dns.. 162361296us : timer_cancel: timer=d03eaa1d
	[  221.671388]   <idle>-0         0.ns.. 162361297us : timer_expire_entry: timer=d03eaa1d function=process_timeout now=4294829657 baseclk=4294670856

And looks to me CPU 0 is the tick_do_timer_cpu CPU, since it's the first
one that got timers after a long wait and was doing a few catch-ups. Now
the problem is why CPU 0 didn't program its hardware timer to expire at
4294670587? I.e. the earliest timer.

Regards,
Boqun

[...]