Re: Unexcepted latency (order of 100-200 ms) with TCP (packet receive)
From: Ilpo_Järvinen [EMAIL PROTECTED]
Date: Mon, 7 May 2007 14:45:53 +0300 (EEST)
I found out this shows up when 900fd17dd01d2c99dfd1ec0b53a860894a2673ee is
included, kernels before that seem to work fine. The problem description
is in this same thread. I'm not going to repeat it here as it is valid
except for the fact that my original claim that it happens with another
hardware is false, please see it in here:
http://marc.info/?l=linux-netdevm=117758295411277w=2
Should these delays I see be considered as evindence of mmio not working
with this card/model or could there be something else wrong somewhere?
...I can just disable it using global_use_mmio parameter, which removes
the problem in 2.6.20.7 (tested) but just in case somebody has more clue
than I do about this, I'm willing to do more testing...
One thing that MMIO changes a lot is timing.
The port I/O instructions on x86 have fixed timings so take the same
amount of time to execute regardless of the underlying bus
capabilities.
This could have been masking some issue in the driver or the hardware.
Port I/O also does not have any write posting issues like MMIO does.
In my opinion it can only cause trouble to start using MMIO on such
old chips when we've been using port I/O to access them for 5+ years.
:-)
Wait, it's timing, I see the bug. There was a similar problem like
this in the Linux floppy driver some 6 years ago.
Look at issue_and_wait(), how it polls:
iowrite16(cmd, ioaddr + EL3_CMD);
for (i = 0; i 2000; i++) {
if (!(ioread16(ioaddr + EL3_STATUS) CmdInProgress))
return;
}
That takes longer to run with port I/O than MMIO. So I bet it
breaks out of the loop faster with MMIO and thus can trigger
this thing:
/* OK, that didn't work. Do it the slow way. One second */
for (i = 0; i 10; i++) {
if (!(ioread16(ioaddr + EL3_STATUS) CmdInProgress)) {
if (vortex_debug 1)
printk(KERN_INFO %s: command 0x%04x took %d
usecs\n,
dev-name, cmd, i * 10);
return;
}
udelay(10);
}
and that's where your delays are coming from.
I would suggest adding some kind of (very small) fixed delay to the
first loop.
The rest of the driver should be audited for this kind of problem.
-
To unsubscribe from this list: send the line unsubscribe netdev in
the body of a message to [EMAIL PROTECTED]
More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: Unexcepted latency (order of 100-200 ms) with TCP (packet receive)
On Fri, 27 Apr 2007, Ilpo Järvinen wrote: On Thu, 26 Apr 2007, Ilpo Järvinen wrote: On Thu, 26 Apr 2007, Chuck Ebbert wrote: Try a different network adapter. Hmm, I thought I had already done this but I just noticed that it is so that the adapter was still the same as the other host has two adapter (now that I look again). I'll give it a try tomorrow to see if using the another adapter makes any difference. ...Much more promising result this time. I noticed that there was another eth hw on mainboard, thus my previous test with different hw was not valid as I assumed wrong (didn't even notice the other) one to be eth0: 02:05.0 Ethernet controller: 3Com Corporation 3c905C-TX/TX-M [Tornado] (rev 74) 02:08.0 Ethernet controller: Intel Corporation 82801DB PRO/100 VE (LOM) Ethernet Controller (rev 82) With 3c905 I have the problem, with Intel one it does not show up (tested today). I found out this shows up when 900fd17dd01d2c99dfd1ec0b53a860894a2673ee is included, kernels before that seem to work fine. The problem description is in this same thread. I'm not going to repeat it here as it is valid except for the fact that my original claim that it happens with another hardware is false, please see it in here: http://marc.info/?l=linux-netdevm=117758295411277w=2 Should these delays I see be considered as evindence of mmio not working with this card/model or could there be something else wrong somewhere? ...I can just disable it using global_use_mmio parameter, which removes the problem in 2.6.20.7 (tested) but just in case somebody has more clue than I do about this, I'm willing to do more testing... This output comes from 2.6.20.7: [ 15.553104] 3c59x: Donald Becker and others. www.scyld.com/network/vortex.html [ 15.553214] :02:05.0: 3Com PCI 3c905C Tornado at f8800c00. 02:05.0 Ethernet controller: 3Com Corporation 3c905C-TX/TX-M [Tornado] (rev 74) Subsystem: 3Com Corporation 3C905C-TX Fast Etherlink for PC Management NIC Flags: bus master, medium devsel, latency 32, IRQ 18 I/O ports at dc00 [size=128] Memory at feaffc00 (32-bit, non-prefetchable) [size=128] Expansion ROM at f570 [disabled] [size=128K] Capabilities: [dc] Power Management version 2 00: b7 10 00 92 17 01 10 02 74 00 00 02 08 20 00 00 10: 01 dc 00 00 00 fc af fe 00 00 00 00 00 00 00 00 20: 00 00 00 00 00 00 00 00 00 00 00 00 b7 10 00 10 30: 00 00 ac fe dc 00 00 00 00 00 00 00 09 01 0a 0a # cat /proc/interrupts CPU0 0: 126277 IO-APIC-edge timer 1: 8 IO-APIC-edge i8042 2: 0XT-PIC-XTcascade 6: 5 IO-APIC-edge floppy 12: 4 IO-APIC-edge i8042 14: 3392 IO-APIC-edge ide0 15: 0 IO-APIC-edge ide1 18: 1269 IO-APIC-fasteoi eth0 20: 4 IO-APIC-fasteoi eth1 NMI: 0 LOC: 126238 ERR: 0 MIS: 0 eth0 is the 3c59x, eth1 is the intel. Network is 100/Full duplex, switched. No additional parameters are given to 3c59x. -- i.
Re: Unexcepted latency (order of 100-200 ms) with TCP (packet receive)
On Fri, 27 Apr 2007, Bill Fink wrote: On Thu, 26 Apr 2007, Ilpo Järvinen wrote: On Thu, 26 Apr 2007, Chuck Ebbert wrote: Ilpo Järvinen wrote: ...I'm unsure how to continue the investigation from this point onward and asking for ideas/suggestions or how to rule out more possibilities... Or is there some knob which I don't know of that should be toggled or something, is 2.6 network stack expected to behave this way? Try a different network adapter. Hmm, I thought I had already done this but I just noticed that it is so that the adapter was still the same as the other host has two adapter (now that I look again). I'll give it a try tomorrow to see if using the another adapter makes any difference. ...Much more promising result this time. I noticed that there was another eth hw on mainboard, thus my previous test with different hw was not valid as I assumed wrong (didn't even notice the other) one to be eth0: 02:05.0 Ethernet controller: 3Com Corporation 3c905C-TX/TX-M [Tornado] (rev 74) 02:08.0 Ethernet controller: Intel Corporation 82801DB PRO/100 VE (LOM) Ethernet Controller (rev 82) With 3c905 I have the problem, with Intel one it does not show up (tested today). Try turning off hardware TSO offload: ethtool -K ethX tso off # ethtool -K eth0 tso off Cannot set device tcp segmentation offload settings: Operation not supported Could the delays be caused by Ethernet PAUSE frames (which might not be rquired at the slower 10FD but might at 100)? TX and RX pause control settings (check with ethtool -a) might be different between the 2.4 and 2.6 kernels. # ethtool -a eth0 Pause parameters for eth0: Cannot get device pause settings: Operation not supported Also check things like net.core.netdev_max_backlog and ifconfig txqueuelen settings. # cat /proc/sys/net/core/netdev_max_backlog 1000 ...and... txqueuelen:1000 And check ethtool -S, netstat -s, and ifconfig error counters. Nothigh really alarming was found, errors were all zero, only thing that could be even remotely interesting is this: 5 delayed acks further delayed because of locked socket -- i.
Unexcepted latency (order of 100-200 ms) with TCP (packet receive)
Hi, I've been trying to figure out unexcepted delay spikes that seem to occur for TCP flows with 2.6 (tested 2.6.18.8 + a punch of own modifications and also with 2.6.20.7 with a single additional changeset only that enables me to TCP's control initial window at will). I'll first describe the problem and then give a more complete description of the workload on the host. Less than year ago, my test network kernels where upgraded from 2.4.22 to 2.6.18. With 2.4.22 I was able to achieve very good timings in transfers between components. Some time ago I noticed that with 2.6.18 I occassionally get latency spikes as long as 100-200ms in the TCP transfers between components (I describe later how TCP was tuned during these tests to avoid problems that occur with small segments). I started to investigate the spikes, and here are the findings so far: - Problem is very well reproducable with the workload but I haven't been able to come up with simple client + server to cause the same with it. - Downgrading the emulator host to 2.4.22 removes the problem - Moving the emulator to another host in the network does not remove the problem. It had different ethernet hw (and not the same driver). - I placed a hub to get exact timings on the wire without potential interference from tcpdump on the emulator host (test done with 2.6.18) but to my great surprise, the problem vanished completely - Due to the hub test result, I tested 10/100/duplex settings and found out that if the emulator host has 10fd, the problem does not occur with 2.6 either?!? This could be due to luck but I cannot say for sure, yet the couple of tests I've run with 10fd, did not show this... - Tried to change cable switch that connect hosts together, no effect To prove this with 100Mbps, I setup routing so that with a host with 10/FD configuration (known, based on earlier, to be unlikely to cause errors) I collected all traffic between the emulator host and one of the packet capture hosts. Here is one example point where a long delay occurs (EMU is the emulator host, in the real log each packet is shown twice, I only leave the later one here): 1177577267.364596 IP CAP.35305 EMU.52246: . 17231434:17232894(1460) ack 383357 win 16293 1177577267.364688 IP CAP.35305 EMU.52246: P 17232894:17232946(52) ack 383357 win 16293 1177577267.366093 IP EMU.52246 CAP.35305: . ack 17232894 win 32718 1177577267.493815 IP EMU.52246 CAP.35305: P 383357:383379(22) ack 17232894 win 32718 1177577267.534252 IP CAP.35305 EMU.52246: . ack 383379 win 16293 1177577267.534517 IP EMU.59050 CAP.58452: P 624496:624528(32) ack 328 win 365 1177577267.534730 IP CAP.58452 EMU.59050: . ack 624528 win 16293 1177577267.536267 IP CAP.35305 EMU.52246: . 17232946:17234406(1460) ack 383379 win 16293 1177577267.536360 IP CAP.35305 EMU.52246: P 17234406:17234458(52) ack 383379 win 16293 1177577267.537764 IP EMU.52246 CAP.35305: . ack 17234406 win 32718 In the receiving emulator process I have, at the same time, this debug output (select calls while in busywait are not printed to avoid performance and huge log problems): To select 1177577267.362959 timeout: 0.011148 trackfd: 4 (in set) Out select 1177577267.365923 trackfd: 4 (in set) Read at 1177577267.365936 fromfd: 4 (had 0, tried 2048, got more 1460), while in busywait: 0 To select 1177577267.365949 timeout: 0.008158 trackfd: 4 (in set) Out select 1177577267.377752 trackfd: 4 (not in set) 567.177960: DL: delayed: [...emulation event...] To select 1177577267.394121 timeout: 0.079489 trackfd: 4 (in set) Out select 1177577267.473751 trackfd: 4 (not in set) 567.277465: UL: delayed: [...emulation event...] 567.277494: UL: sent : [...emulation event...] 567.297236: DL: delayed: [...emulation event...] To select 1177577267.513401 timeout: 0.014452 trackfd: 4 (in set) Out select 1177577267.513406 trackfd: 4 (not in set) 567.297268: DL: sent : [...emulation event...] To select 1177577267.513431 timeout: 0.014422 trackfd: 4 (in set) Out select 1177577267.529751 trackfd: 4 (not in set) Read at 1177577267.534294 fromfd: 4 (had 0, tried 2048, got more 52), while in busywait: 1 567.318147: DL: pktinfo: [...full 1460+52 bytes finally received...] The first part of the 1460+52 bytes is received by the emulator process at 1177577267.365936 while the 52 bytes is enourmously delayed and arrives at 1177577267.534294 (=168ms later!?!). During this time the emulator process is able to sleep in select 11.8 + 79.6 + 16.3 ms + does tons of calls to select during busy-wait with timeout being set to zero (not shown) and the packet just does not arrive?!? Also the tcpdump above shows the delay, the ack field at 1177577267.493815 does not yet show the latest segment though it already had more than 120 ms to reach TCP, that should be plenty of time, shouldn't it? :-) I've tried once to run tcpdump on the emulator host too and the delay was also in there (tcpdump shows the
Re: Unexcepted latency (order of 100-200 ms) with TCP (packet receive)
Ilpo Järvinen wrote: ...I'm unsure how to continue the investigation from this point onward and asking for ideas/suggestions or how to rule out more possibilities... Or is there some knob which I don't know of that should be toggled or something, is 2.6 network stack expected to behave this way? Try a different network adapter. Try turning off hardware TSO offload: ethtool -K ethX tso off - To unsubscribe from this list: send the line unsubscribe netdev in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: Unexcepted latency (order of 100-200 ms) with TCP (packet receive)
Ilpo Järvinen wrote: Hi, ... Some time ago I noticed that with 2.6.18 I occassionally get latency spikes as long as 100-200ms in the TCP transfers between components (I describe later how TCP was tuned during these tests to avoid problems that occur with small segments). I started to investigate the spikes, and here are the findings so far: ... - I placed a hub to get exact timings on the wire without potential interference from tcpdump on the emulator host (test done with 2.6.18) but to my great surprise, the problem vanished completely Sounds like tcpdump getting in the way? How many CPUs do you have in the system, and have you tried some explicit binding of processes to different CPUs? (taskset etc...) When running tcpdump are you simply sending raw traces to a file, or are you having the ASCII redirected to a file? What about name resolution (ie areyou using -n)? - Due to the hub test result, I tested 10/100/duplex settings and found out that if the emulator host has 10fd, the problem does not occur with 2.6 either?!? This could be due to luck but I cannot say for sure, yet the couple of tests I've run with 10fd, did not show this... - Tried to change cable switch that connect hosts together, no effect To prove this with 100Mbps, I setup routing so that with a host with 10/FD configuration (known, based on earlier, to be unlikely to cause errors) I collected all traffic between the emulator host and one of the packet capture hosts. Here is one example point where a long delay occurs (EMU is the emulator host, in the real log each packet is shown twice, I only leave the later one here): 1177577267.364596 IP CAP.35305 EMU.52246: . 17231434:17232894(1460) ack 383357 win 16293 1177577267.364688 IP CAP.35305 EMU.52246: P 17232894:17232946(52) ack 383357 win 16293 1177577267.366093 IP EMU.52246 CAP.35305: . ack 17232894 win 32718 1177577267.493815 IP EMU.52246 CAP.35305: P 383357:383379(22) ack 17232894 win 32718 1177577267.534252 IP CAP.35305 EMU.52246: . ack 383379 win 16293 What is the length of the standalone ACK timer these days? 1177577267.534517 IP EMU.59050 CAP.58452: P 624496:624528(32) ack 328 win 365 1177577267.534730 IP CAP.58452 EMU.59050: . ack 624528 win 16293 1177577267.536267 IP CAP.35305 EMU.52246: . 17232946:17234406(1460) ack 383379 win 16293 1177577267.536360 IP CAP.35305 EMU.52246: P 17234406:17234458(52) ack 383379 win 16293 1177577267.537764 IP EMU.52246 CAP.35305: . ack 17234406 win 32718 ... All things use TCP_NODELAY. The network is isolated so that no other traffic can cause unexcepted effects. The emulator does collect log only to a mem buffer that is flushed through TCP only between tests (and thus does not cause timing problems). Might tcp_abc have crept back-in? rick jones - To unsubscribe from this list: send the line unsubscribe netdev in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: Unexcepted latency (order of 100-200 ms) with TCP (packet receive)
On Thu, 26 Apr 2007, Rick Jones wrote: Ilpo Järvinen wrote: ... Some time ago I noticed that with 2.6.18 I occassionally get latency spikes as long as 100-200ms in the TCP transfers between components (I describe later how TCP was tuned during these tests to avoid problems that occur with small segments). I started to investigate the spikes, and here are the findings so far: ... - I placed a hub to get exact timings on the wire without potential interference from tcpdump on the emulator host (test done with 2.6.18) but to my great surprise, the problem vanished completely Sounds like tcpdump getting in the way? No, tcpdump is not running on the host in question at all (that is what I'm trying to say but my English might betray me). I just describe there that I made a testing configuration when (after) I noticed that this 100-200ms problem exists without any tcpdumps. With hub, the network was configured like this (I tried to avoid additional linux sender): packet capture host --- switch --- hub --- emulation host | | \ / host with tcpdump (for the record: due to the emulator nature, the sender in this case is called packet capture host even though I don't mean that I capture these tcpdumps at it.) Sadle enough, the problem disappeared with it (as the hub caused eth to become 10mbps network...). Because of that, the tcpdump I'm showing below is captured with this route though another host configuration (additional sender is there which I tried to completely avoid by using the above hub setup): host with tcpdump, ip_forward = 1 (10Mbps eth on purpose) / \ | | | | \ / packet capture host switch - emulation host ...the reason being that tcpdump on the emulation host could get into the way like you're saying. I run it once there too, and it saw the packet delayed by the 100-130ms which probably is valid occurance of this same problem (too large to be due to scheduling or so, IMHO) that occurs without either of the tcpdump configs presented here, when traffic just goes directly from packet capture host through the switch to emulation host. How many CPUs do you have in the system, and have you tried some explicit binding of processes to different CPUs? (taskset etc...) One p4. What processes do you mean, I've carefully disabled most of the services (please read the explination in the end of the original mail), and the s/utimes of the remaining (from proc/pid/stat) processes on the emulation host do not increase during the test... Is it still possible that they could have been scheduled but did not get s/utime incremented, I'm not qualified to say that but perhaps you or somebody else knows if it's so? Besides, I've the very same configuration (no problem = without tcpdump) working perfectly with 2.4 and also with 2.6 when the emulation host eth is set to 10Mbps instead of 100Mbps using ethtool. Could 2.6 with 100Mbps eth really cause 100ms latency spikes, especially, considering that my emulated wireless link is just 384kbps, so the amount of data that is going past ain't much larger than that... When running tcpdump are you simply sending raw traces to a file, or are you having the ASCII redirected to a file? What about name resolution (ie areyou using -n)? I used this command: tcpdump -i eth0 -w tracefile host 192.168.1.3 or host 192.168.1.2 All hosts in the network should be in /etc/hosts, but I can try with -n tomorrow but I doubt that it will make any difference because the problem is there regardless of the tcpdump. The very reason of the tcpdump being there is I just to debug the problem between the emulation host and the sender to see whether the problem is in the sender end or in the receiving end. To prove this with 100Mbps, I setup routing so that with a host with 10/FD configuration (known, based on earlier, to be unlikely to cause errors) I collected all traffic between the emulator host and one of the packet capture hosts. Here is one example point where a long delay occurs (EMU is the emulator host, in the real log each packet is shown twice, I only leave the later one here): 1177577267.364596 IP CAP.35305 EMU.52246: . 17231434:17232894(1460) ack 383357 win 16293 1177577267.364688 IP CAP.35305 EMU.52246: P 17232894:17232946(52) ack 383357 win 16293 1177577267.366093 IP EMU.52246 CAP.35305: . ack 17232894 win 32718 1177577267.493815 IP EMU.52246 CAP.35305: P 383357:383379(22) ack 17232894 win 32718 At this point the segment with seq 17232946 hasn't yet reached TCP (to be more precise, when this was sent) because cumulatively acks only to 17232894! That's 129 ms later than the segment with seq 17232946 was
Re: Unexcepted latency (order of 100-200 ms) with TCP (packet receive)
On Thu, 26 Apr 2007, Chuck Ebbert wrote: Ilpo Järvinen wrote: ...I'm unsure how to continue the investigation from this point onward and asking for ideas/suggestions or how to rule out more possibilities... Or is there some knob which I don't know of that should be toggled or something, is 2.6 network stack expected to behave this way? Try a different network adapter. Hmm, I thought I had already done this but I just noticed that it is so that the adapter was still the same as the other host has two adapter (now that I look again). I'll give it a try tomorrow to see if using the another adapter makes any difference. Try turning off hardware TSO offload: ethtool -K ethX tso off # ethtool -K eth0 tso off Cannot set device tcp segmentation offload settings: Operation not supported -- i.
