Did you test also with the latest linux-next kernel? Some recent changes like
2e6eedb4813e
"r8169: make use of xmit_more and __netdev_sent_queue" may have a positive
impact.
On 10.12.2018 00:28, Risto Pajula wrote:
>
> Hello.
>
> Old subject: "Re: IP fragmentation performance and don't fragment bug when
> forwarding
>
>
> I have now been tracing the kernel and finding the bug seems difficult. I
> think the bug is combination of several things, likely cause is that it only
> occurs with rtl8169 and how it is using the netdevapi/DQL api.
>
> From my investigations seems that following happens:
>
> *Burst of frames is received from internet. (eth0)
> *These are accepted and forwarded to the (eth1)
> *DQL hits the limit, this causes the scheduling for the device to be stopped
> (__QUEUE_STATE_STACK_XOFF)
> *This and combination of some timing causes the performance degradation,
> messages are only scheduled for transmission in soft Irq context.
>
> I still do now know, why the DQL hits the limits.. I think it should not,
> maybe something undesirable first happens with rtl8169.
>
> I inserted following trace printk functions to the code..
>
> rtl8169_start_xmit:
> trace_printk("ORP33 %s rtl8169_start_xmit len: %d entry: %u cur_tx: %u frags:
> %d dirty_tx: %u tx_left: %u\n" , tp->dev->name, skb->len, entry, tp->cur_tx,
> frags, tp->dirty_tx, (tp->cur_tx - tp->dirty_tx) );
>
>
> rtl_tx:
> trace_printk("ORP33 %s rtl_tx len: %d entry: %u cur_tx: %u frags: %d
> dirty_tx: %u tx_left: %u\n" , tp->dev->name, tx_skb->skb->len, tp->cur_tx %
> NUM_TX_DESC, tp->cur_tx, 0, dirty_tx, tx_left );
>
>
> Here is some grepped output only filtering the ping packet in two different
> situations:
>
> //trace when downloading ubuntu (~20MB/s), only 3 secs fit to buffer. ping is
> all the time normal....
> //orig tracing.out3754
> 117493: <idle>-0 [000] ..s. 5235.407116: rtl8169_poll: ORP33
> eth1 rtl_tx len: 54 entry: 57 cur_tx: 3747641 frags: 0 dirty_tx: 3747640
> tx_left: 1
> 118704: <idle>-0 [000] ..s. 5235.416057: rtl8169_poll: ORP33
> eth1 rtl_tx len: 54 entry: 20 cur_tx: 3747668 frags: 0 dirty_tx: 3747667
> tx_left: 1
> 346319: hping3-2871 [000] .... 5236.002456: rtl8169_start_xmit:
> ORP33 eth1 rtl8169_start_xmit len: 54 entry: 8 cur_tx: 3754312 frags: 0
> dirty_tx: 3754312 tx_left: 0
> 346337: hping3-2871 [000] ..s. 5236.002475: rtl8169_poll: ORP33
> eth1 rtl_tx len: 54 entry: 9 cur_tx: 3754313 frags: 0 dirty_tx: 3754312
> tx_left: 1
> 1277155: hping3-2871 [001] .... 5237.002627: rtl8169_start_xmit:
> ORP33 eth1 rtl8169_start_xmit len: 54 entry: 38 cur_tx: 3766502 frags: 0
> dirty_tx: 3766502 tx_left: 0
> 1277173: <idle>-0 [000] ..s. 5237.002646: rtl8169_poll: ORP33
> eth1 rtl_tx len: 54 entry: 39 cur_tx: 3766503 frags: 0 dirty_tx: 3766502
> tx_left: 1
>
>
> //imcp messages from route to intenal network when TCP stream is on.
> tracing.out3236/eth1_ring.txt is the original
> //no idea why the first frame is tripled...
> 200792: hping3-2871 [001] .... 3239.593384: rtl8169_start_xmit:
> ORP33 eth1 rtl8169_start_xmit len: 54 entry: 34 cur_tx: 2132770 frags: 0
> dirty_tx: 2132770 tx_left: 0
> 201578: hping3-2871 [001] .... 3240.593625: rtl8169_start_xmit:
> ORP33 eth1 rtl8169_start_xmit len: 54 entry: 40 cur_tx: 2132776 frags: 0
> dirty_tx: 2132776 tx_left: 0
> 341061: <idle>-0 [000] ..s. 3241.738011: rtl8169_start_xmit:
> ORP33 eth1 rtl8169_start_xmit len: 54 entry: 52 cur_tx: 2133684 frags: 0
> dirty_tx: 2133680 tx_left: 4
> 342112: <idle>-0 [000] ..s. 3241.745297: rtl8169_poll: ORP33
> eth1 rtl_tx len: 54 entry: 59 cur_tx: 2133691 frags: 0 dirty_tx: 2133684
> tx_left: 7
> 500126: <idle>-0 [000] ..s. 3242.739500: rtl8169_start_xmit:
> ORP33 eth1 rtl8169_start_xmit len: 54 entry: 49 cur_tx: 2134513 frags: 0
> dirty_tx: 2134505 tx_left: 8
> 501739: <idle>-0 [000] ..s. 3242.751654: rtl8169_poll: ORP33
> eth1 rtl_tx len: 54 entry: 58 cur_tx: 2134522 frags: 0 dirty_tx: 2134513
> tx_left: 9
> 646220: <idle>-0 [000] ..s. 3243.745761: rtl8169_start_xmit:
> ORP33 eth1 rtl8169_start_xmit len: 54 entry: 41 cur_tx: 2135273 frags: 0
> dirty_tx: 2135267 tx_left: 6
> 647633: <idle>-0 [000] ..s. 3243.755486: rtl8169_poll: ORP33
> eth1 rtl_tx len: 54 entry: 49 cur_tx: 2135281 frags: 0 dirty_tx: 2135273
> tx_left: 8
> 802878: <idle>-0 [000] ..s. 3244.739947: rtl8169_start_xmit:
> ORP33 eth1 rtl8169_start_xmit len: 54 entry: 23 cur_tx: 2136087 frags: 0
> dirty_tx: 2136081 tx_left: 6
> 804298: <idle>-0 [000] ..s. 3244.749677: rtl8169_poll: ORP33
> eth1 rtl_tx len: 54 entry: 31 cur_tx: 2136095 frags: 0 dirty_tx: 2136087
> tx_left: 8
> 961190: <idle>-0 [000] ..s. 3245.746217: rtl8169_start_xmit:
> ORP33 eth1 rtl8169_start_xmit len: 54 entry: 16 cur_tx: 2136912 frags: 0
> dirty_tx: 2136906 tx_left: 6
> 962610: <idle>-0 [000] ..s. 3245.755946: rtl8169_poll: ORP33
> eth1 rtl_tx len: 54 entry: 24 cur_tx: 2136920 frags: 0 dirty_tx: 2136912
> tx_left: 8
> 1118044: <idle>-0 [000] ..s. 3246.740336: rtl8169_start_xmit:
> ORP33 eth1 rtl8169_start_xmit len: 54 entry: 62 cur_tx: 2137726 frags: 0
> dirty_tx: 2137720 tx_left: 6
> 1119443: <idle>-0 [000] ..s. 3246.750047: rtl8169_poll: ORP33
> eth1 rtl_tx len: 54 entry: 5 cur_tx: 2137733 frags: 0 dirty_tx: 2137726
> tx_left: 7
> 1264047: <idle>-0 [000] ..s. 3247.709202: rtl8169_start_xmit:
> ORP33 eth1 rtl8169_start_xmit len: 54 entry: 29 cur_tx: 2138525 frags: 0
> dirty_tx: 2138518 tx_left: 7
> 1264740: <idle>-0 [000] ..s. 3247.718918: rtl8169_poll: ORP33
> eth1 rtl_tx len: 54 entry: 33 cur_tx: 2138529 frags: 0 dirty_tx: 2138525
> tx_left: 4
> 1419958: <idle>-0 [000] ..s. 3248.736436: rtl8169_start_xmit:
> ORP33 eth1 rtl8169_start_xmit len: 54 entry: 48 cur_tx: 2139312 frags: 0
> dirty_tx: 2139305 tx_left: 7
> 1421551: <idle>-0 [000] ..s. 3248.746189: rtl8169_poll: ORP33
> eth1 rtl_tx len: 54 entry: 56 cur_tx: 2139320 frags: 0 dirty_tx: 2139312
> tx_left: 8
> 1578746: <idle>-0 [000] ..s. 3249.742702: rtl8169_start_xmit:
> ORP33 eth1 rtl8169_start_xmit len: 54 entry: 46 cur_tx: 2140142 frags: 0
> dirty_tx: 2140135 tx_left: 7
> 1580194: <idle>-0 [000] ..s. 3249.752457: rtl8169_poll: ORP33
> eth1 rtl_tx len: 54 entry: 54 cur_tx: 2140150 frags: 0 dirty_tx: 2140142
> tx_left: 8
> 1729597: <idle>-0 [000] ..s. 3250.746839: rtl8169_start_xmit:
> ORP33 eth1 rtl8169_start_xmit len: 54 entry: 36 cur_tx: 2140964 frags: 0
> dirty_tx: 2140957 tx_left: 7
> 1731015: <idle>-0 [000] ..s. 3250.756594: rtl8169_poll: ORP33
> eth1 rtl_tx len: 54 entry: 43 cur_tx: 2140971 frags: 0 dirty_tx: 2140964
> tx_left: 7
> 1881028: <idle>-0 [000] ..s. 3251.740991: rtl8169_start_xmit:
> ORP33 eth1 rtl8169_start_xmit len: 54 entry: 19 cur_tx: 2141779 frags: 0
> dirty_tx: 2141772 tx_left: 7
> 1881381: <idle>-0 [000] ..s. 3251.750718: rtl8169_poll: ORP33
> eth1 rtl_tx len: 54 entry: 26 cur_tx: 2141786 frags: 0 dirty_tx: 2141779
> tx_left: 7
> //something happens, the output queue empties.. now it is fast, and
> rtl8169_start_xmit is not called from soft_irq
> 1896178: hping3-2871 [001] .... 3252.595994: rtl8169_start_xmit:
> ORP33 eth1 rtl8169_start_xmit len: 54 entry: 23 cur_tx: 2141911 frags: 0
> dirty_tx: 2141911 tx_left: 0
> 1896196: <idle>-0 [000] ..s. 3252.596055: rtl8169_poll: ORP33
> eth1 rtl_tx len: 54 entry: 24 cur_tx: 2141912 frags: 0 dirty_tx: 2141911
> tx_left: 1
> 1923136: hping3-2871 [001] .... 3253.596227: rtl8169_start_xmit:
> ORP33 eth1 rtl8169_start_xmit len: 54 entry: 50 cur_tx: 2142066 frags: 0
> dirty_tx: 2142066 tx_left: 0
> 1923154: <idle>-0 [000] ..s. 3253.596289: rtl8169_poll: ORP33
> eth1 rtl_tx len: 54 entry: 51 cur_tx: 2142067 frags: 0 dirty_tx: 2142066
> tx_left: 1
> 1951633: hping3-2871 [001] .... 3254.596459: rtl8169_start_xmit:
> ORP33 eth1 rtl8169_start_xmit len: 54 entry: 5 cur_tx: 2142213 frags: 0
> dirty_tx: 2142213 tx_left: 0
> 1951651: <idle>-0 [000] ..s. 3254.596521: rtl8169_poll: ORP33
> eth1 rtl_tx len: 54 entry: 6 cur_tx: 2142214 frags: 0 dirty_tx: 2142213
> tx_left: 1
> 1954472: hping3-2871 [001] .... 3255.596700: rtl8169_start_xmit:
> ORP33 eth1 rtl8169_start_xmit len: 54 entry: 15 cur_tx: 2142223 frags: 0
> dirty_tx: 2142223 tx_left: 0
> 1954490: <idle>-0 [000] ..s. 3255.596763: rtl8169_poll: ORP33
> eth1 rtl_tx len: 54 entry: 16 cur_tx: 2142224 frags: 0 dirty_tx: 2142223
> tx_left: 1
> //until it soon, again is slow..
>
>
> BR.
> Risto
>
>
>
> On 7.12.2018 16:46, Risto Pajula wrote:
>> Hello.
>>
>> I have been to track the poor forwarding latency to the TCP Window scale
>> options. The Netgem device uses rather large windows scale options (x256)
>> and I have been able to reproduce the routers poor forwarding latency also
>> with linux box running in the internal network and changing the
>> net.ipv4.tcp_rmem to a large value and thus changing the TCP window scaling
>> options to larger ones. I still do not have clue why this causes the
>> forwarfing in the linux kernel to block? Maybe something in the connection
>> tracking....?
>>
>>
>> With the ICMP timestamp messages I have been able to also pinpoint that the
>> latency is caused in the eth1 sending side (the following hping3 example is
>> run in the router toward the internal network...
>>
>>
>> xxx:/usr/src/linux-4.20-rc2 # hping3 192.168.0.112 --icmp --icmp-ts -V
>> using eth1, addr: 192.168.0.1, MTU: 1500
>> HPING 192.168.0.112 (eth1 192.168.0.112): icmp mode set, 28 headers + 0 data
>> bytes
>> len=46 ip=192.168.0.112 ttl=64 id=49464 tos=0 iplen=40
>> icmp_seq=0 rtt=7.9 ms
>> ICMP timestamp: Originate=52294891 Receive=52294895 Transmit=52294895
>> ICMP timestamp RTT tsrtt=7
>>
>> len=46 ip=192.168.0.112 ttl=64 id=49795 tos=0 iplen=40
>> icmp_seq=1 rtt=235.9 ms
>> ICMP timestamp: Originate=52295891 Receive=52296128 Transmit=52296128
>> ICMP timestamp RTT tsrtt=235
>>
>> len=46 ip=192.168.0.112 ttl=64 id=49941 tos=0 iplen=40
>> icmp_seq=2 rtt=3.8 ms
>> ICMP timestamp: Originate=52296891 Receive=52296895 Transmit=52296895
>> ICMP timestamp RTT tsrtt=3
>>
>> len=46 ip=192.168.0.112 ttl=64 id=50685 tos=0 iplen=40
>> icmp_seq=3 rtt=47.8 ms
>> ICMP timestamp: Originate=52297891 Receive=52297940 Transmit=52297940
>> ICMP timestamp RTT tsrtt=47
>>
>> len=46 ip=192.168.0.112 ttl=64 id=51266 tos=0 iplen=40
>> icmp_seq=4 rtt=7.7 ms
>> ICMP timestamp: Originate=52298891 Receive=52298895 Transmit=52298895
>> ICMP timestamp RTT tsrtt=7
>>
>> len=46 ip=192.168.0.112 ttl=64 id=52245 tos=0 iplen=40
>> icmp_seq=5 rtt=3.7 ms
>> ICMP timestamp: Originate=52299891 Receive=52299895 Transmit=52299895
>> ICMP timestamp RTT tsrtt=3
>>
>> ^C
>> --- 192.168.0.112 hping statistic ---
>> 6 packets tramitted, 6 packets received, 0% packet loss
>> round-trip min/avg/max = 3.7/51.1/235.9 ms
>>
>>
>>
>> BR.
>> Risto
>>
>> On 2.12.2018 23:32, Risto Pajula wrote:
>>> Hello.
>>>
>>> You can most likely ignore the "DF Bit, mtu bug when forwarding" case.
>>> There isn't actually big IP packets on the wire, instead there is burst of
>>> packets on the wire, which are combined by the GRO... And thus dropping
>>> them should not happen. Sorry about the invalid bug report.
>>>
>>> However the poor latency from intenal network to the internet still remain,
>>> both GRO enabled and disabled. I will try to study further...
>>>
>>>
>>> BR.
>>> Risto
>>>
>>>
>>> On 2.12.2018 14:01, Risto Pajula wrote:
>>>> Hello.
>>>>
>>>> I have encountered a weird performance problem in Linux IP fragmentation
>>>> when using video streaming services behind the NAT. Also I have studied a
>>>> possible bug in the DF bit (don't fragment) handling when forwarding the
>>>> IP packets.
>>>>
>>>> First the system setup description:
>>>>
>>>> [host1]-int lan-(eth1)[linux router](eth0)-extlan-[fibre router]-internet
>>>>
>>>> where:
>>>> host1: is a Netgem N7800 "cable box" for online video streaming services
>>>> provided by local telco (Can access Netflix, HBO nordic, "live TV", etc.)
>>>> linux router: Linux computer with Dualcore Intel Celeron G1840, running
>>>> currently Linux kernel 4.20.0-rc2, and openSUSE Leap 15.0
>>>> eth1: Linux Routers internal (NAT) interface, 192.168.0.1/24 network, mtu
>>>> set to 1500, RTL8169sb/8110sb
>>>> eth0: Linux Routers internet facing interface, public ip address, mtu set
>>>> to 1500, RTL8168evl/8111evl
>>>> fibre router: Alcatel Lucent fibre router (I-241G-Q), directly connected
>>>> to the eth0 of the Linux router.
>>>>
>>>> And now when using the Netgem N7800 with online video services (Netflix,
>>>> HBO nordic, etc) the Linux router will receive very BIG IP packets in the
>>>> eth0 upto ~20kB, this seems to lead to the following problems in the Linux
>>>> IP stack.
>>>>
>>>> IP fragmentation performance:
>>>> When the Linux router receives these large IP packets in the eth0
>>>> everything works, but it seems that them cause very large performance
>>>> degradation from internal network to the internet regarding the latency
>>>> when the IP fragmentation is performed. The ping latency from internal
>>>> network to the internel network increases from stable 15ms-20ms up to
>>>> 700-800ms AND also the ping from the internal network to the linux router
>>>> eth1 (192.168.0.). However up link works perfectly, the ping is still
>>>> stable when streaming the online services (From linux router to the
>>>> internet). It seems that the IP fragmentation is somehow blocking the eth1
>>>> reception or transmission for very long time (which it shouldn't). I'm
>>>> able to test and debug the issue further, but advice regarding where to
>>>> look would be appreciated.
>>>>
>>>>
>>>> DF Bit, mtu bug when forwarding:
>>>> I have started to study the above mentioned problem and have found a
>>>> possible bug in the DF bit and mtu handling in IP forwarding. The BIG
>>>> packets received from streaming services all have the "DF bit" set and the
>>>> question is that should we be forwarding them at all as that would result
>>>> them being fragmented? Apparently we currently are... I have traced this
>>>> down to the ip_forward.c function ip_exceeds_mtu(), and the following
>>>> patch seems to fix that.
>>>>
>>>> --- net/ipv4/ip_forward.c.orig 2018-12-02 11:09:32.764320780 +0200
>>>> +++ net/ipv4/ip_forward.c 2018-12-02 12:53:25.031232347 +0200
>>>> @@ -49,7 +49,7 @@ static bool ip_exceeds_mtu(const struct
>>>> return false;
>>>>
>>>> /* original fragment exceeds mtu and DF is set */
>>>> - if (unlikely(IPCB(skb)->frag_max_size > mtu))
>>>> + if (unlikely(skb->len > mtu))
>>>> return true;
>>>>
>>>> if (skb->ignore_df)
>>>>
>>>>
>>>> This seems to work (in some ways) - after the change IP packets that are
>>>> too large to the internal network get dropped and we are sending "ICMP
>>>> Destination unreachable, The datagram is too big" messages to the
>>>> originator (as we should?). However it seems that not all services really
>>>> like this... Netflix behaves as expected and ping is stable from internal
>>>> network to the internet, but for example HBO nordic will not work anymore
>>>> (too little buffering? Retransimissions not working?). So it seems the
>>>> original issue should be also fixed (And the fragmention should be
>>>> allowed?).
>>>>
>>>>
>>>>
>>>> Any advice would be appreciated. Thanks!
>>>>
>>>> PS. Watching TV was not this intensive 20 years ago :)
>>>>
>
