Skip to contentSkip to conversation

TCP connection stops after high load.

DISCUSSION Ben Greear 10 participants 25 messages Apr 11, 2007 – Apr 14, 2007

Subsystems (3)
lore
Share & tools
lore

Ben Greear

author
#0 lore raw

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
author
#1 lore raw
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
maintainer
#2 lore raw

From: 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. :(

author
#3 lore raw
Quoted 9 lines · David Miller

From: 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.

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
maintainer
#4 lore raw

From: 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.

author
#5 lore raw
Quoted 13 lines · David Miller

From: 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.

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
maintainer
#6 lore raw

From: 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.

#7 lore raw
In reply to Ben Greear

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 -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.

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

#8 lore raw
In reply to Ben Greear
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]>.
#9 lore raw
In reply to Ben Greear
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

author
#10 lore raw
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/snmp counters for interesting events (e.g. GFP_ATOMIC allocations 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 out

Icmp:
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 out

Icmp:
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
#11 lore raw
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 ?

author
#12 lore raw
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:17

eth1 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-d0020000

eth3 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-d0040000

lo 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_stat
d58236f1 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
#13 lore raw
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: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:17

eth1 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-d0020000

eth3 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-d0040000

lo 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

Quoted 4 lines

[root@lf1001-240 ipv4]# cat /proc/net/softnet_stat
d58236f1 00000000 023badc3 00000000 00000000 00000000 00000000 00000000 0004ef01 3a4354a1 00000000 01b57b4b 00000000 00000000 00000000 00000000 00000000 0005445f

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
author
#14 lore raw
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
#15 lore raw
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
author
#16 lore raw
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
#17 lore raw
In reply to Eric Dumazet
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>

#18 lore raw
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

#19 lore raw
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 call ev_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.txt
maintainer
#20 lore raw

From: 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 call ev_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.

#21 lore raw
In reply to Herbert Xu
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 call ev_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...

maintainer
#22 lore raw

From: 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.

maintainer
#23 lore raw
In reply to Ben Greear

From: 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.

#24 lore raw
In reply to Ben Greear
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
index 322e43c..bf0f74c 100644
@@ -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, u
 
 	if (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