Messages in this thread | | | Date | Wed, 13 Mar 2024 14:30:43 -0700 | From | Florian Fainelli <> | Subject | Re: Unexplained long boot delays [Was Re: [GIT PULL] RCU changes for v6.9] |
| |
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
| |