Re: Unexplained long boot delays [Was Re: [GIT PULL] RCU changes for v6.9]

[Florian Fainelli <f.fainelli@gmail.com>]

Adding Anna-Maria and Russell,

On 3/13/24 09:01, Joel Fernandes wrote:
> Hello Florian,
> 
> On Tue, Mar 12, 2024 at 7:48 PM Boqun Feng <boqun.feng@gmail.com> wrote:
>>
>> On Tue, Mar 12, 2024 at 02:44:14PM -0700, Linus Torvalds wrote:
>>> On Tue, 12 Mar 2024 at 14:34, Florian Fainelli <f.fainelli@gmail.com> wrote:
>>>>
>>>> and here is a log where this fails:
>>>>
>>>> https://gist.github.com/ffainelli/ed08a2b3e853f59343786ebd20364fc8
>>>
>>> You could try the 'initcall_debug' kernel command line.
>>>
>>
>> Right, that'll be helpful.
>>
>> Besides I took a look at the config Florian shared, no TASKS_RCU,
>> RCU_LAZY or RCU nocb is enabled. So probably the only left changes in
>> the PR are around RCU expedited. Florian, could you see if you can build
>> and test with CONFIG_PROVE_RCU=y (you need to select
>> CONFIG_PROVE_LOCKING for that)? That'll call synchronize_rcu() +
>> synchronize_rcu_expedited() before and after we switch
>> rcu_scheduler_active, and it may provide more information. Thanks!
> 
> Adding to everyone's suggestions, could you also try booting with
> "rcupdate.rcu_normal=1" ? This will disable expedited RCU and help us
> further confirm that it is indeed expedited RCU (and then we can look
> into fixing that).

Booting with "rcupdate.rcu_normal=1" did not make any difference here, 
this is looking less and less RCU related, but somewhere else, see below.

> 
> Also there are 2 additional users of expedited RCU in this release I noticed:
> 
> 78c3253f27e5 ("net: use synchronize_rcu_expedited in cleanup_net()")
> 1ebb85f9c03d ("netfilter: conntrack: expedite rcu in
> nf_conntrack_cleanup_net_list")
> 
> Could you also try reverting those patches as well, and see if the
> issue goes away
Sorry had been chasing another regression, with one down, I could 
finally get back to this one.

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")

7ee988770326fca440472200c3eb58935fe712f6~1 is stable, and 
7ee988770326fca440472200c3eb58935fe712f6 consistently reproduces this 
long boot delay on multiple platforms, so we finally have something here.

This seems to be very specific to the ARM 32-bit architecture, and 
booting the same system with an ARM64 kernel does not expose the 
problem, even though the timer hardware is the same (ARM v7/v8 
architected timer).

Let me know if there is any debugging that you want me to add.

Thanks to everyone for your help so far, this is much appreciated!
--
Florian