A problem with "ip=..." ipconfig and Atheros alx driver.
Subsystems (2)
Hello Chris and others,
I'm observing a problem with Atheros alx ethernet driver and in-kernel ip4 configuration (using "ip=192.168....." boot parameter).
The problem first showed itself as a huge unexpected delay in bootup as long as "ip=..." was specified (and a real device is present). I've then noticed a timeout counter "Waiting up to 110 more seconds for network" between the "Atheros(R) AR816x/AR817x" message and "eth0: NIC Up: 1 Gbps Full" message. Meanwhile, this ethernet device is fully operational and my cable is perfectly reliable.
Now, after debugging it a little bit more, I've apparently found the root cause. One can see in net/ipv4/ipconfig.c that ic_open_devs() tries to ensure carrier is physically present. But before opening device(s) and starting wait for the carrier, it calls rtnl_lock(). Now in ethernet/atheros/alx/main.c one can see that at opening, it first calls netif_carrier_off() then schedules alx_link_check() to do actual work, so carrier detection is supposed to happen a bit later. Now looking at this alx_link_check() carefully, first thing is does is rtnl_lock(). Bingo! Double-lock. Effectively actual carrier check in alx is therefore delayed just until ic_open_devs() gave up waiting for it and called rtnl_unlock(). Hence this delay and timeout.
I have checked with clean 4.9.268 and 5.4.115 on real hardware.
Can't check with 5.12 at the moment because my gcc is somewhat old to compile it, but browsing the code it looks like nothing has changed substantially anyway.
Fixing this myself is a bit beyond my capability I'm afraid, but I'd be happy do some testing if someone requests me to.
Thank you,
Reagrds,
Nikolai
Hi Nikolai,
Wow - old code. And yet I'm still even using the device. Time to replace the system that has it ;-)
Quoted 11 lines
Now, after debugging it a little bit more, I've apparently found the root cause. One can see in
net/ipv4/ipconfig.cthatic_open_devs()tries to ensure carrier is physically present. But before opening device(s) and starting wait for the carrier, it callsrtnl_lock(). Now inethernet/atheros/alx/main.cone can see that at opening, it first callsnetif_carrier_off()then schedulesalx_link_check()to do actual work, so carrier detection is supposed to happen a bit later. Now looking at thisalx_link_check()carefully, first thing is does isrtnl_lock(). Bingo! Double-lock. Effectively actual carrier check in alx is therefore delayed just untilic_open_devs()gave up waiting for it and calledrtnl_unlock(). Hence this delay and timeout.
Fun. But we can just do it synchronously?
https://p.sipsolutions.net/e4f076ed1b4c8a78.txt
johannes
Hi Johannes,
30.04.2021 15:08, Johannes Berg:
Quoted 5 lines
Quoted 1 line
rtnl_unlock(). Hence this delay and timeout.Fun. But we can just do it synchronously?
Wow, that was quick! Thanks! However, unfortunately this patch still does not quite fix the problem. Although alx_check_link() now gets called synchronously at open, it somehow does not pass below the "if (old_speed == hw->link_speed) return" line here. I'd guess it is because the chip is not yet able to report meaningfull values immediately after initialization. The result is still the same: 120 seconds timeout happens, then the "eth0: NIC Up: 1 Gbps Full" message appears immediately and all is fine after that. I'll do some more testing later today.
Thank you,
Regards,
Nikolai
Quoted 4 lines
johannes
Quoted 9 lines · Nikolai Zhubr
Hi Johannes,
30.04.2021 15:08, Johannes Berg:
Quoted 5 lines
Quoted 1 line
rtnl_unlock(). Hence this delay and timeout.Fun. But we can just do it synchronously?
Quoted 8 lines
Wow, that was quick! Thanks! However, unfortunately this patch still does not quite fix the problem. Although
alx_check_link()now gets called synchronously at open, it somehow does not pass below the "if (old_speed==hw->link_speed) return" line here. I'd guess it is because the chip is not yet able to report meaningfull values immediately after initialization. The result is still the same: 120 seconds timeout happens, then the "eth0: NIC Up: 1 Gbps Full" message appears immediately and all is fine after that.
Yeah so ... I guess we could poll it, but that's really quite ugly?
I wonder if we can detect this case somehow?
The more reasonable thing is probably to just rework the locking here, but that's a touchy subject I guess.
How about this?
https://p.sipsolutions.net/5adbe659fb061f06.txt
johannes
Hi Johannes,
30.04.2021 22:02, Johannes Berg:
[...]
Quoted 6 lines
The more reasonable thing is probably to just rework the locking here, but that's a touchy subject I guess.
How about this?
Is it supposed to work correctly for unmodified 5.12 kernel? Because it applies cleanly, but the resulting kernel never finishes booting. No panic happens, it just kind of gets stuck forever. Likely somewhere within this ip config steps. The carrier timeout countdown does not show up, but console scrollback magic still does work, so it is not a complete crash.
Thank you,
Regards,
Nikolai
Quoted 3 lines
johannes
Hi Johannes,
01.05.2021 3:01, I wrote:
[...]
Quoted 3 lines
Quoted 1 line
Is it supposed to work correctly for unmodified 5.12 kernel? Because it
Success! I've found an apparently missing mutex_unlock() in alx_probe() just before the "return 0" line. With that inserted, your patch indeed fixes the 120 s boot delay here. And the link apparenly also works fine after boot, in normal operation. Can it be somehow reviewed and submitted unstream please?
I'd like it also ported to 4.xx then. (Maybe I can port myself though)
(Very happy!)
Thank you,
Regards,
Nikolai
Quoted 11 lines · Nikolai Zhubr
Hi Johannes,
01.05.2021 3:01, I wrote:
[...]Quoted 3 lines
Quoted 1 line
Is it supposed to work correctly for unmodified 5.12 kernel? Because it
Success! I've found an apparently missing
mutex_unlock()inalx_probe()just before the "return 0" line.
D'oh, right, missed that place.
Quoted 5 lines
With that inserted, your patch indeed
fixes the 120 s boot delay here. And the link apparenly also works fine after boot, in normal operation.
Can it be somehow reviewed and submitted unstream please? I'd like it also ported to 4.xx then. (Maybe I can port myself though)
Well I don't think anyone's going to still backport such a patch to a 4.x kernel, but of course you can.
I guess I can see about making it a real patch, should only take a little while to audit (again) the hardware access paths wrt. locking.
johannes
Hi Johannes,
02.05.2021 12:04, Johannes Berg:
[...]
Quoted 2 lines
I guess I can see about making it a real patch, should only take a little while to audit (again) the hardware access paths wrt. locking.
Greatly appreciated! Hopefully it makes it into mainline soon.
Regards,
Nikolai
Quoted 3 lines
johannes
Quoted 8 lines · Nikolai Zhubr
Hi Johannes,
02.05.2021 12:04, Johannes Berg:
[...]Quoted 2 lines
I guess I can see about making it a real patch, should only take a little while to audit (again) the hardware access paths wrt. locking.
Greatly appreciated! Hopefully it makes it into mainline soon.
Well, we're in the middle of the merge window now, so realistically it'll be quite a while (until 5.14).
johannes