lkml.org 
[lkml]   [1998]   [Sep]   [8]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
SubjectOutgoing packets queued for ever...
Date
From
I'm seeing extremely strange behaviour in recent 2.1 kernels - I noticed it in 
2.1.120, and dropping back to 2.1.117 hasn't cured it.

The problem seems to be that packets due to be sent out the ISDN interface
aren't being sent until another packet arrives on the queue. So the queue is
never emptied - there are always packets ready to be sent, but even when the
link is idle, they remain queued until a new packet arrives to push them off
the queue and out into the ether.

I can start trying to ping the other end of the link, and get constant round
trip times of extremely close to an integer number of seconds, equal to the
current size of the packet queue, because the packets are remaining on the
outgoing queue until enough new packets have arrived to flush the preceding
packets.


For example... The link is idle, with some packets queued, but unsent, from a
stalled TCP connection. tcpdump is running and shows no activity since the
packet at 14:36:08.550691.

At 14:37:11, I start to ping the other side of the ISDN link. Each time 'ping'
sends a packet, I see a packet go out the ISDN link. It's just that the packet
that gets transmitted bears no relation to the packet that 'ping' tried to
send. The first six packets are from the TCP connection, then when 'ping' tries
to send its seventh packet, its first one is actually transmitted, etc. Hence a
fairly constant round trip time of just over six seconds.

The length of the queue varies between the ideal zero and about nine. I have
yet to see it get any higher.

--- tcpdump output:

14:36:08.550691 195.11.50.200.8080 > 158.152.16.50.1709: . ack 430 win 8760 <nop,nop,timestamp 1072144 15104214>

<Now the link is idle for a minute, even though there are packets to be sent>
<It remains idle until I start 'ping' in another window, at which point...>

14:37:11.424123 158.152.16.50.1709 > 195.11.50.200.8080: . ack 218 win 32120 <nop,nop,timestamp 15104276 1072075> (DF)
14:37:11.454123 195.11.50.200.8080 > 158.152.16.50.1709: R 3963254873:3963254873(0) win 32120 <nop,nop,timestamp 15104276 1072075> (DF)

<The packet is sent at exactly the same time that 'ping' attempts to send
its first ICMP echo request. The response is fast, because it's my
ISP's web cache that it's talking to - I don't think there's a similar
problem with incoming packets.>

14:37:12.424019 158.152.16.50.1709 > 195.11.50.200.8080: . ack 218 win 32120 <nop,nop,timestamp 15104376 1072077> (DF)
14:37:12.454019 195.11.50.200.8080 > 158.152.16.50.1709: R 3963254873:3963254873(0) win 32120 <nop,nop,timestamp 15104376 1072077> (DF)

<Exactly one second later, with 'ping's second packet>

14:37:13.423915 158.152.16.50.1709 > 195.11.50.200.8080: . ack 218 win 32120 <nop,nop,timestamp 15104477 1072079> (DF)
14:37:13.513915 195.11.50.200.8080 > 158.152.16.50.1709: R 3963254873:3963254873(0) win 32120 <nop,nop,timestamp 15104477 1072079> (DF)

14:37:14.423810 158.152.16.50.1709 > 195.11.50.200.8080: . ack 218 win 32120 <nop,nop,timestamp 15104577 1072081> (DF)
14:37:14.453810 195.11.50.200.8080 > 158.152.16.50.1709: R 3963254873:3963254873(0) win 32120 <nop,nop,timestamp 15104577 1072081> (DF)

14:37:15.423706 158.152.16.50.1709 > 195.11.50.200.8080: . ack 218 win 32120 <nop,nop,timestamp 15105073 1072091> (DF)
14:37:15.453706 195.11.50.200.8080 > 158.152.16.50.1709: R 3963254873:3963254873(0) win 32120 <nop,nop,timestamp 15105073 1072091> (DF)

14:37:16.423602 158.152.16.50.1709 > 195.11.50.200.8080: F 429:429(0) ack 218 win 32120 <nop,nop,timestamp 15107679 1072091> (DF)
14:37:16.453602 195.11.50.200.8080 > 158.152.16.50.1709: R 3963254873:3963254873(0) win 32120 <nop,nop,timestamp 15107679 1072091> (DF)

<Now ping has tried to send six packets, and each time it has tried,
an unrelated packet has been sent at exactly the same time.>

14:37:17.423498 158.152.16.50 > 158.152.1.222: icmp: echo request
4500 0054 113c 0000 4001 1a2d 9e98 1032
9e98 01de 0800 8613 b901 00
14:37:17.453498 158.152.1.222 > 158.152.16.50: icmp: echo reply
4500 0054 c521 0000 ff01 a746 9e98 01de
9e98 1032 0000 8e13 b901 00

<Finally an ICMP echo packet. Six seconds late.>

14:37:18.423393 158.152.16.50 > 158.152.1.222: icmp: echo request
4500 0054 1150 0000 4001 1a19 9e98 1032
9e98 01de 0800 c519 b901 01
14:37:18.453393 158.152.1.222 > 158.152.16.50: icmp: echo reply
4500 0054 c621 0000 ff01 a646 9e98 01de
9e98 1032 0000 cd19 b901 01

<etc...>

14:37:19.423289 158.152.16.50 > 158.152.1.222: icmp: echo request
4500 0054 1163 0000 4001 1a06 9e98 1032
9e98 01de 0800 331a b901 02
14:37:19.483289 158.152.1.222 > 158.152.16.50: icmp: echo reply
4500 0054 c821 0000 ff01 a446 9e98 01de
9e98 1032 0000 3b1a b901 02

14:37:20.423185 158.152.16.50 > 158.152.1.222: icmp: echo request
4500 0054 1176 0000 4001 19f3 9e98 1032
9e98 01de 0800 9b1a b901 03
14:37:20.463185 158.152.1.222 > 158.152.16.50: icmp: echo reply
4500 0054 d021 0000 ff01 9c46 9e98 01de
9e98 1032 0000 a31a b901 03

14:37:21.423081 158.152.16.50 > 158.152.1.222: icmp: echo request
4500 0054 1189 0000 4001 19e0 9e98 1032
9e98 01de 0800 071b b901 04
14:37:21.453081 158.152.1.222 > 158.152.16.50: icmp: echo reply
4500 0054 d521 0000 ff01 9746 9e98 01de
9e98 1032 0000 0f1b b901 04


--- ping output:
firewall /root # date; ping demon-du.demon.co.uk
Tue Sep 8 14:37:11 BST 1998
PING demon-du.demon.co.uk (158.152.1.222): 56 data bytes
64 bytes from 158.152.1.222: icmp_seq=0 ttl=255 time=6038.1 ms
64 bytes from 158.152.1.222: icmp_seq=1 ttl=255 time=6037.6 ms
64 bytes from 158.152.1.222: icmp_seq=2 ttl=255 time=6069.6 ms
64 bytes from 158.152.1.222: icmp_seq=3 ttl=255 time=6044.7 ms
64 bytes from 158.152.1.222: icmp_seq=4 ttl=255 time=6036.8 ms
64 bytes from 158.152.1.222: icmp_seq=5 ttl=255 time=6037.8 ms
64 bytes from 158.152.1.222: icmp_seq=6 ttl=255 time=6039.7 ms
64 bytes from 158.152.1.222: icmp_seq=7 ttl=255 time=6041.3 ms
64 bytes from 158.152.1.222: icmp_seq=8 ttl=255 time=6037.6 ms
64 bytes from 158.152.1.222: icmp_seq=9 ttl=255 time=6037.4 ms



Kernel is a stock 2.1.120, Intel UP.
ISDN is a Teles 16.3PnP.
This machine is also masquerading.
Closing down the link and restarting it seems to make no difference,
and the machine doesn't show any signs of misbehaviour when routing packets on
the Ethernet - it has 100Base-T and 10Base-2, both Tulip cards.

Rebooting the machine seems to help. Sometimes the problem comes back within
minutes, though. Sometimes it takes a few days.

What else can I do to try to find the problem?


---- ---- ----
David Woodhouse David.Woodhouse@mvhi.com Office: (+44) 1223 810302
Project Leader, Process Information Systems Mobile: (+44) 976 658355
Axiom (Cambridge) Ltd., Swaffham Bulbeck, Cambridge, CB5 0NA, UK.
finger dwmw2@ferret.lmh.ox.ac.uk for PGP key.



-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.rutgers.edu
Please read the FAQ at http://www.tux.org/lkml/faq.html

\
 
 \ /
  Last update: 2005-03-22 13:44    [W:0.036 / U:0.032 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site