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

[Russell King (Oracle)]

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.

The last straw I can attempt to grasp at is maybe this has something to
do with an inappropriate data type being used - maybe something in the
timer code that the blamed commit changes that a 32-bit type is too
small?

-- 
RMK's Patch system: https://www.armlinux.org.uk/developer/patches/
FTTP is here! 80Mbps down 10Mbps up. Decent connectivity at last!