TCP connection stops after high load.
Subsystems (3)
Back in May of last year, I reported this problem, but worked around it at the time by changing the kernel memory settings in the networking stack. I reproduced the problem again today with the previously working kernel memory settings..which is not supprising since I just papered over the bug last time.
The problem is that I set up a TCP connection with bi-directional traffic of around 800Mbps, doing large (20k - 64k writes and reads) between two ports on the same machine (this 2.6.18.2 kernel is tainted with my full patch set, but I also reproduced with only the non-tainted send-to-self patch applied last may on the 2.6.16 kernel, so I assume the bug is not particular to my patch set).
At first, all is well, but within 5-10 minutes, the TCP connection will stall and I only see a massive amount of duplicate ACKs on the link. Before, I sometimes saw OOM messages, but this time there are no OOM messages. The system has a two-port pro/1000 fibre NIC, 1GB RAM, kernel 2.6.18.2 + hacks, etc. Stopping and starting the connection allows traffic to flow again (if briefly). Starting a new connection works fine even if the old one is still stalled, so it's not a global memory exhaustion problem.
So, I would like to dig into this problem myself since no one else is reporting this type of problem, but I am quite ignorant of the TCP stack implementation. Based on the dup-acks I see on the wire, I assume the TCP state machine is messed up somehow. Could anyone point me to likely places in the TCP stack to start looking for this bug?
Thanks,
Ben
Signature · 2 lines
Ben Greear <[email protected]> Candela Technologies Inc http://www.candelatech.com
Quoted 5 lines · Ben Greear
Back in May of last year, I reported this problem, but worked around it at the time by changing the kernel memory settings in the networking stack. I reproduced the problem again today with the previously working kernel memory settings..which is not supprising since I just papered over the bug last time.
So, I have been poking around. Disabling tso makes the problem happen sooner (< 1 minute). Changing the tcp_congestion_control does not help.
Interestingly, I found this page mentioning a SACK problem in Linux:
http://www-didc.lbl.gov/TCP-tuning/linux.html
I tried disabling SACK, but the problem still happens. However, I do see the CWND go to 1 as soon as the connection stalls (I'm not sure exactly which happens first.) Before the stall, I see CWND reported in the ~40 range.
Maybe something similar to the SACK bug can happen on very fast, very low latency links, with large send/receive buffers configured?
Thanks,
Ben
Signature · 2 lines
Ben Greear <[email protected]> Candela Technologies Inc http://www.candelatech.com
David Miller
maintainerFrom: Ben Greear <[email protected]>
Date: Wed, 11 Apr 2007 13:26:36 -0700
Quoted 2 lines
Interestingly, I found this page mentioning a SACK problem in Linux:
http://www-didc.lbl.gov/TCP-tuning/linux.html
Don't read that page, it is the last place in the world your should take hints and advice from, most of the problems they speak of there have been fixed years ago.
Please start instrumenting the TCP code instead of "poking around" hoping you'll hit the grand jackpot by manipulating some sysctl setting.
It doesn't help us and it won't help you, start reading and understanding the TCP code, add debugging printk's, anything to get more information about this.
And please don't report anything here until you have some solid piece of debugging information, else I'll just sit here replying and prodding you along ever so slowly. :(
Quoted 9 lines · David Miller
From: Ben Greear <[email protected]>
Date: Wed, 11 Apr 2007 13:26:36 -0700Quoted 2 lines
Interestingly, I found this page mentioning a SACK problem in Linux:
http://www-didc.lbl.gov/TCP-tuning/linux.htmlDon't read that page, it is the last place in the world your should take hints and advice from, most of the problems they speak of there have been fixed years ago.
Much of their memory and buffer settings are similar to what I've seen elsewhere..and what I use, but it could be we're all getting the same info from the same faulty source. Suggestions of a proper site for tuning TCP for high speed/high latency links are welcome.
Quoted 11 lines
Please start instrumenting the TCP code instead of "poking around" hoping you'll hit the grand jackpot by manipulating some sysctl setting.
It doesn't help us and it won't help you, start reading and understanding the TCP code, add debugging printk's, anything to get more information about this.
And please don't report anything here until you have some solid piece of debugging information, else I'll just sit here replying and prodding you along ever so slowly. :(
Does the CWND == 1 count as solid? Any idea how/why this would go to 1 in conjunction with the dup acks?
For the dup acks, I see nothing *but* dup acks on the wire...going in both directions interestingly, at greater than 100,000 packets per second.
I don't mind adding printks...and I've started reading through the code, but there is a lot of it, and indiscriminate printks will likely just hide the problem because it will slow down performance so much.
Thanks,
Ben
Signature · 2 lines
Ben Greear <[email protected]> Candela Technologies Inc http://www.candelatech.com
David Miller
maintainerFrom: Ben Greear <[email protected]>
Date: Wed, 11 Apr 2007 14:06:31 -0700
Quoted 9 lines
Does the CWND == 1 count as solid? Any idea how/why this would go to 1 in conjunction with the dup acks?
For the dup acks, I see nothing *but* dup acks on the wire...going in both directions interestingly, at greater than 100,000 packets per second.
I don't mind adding printks...and I've started reading through the code, but there is a lot of it, and indiscriminate printks will likely just hide the problem because it will slow down performance so much.
If you know that it doesn't take Einstein to figure out that maybe you should add logging when CWND is one and we're sending out an ACK?
This is why I think you're very lazy Ben and I get very agitated with all of your reports, you put zero effort into thinking about how to debug the problem even though you know full well how to do it.
Quoted 13 lines · David Miller
From: Ben Greear <[email protected]>
Date: Wed, 11 Apr 2007 14:06:31 -0700Quoted 9 lines
Does the CWND == 1 count as solid? Any idea how/why this would go to 1 in conjunction with the dup acks?
For the dup acks, I see nothing *but* dup acks on the wire...going in both directions interestingly, at greater than 100,000 packets per second.
I don't mind adding printks...and I've started reading through the code, but there is a lot of it, and indiscriminate printks will likely just hide the problem because it will slow down performance so much.
Quoted 6 lines
If you know that it doesn't take Einstein to figure out that maybe you should add logging when CWND is one and we're sending out an ACK?
This is why I think you're very lazy Ben and I get very agitated with all of your reports, you put zero effort into thinking about how to debug the problem even though you know full well how to do it.
I've spent solid weeks tracking down obscure races. I'm hoping that someone who knows the tcp stack will have some idea of places to look based on the reported symptoms so that I don't have to spend another solid week chasing this one. If not, so be it..I'm still working on this between sending emails. For what it's worth, the problem (or something similar) is reproducible on a stock FC5 .18-ish kernel as well, running between two machines, 2 ports each.
Ben
Signature · 2 lines
Ben Greear <[email protected]> Candela Technologies Inc http://www.candelatech.com
David Miller
maintainerFrom: Ben Greear <[email protected]>
Date: Wed, 11 Apr 2007 14:31:00 -0700
Quoted 1 line
I've spent solid weeks tracking down obscure races.
I've spent solid weeks tracking down kernel stack corruption and scsi problems on sparc64, as well as attending to my network maintainer duties, what is your point?
Quoted 3 lines
I'm hoping that someone who knows the tcp stack will have some idea of places to look based on the reported symptoms so that I don't have to spend another solid week chasing this one.
If you can reproduce the bug and others cannot, you are the one in the best possible situation to add diagnostics and figure out what's wrong. Please do this.
You get a lot from Linux in your work, but you sure grumble a lot when you might need to give even a smidgen back. You just dump random pieces of information at this list and expect other people to just fix it for you. It's this part of your attitude that I absolutely do not like. Other people are able to report bugs in a pleasant and non-selfish way that makes me want to go and fix the bug for them proactively, you do not.
I also noticed this happening with 2.6.18 kernel version, but this was not severe with linux 2.6.20.3. So, the short-term solution will be upgrading to the latest kernel of FC-6.
A long black-out is mostly observed when a lot of packet losses happened in slow start. You can prevent this by applying a patch (limited slow start) to your slow start. Did you have same problems with cubic which employs a less aggressive slow start? I leave this debugging for some later version of kernel but you are welcome to debug this problem.
I recommend you install tcp_probe and recreate the problem. Whenever you get an ack from the receiver, the probe will print the current congestion information. Also, you can easily include some other information you want in that module. You can get some information from some statistics on /proc/net/tcp and /proc/net/netstat.
See http://netsrv.csc.ncsu.edu/wiki/index.php/Efficiency_of_SACK_processing
Thanks,
Sangtae
Quoted 40 lines · Ben Greear
Quoted 13 lines · David Miller
From: Ben Greear <[email protected]>
Date: Wed, 11 Apr 2007 14:06:31 -0700Quoted 9 lines
Does the CWND == 1 count as solid? Any idea how/why this would go to 1 in conjunction with the dup acks?
For the dup acks, I see nothing *but* dup acks on the wire...going in both directions interestingly, at greater than 100,000 packets per second.
I don't mind adding printks...and I've started reading through the code, but there is a lot of it, and indiscriminate printks will likely just hide the problem because it will slow down performance so much.
Quoted 6 lines
If you know that it doesn't take Einstein to figure out that maybe you should add logging when CWND is one and we're sending out an ACK?
This is why I think you're very lazy Ben and I get very agitated with all of your reports, you put zero effort into thinking about how to debug the problem even though you know full well how to do it.
I've spent solid weeks tracking down obscure races. I'm hoping that someone who knows the tcp stack will have some idea of places to look based on the reported symptoms so that I don't have to spend another solid week chasing this one. If not, so be it..I'm still working on this between sending emails. For what it's worth, the problem (or something similar) is reproducible on a stock FC5 .18-ish kernel as well, running between two machines, 2 ports each.
Ben
--
Ben Greear <[email protected]>
Candela Technologies Inc http://www.candelatech.com-
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
Quoted 6 lines · Ben Greear
For the dup acks, I see nothing *but* dup acks on the wire...going in both directions interestingly, at greater than 100,000 packets per second.
I don't mind adding printks...and I've started reading through the code, but there is a lot of it, and indiscriminate printks will likely just hide the problem because it will slow down performance so much.
What do the timestamps look like? PAWS contains logic which will drop packets if the timestamps are too old compared to what the receiver expects.
-ben
Signature · 2 lines
"Time is of no importance, Mr. President, only life is important." Don't Email: <[email protected]>.
Quoted 4 lines · Ben Greear
I don't mind adding printks...and I've started reading through the code, but there is a lot of it, and indiscriminate printks will likely just hide the problem because it will slow down performance so much.
You could add /proc/net/snmp counters for interesting events (e.g. GFP_ATOMIC allocations failing). Perhaps netstat -s already shows something interesting.
-Andi
Quoted 7 lines · Andi Kleen
Quoted 3 lines · Ben Greear
I don't mind adding printks...and I've started reading through the code, but there is a lot of it, and indiscriminate printks will likely just hide the problem because it will slow down performance so much.
You could add
/proc/net/snmpcounters for interesting events (e.g.GFP_ATOMICallocations failing). Perhaps netstat -s already shows something interesting.
I will look for more interesting events to add counters for, thanks for the suggestion. Thanks for the rest of the suggestions and patches from others as well, I will be trying those out today and will let you know how it goes. I can also try this on the 2.6.20 kernel.
This is on the machine connected to itself. This is by far the easiest
way to reproduce the problem. This is from the stalled state. About 3-5 minutes later (I wasn't watching too closely), the connection briefly started up again and then stalled again. While it is stalled and sending ACKs, the netstat -an counters remain the same. It appears this run/stall behaviour happens repeatedly, as the over-all bits-per-second average overnight was around 90Mbps, and it runs at ~800Mbps when running full speed.
from netstat -an:
tcp 0 759744 20.20.20.30:33012 20.20.20.20:33011 ESTABLISHED tcp 0 722984 20.20.20.20:33011 20.20.20.30:33012 ESTABLISHED
I'm not sure if netstat -s shows interesting things or not...it does show a very large number of packets in and out. I ran it twice..about 5 seconds apart. I pasted some values from the second run on the right-hand side where the numbers looked interesting. This info is at the bottom of this email.
For GFP_ATOMIC allocations failing, doesn't that show up as order X allocation failure messages in the kernel (I see no messages of this type.)?
Here is a tcpdump of the connection in the stalled state. As you can see by the 'time' output, it's running at around 100,000 packets per second. tcpdump dropped the vast majority of these. Based on the network interface stats, I believe both sides of the connection are sending acks at about the same rate (about 160kpps when tcpdump is not running it seems).
10:46:46.541490 IP 20.20.20.20.33011 > 20.20.20.30.33012: . ack 48 win 6132 <nop,nop,timestamp 85158912 84963208> 10:46:46.541494 IP 20.20.20.30.33012 > 20.20.20.20.33011: . ack 1 win 114 <nop,nop,timestamp 85158912 84963208> 10:46:46.541567 IP 20.20.20.30.33012 > 20.20.20.20.33011: . ack 1 win 114 <nop,nop,timestamp 85158912 84963208> 10:46:46.541653 IP 20.20.20.30.33012 > 20.20.20.20.33011: . ack 1 win 114 <nop,nop,timestamp 85158912 84963208> 10:46:46.541886 IP 20.20.20.30.33012 > 20.20.20.20.33011: . ack 1 win 114 <nop,nop,timestamp 85158912 84963208> 10:46:46.541891 IP 20.20.20.20.33011 > 20.20.20.30.33012: . ack 48 win 6132 <nop,nop,timestamp 85158912 84963208> 10:46:46.541895 IP 20.20.20.30.33012 > 20.20.20.20.33011: . ack 1 win 114 <nop,nop,timestamp 85158912 84963208> 10:46:46.541988 IP 20.20.20.30.33012 > 20.20.20.20.33011: . ack 1 win 114 <nop,nop,timestamp 85158912 84963208> 10:46:46.542077 IP 20.20.20.30.33012 > 20.20.20.20.33011: . ack 1 win 114 <nop,nop,timestamp 85158912 84963208> 10:46:46.542307 IP 20.20.20.30.33012 > 20.20.20.20.33011: . ack 1 win 114 <nop,nop,timestamp 85158913 84963208> 10:46:46.542312 IP 20.20.20.20.33011 > 20.20.20.30.33012: . ack 48 win 6132 <nop,nop,timestamp 85158913 84963208> 10:46:46.542321 IP 20.20.20.20.33011 > 20.20.20.30.33012: . ack 48 win 6132 <nop,nop,timestamp 85158913 84963208> 10:46:46.542410 IP 20.20.20.30.33012 > 20.20.20.20.33011: . ack 1 win 114 <nop,nop,timestamp 85158913 84963208> 10:46:46.542494 IP 20.20.20.30.33012 > 20.20.20.20.33011: . ack 1 win 114 <nop,nop,timestamp 85158913 84963208> 10:46:46.542708 IP 20.20.20.30.33012 > 20.20.20.20.33011: . ack 1 win 114 <nop,nop,timestamp 85158913 84963208> 10:46:46.542718 IP 20.20.20.30.33012 > 20.20.20.20.33011: . ack 1 win 114 <nop,nop,timestamp 85158913 84963208> 10:46:46.542735 IP 20.20.20.30.33012 > 20.20.20.20.33011: . ack 1 win 114 <nop,nop,timestamp 85158913 84963208> 10:46:46.542818 IP 20.20.20.30.33012 > 20.20.20.20.33011: . ack 1 win 114 <nop,nop,timestamp 85158913 84963208> 10:46:46.542899 IP 20.20.20.20.33011 > 20.20.20.30.33012: . ack 48 win 6132 <nop,nop,timestamp 85158913 84963208>
4214 packets captured
253889 packets received by filter
244719 packets dropped by kernel
real 0m2.640s user 0m0.067s sys 0m0.079s
Two netstat -s outputs....about 5 seconds apart.
[root@lf1001-240 ipv4]# netstat -s
Ip:
2823452436 total packets received 2840939253 total packets received
1 with invalid addresses
0 forwarded
0 incoming packets discarded
2823452435 incoming packets delivered 2840939252 incoming packets delivered
1549687963 requests sent out 1565951477 requests sent outIcmp:
0 ICMP messages received
0 input ICMP message failed.
ICMP input histogram:
0 ICMP messages sent
0 ICMP messages failed
ICMP output histogram:
Tcp:
77 active connections openings
74 passive connection openings
0 failed connection attempts
122 connection resets received
10 connections established
2823426197 segments received 2840914122 segments received
1549683727 segments send out 1565948373 segments send out
2171 segments retransmited 2187 segments retransmited
0 bad segments received.
2203 resets sent
Udp:
21739 packets received
0 packets to unknown port received.
0 packet receive errors
4236 packets sent
TcpExt:
1164 invalid SYN cookies received
31323 packets pruned from receive queue because of socket buffer overrun 31337
4 TCP sockets finished time wait in fast timer
8 packets rejects in established connections because of timestamp
91542 delayed acks sent 91645
1902 delayed acks further delayed because of locked socket Quick ack mode was activated 2201 times
2 packets directly queued to recvmsg prequeue.
1323185164 packets header predicted 1324477473
63077636 acknowledgments not containing data received 63141338
17021279 predicted acknowledgments 17043867
2035 times recovered from packet loss due to fast retransmit 8 times recovered from packet loss due to SACK data Detected reordering 13 times using reno fast retransmit Detected reordering 642 times using time stamp
1971 congestion windows fully recovered
16017 congestion windows partially recovered using Hoe heuristic 19 congestion windows recovered after partial ack
0 TCP data loss events
1 timeouts in loss state
225 fast retransmits
3 forward retransmits
151 other TCP timeouts
TCPRenoRecoveryFail: 1
11658529 packets collapsed in receive queue due to low socket buffer 11664170
123 DSACKs sent for old packets
70 DSACKs received
132 connections aborted due to timeout
[root@lf1001-240 ipv4]# netstat -s
Ip:
2840939253 total packets received
1 with invalid addresses
0 forwarded
0 incoming packets discarded
2840939252 incoming packets delivered
1565951477 requests sent outIcmp:
0 ICMP messages received
0 input ICMP message failed.
ICMP input histogram:
0 ICMP messages sent
0 ICMP messages failed
ICMP output histogram:
Tcp:
77 active connections openings
74 passive connection openings
0 failed connection attempts
122 connection resets received
10 connections established
2840914122 segments received
1565948373 segments send out
2187 segments retransmited
0 bad segments received.
2203 resets sent
Udp:
21755 packets received
0 packets to unknown port received.
0 packet receive errors
4239 packets sent
TcpExt:
1164 invalid SYN cookies received
31337 packets pruned from receive queue because of socket buffer overrun 4 TCP sockets finished time wait in fast timer
8 packets rejects in established connections because of timestamp 91645 delayed acks sent
1912 delayed acks further delayed because of locked socket Quick ack mode was activated 2217 times
2 packets directly queued to recvmsg prequeue.
1324477473 packets header predicted
63141338 acknowledgments not containing data received 17043867 predicted acknowledgments
2037 times recovered from packet loss due to fast retransmit 8 times recovered from packet loss due to SACK data
Detected reordering 13 times using reno fast retransmit Detected reordering 642 times using time stamp
1973 congestion windows fully recovered
16021 congestion windows partially recovered using Hoe heuristic 19 congestion windows recovered after partial ack
0 TCP data loss events
1 timeouts in loss state
225 fast retransmits
3 forward retransmits
153 other TCP timeouts
TCPRenoRecoveryFail: 1
11664170 packets collapsed in receive queue due to low socket buffer 123 DSACKs sent for old packets
70 DSACKs received
132 connections aborted due to timeout
Quoted 6 lines
(quoted diff) +0
-2-Andi -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
Signature · 2 lines
Ben Greear <[email protected]> Candela Technologies Inc http://www.candelatech.com
Quoted 6 lines · On Thu, 12 Apr 2007 10:59:19 -0700 Ben Greear <[email protected]> wrote:
Here is a tcpdump of the connection in the stalled state. As you can see by the 'time' output, it's running at around 100,000 packets per second. tcpdump dropped the vast majority of these. Based on the network interface stats, I believe both sides of the connection are sending acks at about the same rate (about 160kpps when tcpdump is not running it seems).
Warning : tcpdump can lie, telling you packets being transmited several time.
And yes, tcpdump slow things down because of enabling accurate timestamping of packets.
Quoted 11 lines
10:46:46.541490 IP 20.20.20.20.33011 > 20.20.20.30.33012: . ack 48 win 6132 <nop,nop,timestamp 85158912 84963208> 10:46:46.541494 IP 20.20.20.30.33012 > 20.20.20.20.33011: . ack 1 win 114 <nop,nop,timestamp 85158912 84963208> 10:46:46.541567 IP 20.20.20.30.33012 > 20.20.20.20.33011: . ack 1 win 114 <nop,nop,timestamp 85158912 84963208> 10:46:46.541653 IP 20.20.20.30.33012 > 20.20.20.20.33011: . ack 1 win 114 <nop,nop,timestamp 85158912 84963208> 10:46:46.541886 IP 20.20.20.30.33012 > 20.20.20.20.33011: . ack 1 win 114 <nop,nop,timestamp 85158912 84963208> 10:46:46.541891 IP 20.20.20.20.33011 > 20.20.20.30.33012: . ack 48 win 6132 <nop,nop,timestamp 85158912 84963208> 10:46:46.541895 IP 20.20.20.30.33012 > 20.20.20.20.33011: . ack 1 win 114 <nop,nop,timestamp 85158912 84963208> 10:46:46.541988 IP 20.20.20.30.33012 > 20.20.20.20.33011: . ack 1 win 114 <nop,nop,timestamp 85158912 84963208>
What
"tc -s -d qdisc"
"ifconfig -a"
"cat /proc/interrupts"
"cat /proc/net/sockstat" and
"cat /proc/net/softnet_stat" are telling ?
Quoted 4 lines · Eric Dumazet
What "tc -s -d qdisc"
"ifconfig -a"
"cat/proc/interrupts" "cat/proc/net/sockstat" and "cat/proc/net/softnet_stat" are telling ?
In this test, eth2 is talking to eth3, using something similar to this send-to-self patch:
http://www.candelatech.com/oss/sts.patch
[root@lf1001-240 ipv4]# ifconfig -a
eth0 Link encap:Ethernet HWaddr 00:30:48:89:74:60
inet addr:192.168.100.187 Bcast:192.168.100.255 Mask:255.255.255.0
UP BROADCAST RUNNING MULTICAST MTU:1500 Metric:1
RX packets:1672220 errors:0 dropped:0 overruns:0 frame:0
TX packets:1560305 errors:0 dropped:0 overruns:0 carrier:0
collisions:0 txqueuelen:1000
RX bytes:151896589 (144.8 MiB) TX bytes:1375280163 (1.2 GiB)
Interrupt:17eth1 Link encap:Ethernet HWaddr 00:30:48:89:74:61
UP BROADCAST MULTICAST MTU:1500 Metric:1 RX packets:0 errors:0 dropped:0 overruns:0 frame:0 TX packets:0 errors:0 dropped:0 overruns:0 carrier:0 collisions:0 txqueuelen:1000
RX bytes:0 (0.0 b) TX bytes:0 (0.0 b) Interrupt:18
eth2 Link encap:Ethernet HWaddr 00:07:E9:1F:CE:02
inet addr:20.20.20.20 Bcast:20.20.20.255 Mask:255.255.255.0
UP BROADCAST RUNNING MULTICAST MTU:1500 Metric:1
RX packets:2175144684 errors:0 dropped:2 overruns:0 frame:0
TX packets:2196560123 errors:0 dropped:0 overruns:0 carrier:0
collisions:0 txqueuelen:1000
RX bytes:1321380186 (1.2 GiB) TX bytes:2274982574 (2.1 GiB)
Base address:0xd000 Memory:d0000000-d0020000eth3 Link encap:Ethernet HWaddr 00:07:E9:1F:CE:03
inet addr:20.20.20.30 Bcast:20.20.20.255 Mask:255.255.255.0
UP BROADCAST RUNNING MULTICAST MTU:1500 Metric:1
RX packets:2196315966 errors:0 dropped:0 overruns:0 frame:0
TX packets:2174900538 errors:0 dropped:0 overruns:0 carrier:0
collisions:0 txqueuelen:1000
RX bytes:2257901986 (2.1 GiB) TX bytes:1304493504 (1.2 GiB)
Base address:0xd100 Memory:d0020000-d0040000lo Link encap:Local Loopback
inet addr:127.0.0.1 Mask:255.0.0.0
UP LOOPBACK RUNNING MTU:16436 Metric:1
RX packets:1159378 errors:0 dropped:0 overruns:0 frame:0
TX packets:1159378 errors:0 dropped:0 overruns:0 carrier:0
collisions:0 txqueuelen:0
RX bytes:1133646590 (1.0 GiB) TX bytes:1133646590 (1.0 GiB)[root@lf1001-240 ipv4]# tc -s -d qdisc
qdisc pfifo_fast 0: dev eth0 bands 3 priomap 1 2 2 2 1 2 0 0 1 1 1 1 1 1 1 1
Sent 1367521025 bytes 1324808 pkt (dropped 0, overlimits 0 requeues 0) rate 0bit 0pps backlog 0b 0p requeues 0
qdisc pfifo_fast 0: dev eth1 bands 3 priomap 1 2 2 2 1 2 0 0 1 1 1 1 1 1 1 1
Sent 0 bytes 0 pkt (dropped 0, overlimits 0 requeues 0)
rate 0bit 0pps backlog 0b 0p requeues 0
qdisc pfifo_fast 0: dev eth2 bands 3 priomap 1 2 2 2 1 2 0 0 1 1 1 1 1 1 1 1
Sent 1815657070136 bytes 1536674488 pkt (dropped 0, overlimits 0 requeues 1448094) rate 0bit 0pps backlog 0b 0p requeues 1448094
qdisc pfifo_fast 0: dev eth3 bands 3 priomap 1 2 2 2 1 2 0 0 1 1 1 1 1 1 1 1
Sent 1752033393324 bytes 1536906566 pkt (dropped 0, overlimits 0 requeues 1063672) rate 0bit 0pps backlog 0b 0p requeues 1063672
[root@lf1001-240 ipv4]# cat /proc/interrupts
CPU0 CPU1
0: 46020594 44501954 IO-APIC-edge timer 1: 9 0 IO-APIC-edge i8042 7: 0 0 IO-APIC-edge parport0 8: 1 0 IO-APIC-edge rtc 9: 0 0 IO-APIC-level acpi 12: 96 0 IO-APIC-edge i8042 14: 394023 407282 IO-APIC-edge ide0 16: 0 0 IO-APIC-level uhci_hcd:usb4 17: 1134346 1034006 IO-APIC-level uhci_hcd:usb3, eth0 18: 81605 83739 IO-APIC-level libata, uhci_hcd:usb2, eth1 19: 0 0 IO-APIC-level uhci_hcd:usb1, ehci_hcd:usb5 20: 53056128 46598235 IO-APIC-level eth2 21: 47534577 52189674 IO-APIC-level eth3 NMI: 0 0 LOC: 90485383 90485382 ERR: 0 MIS: 0
[root@lf1001-240 ipv4]# cat /proc/net/sockstat
sockets: used 334
TCP: inuse 27 orphan 0 tw 0 alloc 27 mem 360
UDP: inuse 12
RAW: inuse 0
FRAG: inuse 0 memory 0
[root@lf1001-240 ipv4]# cat /proc/net/softnet_statd58236f1 00000000 023badc3 00000000 00000000 00000000 00000000 00000000 0004ef01 3a4354a1 00000000 01b57b4b 00000000 00000000 00000000 00000000 00000000 0005445f
Thanks,
Ben
Quoted 5 lines
-
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
Signature · 2 lines
Ben Greear <[email protected]> Candela Technologies Inc http://www.candelatech.com
Quoted 101 lines · Ben Greear
Quoted 4 lines · Eric Dumazet
What "tc -s -d qdisc"
"ifconfig -a"
"cat/proc/interrupts" "cat/proc/net/sockstat" and "cat/proc/net/softnet_stat" are telling ?In this test, eth2 is talking to eth3, using something similar to this send-to-self patch:
http://www.candelatech.com/oss/sts.patch[root@lf1001-240 ipv4]# ifconfig -a
eth0 Link encap:Ethernet HWaddr 00:30:48:89:74:60inet addr:192.168.100.187 Bcast:192.168.100.255 Mask:255.255.255.0 UP BROADCAST RUNNING MULTICAST MTU:1500 Metric:1 RX packets:1672220 errors:0 dropped:0 overruns:0 frame:0 TX packets:1560305 errors:0 dropped:0 overruns:0 carrier:0 collisions:0 txqueuelen:1000 RX bytes:151896589 (144.8 MiB) TX bytes:1375280163 (1.2 GiB) Interrupt:17eth1 Link encap:Ethernet HWaddr 00:30:48:89:74:61
UP BROADCAST MULTICAST MTU:1500 Metric:1 RX packets:0 errors:0 dropped:0 overruns:0 frame:0 TX packets:0 errors:0 dropped:0 overruns:0 carrier:0 collisions:0 txqueuelen:1000
RX bytes:0 (0.0 b) TX bytes:0 (0.0 b) Interrupt:18eth2 Link encap:Ethernet HWaddr 00:07:E9:1F:CE:02
inet addr:20.20.20.20 Bcast:20.20.20.255 Mask:255.255.255.0 UP BROADCAST RUNNING MULTICAST MTU:1500 Metric:1 RX packets:2175144684 errors:0 dropped:2 overruns:0 frame:0 TX packets:2196560123 errors:0 dropped:0 overruns:0 carrier:0 collisions:0 txqueuelen:1000 RX bytes:1321380186 (1.2 GiB) TX bytes:2274982574 (2.1 GiB) Base address:0xd000 Memory:d0000000-d0020000eth3 Link encap:Ethernet HWaddr 00:07:E9:1F:CE:03
inet addr:20.20.20.30 Bcast:20.20.20.255 Mask:255.255.255.0 UP BROADCAST RUNNING MULTICAST MTU:1500 Metric:1 RX packets:2196315966 errors:0 dropped:0 overruns:0 frame:0 TX packets:2174900538 errors:0 dropped:0 overruns:0 carrier:0 collisions:0 txqueuelen:1000 RX bytes:2257901986 (2.1 GiB) TX bytes:1304493504 (1.2 GiB) Base address:0xd100 Memory:d0020000-d0040000lo Link encap:Local Loopback
inet addr:127.0.0.1 Mask:255.0.0.0 UP LOOPBACK RUNNING MTU:16436 Metric:1 RX packets:1159378 errors:0 dropped:0 overruns:0 frame:0 TX packets:1159378 errors:0 dropped:0 overruns:0 carrier:0 collisions:0 txqueuelen:0 RX bytes:1133646590 (1.0 GiB) TX bytes:1133646590 (1.0 GiB)[root@lf1001-240 ipv4]# tc -s -d qdisc
qdiscpfifo_fast0: dev eth0 bands 3 priomap 1 2 2 2 1 2 0 0 1 1 1 1 1 1 1 1
Sent 1367521025 bytes 1324808 pkt (dropped 0, overlimits 0 requeues 0) rate 0bit 0pps backlog 0b 0p requeues 0
qdiscpfifo_fast0: dev eth1 bands 3 priomap 1 2 2 2 1 2 0 0 1 1 1 1 1 1 1 1
Sent 0 bytes 0 pkt (dropped 0, overlimits 0 requeues 0)
rate 0bit 0pps backlog 0b 0p requeues 0
qdiscpfifo_fast0: dev eth2 bands 3 priomap 1 2 2 2 1 2 0 0 1 1 1 1 1 1 1 1
Sent 1815657070136 bytes 1536674488 pkt (dropped 0, overlimits 0
requeues 1448094)
rate 0bit 0pps backlog 0b 0p requeues 1448094
qdiscpfifo_fast0: dev eth3 bands 3 priomap 1 2 2 2 1 2 0 0 1 1 1 1 1 1 1 1
Sent 1752033393324 bytes 1536906566 pkt (dropped 0, overlimits 0
requeues 1063672)
rate 0bit 0pps backlog 0b 0p requeues 1063672[root@lf1001-240 ipv4]# cat
/proc/interrupts
CPU0 CPU10: 46020594 44501954 IO-APIC-edge timer 1: 9 0 IO-APIC-edge i8042 7: 0 0 IO-APIC-edge parport0 8: 1 0 IO-APIC-edge rtc 9: 0 0 IO-APIC-level acpi 12: 96 0 IO-APIC-edge i8042 14: 394023 407282 IO-APIC-edge ide0 16: 0 0 IO-APIC-level uhci_hcd:usb4 17: 1134346 1034006 IO-APIC-level uhci_hcd:usb3, eth0 18: 81605 83739 IO-APIC-level libata, uhci_hcd:usb2, eth1 19: 0 0 IO-APIC-level uhci_hcd:usb1, ehci_hcd:usb5 20: 53056128 46598235 IO-APIC-level eth2 21: 47534577 52189674 IO-APIC-level eth3 NMI: 0 0 LOC: 90485383 90485382 ERR: 0 MIS: 0[root@lf1001-240 ipv4]# cat
/proc/net/sockstat
sockets: used 334
TCP: inuse 27 orphan 0 tw 0 alloc 27 mem 360
UDP: inuse 12
RAW: inuse 0
FRAG: inuse 0 memory 0
Quoted 4 lines
[root@lf1001-240 ipv4]# cat
/proc/net/softnet_statd58236f100000000023badc300000000 00000000 00000000 00000000 000000000004ef013a4354a10000000001b57b4b00000000 00000000 00000000 00000000 000000000005445f
Hum, could you try to bind nic irqs on separate cpus ?
eth2 -> CPU0 and eth3 -> CPU1
# echo 1 >/proc/irq/20/smp_affinity # echo 2 >/proc/irq/21/smp_affinity
Quoted 1 line · Eric Dumazet
Hum, could you try to bind nic irqs on separate cpus ?
I just started a run on 2.6.20.4, and so far (~20 minutes), it is behaving perfect..running at around 925Mbps in both directions. CWND averages about 600, bouncing from a low of 300 up to 800, but that could very well be perfectly normal. I'm quite pleased with the faster performance in this kernel as well...seems like the old one would rarely get above 800Mbps even when it was passing traffic!
I am not sure if the problem is fixed or just harder to hit, but for now it looks good.
I'm going to also try a 2.6.19 kernel and see if the problem hits there in an attempt to figure out what patch changed the behaviour.
Thanks,
Ben
Signature · 2 lines
Ben Greear <[email protected]> Candela Technologies Inc http://www.candelatech.com
Quoted 2 lines · Ben Greear
I am not sure if the problem is fixed or just harder to hit, but for now it looks good.
Wasn't default congestion control algo changed between that kernel releases?
With such small rtt like in your setup there could be some obscure bug, try to set different one and check if it still works good/bad.
Signature · 1 line
Evgeniy Polyakov
Quoted 11 lines · Evgeniy Polyakov
Quoted 3 lines · Ben Greear
I am not sure if the problem is fixed or just harder to hit, but for now it looks good.
Wasn't default congestion control algo changed between that kernel releases?
With such small rtt like in your setup there could be some obscure bug, try to set different one and check if it still works good/bad.
I had earlier tried changing between bic and reno (the only two I had compiled in that kernel), and it did not affect anything. I also realized that I had been reproducing the bug (and the traces I sent to this list earlier) on a 2.6.17.4 kernel..not 2.6.18 as I had supposed. So, it's possible that the problem was fixed between 2.6.17.4 and 2.6.18.2 as well.
I also figured out yesterday that rebooting to go to a new kernel makes it slower to reproduce, even on kernels known to have the problem. This is probably because lots of memory is available after a reboot. I am going to set up some long term tests on 2.6.18, 2.6.19 and 2.6.20 and let them cook for several days to make sure the problem is truly fixed in the later kernels.
Thanks,
Ben
Signature · 1 line
Ben Greear <[email protected]> Candela Technologies Inc http://www.candelatech.com
Quoted 10 lines · Eric Dumazet
Quoted 6 lines · On Thu, 12 Apr 2007 10:59:19 -0700 Ben Greear <[email protected]> wrote:
Here is a tcpdump of the connection in the stalled state. As you can see by the 'time' output, it's running at around 100,000 packets per second. tcpdump dropped the vast majority of these. Based on the network interface stats, I believe both sides of the connection are sending acks at about the same rate (about 160kpps when tcpdump is not running it seems).
Warning : tcpdump can lie, telling you packets being transmited several time.
Maybe you have further pointers how come that tcpdump lies about duplicated packets?
Thanks a lot,
Daniel
Quoted 13 lines
And yes, tcpdump slow things down because of enabling accurate timestamping of packets.
Quoted 10 lines
10:46:46.541490 IP 20.20.20.20.33011 > 20.20.20.30.33012: . ack 48 win 6132 <nop,nop,timestamp 85158912 84963208> 10:46:46.541494 IP 20.20.20.30.33012 > 20.20.20.20.33011: . ack 1 win 114 <nop,nop,timestamp 85158912 84963208> 10:46:46.541567 IP 20.20.20.30.33012 > 20.20.20.20.33011: . ack 1 win 114 <nop,nop,timestamp 85158912 84963208> 10:46:46.541653 IP 20.20.20.30.33012 > 20.20.20.20.33011: . ack 1 win 114 <nop,nop,timestamp 85158912 84963208> 10:46:46.541886 IP 20.20.20.30.33012 > 20.20.20.20.33011: . ack 1 win 114 <nop,nop,timestamp 85158912 84963208> 10:46:46.541891 IP 20.20.20.20.33011 > 20.20.20.30.33012: . ack 48 win 6132 <nop,nop,timestamp 85158912 84963208> 10:46:46.541895 IP 20.20.20.30.33012 > 20.20.20.20.33011: . ack 1 win 114 <nop,nop,timestamp 85158912 84963208> 10:46:46.541988 IP 20.20.20.30.33012 > 20.20.20.20.33011: . ack 1 win 114 <nop,nop,timestamp 85158912 84963208>
Quoted 8 lines · On Fri, 13 Apr 2007 18:10:12 +0200 Daniel Schaffrath…
Quoted 3 lines · Eric Dumazet
Warning : tcpdump can lie, telling you packets being transmited several time.
Maybe you have further pointers how come that tcpdump lies about duplicated packets?
dev_queue_xmit_nit() is called before attempting to send packet to device.
If device could not accept the packet (hard_start_xmit() returns an error), packet is requeued and retried later. each retry means call ev_queue_xmit_nit() again, so tcpdump/sniffers can 'see' packet transmited several times.
This is why I asked for "tc -s -d qdisc" results : to check the requeue counter (not its absolute value, but relative to number of packets sent)
See dev_hard_start_xmit() in net/core/dev.c
Quoted 5 lines · Eric Dumazet
dev_queue_xmit_nit()is called before attempting to send packet to device.If device could not accept the packet (
hard_start_xmit()returns an error), packet is requeued and retried later. each retry means callev_queue_xmit_nit()again, so tcpdump/sniffers can 'see' packet transmited several times.
This should only happen with LLTX drivers. In fact, LLTX drivers are really more trouble than they're worth. They should all be rewritten to follow the model used in tg3.
Cheers,
Signature · 4 lines
Visit Openswan at http://www.openswan.org/
Email: Herbert Xu ~{PmV>HI~} <[email protected]>
Home Page: http://gondor.apana.org.au/~herbert/
PGP Key: http://gondor.apana.org.au/~herbert/pubkey.txtDavid Miller
maintainerFrom: Herbert Xu <[email protected]>
Date: Sat, 14 Apr 2007 14:21:44 +1000
Quoted 10 lines
Quoted 5 lines · Eric Dumazet
dev_queue_xmit_nit()is called before attempting to send packet to device.If device could not accept the packet (
hard_start_xmit()returns an error), packet is requeued and retried later. each retry means callev_queue_xmit_nit()again, so tcpdump/sniffers can 'see' packet transmited several times.This should only happen with LLTX drivers. In fact, LLTX drivers are really more trouble than they're worth. They should all be rewritten to follow the model used in tg3.
Agreed.
Quoted 9 lines · Herbert Xu
Quoted 4 lines · Eric Dumazet
dev_queue_xmit_nit()is called before attempting to send packet to device.If device could not accept the packet (
hard_start_xmit()returns an error), packet is requeued and retried later. each retry means callev_queue_xmit_nit()again, so tcpdump/sniffers can 'see' packet transmited several times.This should only happen with LLTX drivers. In fact, LLTX drivers are really more trouble than they're worth. They should all be rewritten to follow the model used in tg3.
When did tg3 model changed exactly ?
Because I remember having this 'problem' with tg3 devices not a long time ago...
David Miller
maintainerFrom: Eric Dumazet <[email protected]>
Date: Sat, 14 Apr 2007 07:31:35 +0200
Quoted 1 line
When did tg3 model changed exactly ?
June of 2006:
commit 00b7050426da8e7e58c889c5c80a19920d2d41b3
Author: Michael Chan <[email protected]> Date: Sat Jun 17 21:58:45 2006 -0700
[TG3]: Convert to non-LLTX
Herbert Xu pointed out that it is unsafe to call netif_tx_disable() from LLTX drivers because it uses dev->xmit_lock to synchronize whereas LLTX drivers use private locks.
Convert tg3 to non-LLTX to fix this issue. tg3 is a lockless driver where hard_start_xmit and tx completion handling can run concurrently under normal conditions. A tx_lock is only needed to prevent netif_stop_queue and netif_wake_queue race condtions when the queue is full.
So whether we use LLTX or non-LLTX, it makes practically no difference.
David Miller
maintainerFrom: Ben Greear <[email protected]>
Date: Wed, 11 Apr 2007 11:50:18 -0700
Quoted 5 lines
So, I would like to dig into this problem myself since no one else is reporting this type of problem, but I am quite ignorant of the TCP stack implementation. Based on the dup-acks I see on the wire, I assume the TCP state machine is messed up somehow. Could anyone point me to likely places in the TCP stack to start looking for this bug?
Dup acks mean that packets are being dropped and there are thus holes in the sequence seen at the receiver.
Likely what happens is that we hit the global memory pressure limit, start dropping packets, and never recover even after the memory pressure is within it's limits again.
Quoted 19 lines · Ben Greear
The problem is that I set up a TCP connection with bi-directional traffic of around 800Mbps, doing large (20k - 64k writes and reads) between two ports on
the same machine (this 2.6.18.2 kernel is tainted with my full patch set, but I also reproduced with only the non-tainted send-to-self patch applied last may on the 2.6.16 kernel, so I assume the bug is not particular to my patch
set).At first, all is well, but within 5-10 minutes, the TCP connection will stall and I only see a massive amount of duplicate ACKs on the link. Before, I sometimes saw OOM messages, but this time there are no OOM messages. The system
has a two-port pro/1000 fibre NIC, 1GB RAM, kernel 2.6.18.2 + hacks, etc. Stopping and starting the connection allows traffic to flow again (if briefly).
Starting a new connection works fine even if the old one is still stalled, so it's not a global memory exhaustion problem.
Quoted 5 lines
So, I would like to dig into this problem myself since no one else is reporting this type of problem, but I am quite ignorant of the TCP stack implementation. Based on the dup-acks I see on the wire, I assume the TCP state machine is messed up somehow. Could anyone point me to likely places in the TCP stack to start looking for this bug?
Since your doing bidirectional, try this patch below (probably you'll have apply it manually to 2.6.18 series due to space changes that were made after it in net/ hierarchy). I suspect it's a part of the problem but there could be other things as well because this should only hinder TCP before RTO occurs:
[PATCH] [TCP]: Fix ratehalving with bidirectional flows
Actually, the ratehalving seems to work too well, as cwnd is reduced on every second ACK even though the packets in flight remains unchanged. Recoveries in a bidirectional flows suffer quite badly because of this, both NewReno and SACK are affected.
After this patch, rate halving is performed per ACK only if packets in flight was supposedly changed too.
--- net/ipv4/tcp_input.c | 23 +++++++++++++---------- 1 files changed, 13 insertions(+), 10 deletions(-)
net/ipv4/tcp_input.c +13 -10
@@ -1823,19 +1823,22 @@ static inline u32 tcp_cwnd_min(const str }/* Decrease cwnd each second ack. */ -static void tcp_cwnd_down (struct sock *sk) +static void tcp_cwnd_down (struct sock *sk,int flag) {struct tcp_sock *tp =tcp_sk (sk);int decr = tp->snd_cwnd_cnt +1 ; + +if ((flag&FLAG_FORWARD_PROGRESS ) || + (IsReno (tp) && !(flag&FLAG_NOT_DUP ))) { + tp->snd_cwnd_cnt = decr&1 ; + decr >>=1 ; - tp->snd_cwnd_cnt = decr&1 ; - decr >>=1 ; +if (decr && tp->snd_cwnd >tcp_cwnd_min (sk)) + tp->snd_cwnd -= decr; -if (decr && tp->snd_cwnd >tcp_cwnd_min (sk)) - tp->snd_cwnd -= decr; - - tp->snd_cwnd =min (tp->snd_cwnd,tcp_packets_in_flight (tp)+1 ); - tp->snd_cwnd_stamp = tcp_time_stamp; + tp->snd_cwnd =min (tp->snd_cwnd,tcp_packets_in_flight (tp)+1 ); + tp->snd_cwnd_stamp = tcp_time_stamp; + } }/* Nothing was retransmitted or returned timestamp is less
@@ -2020,7 +2023,7 @@ static void tcp_try_to_open(struct sock }tcp_moderate_cwnd (tp); }else { -tcp_cwnd_down (sk); +tcp_cwnd_down (sk, flag); } }
@@ -2220,7 +2223,7 @@ tcp_fastretrans_alert(struct sock *sk, uif (is_dupack ||tcp_head_timedout (sk, tp))tcp_update_scoreboard (sk, tp); -tcp_cwnd_down (sk); +tcp_cwnd_down (sk, flag);tcp_xmit_retransmit_queue (sk); }
Signature · 1 line
1.4.2