[OpenWrt-Devel] latency on PPPoA ADSL Annex A on using Lantiq
Daniel Niasoff
daniel at redactus.co.uk
Tue Aug 9 04:17:37 EDT 2016
Hi Martin/John,
Can you give us an idea where to look. If I use an external modem in bridge mode and run PPPoE on the router then it works fine.
However with PPPoA, TCP and UDP misbehaves, UDP packets over 1300 seems to be dropped silently and the first tcp packet is dropped with no logs in IPTABLES.
Leonid has done some hard work to debug this.
Can you please help?
Thanks
Daniel
-----Original Message-----
From: openwrt-devel [mailto:openwrt-devel-bounces at lists.openwrt.org] On Behalf Of Leonid Evdokimov
Sent: 07 August 2016 10:33
To: Martin Blumenstingl <martin.blumenstingl at googlemail.com>
Cc: hauke at hauke-m.de; lede-dev at lists.infradead.org; openwrt-devel at lists.openwrt.org
Subject: Re: [OpenWrt-Devel] latency on PPPoA ADSL Annex A on using Lantiq
On Wed, Aug 3, 2016 at 10:02 AM, Martin Blumenstingl <martin.blumenstingl at googlemail.com> wrote:
> I did not have time to look into this yet, but maybe Hauke or John
> have an idea what's going on.
I have a testcase, maybe it'll be useful to debug the issue.
brie.darkk.net.ru (139.162.172.21) is server hosted in London.
2.30.18.250 is ADSL router in UK.
Non-empty TCP packets are delayed till TCP RTO timer fires starting with the third datagram.
I get following RTT estimates using tcp-echo, different `--delay` between packets does not change the result:
brie $ ./mturtt --host 2.30.18.250 --port 4242 --count 10 --tcp --size
1400 --delay 1
sz seq rtt there back
1400 1 0.036 0.006 0.030
1400 2 0.036 0.006 0.030
1400 3 0.261 0.006 0.255 # woops! plus TCP RTO
1400 4 0.263 0.007 0.256
1400 5 0.264 0.006 0.258
1400 6 0.265 0.007 0.258
1400 7 0.266 0.006 0.260
1400 8 0.267 0.006 0.260
1400 9 0.266 0.006 0.260
1400 10 0.265 0.006 0.259
Running busy-loop at the router with `ss -4t 'sport = 4242' -ieom` reports following timer inforation:
ESTAB 0 0 2.30.18.250:4242 139.162.172.21:53328 ino:42363
sk:80f19ae0 rto:0.23 ato:0.04 qack:15 bidir cwnd:10 reordering:0
ESTAB 0 0 2.30.18.250:4242 139.162.172.21:53328 ino:42363
sk:80f19ae0 rto:0.23 ato:0.04 qack:15 bidir cwnd:10 reordering:0
ESTAB 0 0 2.30.18.250:4242 139.162.172.21:53328 ino:42363
sk:80f19ae0 rto:0.23 ato:0.04 qack:15 bidir cwnd:10 reordering:0·
ESTAB 0 1400 2.30.18.250:4242 139.162.172.21:53328
timer:(persist,230ms,0) ino:42363 sk:80f19ae0 rto:0.23 ato:0.04
qack:16 cwnd:10 reordering:0
ESTAB 0 1400 2.30.18.250:4242 139.162.172.21:53328
timer:(persist,220ms,0) ino:42363 sk:80f19ae0 rto:0.23 ato:0.04
qack:16 cwnd:10 reordering:0
ESTAB 0 1400 2.30.18.250:4242 139.162.172.21:53328
timer:(persist,200ms,0) ino:42363 sk:80f19ae0 rto:0.23 ato:0.04
qack:16 cwnd:10 reordering:0
ESTAB 0 1400 2.30.18.250:4242 139.162.172.21:53328
timer:(persist,190ms,0) ino:42363 sk:80f19ae0 rto:0.23 ato:0.04
qack:16 cwnd:10 reordering:0
ESTAB 0 1400 2.30.18.250:4242 139.162.172.21:53328
timer:(persist,180ms,0) ino:42363 sk:80f19ae0 rto:0.23 ato:0.04
qack:16 cwnd:10 reordering:0
ESTAB 0 1400 2.30.18.250:4242 139.162.172.21:53328
timer:(persist,160ms,0) ino:42363 sk:80f19ae0 rto:0.23 ato:0.04
qack:16 cwnd:10 reordering:0
ESTAB 0 1400 2.30.18.250:4242 139.162.172.21:53328
timer:(persist,150ms,0) ino:42363 sk:80f19ae0 rto:0.23 ato:0.04
qack:16 cwnd:10 reordering:0
ESTAB 0 1400 2.30.18.250:4242 139.162.172.21:53328
timer:(persist,140ms,0) ino:42363 sk:80f19ae0 rto:0.23 ato:0.04
qack:16 cwnd:10 reordering:0
ESTAB 0 1400 2.30.18.250:4242 139.162.172.21:53328
timer:(persist,130ms,0) ino:42363 sk:80f19ae0 rto:0.23 ato:0.04
qack:16 cwnd:10 reordering:0
ESTAB 0 1400 2.30.18.250:4242 139.162.172.21:53328
timer:(persist,110ms,0) ino:42363 sk:80f19ae0 rto:0.23 ato:0.04
qack:16 cwnd:10 reordering:0
ESTAB 0 1400 2.30.18.250:4242 139.162.172.21:53328
timer:(persist,100ms,0) ino:42363 sk:80f19ae0 rto:0.23 ato:0.04
qack:16 cwnd:10 reordering:0
ESTAB 0 1400 2.30.18.250:4242 139.162.172.21:53328
timer:(persist,090ms,0) ino:42363 sk:80f19ae0 rto:0.23 ato:0.04
qack:16 cwnd:10 reordering:0
ESTAB 0 1400 2.30.18.250:4242 139.162.172.21:53328
timer:(persist,080ms,0) ino:42363 sk:80f19ae0 rto:0.23 ato:0.04
qack:16 cwnd:10 reordering:0
ESTAB 0 1400 2.30.18.250:4242 139.162.172.21:53328
timer:(persist,060ms,0) ino:42363 sk:80f19ae0 rto:0.23 ato:0.04
qack:16 cwnd:10 reordering:0
ESTAB 0 1400 2.30.18.250:4242 139.162.172.21:53328
timer:(persist,050ms,0) ino:42363 sk:80f19ae0 rto:0.23 ato:0.04
qack:16 cwnd:10 reordering:0
ESTAB 0 1400 2.30.18.250:4242 139.162.172.21:53328
timer:(persist,040ms,0) ino:42363 sk:80f19ae0 rto:0.23 ato:0.04
qack:16 cwnd:10 reordering:0
ESTAB 0 1400 2.30.18.250:4242 139.162.172.21:53328
timer:(persist,020ms,0) ino:42363 sk:80f19ae0 rto:0.23 ato:0.04
qack:16 cwnd:10 reordering:0
ESTAB 0 1400 2.30.18.250:4242 139.162.172.21:53328
timer:(persist,010ms,0) ino:42363 sk:80f19ae0 rto:0.23 ato:0.04
qack:16 cwnd:10 reordering:0
ESTAB 0 1400 2.30.18.250:4242 139.162.172.21:53328
timer:(on,230ms,0) ino:42363 sk:80f19ae0 rto:0.23 ato:0.04 qack:15 bidir cwnd:10 reordering:0
ESTAB 0 1400 2.30.18.250:4242 139.162.172.21:53328
timer:(on,220ms,0) ino:42363 sk:80f19ae0 rto:0.23 ato:0.04 qack:15 bidir cwnd:10 reordering:0
ESTAB 0 1400 2.30.18.250:4242 139.162.172.21:53328
timer:(on,210ms,0) ino:42363 sk:80f19ae0 rto:0.23 ato:0.04 qack:15 bidir cwnd:10 reordering:0
ESTAB 0 0 2.30.18.250:4242 139.162.172.21:53328 ino:42363
sk:80f19ae0 rto:0.23 ato:0.04 qack:15 bidir cwnd:10 reordering:0
Same behavior is observed with small payload (50 bytes).
Looking at tcpdump[1] recorded at the router:
00:00:00.000000 IP brie.darkk.net.ru.52566 > 2.30.18.250.4242: Flags [S], seq 2422862909, win 29200, options [mss 1460,sackOK,TS val
1141259943 ecr 0,nop,wscale 7], length 0
00:00:00.000314 IP 2.30.18.250.4242 > brie.darkk.net.ru.52566: Flags [S.], seq 4132184401, ack 2422862910, win 28800, options [mss 1452,sackOK,TS val 3539818 ecr 1141259943,nop,wscale 3], length 0
00:00:00.022541 IP brie.darkk.net.ru.52566 > 2.30.18.250.4242: Flags [.], ack 1, win 229, options [nop,nop,TS val 1141259950 ecr 3539818], length 0
00:00:00.022999 IP brie.darkk.net.ru.52566 > 2.30.18.250.4242: Flags [P.], seq 1:51, ack 1, win 229, options [nop,nop,TS val 1141259950 ecr 3539818], length 50
00:00:00.023192 IP 2.30.18.250.4242 > brie.darkk.net.ru.52566: Flags [.], ack 51, win 3600, options [nop,nop,TS val 3539824 ecr 1141259950], length 0
00:00:00.029527 IP 2.30.18.250.4242 > brie.darkk.net.ru.52566: Flags [P.], seq 1:51, ack 51, win 3600, options [nop,nop,TS val 3539826 ecr 1141259950], length 50 #### ~6ms to echo
00:00:00.052116 IP brie.darkk.net.ru.52566 > 2.30.18.250.4242: Flags [.], ack 51, win 229, options [nop,nop,TS val 1141259959 ecr 3539826], length 0
00:00:00.553865 IP brie.darkk.net.ru.52566 > 2.30.18.250.4242: Flags [P.], seq 51:101, ack 51, win 229, options [nop,nop,TS val 1141260110 ecr 3539826], length 50
00:00:00.556725 IP 2.30.18.250.4242 > brie.darkk.net.ru.52566: Flags [P.], seq 51:101, ack 101, win 3600, options [nop,nop,TS val 3539957 ecr 1141260110], length 50 #### ~3ms
00:00:00.579130 IP brie.darkk.net.ru.52566 > 2.30.18.250.4242: Flags [.], ack 101, win 229, options [nop,nop,TS val 1141260117 ecr 3539957], length 0
00:00:01.080645 IP brie.darkk.net.ru.52566 > 2.30.18.250.4242: Flags [P.], seq 101:151, ack 101, win 229, options [nop,nop,TS val
1141260267 ecr 3539957], length 50
00:00:01.120859 IP 2.30.18.250.4242 > brie.darkk.net.ru.52566: Flags [.], ack 151, win 3600, options [nop,nop,TS val 3540099 ecr 1141260267], length 0
00:00:01.304887 IP 2.30.18.250.4242 > brie.darkk.net.ru.52566: Flags [P.], seq 101:151, ack 151, win 3600, options [nop,nop,TS val 3540145 ecr 1141260267], length 50 #### ~224ms!
00:00:01.327310 IP brie.darkk.net.ru.52566 > 2.30.18.250.4242: Flags [.], ack 151, win 229, options [nop,nop,TS val 1141260341 ecr 3540145], length 0 ...
`strace` shows no evidence[2] that it's userspace delay, the echo server gets the data promptly and responds within couple of milliseconds.
TCP_NODELAY is turned on, TCP_CORK guard is added to tcp server code to get clear timestamps in strace.
[1] https://gist.github.com/darkk/6b7f3127c1c343a1ccb8e0b59a44f5bf#file-trace-2-pcap-txt
[2] https://gist.github.com/darkk/6b7f3127c1c343a1ccb8e0b59a44f5bf#file-trace-2-strace
tc qdisc is default one and does not report drops, moreover, changing qdisc to plain fifo does not help:
qdisc fq_codel 0: dev pppoa-wan root refcnt 2 limit 1024p flows 1024 quantum 1496 target 5.0ms interval 100.0ms ecn Sent 10859227 bytes 18757 pkt (dropped 0, overlimits 0 requeues 0) backlog 0b 0p requeues 0
maxpacket 0 drop_overlimit 0 new_flow_count 0 ecn_mark 0
new_flows_len 0 old_flows_len 0
I've also run testcase using the link with different RTT (thus different RTO), got same results — the third and following packets are delayed by the router for one RTO so it does not look like hardcoded Nagle's delay. It looks like TCP retransmission, but the first packet is never logged. It's not captured by `tcpdump` or corresponding `iptables -j LOG` rule. The kernel has no /proc/net/snmp, so I can't tell if the RetransSegs counter is bumped.
You can get the tools I use to reproduce the issue at https://gist.github.com/darkk/6b7f3127c1c343a1ccb8e0b59a44f5bf
UDP and ICMP are not affected. I've also seen some issues in IP fragmentation/reassembly of over-MTU UDP datagrams, but they were not reproducible with another ISP.
Versions:
MOTD: DESIGNATED DRIVER (Bleeding Edge, r49162)
uname: Linux OpenWrt 4.4.6 #1 Fri May 13 12:56:05 UTC 2016 mips GNU/Linux
--
WBRBW, Leonid Evdokimov
xmpp:leon at darkk.net.ru && http://darkk.net.ru && tel:+79816800702 _______________________________________________
openwrt-devel mailing list
openwrt-devel at lists.openwrt.org
https://lists.openwrt.org/cgi-bin/mailman/listinfo/openwrt-devel
_______________________________________________
openwrt-devel mailing list
openwrt-devel at lists.openwrt.org
https://lists.openwrt.org/cgi-bin/mailman/listinfo/openwrt-devel
More information about the openwrt-devel
mailing list