Re: [lwip-users] strange TCP ack

[yueyue papa]

I enable TCP debug.  But I did not find how to shorten the resend time.

connect: 192.168.8.130 port 3030
    No,   Conn, Receiv, Error, byes(default: 1 F1: TCP_NODELAY (0),
F2: TCP_DELAY)(1)
     1,    690,   5870,      0,   1025         <<<========my log

######################
malloc(1025), sendData = 0x2040eec0
connect: 192.168.8.130 port 3030
    No,   Conn, Receiv, Error, byes(default: 1 F1: TCP_NODELAY (0),
F2: TCP_DELAY)(1)

tcp_connect to port 3030
tcp_enqueue(pcb=0x201c9690, arg=0x00000000, len=0, flags=2, apiflags=0)
tcp_enqueue: queuelen: 0
tcp_enqueue: queueing 8655:8656 (0x2)
tcp_enqueue: 1 (after enqueued)
tcp_output: snd_wnd 16060, cwnd 1, wnd 1, effwnd 0, seq 8655, ack 8655
tcp_output: snd_wnd 16060, cwnd 1, wnd 1, effwnd 0, seq 8655, ack 8655, i 0
tcp_output_segment: rtseq 8655
tcp_output_segment: 8655:8655
tcp_slowtmr: processing active pcb
TCP header:
+-------------------------------+
|     3030      |     4107      | (src port, dest port)
+-------------------------------+
|           2712639489          | (seq no)
+-------------------------------+
|           0000008656          | (ack no)
+-------------------------------+
|  6 |   |010010|      8192     | (hdrlen, flags (SYN ACK
), win)
+-------------------------------+
|    0xd6aa     |         0     | (chksum, urgp)
+-------------------------------+
+-+-+-+-+-+-+-+-+-+-+-+-+-+- tcp_input: flags SYN ACK
-+-+-+-+-+-+-+-+-+-+-+-+-+-+
State: SYN_SENT
tcp_parseopt: MSS
SYN-SENT: ackno 8656 pcb->snd_nxt 8656 unacked 8655
tcp_process: SYN-SENT --queuelen 0
tcp_output: sending ACK for 2712639490
State: ESTABLISHED
tcp_write(pcb=0x201c9690, data=0x2040eec0, len=1025, apiflags=1)
tcp_enqueue(pcb=0x201c9690, arg=0x2040eec0, len=1025, flags=0, apiflags=1)
tcp_enqueue: queuelen: 0
tcp_enqueue: queueing 8656:9681 (0x0)
tcp_enqueue: 1 (after enqueued)
tcp_output: snd_wnd 8192, cwnd 2920, wnd 2920, effwnd 1025, seq 8656, ack 8656
tcp_output: snd_wnd 8192, cwnd 2920, wnd 2920, effwnd 1025, seq 8656,
ack 8656, i 0
tcp_output_segment: 8656:9681
tcp_slowtmr: processing active pcb
tcp_slowtmr: processing active pcb
TCP header:
+-------------------------------+
|     3030      |     4107      | (src port, dest port)
+-------------------------------+
|           2712639490          | (seq no)
+-------------------------------+
|           0000009680          | (ack no)
+-------------------------------+
|  5 |   |010000|      1024     | (hdrlen, flags (ACK
), win)
+-------------------------------+
|    0x0668     |         0     | (chksum, urgp)
+-------------------------------+
+-+-+-+-+-+-+-+-+-+-+-+-+-+- tcp_input: flags ACK
-+-+-+-+-+-+-+-+-+-+-+-+-+-+
State: ESTABLISHED
tcp_receive: window update 1024
tcp_receive: slow start cwnd 4380
tcp_receive: ACK for 9680, unacked->seqno 8656:9681
tcp_receive: pcb->rttest 400 rtseq 8655 ackno 9680
tcp_receive: experienced rtt 3 ticks (1500 msec).
tcp_receive: RTO 8 (4000 milliseconds)
tcp_output: nothing to send (0x00000000)
tcp_output: snd_wnd 1024, cwnd 4380, wnd 1024, seg == NULL, ack 9680
State: ESTABLISHED
tcp_slowtmr: processing active pcb
tcp_slowtmr: processing active pcb
tcp_slowtmr: processing active pcb
tcp_slowtmr: processing active pcb
tcp_slowtmr: polling application
tcp_output: nothing to send (0x00000000)
tcp_output: snd_wnd 1024, cwnd 4380, wnd 1024, seg == NULL, ack 9680
tcp_slowtmr: processing active pcb
tcp_slowtmr: processing active pcb
tcp_slowtmr: processing active pcb
tcp_slowtmr: processing active pcb
tcp_slowtmr: rtime 8 pcb->rto 8
tcp_slowtmr: cwnd 1460 ssthresh 2920
tcp_output: snd_wnd 1024, cwnd 1460, wnd 1024, effwnd 1, seq 8656, ack 9680
tcp_output: snd_wnd 1024, cwnd 1460, wnd 1024, effwnd 1, seq 8656, ack 9680, i 0
tcp_output_segment: rtseq 8656
tcp_output_segment: 8656:9681
tcp_slowtmr: polling application
tcp_output: nothing to send (0x00000000)
tcp_output: snd_wnd 1024, cwnd 1460, wnd 1024, seg == NULL, ack 9680
tcp_slowtmr: processing active pcb
tcp_slowtmr: processing active pcb
TCP header:
+-------------------------------+
|     3030      |     4107      | (src port, dest port)
+-------------------------------+
|           2712639490          | (seq no)
+-------------------------------+
|           0000009681          | (ack no)
+-------------------------------+
|  5 |   |011000|      1023     | (hdrlen, flags (PSH ACK
), win)
+-------------------------------+
|    0x4205     |         0     | (chksum, urgp)
+-------------------------------+
+-+-+-+-+-+-+-+-+-+-+-+-+-+- tcp_input: flags PSH ACK
-+-+-+-+-+-+-+-+-+-+-+-+-+-+
State: ESTABLISHED
tcp_receive: window update 1023
tcp_receive: slow start cwnd 2920
tcp_receive: ACK for 9681, unacked->seqno 8656:9681
tcp_receive: removing 8656:9681 from pcb->unacked
tcp_receive: queuelen 1 ... 0 (after freeing unacked)
tcp_receive: pcb->rttest 411 rtseq 8656 ackno 9681
tcp_receive: experienced rtt 2 ticks (1000 msec).
tcp_receive: RTO 8 (4000 milliseconds)
tcp_output: nothing to send (0x00000000)
tcp_output: snd_wnd 1023, cwnd 2920, wnd 1023, seg == NULL, ack 9681
State: ESTABLISHED
tcp_recved: recveived 1025 bytes, wnd 16060 (0).
     1,    690,   5870,      0,   1025         <<<========my log

tcp_close: closing in State: ESTABLISHED
######################

On Tue, Apr 27, 2010 at 10:55 PM, Kieran Mansley <address@hidden> wrote:
> On Tue, 2010-04-27 at 21:24 +0800, yueyue papa wrote:
>> >>Have you attached the right packet capture?
>> i check. It is right.
>>
>> >>The IP addresses don't match the ones in your email,
>> I am not understand. One is 192.168.8.130, another is 192.168.8.40.
>> There are only two IP address in the capture.
>
> My apologies - I was looking at a similarly named file from an earlier
> problem.
>
>> >> I can't see either end ACKing 1024 bytes of a segment.
>> Item 4:  192.168.8.40 send 1400 bytes to 192.168.8.130 (server in vista)
>> Item 5:  192.168.8.130 only ack 1025. 1400 is get, it should ack 1401
>> (like item 7)
>> Item 6:  Due to the windows strange ACK, lwIP resend after 5s
>> Item 7:  acked by lwIP.  One echo finihsed.
>>
>> I am not understand this flow.
>>
>> 1. why lwIP resend after 5s.
>
> lwIP will resend when the retransmission timeout (RTO) occurs.  This
> should be closer to 500ms rather than 5s, but the RTO is a dynamic value
> that changes for each connection.  TCP tries to measure the round trip
> time and base the RTO on that.  It is initialized in tcp_alloc():
>
>    pcb->rto = 3000 / TCP_SLOW_INTERVAL;
>
> and then updated when ACKs are received back.  There are debug log
> statements you can enable to see how it changes.
>
> If you think it is wrong, check that TCP_SLOW_INTERVAL is set correctly,
> and that your port is calling tcp_tmr() at the correct frequency.
>
>> 2. why windows ack 1025.
>
> It looks like it is being a bit naughty, and lwIP does not cope will
> with this.  It initially offers 8K of window space in the SYN-ACK.  When
> it receives data it decides to decrease the available window to 1K.
> I.e. it's going back on what it previously advertised we could do.  I
> don't know why it does this, nor why it throws away and refuses to ACK
> part of the packet - it seems a very odd thing to do as it forces a
> retransmission which is very slow.  It is then expecting lwIP to
> re-segment the frames and send the next portion, but lwIP prefers to
> just wait for the window to get bigger as re-segmenting is hard work for
> a small device.
>
> Kieran
>
>
>
> _______________________________________________
> lwip-users mailing list
> address@hidden
> http://lists.nongnu.org/mailman/listinfo/lwip-users
>