3.14 regression: huge latency in read/select on tun

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

Nothing else than autocorking comes to mind.

You could post a tcpdump maybe ?

I believe some tools exist to anonymize a pcap file.

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.

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.

I finally found time to bisect this:

53d6471cef17262d3ad1c7ce8982a234244f68ec is the first bad commit commit 53d6471cef17262d3ad1c7ce8982a234244f68ec

Author: Vlad Yasevich <[email protected]>
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.

: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")

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

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

Lukas