nonagle flags for TSQ

nonagle flags for TSQ

[John Ogness]

Hi,

This email is referring to your Linux patch
46d3ceabd8d98ed0ad10f20c595ca784e34786c5.

https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/?id=46d3ceabd8d98ed0ad10f20c595ca784e34786c5

I have a question about the use of tcp_write_xmit() in
net/ipv4/tcp_output.c

When tcp_write_xmit() is called, the nonagle flag of the tcp socket is
ignored and instead 0 is passed. This causes the Nagle-algorithm to be
used even if it should not be, which in some cases causes a large delay.

Was there a reason that 0 was hard-coded?

Although current mainline code has been refactored, 0 is still
hard-coded for TSQ cases.

John Ogness

Re: nonagle flags for TSQ

[Eric Dumazet]

On Fri, 2014-02-07 at 16:08 +0100, John Ogness wrote:
> Hi,
> 
> This email is referring to your Linux patch
> 46d3ceabd8d98ed0ad10f20c595ca784e34786c5.
> 
> https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/?id=46d3ceabd8d98ed0ad10f20c595ca784e34786c5
> 
> I have a question about the use of tcp_write_xmit() in
> net/ipv4/tcp_output.c
> 
> When tcp_write_xmit() is called, the nonagle flag of the tcp socket is
> ignored and instead 0 is passed. This causes the Nagle-algorithm to be
> used even if it should not be, which in some cases causes a large delay.
> 
> Was there a reason that 0 was hard-coded?
> 
> Although current mainline code has been refactored, 0 is still
> hard-coded for TSQ cases.

Hi John

Do you have any data, like exact kernel version you use, tcpdump or
things like that ?

When the TCP writes are throttled, its only up to the point next packet
is TX completed, and only if you have at least 128KB worth of bytes
consumed in the QDISC/NIC layers for this socket.

We had some issues at very high speeds, not related to Nagle at all.

98e09386c0ef tcp: tsq: restore minimal amount of queueing
c9eeec26e32e tcp: TSQ can use a dynamic limit
d6a4a1041176 tcp: GSO should be TSQ friendly
d01cb20711e3 tcp: add LAST_ACK as a valid state for TSQ

I am not aware of TSQ being a problem for Nagle.

Also take a look at recent TCP autocork patches, as they are more
related to Nagle

a181ceb501b3 tcp: autocork should not hold first packet in write queue
f54b311142a9 tcp: auto corking

Thanks

Re: nonagle flags for TSQ

[Eric Dumazet]

On Fri, 2014-02-07 at 07:34 -0800, Eric Dumazet wrote:
> On Fri, 2014-02-07 at 16:08 +0100, John Ogness wrote:
> > Hi,
> > 
> > This email is referring to your Linux patch
> > 46d3ceabd8d98ed0ad10f20c595ca784e34786c5.
> > 
> > https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/?id=46d3ceabd8d98ed0ad10f20c595ca784e34786c5
> > 
> > I have a question about the use of tcp_write_xmit() in
> > net/ipv4/tcp_output.c
> > 
> > When tcp_write_xmit() is called, the nonagle flag of the tcp socket is
> > ignored and instead 0 is passed. This causes the Nagle-algorithm to be
> > used even if it should not be, which in some cases causes a large delay.
> > 
> > Was there a reason that 0 was hard-coded?
> > 
> > Although current mainline code has been refactored, 0 is still
> > hard-coded for TSQ cases.
> 
> Hi John
> 
> Do you have any data, like exact kernel version you use, tcpdump or
> things like that ?
> 
> When the TCP writes are throttled, its only up to the point next packet
> is TX completed, and only if you have at least 128KB worth of bytes
> consumed in the QDISC/NIC layers for this socket.
> 
> We had some issues at very high speeds, not related to Nagle at all.
> 
> 98e09386c0ef tcp: tsq: restore minimal amount of queueing
> c9eeec26e32e tcp: TSQ can use a dynamic limit
> d6a4a1041176 tcp: GSO should be TSQ friendly
> d01cb20711e3 tcp: add LAST_ACK as a valid state for TSQ
> 
> I am not aware of TSQ being a problem for Nagle.
> 
> Also take a look at recent TCP autocork patches, as they are more
> related to Nagle
> 
> a181ceb501b3 tcp: autocork should not hold first packet in write queue
> f54b311142a9 tcp: auto corking
> 
> Thanks

I think I mentioned this once, but the "a181ceb501b3" fix
included this bit :

 Also, as TX completion is lockless, it's safer to perform sk_wmem_alloc
 test after setting TSQ_THROTTLED.

So its possible you hit the same race, its only a guess...

diff --git a/net/ipv4/tcp_output.c b/net/ipv4/tcp_output.c
index 03d26b85eab8..c99a63c6e91a 100644
--- a/net/ipv4/tcp_output.c
+++ b/net/ipv4/tcp_output.c
@@ -1904,7 +1904,12 @@ static bool tcp_write_xmit(struct sock *sk, unsigned int mss_now, int nonagle,
 
 		if (atomic_read(&sk->sk_wmem_alloc) > limit) {
 			set_bit(TSQ_THROTTLED, &tp->tsq_flags);
-			break;
+			/* It is possible TX completion already happened
+			 * before we set TSQ_THROTTLED, so we must
+			 * test again the condition.
+			 */
+			if (atomic_read(&sk->sk_wmem_alloc) > limit)
+				break;
 		}
 
 		limit = mss_now;

Re: nonagle flags for TSQ

[John Ogness]

Hi Eric,

On 2014-02-07, Eric Dumazet <eric.dumazet@gmail.com> wrote:
>> I have a question about the use of tcp_write_xmit() in
>> net/ipv4/tcp_output.c
>> 
>> When tcp_write_xmit() is called, the nonagle flag of the tcp socket
>> is ignored and instead 0 is passed. This causes the Nagle-algorithm
>> to be used even if it should not be, which in some cases causes a
>> large delay.
>> 
>> Was there a reason that 0 was hard-coded?
>> 
>> Although current mainline code has been refactored, 0 is still
>> hard-coded for TSQ cases.
>
> Do you have any data, like exact kernel version you use, tcpdump or
> things like that ?

Yes. Provided below.

> I am not aware of TSQ being a problem for Nagle.

We are talking about a scenario where Nagle is not supposed to be used
(i.e. TCP_NODELAY is set on the socket).

Here are TCP dumps taken when initiating a gdb debug session from host
to clnt. One from a 2.6 kernel, where the delay is not present. One from
a 3.10 kernel, where a 39ms(!) delay is present. The packets are the
same except the 3.10 kernel shows an extra ACK packet (14th packet from
3.10 dump).

On 2.6 Kernel:
00:00:00.000000 IP host.51922 > clnt.10123: Flags [S], seq 2979238116, win 5840, options [mss 1460,sackOK,TS val 1988280883 ecr 0,nop,wscale 6], length 0
00:00:00.000587 IP clnt.10123 > host.51922: Flags [S.], seq 3460146061, ack 2979238117, win 5792, options [mss 1460,sackOK,TS val 4294688455 ecr 1988280883,nop,wscale 6], length 0
00:00:00.000022 IP host.51922 > clnt.10123: Flags [.], ack 1, win 92, options [nop,nop,TS val 1988280883 ecr 4294688455], length 0
00:00:00.000064 IP host.51922 > clnt.10123: Flags [P.], seq 1:15, ack 1, win 92, options [nop,nop,TS val 1988280883 ecr 4294688455], length 14
00:00:00.000507 IP clnt.10123 > host.51922: Flags [.], ack 15, win 91, options [nop,nop,TS val 4294688456 ecr 1988280883], length 0
00:00:00.000010 IP clnt.10123 > host.51922: Flags [P.], seq 1:2, ack 15, win 91, options [nop,nop,TS val 4294688456 ecr 1988280883], length 1
00:00:00.000010 IP host.51922 > clnt.10123: Flags [.], ack 2, win 92, options [nop,nop,TS val 1988280884 ecr 4294688456], length 0
00:00:00.000005 IP clnt.10123 > host.51922: Flags [P.], seq 2:94, ack 15, win 91, options [nop,nop,TS val 4294688456 ecr 1988280883], length 92
00:00:00.000006 IP host.51922 > clnt.10123: Flags [.], ack 94, win 92, options [nop,nop,TS val 1988280884 ecr 4294688456], length 0
00:00:00.000027 IP host.51922 > clnt.10123: Flags [P.], seq 15:16, ack 94, win 92, options [nop,nop,TS val 1988280884 ecr 4294688456], length 1
00:00:00.000030 IP host.51922 > clnt.10123: Flags [P.], seq 16:56, ack 94, win 92, options [nop,nop,TS val 1988280884 ecr 4294688456], length 40
00:00:00.000450 IP clnt.10123 > host.51922: Flags [.], ack 56, win 91, options [nop,nop,TS val 4294688456 ecr 1988280884], length 0
00:00:00.000010 IP clnt.10123 > host.51922: Flags [P.], seq 94:95, ack 56, win 91, options [nop,nop,TS val 4294688456 ecr 1988280884], length 1
00:00:00.000006 IP clnt.10123 > host.51922: Flags [P.], seq 95:150, ack 56, win 91, options [nop,nop,TS val 4294688456 ecr 1988280884], length 55
00:00:00.000053 IP host.51922 > clnt.10123: Flags [.], ack 150, win 92, options [nop,nop,TS val 1988280885 ecr 4294688456], length 0

On 3.10 Kernel:
00:00:00.000000 IP host.56618 > clnt.10123: Flags [S], seq 315694752, win 5840, options [mss 1460,sackOK,TS val 1987836230 ecr 0,nop,wscale 6], length 0
00:00:00.000267 IP clnt.10123 > host.56618: Flags [S.], seq 469364385, ack 315694753, win 14480, options [mss 1460,sackOK,TS val 6070753 ecr 1987836230,nop,wscale 7], length 0
00:00:00.000022 IP host.56618 > clnt.10123: Flags [.], ack 1, win 92, options [nop,nop,TS val 1987836231 ecr 6070753], length 0
00:00:00.000071 IP host.56618 > clnt.10123: Flags [P.], seq 1:15, ack 1, win 92, options [nop,nop,TS val 1987836231 ecr 6070753], length 14
00:00:00.000501 IP clnt.10123 > host.56618: Flags [.], ack 15, win 114, options [nop,nop,TS val 6070753 ecr 1987836231], length 0
00:00:00.000011 IP clnt.10123 > host.56618: Flags [P.], seq 1:2, ack 15, win 114, options [nop,nop,TS val 6070753 ecr 1987836231], length 1
00:00:00.000007 IP host.56618 > clnt.10123: Flags [.], ack 2, win 92, options [nop,nop,TS val 1987836231 ecr 6070753], length 0
00:00:00.000502 IP clnt.10123 > host.56618: Flags [P.], seq 2:94, ack 15, win 114, options [nop,nop,TS val 6070753 ecr 1987836231], length 92
00:00:00.000008 IP host.56618 > clnt.10123: Flags [.], ack 94, win 92, options [nop,nop,TS val 1987836232 ecr 6070753], length 0
00:00:00.000022 IP host.56618 > clnt.10123: Flags [P.], seq 15:16, ack 94, win 92, options [nop,nop,TS val 1987836232 ecr 6070753], length 1
00:00:00.000030 IP host.56618 > clnt.10123: Flags [P.], seq 16:56, ack 94, win 92, options [nop,nop,TS val 1987836232 ecr 6070753], length 40
00:00:00.000507 IP clnt.10123 > host.56618: Flags [.], ack 56, win 114, options [nop,nop,TS val 6070753 ecr 1987836232], length 0
00:00:00.000009 IP clnt.10123 > host.56618: Flags [P.], seq 94:95, ack 56, win 114, options [nop,nop,TS val 6070753 ecr 1987836232], length 1
00:00:00.039314 IP host.56618 > clnt.10123: Flags [.], ack 95, win 92, options [nop,nop,TS val 1987836272 ecr 6070753], length 0
00:00:00.000502 IP clnt.10123 > host.56618: Flags [P.], seq 95:150, ack 56, win 114, options [nop,nop,TS val 6070757 ecr 1987836272], length 55
00:00:00.000031 IP host.56618 > clnt.10123: Flags [.], ack 150, win 92, options [nop,nop,TS val 1987836272 ecr 6070757], length 0


Using the following patch fixed the problem, but maybe there was a
reason why it wasn't implemented like this in the first place?


diff --git a/net/ipv4/tcp_output.c b/net/ipv4/tcp_output.c
index 03d26b8..9408a0d 100644
--- a/net/ipv4/tcp_output.c
+++ b/net/ipv4/tcp_output.c
@@ -697,8 +697,11 @@ static void tcp_tsq_handler(struct sock *sk)
 {
 	if ((1 << sk->sk_state) &
 	    (TCPF_ESTABLISHED | TCPF_FIN_WAIT1 | TCPF_CLOSING |
-	     TCPF_CLOSE_WAIT  | TCPF_LAST_ACK))
-		tcp_write_xmit(sk, tcp_current_mss(sk), 0, 0, GFP_ATOMIC);
+	     TCPF_CLOSE_WAIT  | TCPF_LAST_ACK)) {
+		struct tcp_sock *tp = tcp_sk(sk);
+		tcp_write_xmit(sk, tcp_current_mss(sk), tp->nonagle, 0,
+			       GFP_ATOMIC);
+	}
 }
 /*
  * One tasklet per cpu tries to send more skbs.


John Ogness

Re: nonagle flags for TSQ

[Eric Dumazet]

On Fri, 2014-02-07 at 17:34 +0100, John Ogness wrote:
> Hi Eric,

> 
> We are talking about a scenario where Nagle is not supposed to be used
> (i.e. TCP_NODELAY is set on the socket).
> 
> Here are TCP dumps taken when initiating a gdb debug session from host
> to clnt. One from a 2.6 kernel, where the delay is not present. One from
> a 3.10 kernel, where a 39ms(!) delay is present. The packets are the
> same except the 3.10 kernel shows an extra ACK packet (14th packet from
> 3.10 dump).
> 
> On 2.6 Kernel:
> 00:00:00.000000 IP host.51922 > clnt.10123: Flags [S], seq 2979238116, win 5840, options [mss 1460,sackOK,TS val 1988280883 ecr 0,nop,wscale 6], length 0
> 00:00:00.000587 IP clnt.10123 > host.51922: Flags [S.], seq 3460146061, ack 2979238117, win 5792, options [mss 1460,sackOK,TS val 4294688455 ecr 1988280883,nop,wscale 6], length 0
> 00:00:00.000022 IP host.51922 > clnt.10123: Flags [.], ack 1, win 92, options [nop,nop,TS val 1988280883 ecr 4294688455], length 0
> 00:00:00.000064 IP host.51922 > clnt.10123: Flags [P.], seq 1:15, ack 1, win 92, options [nop,nop,TS val 1988280883 ecr 4294688455], length 14
> 00:00:00.000507 IP clnt.10123 > host.51922: Flags [.], ack 15, win 91, options [nop,nop,TS val 4294688456 ecr 1988280883], length 0
> 00:00:00.000010 IP clnt.10123 > host.51922: Flags [P.], seq 1:2, ack 15, win 91, options [nop,nop,TS val 4294688456 ecr 1988280883], length 1
> 00:00:00.000010 IP host.51922 > clnt.10123: Flags [.], ack 2, win 92, options [nop,nop,TS val 1988280884 ecr 4294688456], length 0
> 00:00:00.000005 IP clnt.10123 > host.51922: Flags [P.], seq 2:94, ack 15, win 91, options [nop,nop,TS val 4294688456 ecr 1988280883], length 92
> 00:00:00.000006 IP host.51922 > clnt.10123: Flags [.], ack 94, win 92, options [nop,nop,TS val 1988280884 ecr 4294688456], length 0
> 00:00:00.000027 IP host.51922 > clnt.10123: Flags [P.], seq 15:16, ack 94, win 92, options [nop,nop,TS val 1988280884 ecr 4294688456], length 1
> 00:00:00.000030 IP host.51922 > clnt.10123: Flags [P.], seq 16:56, ack 94, win 92, options [nop,nop,TS val 1988280884 ecr 4294688456], length 40
> 00:00:00.000450 IP clnt.10123 > host.51922: Flags [.], ack 56, win 91, options [nop,nop,TS val 4294688456 ecr 1988280884], length 0
> 00:00:00.000010 IP clnt.10123 > host.51922: Flags [P.], seq 94:95, ack 56, win 91, options [nop,nop,TS val 4294688456 ecr 1988280884], length 1
> 00:00:00.000006 IP clnt.10123 > host.51922: Flags [P.], seq 95:150, ack 56, win 91, options [nop,nop,TS val 4294688456 ecr 1988280884], length 55
> 00:00:00.000053 IP host.51922 > clnt.10123: Flags [.], ack 150, win 92, options [nop,nop,TS val 1988280885 ecr 4294688456], length 0
> 
> On 3.10 Kernel:
> 00:00:00.000000 IP host.56618 > clnt.10123: Flags [S], seq 315694752, win 5840, options [mss 1460,sackOK,TS val 1987836230 ecr 0,nop,wscale 6], length 0
> 00:00:00.000267 IP clnt.10123 > host.56618: Flags [S.], seq 469364385, ack 315694753, win 14480, options [mss 1460,sackOK,TS val 6070753 ecr 1987836230,nop,wscale 7], length 0
> 00:00:00.000022 IP host.56618 > clnt.10123: Flags [.], ack 1, win 92, options [nop,nop,TS val 1987836231 ecr 6070753], length 0
> 00:00:00.000071 IP host.56618 > clnt.10123: Flags [P.], seq 1:15, ack 1, win 92, options [nop,nop,TS val 1987836231 ecr 6070753], length 14
> 00:00:00.000501 IP clnt.10123 > host.56618: Flags [.], ack 15, win 114, options [nop,nop,TS val 6070753 ecr 1987836231], length 0
> 00:00:00.000011 IP clnt.10123 > host.56618: Flags [P.], seq 1:2, ack 15, win 114, options [nop,nop,TS val 6070753 ecr 1987836231], length 1
> 00:00:00.000007 IP host.56618 > clnt.10123: Flags [.], ack 2, win 92, options [nop,nop,TS val 1987836231 ecr 6070753], length 0
> 00:00:00.000502 IP clnt.10123 > host.56618: Flags [P.], seq 2:94, ack 15, win 114, options [nop,nop,TS val 6070753 ecr 1987836231], length 92
> 00:00:00.000008 IP host.56618 > clnt.10123: Flags [.], ack 94, win 92, options [nop,nop,TS val 1987836232 ecr 6070753], length 0
> 00:00:00.000022 IP host.56618 > clnt.10123: Flags [P.], seq 15:16, ack 94, win 92, options [nop,nop,TS val 1987836232 ecr 6070753], length 1
> 00:00:00.000030 IP host.56618 > clnt.10123: Flags [P.], seq 16:56, ack 94, win 92, options [nop,nop,TS val 1987836232 ecr 6070753], length 40
> 00:00:00.000507 IP clnt.10123 > host.56618: Flags [.], ack 56, win 114, options [nop,nop,TS val 6070753 ecr 1987836232], length 0
> 00:00:00.000009 IP clnt.10123 > host.56618: Flags [P.], seq 94:95, ack 56, win 114, options [nop,nop,TS val 6070753 ecr 1987836232], length 1
> 00:00:00.039314 IP host.56618 > clnt.10123: Flags [.], ack 95, win 92, options [nop,nop,TS val 1987836272 ecr 6070753], length 0
> 00:00:00.000502 IP clnt.10123 > host.56618: Flags [P.], seq 95:150, ack 56, win 114, options [nop,nop,TS val 6070757 ecr 1987836272], length 55
> 00:00:00.000031 IP host.56618 > clnt.10123: Flags [.], ack 150, win 92, options [nop,nop,TS val 1987836272 ecr 6070757], length 0
> 
> 
> Using the following patch fixed the problem, but maybe there was a
> reason why it wasn't implemented like this in the first place?
> 

I cant see how TSQ would even trigger with this test.

What value do you have on /proc/sys/net/ipv4/tcp_limit_output_bytes ?

Normal value is 128KB, meaning you have to queue about 56 small frames
before hitting the TSQ condition. (skb->truesize of small frames being
2304 bytes)

I think your patch might makes sense if we remembered (at the time we
decide to throttle the write) the value of nonagle parameter passed to
tcp_write_xmit() : Not sure it really should the current tp->nonagle
value...

Thanks !

Re: nonagle flags for TSQ

[John Ogness]

Hi Eric,

Since the patch has already been pulled, I don't know how much energy
you want to spend to track this down. I am acting as a middle-man for
the person with the problem, which is the reason for the large latency
in my responses.

On 2014-02-07, Eric Dumazet <eric.dumazet@gmail.com> wrote:
> I cant see how TSQ would even trigger with this test.

The problem is appearing on a kernel with the PREEMPT_RT patch
(3.10.20-rt17). I do not see anything in the PREEMPT_RT patch that would
affect the use of TSQ.

> What value do you have on /proc/sys/net/ipv4/tcp_limit_output_bytes ?

conf 	: icmp_echo_ignore_all 	: 0
icmp_echo_ignore_broadcasts 	: 1
icmp_echo_sysrq 	: 0
icmp_errors_use_inbound_ifaddr 	: 0
icmp_ignore_bogus_error_responses 	: 1
icmp_ratelimit 	: 1000
icmp_ratemask 	: 6168
igmp_max_memberships 	: 20
igmp_max_msf 	: 10
inet_peer_maxttl 	: 600
inet_peer_minttl 	: 120
inet_peer_threshold 	: 65664
ip_default_ttl 	: 64
ip_dynaddr 	: 0
ip_early_demux 	: 1
ip_forward 	: 0
ip_local_port_range 	: 32768	61000
ip_local_reserved_ports 	: 
ip_no_pmtu_disc 	: 0
ip_nonlocal_bind 	: 0
ipfrag_high_thresh 	: 4194304
ipfrag_low_thresh 	: 3145728
ipfrag_max_dist 	: 64
ipfrag_secret_interval 	: 600
ipfrag_time 	: 30
neigh 	: ping_group_range 	: 1	0
route 	: tcp_abort_on_overflow 	: 0
tcp_adv_win_scale 	: 1
tcp_allowed_congestion_control 	: cubic reno
tcp_app_win 	: 31
tcp_available_congestion_control 	: cubic reno
tcp_base_mss 	: 512
tcp_challenge_ack_limit 	: 100
tcp_congestion_control 	: cubic
tcp_dsack 	: 1
tcp_early_retrans 	: 3
tcp_ecn 	: 2
tcp_fack 	: 1
tcp_fastopen 	: 0
tcp_fastopen_key 	: fe6450bc-a4524655-c76e138c-10df4490
tcp_fin_timeout 	: 60
tcp_frto 	: 2
tcp_keepalive_intvl 	: 75
tcp_keepalive_probes 	: 9
tcp_keepalive_time 	: 7200
tcp_limit_output_bytes 	: 131072
tcp_low_latency 	: 0
tcp_max_orphans 	: 4096
tcp_max_ssthresh 	: 0
tcp_max_syn_backlog 	: 128
tcp_max_tw_buckets 	: 4096
tcp_mem 	: 20187	26919	40374
tcp_min_tso_segs 	: 2
tcp_moderate_rcvbuf 	: 1
tcp_mtu_probing 	: 0
tcp_no_metrics_save 	: 0
tcp_orphan_retries 	: 0
tcp_reordering 	: 3
tcp_retrans_collapse 	: 1
tcp_retries1 	: 3
tcp_retries2 	: 15
tcp_rfc1337 	: 0
tcp_rmem 	: 4096	87380	6291456
tcp_sack 	: 1
tcp_slow_start_after_idle 	: 1
tcp_stdurg 	: 0
tcp_syn_retries 	: 6
tcp_synack_retries 	: 5
tcp_syncookies 	: 1
tcp_thin_dupack 	: 0
tcp_thin_linear_timeouts 	: 0
tcp_timestamps 	: 1
tcp_tso_win_divisor 	: 3
tcp_tw_recycle 	: 0
tcp_tw_reuse 	: 0
tcp_window_scaling 	: 1
tcp_wmem 	: 4096	16384	4194304
tcp_workaround_signed_windows 	: 0
udp_mem 	: 20319	27093	40638
udp_rmem_min 	: 4096
udp_wmem_min 	: 4096

John Ogness