netdev.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
* FEC MDIO read timeout on linkup
@ 2022-04-22 15:26 Francesco Dolcini
  2022-04-22 15:55 ` Fabio Estevam
  2022-05-02 17:05 ` Francesco Dolcini
  0 siblings, 2 replies; 14+ messages in thread
From: Francesco Dolcini @ 2022-04-22 15:26 UTC (permalink / raw)
  To: Joakim Zhang, Andrew Lunn, Heiner Kallweit, Russell King
  Cc: netdev, Jakub Kicinski, Paolo Abeni, David S. Miller,
	Fabio Estevam, Tim Harvey

Hello all,
I have been recently trying to debug an issue with FEC driver erroring
a MDIO read timeout during linkup [0]. At the beginning I was working
with an old 5.4 kernel, but today I tried with the current master
(5.18.0-rc3-00080-gd569e86915b7) and the issue is just there.

I'm also aware of the old discussions on the topic and I tried to
increase the timeout without success (even if I'm not sure is relevant
with the newer polling solution).

The issue was reproduced on an apalis-imx6 that has a KSZ9131
ethernet connected to the FEC MAC.

No load on the machine, 4 cores just idling during my test.

What I can see from the code is that the timeout is coming from
net/phy/micrel.c:kszphy_handle_interrupt().

Could this be some sort of race condition? Any suggestion for debugging
this?

Here the stack trace:

[  146.195696] fec 2188000.ethernet eth0: MDIO read timeout
[  146.201779] ------------[ cut here ]------------
[  146.206671] WARNING: CPU: 0 PID: 571 at drivers/net/phy/phy.c:942 phy_error+0x24/0x6c
[  146.214744] Modules linked in: bnep imx_vdoa imx_sdma evbug
[  146.220640] CPU: 0 PID: 571 Comm: irq/128-2188000 Not tainted 5.18.0-rc3-00080-gd569e86915b7 #9
[  146.229563] Hardware name: Freescale i.MX6 Quad/DualLite (Device Tree)
[  146.236257]  unwind_backtrace from show_stack+0x10/0x14
[  146.241640]  show_stack from dump_stack_lvl+0x58/0x70
[  146.246841]  dump_stack_lvl from __warn+0xb4/0x24c
[  146.251772]  __warn from warn_slowpath_fmt+0x5c/0xd4
[  146.256873]  warn_slowpath_fmt from phy_error+0x24/0x6c
[  146.262249]  phy_error from kszphy_handle_interrupt+0x40/0x48
[  146.268159]  kszphy_handle_interrupt from irq_thread_fn+0x1c/0x78
[  146.274417]  irq_thread_fn from irq_thread+0xf0/0x1dc
[  146.279605]  irq_thread from kthread+0xe4/0x104
[  146.284267]  kthread from ret_from_fork+0x14/0x28
[  146.289164] Exception stack(0xe6fa1fb0 to 0xe6fa1ff8)
[  146.294448] 1fa0:                                     00000000 00000000 00000000 00000000
[  146.302842] 1fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
[  146.311281] 1fe0: 00000000 00000000 00000000 00000000 00000013 00000000
[  146.318262] irq event stamp: 12325
[  146.321780] hardirqs last  enabled at (12333): [<c01984c4>] __up_console_sem+0x50/0x60
[  146.330013] hardirqs last disabled at (12342): [<c01984b0>] __up_console_sem+0x3c/0x60
[  146.338259] softirqs last  enabled at (12324): [<c01017f0>] __do_softirq+0x2c0/0x624
[  146.346311] softirqs last disabled at (12319): [<c01300ac>] __irq_exit_rcu+0x138/0x178
[  146.354447] ---[ end trace 0000000000000000 ]---


The issue is not systematic, however using the following script is
pretty easy (minutes) to trigger:

```
#!/bin/bash

count=0

wait_link_or_exit()
{
	tmo=600
	while ! ethtool eth0 |grep -qF 'Link detected: yes'
	do
		sleep 0.1
		tmo=$((tmo - 1))
		[ $tmo -gt 0 ] || exit 1
	done
}

while true
do
	count=$((count + 1))
	echo "run $count"

	ethtool -s eth0 speed 10 duplex half autoneg on
	wait_link_or_exit

	ethtool -s eth0 speed 10 duplex full autoneg on
	wait_link_or_exit

	ethtool -s eth0 speed 100 duplex half autoneg on
	wait_link_or_exit

	ethtool -s eth0 speed 100 duplex full autoneg on
	wait_link_or_exit
done

```

Francesco

[0] https://lore.kernel.org/all/20220325140808.GA1047855@francesco-nb.int.toradex.com/



^ permalink raw reply	[flat|nested] 14+ messages in thread

* Re: FEC MDIO read timeout on linkup
  2022-04-22 15:26 FEC MDIO read timeout on linkup Francesco Dolcini
@ 2022-04-22 15:55 ` Fabio Estevam
  2022-04-22 16:04   ` Francesco Dolcini
  2022-05-02 17:05 ` Francesco Dolcini
  1 sibling, 1 reply; 14+ messages in thread
From: Fabio Estevam @ 2022-04-22 15:55 UTC (permalink / raw)
  To: Francesco Dolcini
  Cc: Joakim Zhang, Andrew Lunn, Heiner Kallweit, Russell King, netdev,
	Jakub Kicinski, Paolo Abeni, David S. Miller, Tim Harvey

Hi Francesco,

On Fri, Apr 22, 2022 at 12:26 PM Francesco Dolcini
<francesco.dolcini@toradex.com> wrote:
>
> Hello all,
> I have been recently trying to debug an issue with FEC driver erroring
> a MDIO read timeout during linkup [0]. At the beginning I was working
> with an old 5.4 kernel, but today I tried with the current master
> (5.18.0-rc3-00080-gd569e86915b7) and the issue is just there.
>
> I'm also aware of the old discussions on the topic and I tried to
> increase the timeout without success (even if I'm not sure is relevant
> with the newer polling solution).
>
> The issue was reproduced on an apalis-imx6 that has a KSZ9131
> ethernet connected to the FEC MAC.
>
> No load on the machine, 4 cores just idling during my test.
>
> What I can see from the code is that the timeout is coming from
> net/phy/micrel.c:kszphy_handle_interrupt().

For debugging purposes, could you try not to describe the Ethernet PHY
irq pin inside imx6qdl-apalis.dtsi?

Looking at its pinctrl, I don't see it has pull-up enabled. Is there
an external pull-up
on the KSZ9131 pin?

^ permalink raw reply	[flat|nested] 14+ messages in thread

* Re: FEC MDIO read timeout on linkup
  2022-04-22 15:55 ` Fabio Estevam
@ 2022-04-22 16:04   ` Francesco Dolcini
  2022-04-29 15:15     ` Francesco Dolcini
  0 siblings, 1 reply; 14+ messages in thread
From: Francesco Dolcini @ 2022-04-22 16:04 UTC (permalink / raw)
  To: Fabio Estevam
  Cc: Francesco Dolcini, Joakim Zhang, Andrew Lunn, Heiner Kallweit,
	Russell King, netdev, Jakub Kicinski, Paolo Abeni,
	David S. Miller, Tim Harvey

Hello Fabio,

On Fri, Apr 22, 2022 at 12:55:22PM -0300, Fabio Estevam wrote:
> On Fri, Apr 22, 2022 at 12:26 PM Francesco Dolcini
> <francesco.dolcini@toradex.com> wrote:
> > What I can see from the code is that the timeout is coming from
> > net/phy/micrel.c:kszphy_handle_interrupt().
> 
> For debugging purposes, could you try not to describe the Ethernet PHY
> irq pin inside imx6qdl-apalis.dtsi?
Yep, we'll try to see what's going on with polling instead that having the
interrupt enabled.

> Looking at its pinctrl, I don't see it has pull-up enabled. Is there
> an external pull-up on the KSZ9131 pin?
yes, we have a 4.7K Ohm pull-up on the board.

In addition to that I just tried with

@@ -4151,7 +4151,7 @@ static int __maybe_unused fec_runtime_suspend(struct device *dev)
        struct fec_enet_private *fep = netdev_priv(ndev);

        clk_disable_unprepare(fep->clk_ahb);
-       clk_disable_unprepare(fep->clk_ipg);
+       //clk_disable_unprepare(fep->clk_ipg);

and the issue is still present.

Francesco


^ permalink raw reply	[flat|nested] 14+ messages in thread

* Re: FEC MDIO read timeout on linkup
  2022-04-22 16:04   ` Francesco Dolcini
@ 2022-04-29 15:15     ` Francesco Dolcini
  0 siblings, 0 replies; 14+ messages in thread
From: Francesco Dolcini @ 2022-04-29 15:15 UTC (permalink / raw)
  To: Fabio Estevam
  Cc: Francesco Dolcini, Joakim Zhang, Andrew Lunn, Heiner Kallweit,
	Russell King, netdev, Jakub Kicinski, Paolo Abeni,
	David S. Miller, Tim Harvey

On Fri, Apr 22, 2022 at 06:04:00PM +0200, Francesco Dolcini wrote:
> On Fri, Apr 22, 2022 at 12:55:22PM -0300, Fabio Estevam wrote:
> > On Fri, Apr 22, 2022 at 12:26 PM Francesco Dolcini
> > <francesco.dolcini@toradex.com> wrote:
> > > What I can see from the code is that the timeout is coming from
> > > net/phy/micrel.c:kszphy_handle_interrupt().
> > 
> > For debugging purposes, could you try not to describe the Ethernet PHY
> > irq pin inside imx6qdl-apalis.dtsi?
> Yep, we'll try to see what's going on with polling instead that having the
> interrupt enabled.

So, I was not able to reproduce the issue polling the phy instead of
using interrupt. I gonna investigate more in the direction of a race
condition somewhere, unfortunately I had very limited time to work on
this in the last days.

Francesco


^ permalink raw reply	[flat|nested] 14+ messages in thread

* Re: FEC MDIO read timeout on linkup
  2022-04-22 15:26 FEC MDIO read timeout on linkup Francesco Dolcini
  2022-04-22 15:55 ` Fabio Estevam
@ 2022-05-02 17:05 ` Francesco Dolcini
  2022-05-02 18:21   ` Andrew Lunn
  2022-05-02 18:24   ` Andrew Lunn
  1 sibling, 2 replies; 14+ messages in thread
From: Francesco Dolcini @ 2022-05-02 17:05 UTC (permalink / raw)
  To: Andrew Lunn, netdev, Andy Duan
  Cc: Francesco Dolcini, Joakim Zhang, Heiner Kallweit, Russell King,
	Jakub Kicinski, Paolo Abeni, David S. Miller, Fabio Estevam,
	Tim Harvey, Chris Healy

Hello Andrew (and all),
I have some idea that this issue might be related to a recent change
you did.

On Fri, Apr 22, 2022 at 05:26:12PM +0200, Francesco Dolcini wrote:
> Hello all,
> I have been recently trying to debug an issue with FEC driver erroring
> a MDIO read timeout during linkup [0]. At the beginning I was working
> with an old 5.4 kernel, but today I tried with the current master
> (5.18.0-rc3-00080-gd569e86915b7) and the issue is just there.
> 
...
> 
> Could this be some sort of race condition? Any suggestion for debugging
> this?
> 
> Here the stack trace:
> 
> [  146.195696] fec 2188000.ethernet eth0: MDIO read timeout
> [  146.201779] ------------[ cut here ]------------
> [  146.206671] WARNING: CPU: 0 PID: 571 at drivers/net/phy/phy.c:942 phy_error+0x24/0x6c
> [  146.214744] Modules linked in: bnep imx_vdoa imx_sdma evbug
> [  146.220640] CPU: 0 PID: 571 Comm: irq/128-2188000 Not tainted 5.18.0-rc3-00080-gd569e86915b7 #9
> [  146.229563] Hardware name: Freescale i.MX6 Quad/DualLite (Device Tree)
> [  146.236257]  unwind_backtrace from show_stack+0x10/0x14
> [  146.241640]  show_stack from dump_stack_lvl+0x58/0x70
> [  146.246841]  dump_stack_lvl from __warn+0xb4/0x24c
> [  146.251772]  __warn from warn_slowpath_fmt+0x5c/0xd4
> [  146.256873]  warn_slowpath_fmt from phy_error+0x24/0x6c
> [  146.262249]  phy_error from kszphy_handle_interrupt+0x40/0x48
> [  146.268159]  kszphy_handle_interrupt from irq_thread_fn+0x1c/0x78
> [  146.274417]  irq_thread_fn from irq_thread+0xf0/0x1dc
> [  146.279605]  irq_thread from kthread+0xe4/0x104
> [  146.284267]  kthread from ret_from_fork+0x14/0x28
> [  146.289164] Exception stack(0xe6fa1fb0 to 0xe6fa1ff8)
> [  146.294448] 1fa0:                                     00000000 00000000 00000000 00000000
> [  146.302842] 1fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
> [  146.311281] 1fe0: 00000000 00000000 00000000 00000000 00000013 00000000
> [  146.318262] irq event stamp: 12325
> [  146.321780] hardirqs last  enabled at (12333): [<c01984c4>] __up_console_sem+0x50/0x60
> [  146.330013] hardirqs last disabled at (12342): [<c01984b0>] __up_console_sem+0x3c/0x60
> [  146.338259] softirqs last  enabled at (12324): [<c01017f0>] __do_softirq+0x2c0/0x624
> [  146.346311] softirqs last disabled at (12319): [<c01300ac>] __irq_exit_rcu+0x138/0x178
> [  146.354447] ---[ end trace 0000000000000000 ]---

Could it be that the issue is writing the MSCR in fec_restart(),
`writel(fep->phy_speed, fep->hwp + FEC_MII_SPEED)`?

I do see the issue on link up/down event, when this function is actually
called.

From what I can understand from the previous history:

  1e6114f51f9d (net: fec: fix MDIO probing for some FEC hardware blocks, 2020-10-28) 
  f166f890c8f0 (net: ethernet: fec: Replace interrupt driven MDIO with polled IO, 2020-05-02)

writing to this register could trigger a FEC_ENET_MII interrupt actually
creating a race condition with fec_enet_mdio_read() that is called on
link change also.

Do this explanation makes any sense to you?
I'm testing at the moment a patch that should solve that.

Francesco


^ permalink raw reply	[flat|nested] 14+ messages in thread

* Re: FEC MDIO read timeout on linkup
  2022-05-02 17:05 ` Francesco Dolcini
@ 2022-05-02 18:21   ` Andrew Lunn
  2022-05-02 18:25     ` Francesco Dolcini
  2022-05-02 18:24   ` Andrew Lunn
  1 sibling, 1 reply; 14+ messages in thread
From: Andrew Lunn @ 2022-05-02 18:21 UTC (permalink / raw)
  To: Francesco Dolcini
  Cc: netdev, Andy Duan, Joakim Zhang, Heiner Kallweit, Russell King,
	Jakub Kicinski, Paolo Abeni, David S. Miller, Fabio Estevam,
	Tim Harvey, Chris Healy

> Could it be that the issue is writing the MSCR in fec_restart(),
> `writel(fep->phy_speed, fep->hwp + FEC_MII_SPEED)`?
> 
> I do see the issue on link up/down event, when this function is actually
> called.
> 
> >From what I can understand from the previous history:
> 
>   1e6114f51f9d (net: fec: fix MDIO probing for some FEC hardware blocks, 2020-10-28) 
>   f166f890c8f0 (net: ethernet: fec: Replace interrupt driven MDIO with polled IO, 2020-05-02)
> 
> writing to this register could trigger a FEC_ENET_MII interrupt actually
> creating a race condition with fec_enet_mdio_read() that is called on
> link change also.

You should read the discussion from when this code was added.

Are you planning on adding:

       if (fep->quirks & FEC_QUIRK_CLEAR_SETUP_MII) {
                /* Clear MMFR to avoid to generate MII event by writing MSCR.
                 * MII event generation condition:
                 * - writing MSCR:
                 *      - mmfr[31:0]_not_zero & mscr[7:0]_is_zero &
                 *        mscr_reg_data_in[7:0] != 0
                 * - writing MMFR:
                 *      - mscr[7:0]_not_zero
                 */
                writel(0, fep->hwp + FEC_MII_DATA);
        }

To other locations which change FEC_MII_SPEED?

   Andrew

^ permalink raw reply	[flat|nested] 14+ messages in thread

* Re: FEC MDIO read timeout on linkup
  2022-05-02 17:05 ` Francesco Dolcini
  2022-05-02 18:21   ` Andrew Lunn
@ 2022-05-02 18:24   ` Andrew Lunn
  2022-05-02 18:34     ` Francesco Dolcini
  1 sibling, 1 reply; 14+ messages in thread
From: Andrew Lunn @ 2022-05-02 18:24 UTC (permalink / raw)
  To: Francesco Dolcini
  Cc: netdev, Andy Duan, Joakim Zhang, Heiner Kallweit, Russell King,
	Jakub Kicinski, Paolo Abeni, David S. Miller, Fabio Estevam,
	Tim Harvey, Chris Healy

> writing to this register could trigger a FEC_ENET_MII interrupt actually
> creating a race condition with fec_enet_mdio_read() that is called on
> link change also.

Another point to consider:

static int fec_enet_mdio_wait(struct fec_enet_private *fep)
{
        uint ievent;
        int ret;

        ret = readl_poll_timeout_atomic(fep->hwp + FEC_IEVENT, ievent,
                                        ievent & FEC_ENET_MII, 2, 30000);

        if (!ret)
                writel(FEC_ENET_MII, fep->hwp + FEC_IEVENT);

        return ret;
}

An unexpected interrupt will make this exit too early, and the read
will get invalid data. An unexpected interrupt would not cause a
timeout here, which is what you are reporting.

	Andrew

^ permalink raw reply	[flat|nested] 14+ messages in thread

* Re: FEC MDIO read timeout on linkup
  2022-05-02 18:21   ` Andrew Lunn
@ 2022-05-02 18:25     ` Francesco Dolcini
  0 siblings, 0 replies; 14+ messages in thread
From: Francesco Dolcini @ 2022-05-02 18:25 UTC (permalink / raw)
  To: Andrew Lunn
  Cc: Francesco Dolcini, netdev, Andy Duan, Joakim Zhang,
	Heiner Kallweit, Russell King, Jakub Kicinski, Paolo Abeni,
	David S. Miller, Fabio Estevam, Tim Harvey, Chris Healy

On Mon, May 02, 2022 at 08:21:10PM +0200, Andrew Lunn wrote:
> > Could it be that the issue is writing the MSCR in fec_restart(),
> > `writel(fep->phy_speed, fep->hwp + FEC_MII_SPEED)`?
> > 
> > I do see the issue on link up/down event, when this function is actually
> > called.
> > 
> > >From what I can understand from the previous history:
> > 
> >   1e6114f51f9d (net: fec: fix MDIO probing for some FEC hardware blocks, 2020-10-28) 
> >   f166f890c8f0 (net: ethernet: fec: Replace interrupt driven MDIO with polled IO, 2020-05-02)
> > 
> > writing to this register could trigger a FEC_ENET_MII interrupt actually
> > creating a race condition with fec_enet_mdio_read() that is called on
> > link change also.
> 
> You should read the discussion from when this code was added.

Of course, I did it.

> Are you planning on adding:
> 
>        if (fep->quirks & FEC_QUIRK_CLEAR_SETUP_MII) {
>                 /* Clear MMFR to avoid to generate MII event by writing MSCR.
>                  * MII event generation condition:
>                  * - writing MSCR:
>                  *      - mmfr[31:0]_not_zero & mscr[7:0]_is_zero &
>                  *        mscr_reg_data_in[7:0] != 0
>                  * - writing MMFR:
>                  *      - mscr[7:0]_not_zero
>                  */
>                 writel(0, fep->hwp + FEC_MII_DATA);
>         }
> 
> To other locations which change FEC_MII_SPEED?

Correct, plus the required locking since both fec_enet_mdio_read() and
_write() do write into the same registers.

Francesco


^ permalink raw reply	[flat|nested] 14+ messages in thread

* Re: FEC MDIO read timeout on linkup
  2022-05-02 18:24   ` Andrew Lunn
@ 2022-05-02 18:34     ` Francesco Dolcini
  2022-05-03 16:13       ` Francesco Dolcini
  0 siblings, 1 reply; 14+ messages in thread
From: Francesco Dolcini @ 2022-05-02 18:34 UTC (permalink / raw)
  To: Andrew Lunn
  Cc: Francesco Dolcini, netdev, Andy Duan, Joakim Zhang,
	Heiner Kallweit, Russell King, Jakub Kicinski, Paolo Abeni,
	David S. Miller, Fabio Estevam, Tim Harvey, Chris Healy

On Mon, May 02, 2022 at 08:24:53PM +0200, Andrew Lunn wrote:
> > writing to this register could trigger a FEC_ENET_MII interrupt actually
> > creating a race condition with fec_enet_mdio_read() that is called on
> > link change also.
> 
> Another point to consider:
> 
> static int fec_enet_mdio_wait(struct fec_enet_private *fep)
> {
>         uint ievent;
>         int ret;
> 
>         ret = readl_poll_timeout_atomic(fep->hwp + FEC_IEVENT, ievent,
>                                         ievent & FEC_ENET_MII, 2, 30000);
> 
>         if (!ret)
>                 writel(FEC_ENET_MII, fep->hwp + FEC_IEVENT);
> 
>         return ret;
> }
> 
> An unexpected interrupt will make this exit too early, and the read
> will get invalid data. An unexpected interrupt would not cause a
> timeout here, which is what you are reporting.

yes, I had the exact same thought. Could it be that this creates some
kind of misalignments between the MDIO data and the related FEC
interrupt with the first early exist not triggering any error and the
second one triggering an infinite wait?

I guess I need to sleep on this, in the meantime I have a test running
with the change I described running since a couple of hours.

Francesco


^ permalink raw reply	[flat|nested] 14+ messages in thread

* Re: FEC MDIO read timeout on linkup
  2022-05-02 18:34     ` Francesco Dolcini
@ 2022-05-03 16:13       ` Francesco Dolcini
  2022-05-03 22:17         ` Andrew Lunn
  0 siblings, 1 reply; 14+ messages in thread
From: Francesco Dolcini @ 2022-05-03 16:13 UTC (permalink / raw)
  To: Andrew Lunn, netdev
  Cc: Francesco Dolcini, Andy Duan, Joakim Zhang, Heiner Kallweit,
	Russell King, Jakub Kicinski, Paolo Abeni, David S. Miller,
	Fabio Estevam, Tim Harvey, Chris Healy

Hello all,

On Mon, May 02, 2022 at 08:34:43PM +0200, Francesco Dolcini wrote:
> On Mon, May 02, 2022 at 08:24:53PM +0200, Andrew Lunn wrote:
> > > writing to this register could trigger a FEC_ENET_MII interrupt actually
> > > creating a race condition with fec_enet_mdio_read() that is called on
> > > link change also.
> > 
> > An unexpected interrupt will make this exit too early, and the read
> > will get invalid data. An unexpected interrupt would not cause a
> > timeout here, which is what you are reporting.
> 
> I guess I need to sleep on this, in the meantime I have a test running
> with the change I described running since a couple of hours.

After a long sleep it seems that my change did not solve the issue. I
also verified that writing to the FEC_MII_SPEED does not trigger any
FEC_ENET_MII interrupt on my specific case.

I guess that this could be still a real issue, but it's not my specific
problem.

At the moment I'm a little bit lost, what I have verified so far is the
following:

 - fec_enet_mdio_read()/_write() locking. This is just correct, with the
   mdio mutex.
 - potential race condition with FEC_ENET_MII interrupt while writing
   FEC_MII_SPEED in fec_restart(). Proved wrong by both a test and by the
   fact that I do not have an interrupt generated on my case.
 - increasing fec_enet_mdio_wait() timeout to 100ms does not help.
 - clk_ipg is always active, once the device is open the clock is always
   on (verified with runtime power management debugging)


I'm wondering could this be related to
fec_enet_adjust_link()->fec_restart() during a fec_enet_mdio_read()
and one of the many register write in fec_restart() just creates the
issue, maybe while resetting the FEC? Does this makes any sense?

Francesco



^ permalink raw reply	[flat|nested] 14+ messages in thread

* Re: FEC MDIO read timeout on linkup
  2022-05-03 16:13       ` Francesco Dolcini
@ 2022-05-03 22:17         ` Andrew Lunn
  2022-05-05  8:29           ` Francesco Dolcini
  0 siblings, 1 reply; 14+ messages in thread
From: Andrew Lunn @ 2022-05-03 22:17 UTC (permalink / raw)
  To: Francesco Dolcini
  Cc: netdev, Andy Duan, Joakim Zhang, Heiner Kallweit, Russell King,
	Jakub Kicinski, Paolo Abeni, David S. Miller, Fabio Estevam,
	Tim Harvey, Chris Healy

> I'm wondering could this be related to
> fec_enet_adjust_link()->fec_restart() during a fec_enet_mdio_read()
> and one of the many register write in fec_restart() just creates the
> issue, maybe while resetting the FEC? Does this makes any sense?

phylib is 'single threaded', in that only one thing will be active at
once for a PHY. While fec_enet_adjust_link() is being called, there
will not be any read/writes occurring for that PHY.

However, each PHY in the system runs on its own. If you have multiple
PHYs sharing one MDIO bus, or an Ethernet switch on the bus, they can
be doing read/writes at the same time.

The mdio bus has a lock which prevents actual transactions on the bus
at the same time. Nothing in phylib means that lock is held when
fec_enet_adjust_link() is called, so another PHY could be making MDIO
transfers. If fec_enet_adjust_link() is going to do bad things with
the MDIO bus master, it needs to hold the MDIO lock while doing it.

    Andrew

^ permalink raw reply	[flat|nested] 14+ messages in thread

* Re: FEC MDIO read timeout on linkup
  2022-05-03 22:17         ` Andrew Lunn
@ 2022-05-05  8:29           ` Francesco Dolcini
  2022-05-05 17:41             ` Andrew Lunn
  0 siblings, 1 reply; 14+ messages in thread
From: Francesco Dolcini @ 2022-05-05  8:29 UTC (permalink / raw)
  To: Andrew Lunn, Joakim Zhang, netdev
  Cc: Francesco Dolcini, Andy Duan, Heiner Kallweit, Russell King,
	Jakub Kicinski, Paolo Abeni, David S. Miller, Fabio Estevam,
	Tim Harvey, Chris Healy

Hello Andrew and all, I believe I finally found the problem and I'm
preparing a patch for it.

On Wed, May 04, 2022 at 12:17:59AM +0200, Andrew Lunn wrote:
> > I'm wondering could this be related to
> > fec_enet_adjust_link()->fec_restart() during a fec_enet_mdio_read()
> > and one of the many register write in fec_restart() just creates the
> > issue, maybe while resetting the FEC? Does this makes any sense?
> 
> phylib is 'single threaded', in that only one thing will be active at
> once for a PHY. While fec_enet_adjust_link() is being called, there
> will not be any read/writes occurring for that PHY.

I think this is not the whole story here. We can have a phy interrupt
handler that runs in its own context and it could be doing a MDIO
transaction, and this is exactly my case.

Thread 1 (phylib WQ)       | Thread 2 (phy interrupt)
                           |
                           | phy_interrupt()            <-- PHY IRQ
	                   |  handle_interrupt()
	                   |   phy_read()
	                   |   phy_trigger_machine()
	                   |    --> schedule WQ
                           |
	                   |
phy_state_machine()        |                        
 phy_check_link_status()   |
  phy_link_change()        |
   phydev->adjust_link()   |
    fec_enet_adjust_link() | 
     --> FEC reset         | phy_interrupt()            <-- PHY IRQ
	                   |  phy_read()
	 	           |

To confirm this I have added a spinlock to detect this race condition
with just a trylock and a WARN_ON(1) when the locking is failing. On
"MDIO read timeout" acquiring the spinlock fails.

This is also in agreement with the fact that polling the PHY instead of
having the interrupt is working just fine.

For my specific problem just taking the MDIO lock in
fec_enet_adjust_link() should do the work, however there are other
code path in the FEC that could create this issues:
 - fec_enet_set_pauseparam() => fec_stop()/fec_restart()
 - fec_enet_close() => fec_stop() 
 - fec_set_features() => fec_stop()
 - fec_suspend() => fec_stop()

1. Should all of those be protected? Are these real issues?
2. Which fixes tag to use? This seems likely a quite old issue, not
introduced with the MII polling.

Francesco


^ permalink raw reply	[flat|nested] 14+ messages in thread

* Re: FEC MDIO read timeout on linkup
  2022-05-05  8:29           ` Francesco Dolcini
@ 2022-05-05 17:41             ` Andrew Lunn
  2022-05-05 17:54               ` Francesco Dolcini
  0 siblings, 1 reply; 14+ messages in thread
From: Andrew Lunn @ 2022-05-05 17:41 UTC (permalink / raw)
  To: Francesco Dolcini
  Cc: Joakim Zhang, netdev, Andy Duan, Heiner Kallweit, Russell King,
	Jakub Kicinski, Paolo Abeni, David S. Miller, Fabio Estevam,
	Tim Harvey, Chris Healy

On Thu, May 05, 2022 at 10:29:01AM +0200, Francesco Dolcini wrote:
> Hello Andrew and all, I believe I finally found the problem and I'm
> preparing a patch for it.
> 
> On Wed, May 04, 2022 at 12:17:59AM +0200, Andrew Lunn wrote:
> > > I'm wondering could this be related to
> > > fec_enet_adjust_link()->fec_restart() during a fec_enet_mdio_read()
> > > and one of the many register write in fec_restart() just creates the
> > > issue, maybe while resetting the FEC? Does this makes any sense?
> > 
> > phylib is 'single threaded', in that only one thing will be active at
> > once for a PHY. While fec_enet_adjust_link() is being called, there
> > will not be any read/writes occurring for that PHY.
> 
> I think this is not the whole story here. We can have a phy interrupt
> handler that runs in its own context and it could be doing a MDIO
> transaction, and this is exactly my case.
> 
> Thread 1 (phylib WQ)       | Thread 2 (phy interrupt)
>                            |
>                            | phy_interrupt()            <-- PHY IRQ
> 	                   |  handle_interrupt()
> 	                   |   phy_read()
> 	                   |   phy_trigger_machine()
> 	                   |    --> schedule WQ
>                            |
> 	                   |
> phy_state_machine()        |                        
>  phy_check_link_status()   |
>   phy_link_change()        |
>    phydev->adjust_link()   |
>     fec_enet_adjust_link() | 
>      --> FEC reset         | phy_interrupt()            <-- PHY IRQ
> 	                   |  phy_read()
> 	 	           |
> 
> To confirm this I have added a spinlock to detect this race condition
> with just a trylock and a WARN_ON(1) when the locking is failing. On
> "MDIO read timeout" acquiring the spinlock fails.
> 
> This is also in agreement with the fact that polling the PHY instead of
> having the interrupt is working just fine.

Yes, that makes sense.

But i would fix this differently. The interrupt handler runs in a
threaded interrupt. So it can use mutex. So it should actually take
the phy mutex.

Please try this:

diff --git a/drivers/net/phy/phy.c b/drivers/net/phy/phy.c
index beb2b66da132..7d3a64d04820 100644
--- a/drivers/net/phy/phy.c
+++ b/drivers/net/phy/phy.c
@@ -970,8 +970,13 @@ static irqreturn_t phy_interrupt(int irq, void *phy_dat)
 {
        struct phy_device *phydev = phy_dat;
        struct phy_driver *drv = phydev->drv;
+       int ret;
 
-       return drv->handle_interrupt(phydev);
+       mutex_lock(&phydev->lock);
+       ret = drv->handle_interrupt(phydev);
+       mutex_unlock(&phydev->lock);
+
+       return ret;
 }
 
That will stop it running in parallel to the adjust_link callback, or
anything else in phylib.

	 Andrew

^ permalink raw reply related	[flat|nested] 14+ messages in thread

* Re: FEC MDIO read timeout on linkup
  2022-05-05 17:41             ` Andrew Lunn
@ 2022-05-05 17:54               ` Francesco Dolcini
  0 siblings, 0 replies; 14+ messages in thread
From: Francesco Dolcini @ 2022-05-05 17:54 UTC (permalink / raw)
  To: Andrew Lunn
  Cc: Francesco Dolcini, Joakim Zhang, netdev, Andy Duan,
	Heiner Kallweit, Russell King, Jakub Kicinski, Paolo Abeni,
	David S. Miller, Fabio Estevam, Tim Harvey, Chris Healy

On Thu, May 05, 2022 at 07:41:00PM +0200, Andrew Lunn wrote:
> On Thu, May 05, 2022 at 10:29:01AM +0200, Francesco Dolcini wrote:
> > Hello Andrew and all, I believe I finally found the problem and I'm
> > preparing a patch for it.
> > 
> > On Wed, May 04, 2022 at 12:17:59AM +0200, Andrew Lunn wrote:
> > > > I'm wondering could this be related to
> > > > fec_enet_adjust_link()->fec_restart() during a fec_enet_mdio_read()
> > > > and one of the many register write in fec_restart() just creates the
> > > > issue, maybe while resetting the FEC? Does this makes any sense?
> > > 
> > > phylib is 'single threaded', in that only one thing will be active at
> > > once for a PHY. While fec_enet_adjust_link() is being called, there
> > > will not be any read/writes occurring for that PHY.
> > 
> > I think this is not the whole story here. We can have a phy interrupt
> > handler that runs in its own context and it could be doing a MDIO
> > transaction, and this is exactly my case.
> > 
> > Thread 1 (phylib WQ)       | Thread 2 (phy interrupt)
> >                            |
> >                            | phy_interrupt()            <-- PHY IRQ
> > 	                   |  handle_interrupt()
> > 	                   |   phy_read()
> > 	                   |   phy_trigger_machine()
> > 	                   |    --> schedule WQ
> >                            |
> > 	                   |
> > phy_state_machine()        |                        
> >  phy_check_link_status()   |
> >   phy_link_change()        |
> >    phydev->adjust_link()   |
> >     fec_enet_adjust_link() | 
> >      --> FEC reset         | phy_interrupt()            <-- PHY IRQ
> > 	                   |  phy_read()
> > 	 	           |
> > 
> > To confirm this I have added a spinlock to detect this race condition
> > with just a trylock and a WARN_ON(1) when the locking is failing. On
> > "MDIO read timeout" acquiring the spinlock fails.
> > 
> > This is also in agreement with the fact that polling the PHY instead of
> > having the interrupt is working just fine.
> 
> Yes, that makes sense.
> 
> But i would fix this differently. The interrupt handler runs in a
> threaded interrupt. So it can use mutex. So it should actually take
> the phy mutex.

I was just about to send a patch with phy_lock_mdio_bus() in
fec_enet_adjust_link(), anyway, I'll send the version you proposed in a
bit.

Thanks,
Francesco


^ permalink raw reply	[flat|nested] 14+ messages in thread

end of thread, other threads:[~2022-05-05 17:54 UTC | newest]

Thread overview: 14+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2022-04-22 15:26 FEC MDIO read timeout on linkup Francesco Dolcini
2022-04-22 15:55 ` Fabio Estevam
2022-04-22 16:04   ` Francesco Dolcini
2022-04-29 15:15     ` Francesco Dolcini
2022-05-02 17:05 ` Francesco Dolcini
2022-05-02 18:21   ` Andrew Lunn
2022-05-02 18:25     ` Francesco Dolcini
2022-05-02 18:24   ` Andrew Lunn
2022-05-02 18:34     ` Francesco Dolcini
2022-05-03 16:13       ` Francesco Dolcini
2022-05-03 22:17         ` Andrew Lunn
2022-05-05  8:29           ` Francesco Dolcini
2022-05-05 17:41             ` Andrew Lunn
2022-05-05 17:54               ` Francesco Dolcini

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).