Message-ID: <fe2f6240-f738-712f-2706-8bf521a8dc33@gmail.com>
Date:   Tue, 11 Dec 2018 00:20:27 +0200
From:   Risto Pajula <or.pajula@...il.com>
To:     Heiner Kallweit <hkallweit1@...il.com>
Cc:     "David S. Miller" <davem@...emloft.net>,
        Alexey Kuznetsov <kuznet@....inr.ac.ru>,
        Realtek linux nic maintainers <nic_swsd@...ltek.com>,
        netdev@...r.kernel.org
Subject: Re: IP (rtl8169) forwarding bug (performance)

Hello.

I have not yet tested with linux-next but I will, thanks for pointing 
that out.

...But I have studied the problem a bit more, indeed it seems that the 
rtl8169 transmission queue gets stuck.

Below is some trace log. Starting from 802026 a burst of frames is 
forwarded from eth0 to eth1 and when we get to the rtl_tx only two 
frames have been transmitted.. (Should have had 1,25 ms to transmit 
them).. Also then the sequence seems to repeat for very long time that 
only two massages get transmitted.

800541:          <idle>-0     [001] ..s.  7237.698143: 
rtl8169_start_xmit: ORP33 eth1 rtl8169_start_xmit len: 1506 entry: 34 
cur_tx: 4406946 frags: 0 dirty_tx: 4406946 tx_left: 0
800671:          <idle>-0     [001] ..s.  7237.698189: 
rtl8169_start_xmit: ORP33 eth1 rtl8169_start_xmit len: 1506 entry: 35 
cur_tx: 4406947 frags: 0 dirty_tx: 4406946 tx_left: 1
800835:          <idle>-0     [001] ..s.  7237.698235: 
rtl8169_start_xmit: ORP33 eth1 rtl8169_start_xmit len: 1506 entry: 36 
cur_tx: 4406948 frags: 0 dirty_tx: 4406946 tx_left: 2
800905:          <idle>-0     [000] ..s.  7237.698255: rtl8169_poll: 
ORP33 eth1 rtl_tx len: 1506 entry: 37 cur_tx: 4406949 frags: 0 dirty_tx: 
4406946 tx_left: 3
800932:          <idle>-0     [000] ..s.  7237.698263: rtl8169_poll: 
ORP33 eth1 rtl_tx len: 1506 entry: 37 cur_tx: 4406949 frags: 0 dirty_tx: 
4406947 tx_left: 2
800960:          <idle>-0     [000] ..s.  7237.698270: rtl8169_poll: 
ORP33 eth1 rtl_tx len: 1506 entry: 37 cur_tx: 4406949 frags: 0 dirty_tx: 
4406948 tx_left: 1
800998:          <idle>-0     [001] ..s.  7237.698282: 
rtl8169_start_xmit: ORP33 eth1 rtl8169_start_xmit len: 1506 entry: 37 
cur_tx: 4406949 frags: 0 dirty_tx: 4406949 tx_left: 0
801085:          <idle>-0     [000] ..s.  7237.698312: rtl8169_poll: 
ORP33 eth1 rtl_tx len: 1506 entry: 38 cur_tx: 4406950 frags: 0 dirty_tx: 
4406949 tx_left: 1
801137:          <idle>-0     [001] ..s.  7237.698329: 
rtl8169_start_xmit: ORP33 eth1 rtl8169_start_xmit len: 1506 entry: 38 
cur_tx: 4406950 frags: 0 dirty_tx: 4406950 tx_left: 0
801229:          <idle>-0     [000] ..s.  7237.698363: rtl8169_poll: 
ORP33 eth1 rtl_tx len: 1506 entry: 39 cur_tx: 4406951 frags: 0 dirty_tx: 
4406950 tx_left: 1
801264:          <idle>-0     [001] ..s.  7237.698375: 
rtl8169_start_xmit: ORP33 eth1 rtl8169_start_xmit len: 1506 entry: 39 
cur_tx: 4406951 frags: 0 dirty_tx: 4406951 tx_left: 0
801356:          <idle>-0     [000] ..s.  7237.698409: rtl8169_poll: 
ORP33 eth1 rtl_tx len: 1506 entry: 40 cur_tx: 4406952 frags: 0 dirty_tx: 
4406951 tx_left: 1
801391:          <idle>-0     [001] ..s.  7237.698421: 
rtl8169_start_xmit: ORP33 eth1 rtl8169_start_xmit len: 1506 entry: 40 
cur_tx: 4406952 frags: 0 dirty_tx: 4406952 tx_left: 0
801482:          <idle>-0     [000] ..s.  7237.698455: rtl8169_poll: 
ORP33 eth1 rtl_tx len: 1506 entry: 41 cur_tx: 4406953 frags: 0 dirty_tx: 
4406952 tx_left: 1
801518:          <idle>-0     [001] ..s.  7237.698468: 
rtl8169_start_xmit: ORP33 eth1 rtl8169_start_xmit len: 1506 entry: 41 
cur_tx: 4406953 frags: 0 dirty_tx: 4406953 tx_left: 0
801610:          <idle>-0     [000] ..s.  7237.698502: rtl8169_poll: 
ORP33 eth1 rtl_tx len: 1506 entry: 42 cur_tx: 4406954 frags: 0 dirty_tx: 
4406953 tx_left: 1
801645:          <idle>-0     [001] ..s.  7237.698514: 
rtl8169_start_xmit: ORP33 eth1 rtl8169_start_xmit len: 1506 entry: 42 
cur_tx: 4406954 frags: 0 dirty_tx: 4406954 tx_left: 0
801737:          <idle>-0     [000] ..s.  7237.698548: rtl8169_poll: 
ORP33 eth1 rtl_tx len: 1506 entry: 43 cur_tx: 4406955 frags: 0 dirty_tx: 
4406954 tx_left: 1
801772:          <idle>-0     [001] ..s.  7237.698560: 
rtl8169_start_xmit: ORP33 eth1 rtl8169_start_xmit len: 1506 entry: 43 
cur_tx: 4406955 frags: 0 dirty_tx: 4406955 tx_left: 0
801864:          <idle>-0     [000] ..s.  7237.698594: rtl8169_poll: 
ORP33 eth1 rtl_tx len: 1506 entry: 44 cur_tx: 4406956 frags: 0 dirty_tx: 
4406955 tx_left: 1
801899:          <idle>-0     [001] ..s.  7237.698607: 
rtl8169_start_xmit: ORP33 eth1 rtl8169_start_xmit len: 1506 entry: 44 
cur_tx: 4406956 frags: 0 dirty_tx: 4406956 tx_left: 0
801984:          <idle>-0     [000] ..s.  7237.698640: rtl8169_poll: 
ORP33 eth1 rtl_tx len: 1506 entry: 45 cur_tx: 4406957 frags: 0 dirty_tx: 
4406956 tx_left: 1
802026:          <idle>-0     [001] ..s.  7237.698655: 
rtl8169_start_xmit: ORP33 eth1 rtl8169_start_xmit len: 1506 entry: 45 
cur_tx: 4406957 frags: 0 dirty_tx: 4406957 tx_left: 0
802129:          <idle>-0     [001] ..s.  7237.698701: 
rtl8169_start_xmit: ORP33 eth1 rtl8169_start_xmit len: 1506 entry: 46 
cur_tx: 4406958 frags: 0 dirty_tx: 4406957 tx_left: 1
802232:          <idle>-0     [001] ..s.  7237.698747: 
rtl8169_start_xmit: ORP33 eth1 rtl8169_start_xmit len: 1506 entry: 47 
cur_tx: 4406959 frags: 0 dirty_tx: 4406957 tx_left: 2
802335:          <idle>-0     [001] ..s.  7237.698793: 
rtl8169_start_xmit: ORP33 eth1 rtl8169_start_xmit len: 1506 entry: 48 
cur_tx: 4406960 frags: 0 dirty_tx: 4406957 tx_left: 3
802438:          <idle>-0     [001] ..s.  7237.698840: 
rtl8169_start_xmit: ORP33 eth1 rtl8169_start_xmit len: 1506 entry: 49 
cur_tx: 4406961 frags: 0 dirty_tx: 4406957 tx_left: 4
802541:          <idle>-0     [001] ..s.  7237.698885: 
rtl8169_start_xmit: ORP33 eth1 rtl8169_start_xmit len: 1506 entry: 50 
cur_tx: 4406962 frags: 0 dirty_tx: 4406957 tx_left: 5
802644:          <idle>-0     [001] ..s.  7237.698932: 
rtl8169_start_xmit: ORP33 eth1 rtl8169_start_xmit len: 1506 entry: 51 
cur_tx: 4406963 frags: 0 dirty_tx: 4406957 tx_left: 6
802747:          <idle>-0     [001] ..s.  7237.698978: 
rtl8169_start_xmit: ORP33 eth1 rtl8169_start_xmit len: 1506 entry: 52 
cur_tx: 4406964 frags: 0 dirty_tx: 4406957 tx_left: 7
802851:          <idle>-0     [001] ..s.  7237.699025: 
rtl8169_start_xmit: ORP33 eth1 rtl8169_start_xmit len: 1506 entry: 53 
cur_tx: 4406965 frags: 0 dirty_tx: 4406957 tx_left: 8
805094:          <idle>-0     [000] ..s.  7237.699871: rtl8169_poll: 
ORP33 eth1 rtl_tx len: 1506 entry: 54 cur_tx: 4406966 frags: 0 dirty_tx: 
4406957 tx_left: 9
805126:          <idle>-0     [000] ..s.  7237.699878: rtl8169_poll: 
ORP33 eth1 rtl_tx len: 1506 entry: 54 cur_tx: 4406966 frags: 0 dirty_tx: 
4406958 tx_left: 8
805197:          <idle>-0     [001] ..s.  7237.699905: 
rtl8169_start_xmit: ORP33 eth1 rtl8169_start_xmit len: 1506 entry: 54 
cur_tx: 4406966 frags: 0 dirty_tx: 4406959 tx_left: 7
805234:          <idle>-0     [001] ..s.  7237.699925: 
rtl8169_start_xmit: ORP33 eth1 rtl8169_start_xmit len: 1506 entry: 55 
cur_tx: 4406967 frags: 0 dirty_tx: 4406959 tx_left: 8
811446:          <idle>-0     [000] ..s.  7237.702344: rtl8169_poll: 
ORP33 eth1 rtl_tx len: 1506 entry: 56 cur_tx: 4406968 frags: 0 dirty_tx: 
4406959 tx_left: 9
811479:          <idle>-0     [000] ..s.  7237.702354: rtl8169_poll: 
ORP33 eth1 rtl_tx len: 1506 entry: 56 cur_tx: 4406968 frags: 0 dirty_tx: 
4406960 tx_left: 8
811641:          <idle>-0     [000] ..s.  7237.702395: 
rtl8169_start_xmit: ORP33 eth1 rtl8169_start_xmit len: 1506 entry: 56 
cur_tx: 4406968 frags: 0 dirty_tx: 4406961 tx_left: 7
811733:          <idle>-0     [000] ..s.  7237.702416: 
rtl8169_start_xmit: ORP33 eth1 rtl8169_start_xmit len: 1506 entry: 57 
cur_tx: 4406969 frags: 0 dirty_tx: 4406961 tx_left: 8
812050:          hping3-2871  [000] ..s.  7237.704770: rtl8169_poll: 
ORP33 eth1 rtl_tx len: 1506 entry: 58 cur_tx: 4406970 frags: 0 dirty_tx: 
4406961 tx_left: 9
812061:          hping3-2871  [000] ..s.  7237.704777: rtl8169_poll: 
ORP33 eth1 rtl_tx len: 1506 entry: 58 cur_tx: 4406970 frags: 0 dirty_tx: 
4406962 tx_left: 8
812124:          hping3-2871  [000] ..s.  7237.704811: 
rtl8169_start_xmit: ORP33 eth1 rtl8169_start_xmit len: 1506 entry: 58 
cur_tx: 4406970 frags: 0 dirty_tx: 4406963 tx_left: 7
812176:          hping3-2871  [000] ..s.  7237.704831: 
rtl8169_start_xmit: ORP33 eth1 rtl8169_start_xmit len: 1506 entry: 59 
cur_tx: 4406971 frags: 0 dirty_tx: 4406963 tx_left: 8
812300:          <idle>-0     [000] ..s.  7237.707247: rtl8169_poll: 
ORP33 eth1 rtl_tx len: 1506 entry: 60 cur_tx: 4406972 frags: 0 dirty_tx: 
4406963 tx_left: 9
812312:          <idle>-0     [000] ..s.  7237.707257: rtl8169_poll: 
ORP33 eth1 rtl_tx len: 1506 entry: 60 cur_tx: 4406972 frags: 0 dirty_tx: 
4406964 tx_left: 8
812389:          <idle>-0     [000] ..s.  7237.707297: 
rtl8169_start_xmit: ORP33 eth1 rtl8169_start_xmit len: 1506 entry: 60 
cur_tx: 4406972 frags: 0 dirty_tx: 4406965 tx_left: 7
812426:          <idle>-0     [000] ..s.  7237.707318: 
rtl8169_start_xmit: ORP33 eth1 rtl8169_start_xmit len: 1506 entry: 61 
cur_tx: 4406973 frags: 0 dirty_tx: 4406965 tx_left: 8
812827:          <idle>-0     [000] ..s.  7237.709690: rtl8169_poll: 
ORP33 eth1 rtl_tx len: 1506 entry: 62 cur_tx: 4406974 frags: 0 dirty_tx: 
4406965 tx_left: 9
812838:          <idle>-0     [000] ..s.  7237.709700: rtl8169_poll: 
ORP33 eth1 rtl_tx len: 1506 entry: 62 cur_tx: 4406974 frags: 0 dirty_tx: 
4406966 tx_left: 8
.....


BR.
Risto

On 10.12.2018 23:26, Heiner Kallweit wrote:
> 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 :)
>>>>>

Powered by blists - more mailing lists