Re: [lwip-users] strange TCP ack

[yueyue papa]

tcp.h is not changed,

#define TCP_TMR_INTERVAL       250  /* The TCP timer interval in
milliseconds. */


Every tcp_slowtmr, means 500ms.

###########
tcp_slowtmr: processing active pcb
#############


H50A-socketTest-BT-tcpdebug-2.txt:
############ slow log #############
tcp_recved: recveived 1025 bytes, wnd 16060 (0).
     2,    750,   5710,      0,   1025
#####################################

H50A-socketTest-BT-tcpdebug-faster3.txt:

############ faster log #############
tcp_recved: recveived 1025 bytes, wnd 16060 (0).
     2,    730,    970,      0,   1025
#####################################

I am focus on lwIP resend logical, I uanble to make lwIP resend as
quick as possible. Current the resend is happen after 5 s.

I hope to make it resend with 1s.

Lee

On Wed, Apr 28, 2010 at 1:17 PM, yueyue papa <address@hidden> wrote:
> 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
>>
>

H50A-socketTest-BT-tcpdebug-2.txt
Description: Text document

H50A-socketTest-BT-tcpdebug-faster3.txt
Description: Text document