3.14 regression: huge latency in read/select on tun

3.14 regression: huge latency in read/select on tun

[Ortwin Glück]

Hi,

Since 3.14 the openconnect VPN tunnel becomes unusable for me because
packets appear on the tun device at a horribly low rate. 3.12 and 3.13
do not exhibt the problem.

Here is an strace of openconnect trying to read from its fd
  7 -> /dev/net/tun

15:07:33.130640 read(7, 0x1e05e58, 1280) = -1 EAGAIN (Resource
temporarily unavailable)
===> should return available data already
15:07:33.130745 select(8, [3 6 7], [], [6], {30, 0}) = 1 (in [7], left
{29, 783272})
===> HUGE 217ms delay here
15:07:33.347681 read(6, 0x1dfc973, 5)   = -1 EAGAIN (Resource
temporarily unavailable)
15:07:33.347806 read(7,
"E\10\5\0b\343@\0@\6\17~\n\363X\236\n\271UE\222:\0\26\37O\7\342\315\21q\33"...,
1280) = 1280


The send queue of the socket being routed via the tun device has a lot
of outstanding data (here an scp/ssh upload):
tcp        0  29788 local:46577  remote:22   ESTABLISHED

(IPs replaced for privacy)

toggling TCP autocorking has no influence.

Any ideas what could be the culprit?

Ortwin

Re: 3.14 regression: huge latency in read/select on tun

[Eric Dumazet]

On Wed, 2014-04-02 at 18:17 +0200, Ortwin Glück wrote:
> Hi,
> 
> Since 3.14 the openconnect VPN tunnel becomes unusable for me because
> packets appear on the tun device at a horribly low rate. 3.12 and 3.13
> do not exhibt the problem.
> 
> Here is an strace of openconnect trying to read from its fd
>   7 -> /dev/net/tun
> 
> 15:07:33.130640 read(7, 0x1e05e58, 1280) = -1 EAGAIN (Resource
> temporarily unavailable)
> ===> should return available data already
> 15:07:33.130745 select(8, [3 6 7], [], [6], {30, 0}) = 1 (in [7], left
> {29, 783272})
> ===> HUGE 217ms delay here
> 15:07:33.347681 read(6, 0x1dfc973, 5)   = -1 EAGAIN (Resource
> temporarily unavailable)
> 15:07:33.347806 read(7,
> "E\10\5\0b\343@\0@\6\17~\n\363X\236\n\271UE\222:\0\26\37O\7\342\315\21q\33"...,
> 1280) = 1280
> 
> 
> The send queue of the socket being routed via the tun device has a lot
> of outstanding data (here an scp/ssh upload):
> tcp        0  29788 local:46577  remote:22   ESTABLISHED
> 
> (IPs replaced for privacy)
> 
> toggling TCP autocorking has no influence.
> 
> Any ideas what could be the culprit?

Nothing else than autocorking comes to mind.

You could post a tcpdump maybe ?

I believe some tools exist to anonymize a pcap file.

Re: 3.14 regression: huge latency in read/select on tun

[Ortwin Glück]

[-- Attachment #1: Type: text/plain, Size: 768 bytes --]

On 02.04.2014 18:42, Eric Dumazet wrote:
> You could post a tcpdump maybe ?

This is a dump from on the tun interface (traffic inside the tunnel).
It's an scp upload of a 2MB file. I aborted after a while when not much
progress was seen anymore, but you get the idea.

What I see:
- Frame 28: long delay because I had to enter the key password
- Frame 31: the packets seems to be out of order. It has a sequence
number that is far ahead of previously sent sequence no's. Some
duplicates and retransmissions follow. That pattern repeats randomly all
over the trace.
- from Frame 73 on: ping pong of ACKs and data, while the data is
delayed by ~200ms caused by the select(). The ping pong also shows that
there are virtually no packets in flight (see also Window size).

[-- Attachment #2: dump.pcapng --]
[-- Type: application/octet-stream, Size: 842792 bytes --]

Re: 3.14 regression: huge latency in read/select on tun

[Eric Dumazet]

On Thu, 2014-04-03 at 09:52 +0200, Ortwin Glück wrote:
> On 02.04.2014 18:42, Eric Dumazet wrote:
> > You could post a tcpdump maybe ?
> 
> This is a dump from on the tun interface (traffic inside the tunnel).
> It's an scp upload of a 2MB file. I aborted after a while when not much
> progress was seen anymore, but you get the idea.
> 
> What I see:
> - Frame 28: long delay because I had to enter the key password
> - Frame 31: the packets seems to be out of order. It has a sequence
> number that is far ahead of previously sent sequence no's. Some
> duplicates and retransmissions follow. That pattern repeats randomly all
> over the trace.
> - from Frame 73 on: ping pong of ACKs and data, while the data is
> delayed by ~200ms caused by the select(). The ping pong also shows that
> there are virtually no packets in flight (see also Window size).

It seems TSO support is broken.

Your trace have no 'big' packets but holes like :

00:41:35.832695 IP 10.243.88.168.35846 > 10.185.85.69.22: Flags [.], ack 6093, win 310, options [nop,nop,TS val 78054 ecr 3191538976], length 0
00:41:35.855990 IP 10.243.88.168.35846 > 10.185.85.69.22: Flags [P.], seq 6696:6776, ack 6093, win 310, options [nop,nop,TS val 78060 ecr 3191538976], length 80
00:41:36.047465 IP 10.185.85.69.22 > 10.243.88.168.35846: Flags [P.], seq 6093:6141, ack 6776, win 218, options [nop,nop,TS val 3191539191 ecr 78060], length 48

missing 6776:14144 sequence (6 segments)

00:41:36.048766 IP 10.243.88.168.35846 > 10.185.85.69.22: Flags [.], seq 14144:15372, ack 6141, win 310, options [nop,nop,TS val 78108 ecr 3191539191], length 1228
00:41:36.057995 IP 10.185.85.69.22 > 10.243.88.168.35846: Flags [.], ack 6776, win 218, options [nop,nop,TS val 3191539202 ecr 78060,nop,nop,sack 1 {14144:15372}], length 0

You are 'saved' because retransmits do not use TSO :

00:41:36.058050 IP 10.243.88.168.35846 > 10.185.85.69.22: Flags [.], seq 6776:8004, ack 6141, win 310, options [nop,nop,TS val 78110 ecr 3191539202], length 1228
00:41:36.058070 IP 10.243.88.168.35846 > 10.185.85.69.22: Flags [.], seq 8004:9232, ack 6141, win 310, options [nop,nop,TS val 78110 ecr 3191539202], length 1228

Also receiver seems to be unable to open TCP window, but thats a secondary problem.

Re: 3.14 regression: huge latency in read/select on tun

[Eric Dumazet]

On Thu, 2014-04-03 at 06:19 -0700, Eric Dumazet wrote:

> It seems TSO support is broken.

If bug is in tun.c you have this list of changes  you could bisect
from :

# git log --oneline v3.13..v3.14 drivers/net/tun.c
6671b2240c54 tun: remove bogus hardware vlan acceleration flags from vlan_features
99932d4fc03a netdevice: add queue selection fallback handler for ndo_select_queue
93e14b6d776e tun: add device name(iff) field to proc fdinfo entry
fa35864e0bb7 tuntap: Fix for a race in accessing numqueues
0a379e21c503 Merge git://git.kernel.org/pub/scm/linux/kernel/git/davem/net
fbe4d4565bad tun, rfs: fix the incorrect hash value
9bc8893937c8 tun: Add support for RFS on tun flows
143c90549494 Merge git://git.kernel.org/pub/scm/linux/kernel/git/davem/net
3958afa1b272 net: Change skb_get_rxhash to skb_get_hash
42404c091510 Revert "tun: remove useless codes in tun_chr_aio_read() and tun_recvmsg()"
73713357ab58 tun: remove useless codes in tun_chr_aio_read() and tun_recvmsg()
34f9f437104b Merge git://git.kernel.org/pub/scm/linux/kernel/git/davem/net
f96eb74c84eb tun: remove unused parameter in tun_do_read()
92d4ea6e412a tun: spelling fixes

Re: 3.14 regression: huge latency in read/select on tun

[Ortwin Glück]

On 03.04.2014 15:50, Eric Dumazet wrote:
> If bug is in tun.c you have this list of changes  you could bisect
> from :
> 
> # git log --oneline v3.13..v3.14 drivers/net/tun.c
> 6671b2240c54 tun: remove bogus hardware vlan acceleration flags from vlan_features
> 99932d4fc03a netdevice: add queue selection fallback handler for ndo_select_queue
> 93e14b6d776e tun: add device name(iff) field to proc fdinfo entry
> fa35864e0bb7 tuntap: Fix for a race in accessing numqueues
> 0a379e21c503 Merge git://git.kernel.org/pub/scm/linux/kernel/git/davem/net
> fbe4d4565bad tun, rfs: fix the incorrect hash value
> 9bc8893937c8 tun: Add support for RFS on tun flows
> 143c90549494 Merge git://git.kernel.org/pub/scm/linux/kernel/git/davem/net
> 3958afa1b272 net: Change skb_get_rxhash to skb_get_hash
> 42404c091510 Revert "tun: remove useless codes in tun_chr_aio_read() and tun_recvmsg()"
> 73713357ab58 tun: remove useless codes in tun_chr_aio_read() and tun_recvmsg()
> 34f9f437104b Merge git://git.kernel.org/pub/scm/linux/kernel/git/davem/net
> f96eb74c84eb tun: remove unused parameter in tun_do_read()
> 92d4ea6e412a tun: spelling fixes


That list doesn't look too promising. I'd rather look in net/ipv4 which
does have TSO/GSO related changes. I tried to bisect that but the system
hangs on boot when net devices are enabled. So it may prove difficult to
pin down. I may try again during the weekend.

Re: 3.14 regression: huge latency in read/select on tun

[Ortwin Glück]

On 03.04.2014 15:50, Eric Dumazet wrote:
> On Thu, 2014-04-03 at 06:19 -0700, Eric Dumazet wrote:
> 
>> It seems TSO support is broken.

I finally found time to bisect this:

53d6471cef17262d3ad1c7ce8982a234244f68ec is the first bad commit
commit 53d6471cef17262d3ad1c7ce8982a234244f68ec
Author: Vlad Yasevich <vyasevic@redhat.com>
Date:   Thu Mar 27 17:26:18 2014 -0400

    net: Account for all vlan headers in skb_mac_gso_segment

    skb_network_protocol() already accounts for multiple vlan
    headers that may be present in the skb.  However, skb_mac_gso_segment()
    doesn't know anything about it and assumes that skb->mac_len
    is set correctly to skip all mac headers.  That may not
    always be the case.  If we are simply forwarding the packet (via
    bridge or macvtap), all vlan headers may not be accounted for.

    A simple solution is to allow skb_network_protocol to return
    the vlan depth it has calculated.  This way skb_mac_gso_segment
    will correctly skip all mac headers.

    Signed-off-by: Vlad Yasevich <vyasevic@redhat.com>
    Signed-off-by: David S. Miller <davem@davemloft.net>

:040000 040000 6066ee76dd70dde2f4675155579e550d29ba0216
2196ebff4f9a8b909617dd57beeaa76cbafc8525 M      include
:040000 040000 20fdfb5efc1ada562b7899d0d58998914b1c2ff1
c398988f31e1b1b6ee56cb20b1a7becbdf782a17 M      net

Re: 3.14 regression: huge latency in read/select on tun

[Eric Dumazet]

On Sat, 2014-04-19 at 22:13 +0200, Ortwin Glück wrote:
> On 03.04.2014 15:50, Eric Dumazet wrote:
> > On Thu, 2014-04-03 at 06:19 -0700, Eric Dumazet wrote:
> > 
> >> It seems TSO support is broken.
> 
> I finally found time to bisect this:
> 
> 53d6471cef17262d3ad1c7ce8982a234244f68ec is the first bad commit
> commit 53d6471cef17262d3ad1c7ce8982a234244f68ec
> Author: Vlad Yasevich <vyasevic@redhat.com>
> Date:   Thu Mar 27 17:26:18 2014 -0400
> 
>     net: Account for all vlan headers in skb_mac_gso_segment
> 
>     skb_network_protocol() already accounts for multiple vlan
>     headers that may be present in the skb.  However, skb_mac_gso_segment()
>     doesn't know anything about it and assumes that skb->mac_len
>     is set correctly to skip all mac headers.  That may not
>     always be the case.  If we are simply forwarding the packet (via
>     bridge or macvtap), all vlan headers may not be accounted for.
> 
>     A simple solution is to allow skb_network_protocol to return
>     the vlan depth it has calculated.  This way skb_mac_gso_segment
>     will correctly skip all mac headers.
> 
>     Signed-off-by: Vlad Yasevich <vyasevic@redhat.com>
>     Signed-off-by: David S. Miller <davem@davemloft.net>
> 
> :040000 040000 6066ee76dd70dde2f4675155579e550d29ba0216
> 2196ebff4f9a8b909617dd57beeaa76cbafc8525 M      include
> :040000 040000 20fdfb5efc1ada562b7899d0d58998914b1c2ff1
> c398988f31e1b1b6ee56cb20b1a7becbdf782a17 M      net
> --


Hmm.. probably already solved by commit 
1e785f48d29a09b6cf96db7b49b6320dada332e1
("net: Start with correct mac_len in skb_network_protocol")

Re: 3.14 regression: huge latency in read/select on tun

[Ortwin Glück]

On 20.04.2014 18:31, Eric Dumazet wrote:> On Sat, 2014-04-19 at 22:13
+0200, Ortwin Glück wrote:
>> On 03.04.2014 15:50, Eric Dumazet wrote:
>>
>> I finally found time to bisect this:
>>
>> commit 53d6471cef17262d3ad1c7ce8982a234244f68ec
>> Author: Vlad Yasevich <vyasevic@redhat.com>
>> Date:   Thu Mar 27 17:26:18 2014 -0400
>>
>>     net: Account for all vlan headers in skb_mac_gso_segment
>
> Hmm.. probably already solved by commit
> 1e785f48d29a09b6cf96db7b49b6320dada332e1
> ("net: Start with correct mac_len in skb_network_protocol")

Indeed that fixes it. I have cherry picked that onto 3.14 and it works.
That means 1e785f48 should be applied to stable 3.13.y and 3.14.y too.

Thanks,

Ortwin

RE: 3.14 regression: huge latency in read/select on tun

[Lukas Tribus]

>> Hmm.. probably already solved by commit
>> 1e785f48d29a09b6cf96db7b49b6320dada332e1
>> ("net: Start with correct mac_len in skb_network_protocol")
>
> Indeed that fixes it. I have cherry picked that onto 3.14 and it works.
> That means 1e785f48 should be applied to stable 3.13.y and 3.14.y too.

Its already in davem's stable-queue:
http://patchwork.ozlabs.org/bundle/davem/stable/?state=*
http://patchwork.ozlabs.org/patch/339082/


Lukas