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@xxxxxxxxx> 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@xxxxxxxxx> 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
