Bug 64081

Summary: mdiobus_read fail and return -110 when called from get_phy_id r6040: 0000:00:08.0 failed to register MII bus
Product: Networking Reporter: Nils Koehler (nils.koehler)
Component: OtherAssignee: Stephen Hemminger (stephen)
Status: NEW ---    
Severity: blocking CC: f.fainelli, nils.koehler, szg00000, zenbooster
Priority: P1    
Hardware: All   
OS: Linux   
Kernel Version: 3.10.17 Subsystem:
Regression: No Bisected commit-id:

Description Nils Koehler 2013-10-30 18:10:35 UTC
I have tracked down an issue I have to get the device driver r6040.c to run on Kernel 3.10.17.

It fails called get_phy_id.
In fails sometimes randomly on a phy id between 0 and 31.

the chance to get the error is 50% in my case after insmod r6040.ko

The error is caused by the following function:

int mdiobus_read(struct mii_bus *bus, int addr, u32 regnum)
{
	int retval;

	BUG_ON(in_interrupt());

	mutex_lock(&bus->mdio_lock);
	retval = bus->read(bus, addr, regnum);
	mutex_unlock(&bus->mdio_lock);

printk(KERN_INFO "IBT Debug 1 mdiobus_read retval:%d addr:%d regnum:%d\n",retval,addr,regnum);
	
	return retval;
}
EXPORT_SYMBOL(mdiobus_read);

I have added a debug trace and in case of failure retval returns -110

This cause a break in get_phy_id flow and driver init fully fails because it returns the an -EIO 

I saw that the real existing phy id 1 in my case always was propper detected but the feeding loop try to init up to 31 Phy's and mostly one of them fail.
Comment 1 Florian Fainelli 2013-10-30 18:31:30 UTC
Ok, so a few things to check:

- if you increase the existing 2048 limit to a higher number does it successfully probe for the PHY?

- is your PHY actually accessible on the MDIO bus at all?
Comment 2 Nils Koehler 2013-10-30 19:04:00 UTC
I have tested right now with:
#define MAC_DEF_TIMEOUT	2048*2	/* Default MAC read/write operation timeout */

So i doubled the value, but still the same problem:

The Phy ID 1 response fine on the bus, just one of the not existing phys between 1 and 31 fails randomly if it happens the id where it fail changes i have seen all of them.

but ID 1 respond the right way during init loop
Comment 3 Nils Koehler 2013-10-30 19:17:11 UTC
The init fails on 50% of the trys to insmod the driver, so when init does not fail, eth0 works propper and stable without any receive errors at all.
Comment 4 Nils Koehler 2013-10-31 11:57:14 UTC
I have stuffed the source code files core.c r6040.c mdio.c and phy_device.c with detailed trace information stuff, to see what happens during the driver init and to provide you more information about the missbehavier.

but something supprising happened, to be able to post larger traces I did a change in kernel config to use ttyS0 instead of tty0 which I have used before.
Until that change and the many printk#s I added the error did not happen right now any more.

To be sure, I wrote a testscript to load and unload the driver and have a automated test in between with the following script:

# cat eth_test.sh
counter=1
error=0;
while :
do
insmod /lib/modules/3.10.17/kernel/drivers/net/ethernet/rdc/r6040.ko
ifconfig eth0 192.168.0.10
if ifconfig | grep -qci eth0; then
  echo " trys $counter OK   Errors: $error"
else
  error=$((error+1))
  echo " trys $counter Fail Errors: $error"
fi
rmmod /lib/modules/3.10.17/kernel/drivers/net/ethernet/rdc/r6040
counter=$((counter+1))
done

The script tested 11341 times and no fail detecteble.
 trys 11337 OK   Errors: 0
 trys 11338 OK   Errors: 0
 trys 11339 OK   Errors: 0
 trys 11340 OK   Errors: 0
 trys 11341 OK   Errors: 0

After the lunch I try the same testscript with tty0 instead of ttys0 as i used before...

I hope to be able to bring back the malfunction, I keep you informed

One question as I traced the fail yesterday, the mdiobus_read function failed with returning error -110. I have googeled for error code 110 and google spit out EMULTIHOP for 110, but I can not find information about it.

I think this is byond my knowledge of linux... any idear?
Comment 5 Florian Fainelli 2013-10-31 19:11:08 UTC
Ok, so I think you are mixing up few things here.

-110 = -ETIMEDOUT from r6040_phy_read() or r6040_phy_write().

110 is defined in include/uapi/asm-generic/errno.h

"The Phy ID 1 response fine on the bus, just one of the not existing phys between 1 and 31 fails randomly if it happens the id where it fail changes i have seen all of them."

Ok, so this is totally expected, there is just one PHY responding at address 1. The driver currently probes for all PHYs on the bus, and that is not necessary as we know that PHYs would be.

RDC sent me a patch a while ago that seems like it would fix your issue:

--- linux-3.7.2/drivers/net/ethernet/rdc/r6040.c.orig   2013-06-07 03:00:05.670250988 -0700
+++ linux-3.7.2/drivers/net/ethernet/rdc/r6040.c        2013-06-07 03:05:01.666407765 -0700
@@ -1037,8 +1037,18 @@ static int r6040_mii_probe(struct net_de
 {
        struct r6040_private *lp = netdev_priv(dev);
        struct phy_device *phydev = NULL;
+        static int first_find_addr = 0;
+        int addr;
+        for ( addr = first_find_addr; addr < PHY_MAX_ADDR; addr++ ) {
+
+        if ( lp->mii_bus->phy_map[addr] )
+                phydev = lp->mii_bus->phy_map[addr];
+
+        if(phydev)
+                break;
+        }
+        first_find_addr++ ;

-       phydev = phy_find_first(lp->mii_bus);
        if (!phydev) {
                dev_err(&lp->pdev->dev, "no PHY found\n");
                return -ENODEV;
@@ -1194,6 +1204,10 @@ static int __devinit r6040_init_one(stru
        lp->mii_bus->write = r6040_mdiobus_write;
        lp->mii_bus->reset = r6040_mdiobus_reset;
        lp->mii_bus->name = "r6040_eth_mii";
+        if ( card_idx == 0 )
+            lp->mii_bus->phy_mask = 0x1;
+        else
+            lp->mii_bus->phy_mask = 0x3;
        snprintf(lp->mii_bus->id, MII_BUS_ID_SIZE, "%s-%x",
                dev_name(&pdev->dev), card_idx);
        lp->mii_bus->irq = kmalloc(sizeof(int)*PHY_MAX_ADDR, GFP_KERNEL);

Can you try this?
Comment 6 Nils Koehler 2013-10-31 20:57:50 UTC
Today I had the stupid situation, that all test I did end with the result, that I have  a rock solid functionality. Normally I am happy about that, but in this case I am not able to point out what change fixed the issue. 

So I decided today evening to roll back all last changes, and I got back my unstable situation.

I will do minimal incremental tests on it tomorrow.

Ok thank you as -110 is -ETIMEDOUT I will try to incerase timeout again at first. Then I will apply your patch.

Yesterday I have also gambeled with deprecated switch in .config
I will also try again with enabeled and disabeled the same...
Comment 7 Florian Fainelli 2013-10-31 21:35:42 UTC
Could you try a simpler version of the patch (the phy_mask is wrong in the above patch):

diff --git a/drivers/net/ethernet/rdc/r6040.c b/drivers/net/ethernet/rdc/r6040.c
index 1e49ec5..5c09085 100644
--- a/drivers/net/ethernet/rdc/r6040.c
+++ b/drivers/net/ethernet/rdc/r6040.c
@@ -1192,6 +1192,7 @@ static int r6040_init_one(struct pci_dev *pdev, const struct
        lp->mii_bus->write = r6040_mdiobus_write;
        lp->mii_bus->reset = r6040_mdiobus_reset;
        lp->mii_bus->name = "r6040_eth_mii";
+       lp->mii_bus->phy_mask = ~(1 << (card_idx + 1));
        snprintf(lp->mii_bus->id, MII_BUS_ID_SIZE, "%s-%x",
                dev_name(&pdev->dev), card_idx);
        lp->mii_bus->irq = kmalloc_array(PHY_MAX_ADDR, sizeof(int), GFP_KERNEL);
Comment 8 Nils Koehler 2013-11-01 11:59:52 UTC
The confusion of yesterdays behavier was that the r6040.ko driver was not updated after make, it was only updated when I touched .config before. I think it is an effect of my buildroot setup. Now I double check that .ko is freshly compiled before do a test.

Now I have the unstable starting point for testing the script I wrote bring the information that I have 10 Errors at 26 trys to insmod the driver which is an error rate from 38%

I did the following tests:

1. Test
Change Timeout value from 2048 to 4096
#define MAC_DEF_TIMEOUT	4096	/* Default MAC read/write operation timeout */

Result No Error dectected within 3000 trys. So I think this was the change wich made it rock solid yesterday...



2. Test 
Set Timeout back to 2048 to be unstable again
#define MAC_DEF_TIMEOUT	2048	/* Default MAC read/write operation timeout */

add your last Kernel patch
+       lp->mii_bus->phy_mask = ~(1 << (card_idx + 1));

With that patch it is better than the unpatched version.
With the Patch I need 208 trys to get 10 errors which is an error rate from appr 5%, so it is better but, not good.

 trys 208 OK   Errors: 10
 trys 209 OK   Errors: 10
ifconfig: SIOCSIFADDR: No such device
0
 trys 210 Fail Errors: 11
 trys 211 OK   Errors: 11
 trys 212 OK   Errors: 11
 
 
So the question now is to apply both changes? 
Does the higher Timeout value have any other negative dependecys?

I will run the Test over the weekend with both applyed...
Comment 9 Nils Koehler 2013-11-01 15:39:59 UTC
Snapshot of longterm test (still running)...
 trys 106362 OK   Errors: 0
 trys 106363 OK   Errors: 0
 trys 106364 OK   Errors: 0
 trys 106365 OK   Errors: 0
 trys 106366 OK   Errors: 0
 trys 106367 OK   Errors: 0
 trys 106368 OK   Errors: 0
 trys 106369 OK   Errors: 0
 trys 106370 OK   Errors: 0
Comment 10 Florian Fainelli 2013-11-01 21:17:07 UTC
Ok, so this is with MAC_DEF_TIMEOUT = 4096 right?
Comment 11 Nils Koehler 2013-11-01 23:13:02 UTC
Yes... 

aktually passed 
 
 trys 266950 OK   Errors: 0
 trys 266951 OK   Errors: 0
 trys 266952 OK   Errors: 0
 trys 266953 OK   Errors: 0

May be I can tomorrow level out the border of Timeout value between unstable and stable functionality, to decide a value which is not to hight but low enought to ensure a save operation...
Comment 12 Nils Koehler 2013-11-02 09:13:26 UTC
I have goood news and bad news...

This morning I found the device under test in this condition:

 trys 378722 OK   Errors: 0
 trys 378723 OK   Errors: 0
 trys 378724 OK   Errors: 0
Killed

The good news is, that it run 378724 times without any error, which simulate more than 100 Years of propper operation but...

...the bad news is that the test was killed by the kernel during the night.
My first idear was memory loss

# top
 Mem: 252292K used, 3128K free, 0K shrd, 0K buff, 4972K cached
CPU:   0% usr  99% sys   0% nic   0% idle   0% io   0% irq   0% sirq

It pointed out that it seem that memory is eaten up during the test, so I added that line to the end of the while loop in the test scropt:

cat /proc/meminfo | grep -i MemFree

It shows that the memory decrease not after each cycle but it get lower and lower after a couple of cycles

Meminfo Direct after boot

# cat /proc/meminfo
MemTotal:         255420 kB
MemFree:          247756 kB
Buffers:               0 kB
Cached:             4668 kB
SwapCached:            0 kB
Active:              880 kB
Inactive:           4052 kB
Active(anon):        288 kB
Inactive(anon):        4 kB
Active(file):        592 kB
Inactive(file):     4048 kB
Unevictable:           0 kB
Mlocked:               0 kB
SwapTotal:             0 kB
SwapFree:              0 kB
Dirty:                 0 kB
Writeback:             0 kB
AnonPages:           280 kB
Mapped:              356 kB
Shmem:                28 kB
Slab:               2104 kB
SReclaimable:        324 kB
SUnreclaim:         1780 kB
KernelStack:         216 kB
PageTables:           60 kB
NFS_Unstable:          0 kB
Bounce:                0 kB
WritebackTmp:          0 kB
CommitLimit:      127708 kB
Committed_AS:        972 kB
VmallocTotal:     778116 kB
VmallocUsed:          32 kB
VmallocChunk:     778044 kB
DirectMap4k:      262144 kB
DirectMap4M:           0 kB
#

Meminfo later after 1016 insmod rmmod cycles

# cat /proc/meminfo
MemTotal:         255420 kB
MemFree:          246208 kB
Buffers:               0 kB
Cached:             4964 kB
SwapCached:            0 kB
Active:             1308 kB
Inactive:           3924 kB
Active(anon):        584 kB
Inactive(anon):        8 kB
Active(file):        724 kB
Inactive(file):     3916 kB
Unevictable:           0 kB
Mlocked:               0 kB
SwapTotal:             0 kB
SwapFree:              0 kB
Dirty:                 0 kB
Writeback:             0 kB
AnonPages:           280 kB
Mapped:              356 kB
Shmem:               324 kB
Slab:               2960 kB
SReclaimable:        324 kB
SUnreclaim:         2636 kB
KernelStack:         216 kB
PageTables:           60 kB
NFS_Unstable:          0 kB
Bounce:                0 kB
WritebackTmp:          0 kB
CommitLimit:      127708 kB
Committed_AS:       1268 kB
VmallocTotal:     778116 kB
VmallocUsed:          44 kB
VmallocChunk:     765856 kB
DirectMap4k:      262144 kB
DirectMap4M:           0 kB
#

The biggest difference of both traces is in:

Memory                  before test    after test    difference
VmallocChunk:     	778044		765856	      -12188.00
Comment 13 Nils Koehler 2013-11-02 13:23:46 UTC
...after 84850 trys:

# cat /proc/meminfo
MemTotal:         255420 kB
MemFree:          191528 kB
Buffers:               0 kB
Cached:             5044 kB
SwapCached:            0 kB
Active:             1400 kB
Inactive:           3908 kB
Active(anon):        660 kB
Inactive(anon):        8 kB
Active(file):        740 kB
Inactive(file):     3900 kB
Unevictable:           0 kB
Mlocked:               0 kB
SwapTotal:             0 kB
SwapFree:              0 kB
Dirty:                 0 kB
Writeback:             0 kB
AnonPages:           280 kB
Mapped:              356 kB
Shmem:               404 kB
Slab:              57624 kB
SReclaimable:        348 kB
SUnreclaim:        57276 kB
KernelStack:         208 kB
PageTables:           60 kB
NFS_Unstable:          0 kB
Bounce:                0 kB
WritebackTmp:          0 kB
CommitLimit:      127708 kB
Committed_AS:       1348 kB
VmallocTotal:     778116 kB
VmallocUsed:          44 kB
VmallocChunk:     769376 kB
DirectMap4k:      262144 kB
DirectMap4M:           0 kB

More interesting than VmallocChunk is may be:
Slab:              57624 kB
SReclaimable:        348 kB
SUnreclaim:        57276 kB
Comment 14 Florian Fainelli 2013-11-02 18:07:28 UTC
We might be leaking some memory, which would explain why your free memory shrinks after a while. This would be a second fix. I am a little busy for the weekend, but will start submitting fixes for r6040 next week. Thanks!
Comment 15 Nils Koehler 2013-11-04 08:16:39 UTC
OK... I have evaluated out the critical MAC_DEF_TIMEOUT value, which is between 2132 and 2140 in my system:

2500 OK
2250 OK
2187 OK
2156 OK
2140 OK
2132 FAIL
2125 FAIL
2048 FAIL

The values are not longterm thested just, short tests to evaluate the critical border value.
Comment 16 Florian Fainelli 2013-12-04 01:47:11 UTC
Let me check the datasheet with respect to the actual timings. I think increasing the timing blindly without making it depend on the CPU timebase is not going to work on some other platforms with faster CPU clock rates.
Comment 17 Florian Fainelli 2014-01-10 20:52:41 UTC
It turned out that the datasheet does not give any clue about how fast/slow a MDIO operation should complete, a 1 micro second delay in each loop should be safe though.
Comment 18 ZenBooster 2014-04-10 12:48:01 UTC
I have a same problem with 3.12.13-gentoo on ebox3350mx.

r6040 0000:00:08.0: failed to register MII bus 
r6040: probe of 0000:00:08.0 failed with error -5

After reading this topic, i set:
#define MAC_DEF_TIMEOUT   4096

and then recompile kernel. And now it's work!