Most recent kernel where this bug did not occur: 2.6.11.7 (I don't know about 2.6.11 versions beyond 2.6.11.7. I moved directly from 2.6.11.7 to 2.6.12.) Distribution: None -- self-compiled system Hardware Environment: Asus P4B533 motherboard with 3Com Etherlink 3C900B NIC Software Environment: Standard stock packages Problem Description: On all kernels prior to 2.6.12 (see above) a connection could be established to my Internet cable provider in about 10 seconds. Since 2.6.12, and currently with 2.6.13-rc6, the connection time is about four minutes. No changes whatsoever were made to my hardware or software. Once the connection is finally established, the eth0 link functions normally. Also, no errors/warnings or any other anomolous information is present in any log files. Steps to reproduce: After kernel boot-up, load eth0 module with 'modprobe 3c59x' and then connect to cable provider using 'dhcpcd -t 240'. It requires close to four minutes to connect.
Can you : - send the output of a 'lspci -vx' under 2.6.13-rc6; - send the dmesg from boot to the loading of the module under both 2.6.13-rc6 and 2.6.11.7 - try to revert : http://www.kernel.org/git/?p=linux/kernel/git/torvalds/linux-2.6.git;a=commitdiff_plain;h=3c8fad1829cc33e903500b41d989fa50ab196378;hp=1922163c8dfe717c089bdcc18ade4a65350a09c8 -- Ueimor
bugme-daemon@kernel-bugs.osdl.org wrote: > > http://bugzilla.kernel.org/show_bug.cgi?id=5025 > > Summary: Excessive time to connect to cable provider using dhcpcd > Kernel Version: 2.6.13-rc6 > Status: NEW > Severity: low > Owner: greg@kroah.com > Submitter: frank.peters@comcast.net > > > Most recent kernel where this bug did not occur: 2.6.11.7 (I don't know about > 2.6.11 versions beyond 2.6.11.7. I moved directly from 2.6.11.7 to 2.6.12.) > Distribution: None -- self-compiled system > Hardware Environment: Asus P4B533 motherboard with 3Com Etherlink 3C900B NIC > Software Environment: Standard stock packages > Problem Description: On all kernels prior to 2.6.12 (see above) a connection > could be established to my Internet cable provider in about 10 seconds. Since > 2.6.12, and currently with 2.6.13-rc6, the connection time is about four > minutes. No changes whatsoever were made to my hardware or software. > Once the connection is finally established, the eth0 link functions normally. > Also, no errors/warnings or any other anomolous information is present in > any log files. > Steps to reproduce: After kernel boot-up, load eth0 module with 'modprobe 3c59x' > and then connect to cable provider using 'dhcpcd -t 240'. It requires close > to four minutes to connect. > IIRC, we established that this was not a device driver problem and we're suspecting a generic networking problem. Could someone please talk Frank through generating a suitable tcpdump trace?
On Mon, 8 Aug 2005 13:47:22 -0700 bugme-daemon@kernel-bugs.osdl.org wrote: > http://bugzilla.kernel.org/show_bug.cgi?id=5025 > > Can you : > - send the output of a 'lspci -vx' under 2.6.13-rc6; > - send the dmesg from boot to the loading of the module under both 2.6.13-rc6 > and 2.6.11.7 > All this is attached as lspci-dmsg.txt. > > - try to revert : > http://www.kernel.org/git/?p=linux/kernel/git/torvalds/linux-2.6.git;a=commitdiff_plain;h=3c8fad1829cc33e903500b41d989fa50ab196378;hp=1922163c8dfe717c089bdcc18ade4a65350a09c8 > > -- I'm not sure what this is about. I'll check into it later. > IIRC, we established that this was not a device driver problem and we're > suspecting a generic networking problem. > > Could someone please talk Frank through generating a suitable tcpdump trace? > I'll start doing some research into tcpdump tracing and hopefull will be able to apply to apply it soon. Frank Peters
> Could someone please talk Frank through generating a suitable tcpdump trace? Frank, before the dhcpcd command, can you issue for both 2.6.11.7 and 2.6.13-rc6: tcpdump -v -s 0 -i eth0 -l -n -U -w /tmp/quuz Stop it when the link is up and attach both /tmp/quuz to the bug report. Thanks. -- Ueimor
Created attachment 5551 [details] Output of lspci -vx and dmsg for 2.6.13-rc6 and 2.6.11.7
On Mon, 8 Aug 2005 15:11:51 -0700 bugme-daemon@kernel-bugs.osdl.org wrote: > http://bugzilla.kernel.org/show_bug.cgi?id=5025 > > > Frank, before the dhcpcd command, can you issue for both 2.6.11.7 and 2.6.13-rc6: > tcpdump -v -s 0 -i eth0 -l -n -U -w /tmp/quuz > Stop it when the link is up and attach both /tmp/quuz to the bug report. > That doesn't seem to be possible. Running tcpdump before dhcpcd only gives me a "Network is down" message. I use a non-networked desktop system. Only when I need to establish an Internet connection do I invoke dhcpcd which sets up the eth0 interface. Before then the eth0 interface does not exist. Frank Peters
On Mon, 8 Aug 2005 15:11:51 -0700 bugme-daemon@kernel-bugs.osdl.org wrote: > http://bugzilla.kernel.org/show_bug.cgi?id=5025 > > > Frank, before the dhcpcd command, can you issue for both 2.6.11.7 and 2.6.13-rc6: > tcpdump -v -s 0 -i eth0 -l -n -U -w /tmp/quuz > Stop it when the link is up and attach both /tmp/quuz to the bug report. > Issuing tcpdump before dhcpcd does not work, but what if I use the following bash script to execute tcpdump immediately after dhcpcd: #! /bin/bash dhcpcd -t 240 & tcpdump -v -s 0 -i eth0 -l -n -U -w /tmp/quuz-2.6.13-rc6 Then as soon as 'netstat -nr' shows that the link is established, I would manually terminate tcpdump. Would this give you the information that you need? Frank Peters
On Mon, 8 Aug 2005 15:11:51 -0700 bugme-daemon@kernel-bugs.osdl.org wrote: > http://bugzilla.kernel.org/show_bug.cgi?id=5025 > > > Frank, before the dhcpcd command, can you issue for both 2.6.11.7 and 2.6.13-rc6: > tcpdump -v -s 0 -i eth0 -l -n -U -w /tmp/quuz > Stop it when the link is up and attach both /tmp/quuz to the bug report. > I found a way to use tcpdump even with no eth0 addresses already established. Here is the method I used: ifconfig eth0 up tcpdump -v -s 0 -i eth0 -l -n -U -w /tmp/quuz dhcpcd -t 240 This allows listening on the eth0 interface without any address assigned to it. Tcpdump is then invoked, followed by dhcpcd. If this is acceptable, I have attached files of this packet capture method for both kernels 2.6.11.7 and 2.6.13-rc6. The attached files are quuz-26117 and quuz-2613rc6. Frank Peters
Created attachment 5552 [details] dhcpcd tcpdump for kernel-2.6.11.7
Created attachment 5553 [details] dhcpcd tcpdump for kernel-2.6.13-rc6
Created attachment 5554 [details] dhcpcd tcpdump for kernel-2.6.11.7
Created attachment 5555 [details] dhcpcd tcpdump for kernel-2.6.13rc6
http://bugzilla.kernel.org/show_bug.cgi?id=5025 I am terribly sorry. I posted the same attachments twice as both text/plain and application/octet stream. There is no difference between the two forms, however. They both are produced by tcpdump and both can be loaded into a program like ethereal. Also, my attempts to obsolete the plain/text entries were not accurate. This is my first use of bugzilla and I need to get used to the options. Frank Peters
http://bugzilla.kernel.org/show_bug.cgi?id=5025 Looking at the tcpdump files in Ethereal, a network analyzer, I see only a long delay in the case of 2.6.13-rc6 before the actual dhcp negotiation begins, whereas with 2.6.11.7 it begins immediately. With 2.6.13rc5, during the long delay there are no packets of any kind except the ARP packets originating from the Cisco hardware. Using the debugging option with dhcpcd, the same long delay with no activity is also evident when using 2.6.13-rc6. If this were a general networking problem, wouldn't there be some kind of packet exchange originating from the local machine right from the beginning? Frank Peters
Created attachment 5562 [details] strace of dhcpcd on kernel-2.6.13-rc6
Created attachment 5563 [details] strace of dhcpcd on kernel-2.6.11.7
http://bugzilla.kernel.org/show_bug.cgi?id=5025 Attached are the results of strace done with the the dhcpcd command for both kernel-2.6.13-rc6 and kernel-2.6.11.7. The files are: strace-2613rc6 strace-26117 The only diference I can immediately see between the two traces is a great deal of time spent invoking the gettimeofday() function with kernel-2.6.13rc6. I hope this can shed some light on the problem. Frank Peters
The symptom suggest that the early Tx (Rx ?) packets are lost somewhere. I see no change in the driver which could explain it. However you enabled ACPI in 2.6.13-rc6 whereas it is disabled in 2.6.11.7. So... How does 2.6.13-rc behave if you disable ACPI and/or use the same boot command line options ? -- Ueimor
On Tue, 9 Aug 2005 16:13:16 -0700 bugme-daemon@kernel-bugs.osdl.org wrote: > > So... How does 2.6.13-rc behave if you disable ACPI and/or use the same boot > command line options ? > The same behavior is seen with ACPI disabled. If I boot 2.6.13-rc6 with the option "acpi=off" the same slow start-up with dhcpcd results. ACPI doesn't seem to matter. Frank Peters
Created attachment 5567 [details] modprobe 3c59x debug=3 kernel log
On Wed, 10 Aug 2005 00:39:54 +0200 Tommy Christensen <tommy.christensen@tpack.net> wrote: > > ... could you please try enabling some > debug output from the network driver, and attach the output > to the report? (Only the 2.6.13-rc6 kernel is relevant here). > > # modprobe 3c59x debug=3 > should do it. > The kernel-2.6.13-rc6 log for this module loading followed immediately by dhcpcd is attached as 3c59x-debug. > Another interesting experiment would be to add a delay before > calling dhcpcd, but after ifconfig eth0 up. > > If you do: > # modprobe 3c59x > # ifconfig eth0 up > # sleep 120 > # dhcpcd -t 240 > > does the dhcpcd command complete as fast as it did on the > 2.6.11.7 kernel? > Success! The dhcpcd command completes with no delay at all. I just added the command 'echo "start"' to get a fix on when the dhcpcd process would begin. There was no noticable delay whatsoever. Interestingly, I noticed the same thing with kernel-2.6.11.7 while trying to get a tcpdump. The dhcpcd process finished without any delay after first issuing "ifconfig eth0 up" when otherwise it would require about 10 seconds. Maybe this problem is not so unique to 2.6.12+. Frank Peters
On Thu, 11 Aug 2005 02:08:05 +0200 Tommy Christensen <tommy.christensen@tpack.net> wrote: > > Recent kernels (>= 2.6.12) won't send packets to a network > interface unless the carrier is OK. > > The odd thing here is that the driver waits for 60 seconds > between each check for carrier. That seems rather long. > Coupled with the exponential back-off of the dhcp process, this > leads to the long delays you're experiencing. > > On top of that, it seems that link actually *is* established, > when the phy status register is checked at first. However, due > to the link bit beeing latched low, the driver reports link down > here. When the register is read again (60s later!) everything > falls into place and packets can start flowing. > > The patch below avoids this "false" link down condition by > re-reading the phy status register. Could you give it a try? > Success again! The patch fixes the problem. The dhcpcd now establishes a connection within 10 seconds. Many thanks to all concerned for your time and effort on this rather low priority issue. Frank Peters [3c59x-carrier.patch text/plain (622B)] [3c59x] Read current link status from phy The phy status register must be read twice in order to get the actual link state. Signed-off-by: Tommy S. Christensen <tommy.christensen@tpack.net> --- linux-2.6.13-rc6/drivers/net/3c59x.c-old Sun Aug 7 20:18:56 2005 +++ linux-2.6.13-rc6/drivers/net/3c59x.c Thu Aug 11 01:59:13 2005 @@ -1873,6 +1873,7 @@ vortex_timer(unsigned long data) { spin_lock_bh(&vp->lock); mii_status = mdio_read(dev, vp->phys[0], 1); + mii_status = mdio_read(dev, vp->phys[0], 1); ok = 1; if (vortex_debug > 2) printk(KERN_DEBUG "%s: MII transceiver has status %4.4x.\n",
For me, the problem is fixed. Using the patch supplied by Tommy Christensen eliminates the problem. What happens now? Who is supposed to change the status of this report? Will the kernel driver eventually include this patch or should I just keep manually modifying the code with each new kernel release? Frank Peters
Tommy's patch is in Linus's post-2.6.13 tree.