Message-ID: <4683e9ea-f795-4dab-8a0a-bd0b0f4fbd99@kabelmail.de>
Date: Mon, 22 Sep 2025 10:04:12 +0200
From: Janpieter Sollie <janpieter.sollie@...elmail.de>
To: "Russell King (Oracle)" <linux@...linux.org.uk>
Cc: Andrew Lunn <andrew@...n.ch>, netdev@...r.kernel.org,
 Heiner Kallweit <hkallweit1@...il.com>, "David S. Miller"
 <davem@...emloft.net>, Eric Dumazet <edumazet@...gle.com>,
 Jakub Kicinski <kuba@...nel.org>, Paolo Abeni <pabeni@...hat.com>
Subject: Re: [RFC] increase MDIO i2c poll timeout gradually (including patch)

Op 20/09/2025 om 15:53 schreef Russell King (Oracle):
> So, what we need you to do is to work out how long it takes this module
> to respond, and whether it always takes a long time to respond. Please
> add some debugging to i2c_rollball_mii_poll() to measure the amount of
> time it takes for the module to respond - and please measure it for
> several transactions.
>
> You can use jiffies, and convert to msecs using jiffies_to_msecs(),
> or you could use ktime_get_ns().
>
> Thanks.
>

All right, so I changed the modification to a more debug-friendly function (view below).
I also changed the incremental wait() function from (20+10*(10-i)) to (20+5*(10-i)) to be more 
accurate.
When bringing up with "ip link set sfp-lan up", it starts printing
It keeps polling (which, I guess, is what you expect, I guess the hwmon subsystem, link 
detection, ... )
Mostly, the output is 300-400us.
When the module is up and running, and maintenance polls happen, I saw something new:
It starts responding with a much lower value: something like 30 us. At iteration 10. occasionally.
i = 10 means "immediately", i decrements from 10 to 0.
I got no clarification for that.
The thing I'm mostly sure of, is that no commands return an error, and no mii_polls time out,
but 300-400us is way too much for a loop which expects to return in 200us
...
156724.601882] i2c_rollball_mii_poll:267: mdio_bus i2c:sfp2: poll cmd success after 348074665 ns 
in iteration 4
[156724.941879] i2c_rollball_mii_poll:267: mdio_bus i2c:sfp2: poll cmd success after 328077236 
ns in iteration 4
[156725.301889] i2c_rollball_mii_poll:267: mdio_bus i2c:sfp2: poll cmd success after 348093665 
ns in iteration 4
[156725.661896] i2c_rollball_mii_poll:267: mdio_bus i2c:sfp2: poll cmd success after 348075511 
ns in iteration 4
[156726.081885] i2c_rollball_mii_poll:267: mdio_bus i2c:sfp2: poll cmd success after 408061414 
ns in iteration 3
[156726.441997] i2c_rollball_mii_poll:267: mdio_bus i2c:sfp2: poll cmd success after 348189434 
ns in iteration 4
[156726.781885] i2c_rollball_mii_poll:267: mdio_bus i2c:sfp2: poll cmd success after 327952775 
ns in iteration 4
[156727.831885] i2c_rollball_mii_poll:267: mdio_bus i2c:sfp2: poll cmd success after 30037797 ns 
in iteration 10
[156728.241880] i2c_rollball_mii_poll:267: mdio_bus i2c:sfp2: poll cmd success after 398062738 
ns in iteration 3
[156728.591889] i2c_rollball_mii_poll:267: mdio_bus i2c:sfp2: poll cmd success after 338068066 
ns in iteration 4
[156728.941888] i2c_rollball_mii_poll:267: mdio_bus i2c:sfp2: poll cmd success after 338062605 
ns in iteration 4
[156729.351924] i2c_rollball_mii_poll:267: mdio_bus i2c:sfp2: poll cmd success after 398101891 
ns in iteration 3
[156729.692014] i2c_rollball_mii_poll:267: mdio_bus i2c:sfp2: poll cmd success after 328135697 
ns in iteration 4
[156730.041895] i2c_rollball_mii_poll:267: mdio_bus i2c:sfp2: poll cmd success after 337947143 
ns in iteration 4
[156730.391997] i2c_rollball_mii_poll:267: mdio_bus i2c:sfp2: poll cmd success after 338162758 
ns in iteration 4
[156730.741994] i2c_rollball_mii_poll:267: mdio_bus i2c:sfp2: poll cmd success after 337980912 
ns in iteration 4
[156731.831897] i2c_rollball_mii_poll:267: mdio_bus i2c:sfp2: poll cmd success after 30043259 ns 
in iteration 10
[156732.241897] i2c_rollball_mii_poll:267: mdio_bus i2c:sfp2: poll cmd success after 398065122 
ns in iteration 3
[156732.581982] i2c_rollball_mii_poll:267: mdio_bus i2c:sfp2: poll cmd success after 328157082 
ns in iteration 4
[156732.921978] i2c_rollball_mii_poll:267: mdio_bus i2c:sfp2: poll cmd success after 327986467 
ns in iteration 4

...

This was an example of the output when using the patch below.
No poll command returns an error state. No poll commands time out.
all mii_poll commands return at i = 3 or i = 4,
when the sfp module is completely up, i = 10 occurs from time to time.

Thanks,

Janpieter Sollie

--- a/drivers/net/mdio/mdio-i2c.c       2025-09-22 08:41:12.084752517 +0200
+++ b/drivers/net/mdio/mdio-i2c.c       2025-09-22 08:47:20.230592266 +0200
@@ -232,6 +232,7 @@
         struct i2c_msg msgs[2];
         u8 cmd_addr, tmp, *res;
         int i, ret;
+       long uptime;

         cmd_addr = ROLLBALL_CMD_ADDR;

@@ -252,14 +253,19 @@
          * SFPs. Sleep 20ms between iterations and try 10 times.
          */
         i = 10;
+       uptime = ktime_get_ns();
         do {
-               msleep(20);
+               msleep(20 + 5*(10-i));

                 ret = i2c_transfer_rollball(i2c, msgs, ARRAY_SIZE(msgs));
-               if (ret)
+               if (ret) {
+                       dev_dbg(&bus->dev, "poll cmd return %d after %d ns in iteration %d\n", 
ret, (ktime_get_ns() - uptime), i);
                         return ret;
+               }

-               if (*res == ROLLBALL_CMD_DONE)
+               if (*res == ROLLBALL_CMD_DONE) {
+                       dev_dbg(&bus->dev, "poll cmd success after %d ns in iteration %d\n", 
(ktime_get_ns() - uptime), i);
                         return 0;
+               }
         } while (i-- > 0);

Powered by blists - more mailing lists