Re: STMMAC driver: NFS Problem on 2.6.37

2 messages, 2 authors, 2011-01-28 · open the first message on its own page

Re: STMMAC driver: NFS Problem on 2.6.37

From: Shiraz Hashim <hidden>
Date: 2011-01-28 12:43:31

Hello Chuck,

On Wed, Jan 26, 2011 at 02:04:21AM +0800, Chuck Lever wrote:
See analysis in line.

On Jan 25, 2011, at 6:56 AM, deepaksi wrote:
[...]
quoted
We have made following observations
1. It seems that the time taken by phy auto negotiation process is
long and as soon as the link gets up rpc ping request is getting
timed out and we receive "Unable to reach ICMP" error. The time
out error is same even if you do not connect a network cable and
do a nfs boot.

2. We tried to modify the rate at which the work queue is
scheduled in the phy framework. instead of scheduling every HZ ( 1
sec), we modified it to HZ/10. We did not received
the error. This probably reduced the margin of the phy framework
informing the kernel that the link is up.

3. We tried to use another network card and did a nfs boot. The
only relevant difference we could find was the time of auto
negotiation.
Can you post a similar debugging dump of a root mount that succeeds
using a different network card?
Following is the NFS boot log with a PCIe based e1000e nic card.

....
....
[    1.570000] e1000: Intel(R) PRO/1000 Network Driver - version 7.3.21-k8-NAPI
[    1.580000] e1000: Copyright (c) 1999-2006 Intel Corporation.
[    1.590000] e1000e: Intel(R) PRO/1000 Network Driver - 1.2.7-k2
[    1.590000] e1000e: Copyright (c) 1999 - 2010 Intel Corporation.
[    1.600000] e1000e 0000:01:00.0: Disabling ASPM  L1
[    1.600000] PCI: enabling device 0000:01:00.0 (0140 -> 0142)
[    1.610000] e1000e 0000:01:00.0: (unregistered net_device): Failed to initialize MSI interrupts.  Falling back to legacy interrupts.
[    1.850000] e1000e 0000:01:00.0: eth0: (PCI Express:2.5GB/s:Width x1) 00:15:17:ec:02:ff
[    1.860000] e1000e 0000:01:00.0: eth0: Intel(R) PRO/1000 Network Connection
[    1.870000] e1000e 0000:01:00.0: eth0: MAC: 1, PHY: 4, PBA No: d50861-004
[    1.870000] Intel(R) Gigabit Ethernet Network Driver - version 2.1.0-k2
[    1.880000] Copyright (c) 2007-2009 Intel Corporation.
[    1.880000] Intel(R) Virtual Function Network Driver - version 1.0.0-k0
[    1.890000] Copyright (c) 2009 Intel Corporation.
[    1.900000] CAN device driver interface
[    1.900000] STMMAC driver:
[    1.900000] 	platform registration... 
[    1.910000] 	done!
[    1.910000] 	DWMAC1000 - user ID: 0x10, Synopsys ID: 0x35
[    1.920000] 	Enhanced descriptor structure
[    1.920000] 	eth1 - (dev. name: stmmaceth - id: 0, IRQ #65
[    1.920000] 	IO base addr: 0xd00f0000)
[    1.940000] STMMAC MII Bus: probed
[    1.940000] eth1: PHY ID 20005c7a at 5 IRQ -1 (0:05) active
[    1.950000] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    1.950000] spear-ehci spear-ehci.0: SPEAr EHCI
[    1.960000] spear-ehci spear-ehci.0: new USB bus registered, assigned bus number 1
[    2.020000] spear-ehci spear-ehci.0: irq 96, io mem 0xe4800000
[    2.040000] spear-ehci spear-ehci.0: USB 0.0 started, EHCI 1.00
[    2.040000] hub 1-0:1.0: USB hub found
[    2.050000] hub 1-0:1.0: 1 port detected
[    2.050000] spear-ehci spear-ehci.1: SPEAr EHCI
[    2.060000] spear-ehci spear-ehci.1: new USB bus registered, assigned bus number 2
[    2.120000] spear-ehci spear-ehci.1: irq 98, io mem 0xe5800000
[    2.140000] spear-ehci spear-ehci.1: USB 0.0 started, EHCI 1.00

175 more lines

quoted
Are there some changes in the kernel framework w.r.t rpc ping time
out ? This problem was not there in previous kernels.
There have been changes in the RPC socket code around how it manages
recovery from failed attempts to connect.  We also have new logic
now in the RPC client that causes RPC ping to fail immediately if a
host can't be reached.

Thanks for your efforts so far.  It would be helpful if you could
bisect to determine which commit(s) introduced this RPC client
behavior (or any related changes to your network driver behavior).
We would do so in coming days. By then can you please guide us if you
have something in mind.

-- 
regards
Shiraz
--
To unsubscribe from this list: send the line "unsubscribe linux-nfs" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: STMMAC driver: NFS Problem on 2.6.37

From: Chuck Lever <hidden>
Date: 2011-01-28 16:59:05

Hi-

On Jan 28, 2011, at 7:43 AM, Shiraz Hashim wrote:
Hello Chuck,

On Wed, Jan 26, 2011 at 02:04:21AM +0800, Chuck Lever wrote:
quoted
See analysis in line.

On Jan 25, 2011, at 6:56 AM, deepaksi wrote:
[...]
quoted
quoted
We have made following observations
1. It seems that the time taken by phy auto negotiation process is
long and as soon as the link gets up rpc ping request is getting
timed out and we receive "Unable to reach ICMP" error. The time
out error is same even if you do not connect a network cable and
do a nfs boot.

2. We tried to modify the rate at which the work queue is
scheduled in the phy framework. instead of scheduling every HZ ( 1
sec), we modified it to HZ/10. We did not received
the error. This probably reduced the margin of the phy framework
informing the kernel that the link is up.

3. We tried to use another network card and did a nfs boot. The
only relevant difference we could find was the time of auto
negotiation.
Can you post a similar debugging dump of a root mount that succeeds
using a different network card?
Following is the NFS boot log with a PCIe based e1000e nic card.

....
....
[    1.570000] e1000: Intel(R) PRO/1000 Network Driver - version 7.3.21-k8-NAPI
[    1.580000] e1000: Copyright (c) 1999-2006 Intel Corporation.
[    1.590000] e1000e: Intel(R) PRO/1000 Network Driver - 1.2.7-k2
[    1.590000] e1000e: Copyright (c) 1999 - 2010 Intel Corporation.
[    1.600000] e1000e 0000:01:00.0: Disabling ASPM  L1
[    1.600000] PCI: enabling device 0000:01:00.0 (0140 -> 0142)
[    1.610000] e1000e 0000:01:00.0: (unregistered net_device): Failed to initialize MSI interrupts.  Falling back to legacy interrupts.

146 more quoted lines

In the earlier trace, the transport socket connection attempt returns EHOSTUNREACH when a socket connect operation is attempted before the interface is up.  In this trace, the network layer allows the transport socket to connect straight away; there's no race with interface initialization.  So your problem is not likely to be in the RPC client, but in the network layer or below (hardware driver, etc).
[    5.910000] RPC:     2 __rpc_wake_up_task (now 4294937887)
[    5.910000] RPC:     2 disabling timer
[    5.920000] RPC:     2 removed from queue cfb149dc "xprt_pending"
[    5.920000] RPC:       __rpc_wake_up_task done
[    5.930000] RPC:     2 __rpc_execute flags=0x681
[    5.930000] RPC:     2 xprt_connect_status: retrying
[    5.940000] RPC:     2 call_connect_status (status -11)
[    5.940000] RPC:     2 call_transmit (status 0)
[    5.950000] RPC:     2 xprt_prepare_transmit
[    5.950000] RPC:     2 rpc_xdr_encode (status 0)
[    5.960000] RPC:     2 marshaling UNIX cred cfa93200
[    5.960000] RPC:     2 using AUTH_UNIX cred cfa93200 to wrap rpc data
[    5.970000] RPC:     2 encoding PMAP_GETPORT call (100005, 3, 6, 0)
[    5.980000] RPC:     2 xprt_transmit(92)
[    5.980000] RPC:       xs_tcp_send_request(92) = 92
[    5.980000] RPC:       xs_tcp_data_ready...
[    5.990000] RPC:       xs_tcp_data_recv started
[    5.990000] RPC:       reading TCP record fragment of length 28
[    6.000000] RPC:       reading XID (4 bytes)
[    6.000000] RPC:       reading request with XID aa41d674
[    6.010000] RPC:       reading CALL/REPLY flag (4 bytes)
[    6.010000] RPC:       read reply XID aa41d674
[    6.020000] RPC:       XID aa41d674 read 20 bytes
[    6.020000] RPC:       xprt = cfb14800, tcp_copied = 28, tcp_offset = 28, tcp_reclen = 28
[    6.030000] RPC:     2 xid aa41d674 complete (28 bytes received)
[    6.040000] RPC:       xs_tcp_data_recv done
[    6.040000] RPC:     2 xmit complete
[    6.050000] RPC:       wake_up_next(cfb14974 "xprt_resend")
[    6.050000] RPC:       wake_up_next(cfb1490c "xprt_sending")
[    6.060000] RPC:     2 call_status (status 28)
[    6.060000] RPC:     2 call_decode (status 28)
[    6.070000] RPC:     2 validating UNIX cred cfa93200
[    6.070000] RPC:     2 using AUTH_UNIX cred cfa93200 to unwrap rpc data
[    6.080000] RPC:     2 PMAP_GETPORT result: 48734
[    6.080000] RPC:     2 call_decode result 0
[    6.090000] RPC:       setting port for xprt cfb13800 to 48734
[    6.090000] RPC:     2 rpcb_getport_done(status 0, port 48734)
[    6.100000] RPC:     2 return 0, status 0
[    6.100000] RPC:     2 release task
[    6.110000] RPC:       freeing buffer of size 412 at cfb15000

13 more quoted lines

-- 
Chuck Lever
chuck[dot]lever[at]oracle[dot]com



Keyboard shortcuts
hback out one level
jnext message in thread
kprevious message in thread
ldrill in
Escclose help / fold thread tree
?toggle this help