No more than 2-3 packets/sec from the ESP8266?

[doughboy]

tve, change your test from just sending hello to something larger, like about 64 bytes long.

as you said, it is not about server not sending ack, but I think the esp is using nagle algorithm (which I think should be disabled).

on my original test, I was sending like 2 bytes at a time, and when I changed to 256 bytes at a time, it executed faster.

[tve]

I see, I will try that this evening if have a moment.

[ESP_Faye]

Hi, tve,

Thanks for your interest in ESP8266.

Please refer to this demo http://bbs.espressif.com/viewtopic.php?f=21&t=320

Regards,
Faye

[tve]

Her Majesty thanks for posting your test binary. Your set-up must be different from mine, because I can't get the performance you get. I ran the sommand you indicated:

Code: Select all

connected with tve-home, channel 1
dhcp client start...
ip:192.168.0.29,mask:255.255.255.0,gw:192.168.0.1
:> tcp -W -i 192.168.0.3 -p 2323 -n 1 -c 500 -l 2920

The packet rate is still abysmal. The tcpdump is rather interesting, however. 192.168.0.29 is the esp8266. 192.168.0.3 is my linux box. I'm running "nc -k -l 2323" as tcp server on the linux box. Here is an excerpt from a tcpdump captured on the linux box (the timestamps on the left are delta-times, i.e. they represent the time between two packets. For example, the second packet was captured 0.832610 seconds after the first one:

Code: Select all

00:00:00.011153 IP 192.168.0.29.20553 > 192.168.0.3.2323: Flags [P.], seq 55480:56940, ack 1, win 5840, length 1460
00:00:00.000030 IP 192.168.0.3.2323 > 192.168.0.29.20553: Flags [.], ack 56940, win 64240, length 0
00:00:00.832610 IP 192.168.0.29.20553 > 192.168.0.3.2323: Flags [.], seq 56940:58400, ack 1, win 5840, length 1460
00:00:00.000031 IP 192.168.0.3.2323 > 192.168.0.29.20553: Flags [.], ack 58400, win 64240, length 0
00:00:00.011323 IP 192.168.0.29.20553 > 192.168.0.3.2323: Flags [P.], seq 58400:59860, ack 1, win 5840, length 1460
00:00:00.000029 IP 192.168.0.3.2323 > 192.168.0.29.20553: Flags [.], ack 59860, win 64240, length 0
00:00:00.805641 IP 192.168.0.29.20553 > 192.168.0.3.2323: Flags [.], seq 59860:61320, ack 1, win 5840, length 1460
00:00:00.000029 IP 192.168.0.3.2323 > 192.168.0.29.20553: Flags [.], ack 61320, win 64240, length 0
00:00:00.011554 IP 192.168.0.29.20553 > 192.168.0.3.2323: Flags [P.], seq 61320:62780, ack 1, win 5840, length 1460
00:00:00.000029 IP 192.168.0.3.2323 > 192.168.0.29.20553: Flags [.], ack 62780, win 64240, length 0
00:00:00.809691 IP 192.168.0.29.20553 > 192.168.0.3.2323: Flags [.], seq 62780:64240, ack 1, win 5840, length 1460
00:00:00.000031 IP 192.168.0.3.2323 > 192.168.0.29.20553: Flags [.], ack 64240, win 64240, length 0


What this shows is that the esp is sending two 1460-byte packets in fairly short succession (pretty consistently 11-12ms inter-arrival time) but then waits for 0.8 seconds. Sounds like nagle to me. But the 0.8s delay indicates some problem. The linux box clearly sends acks very promptly so it cannot be taking 0.8 seconds for the esp to receive the acks. Something else in the firmware must be stuffed-up.

You guys are using WPA-PSK encryption on the wifi, right?

Next up I'll try the sample provided by Espressif_Faye...

[tve]

Faye, thanks for the sample code. I hadn't seen the "write_finish" callback before. Looks like this is new in 1.0? Can you explain what it does? I know the docs say "callback which will be called when all sending data is completely write into write buffer or sent", but what does that imply? The fact that my previous espconn_sent data is fully placed into the buffer is irrelevant, isn't it? What would be relevant is for the buffer to have space, no? So does the "write_finish" callback really mean that there is at least 1460 bytes of free space in the send buffer? Or what does it mean?

[tve]

Faye, I'm afraid that the "write_finish" callback doesn't really fix the problem, it just masks it for certain use-cases. Here is a packet trace with my original program slightly modified to send 60-character packets (instead of 6-character). .3 is the linux server, .29 is the esp8266, the timestamps on the left are delta-times, e.g. the second packet below was captured 0.365888 seconds after the first packet, the third 83us after the second, etc:

Code: Select all

00:00:00.377230 IP 192.168.0.29.23 > 192.168.0.3.42676: Flags [P.], seq 980:1050, ack 1, win 5840, length 70
00:00:00.000083 IP 192.168.0.3.42676 > 192.168.0.29.23: Flags [.], ack 1050, win 29200, length 0
00:00:00.365888 IP 192.168.0.29.23 > 192.168.0.3.42676: Flags [P.], seq 1050:1120, ack 1, win 5840, length 70
00:00:00.000083 IP 192.168.0.3.42676 > 192.168.0.29.23: Flags [.], ack 1120, win 29200, length 0
00:00:00.381337 IP 192.168.0.29.23 > 192.168.0.3.42676: Flags [P.], seq 1120:1190, ack 1, win 5840, length 70
00:00:00.000084 IP 192.168.0.3.42676 > 192.168.0.29.23: Flags [.], ack 1190, win 29200, length 0
00:00:00.662622 IP 192.168.0.29.23 > 192.168.0.3.42676: Flags [P.], seq 1120:1190, ack 1, win 5840, length 70
00:00:00.000030 IP 192.168.0.3.42676 > 192.168.0.29.23: Flags [.], ack 1190, win 29200, length 0
00:00:00.002223 IP 192.168.0.29.23 > 192.168.0.3.42676: Flags [P.], seq 1190:1260, ack 1, win 5840, length 70
00:00:00.000030 IP 192.168.0.3.42676 > 192.168.0.29.23: Flags [.], ack 1260, win 29200, length 0

You can see that the esp sends packets about every 0.3 seconds, which is consistent with all my prior tests. It seems very slow at sending the next packet once it has received an ACK. (You can see some variation in the timing above, but looking at a longer trace the typical value is between 0.3 and 0.4s.)

Here is a packet trace for the same program simply modified to use the write_finished callback instead of the sent callback:

Code: Select all

00:00:00.405335 IP 192.168.0.29.23 > 192.168.0.3.42685: Flags [P.], seq 4380:5840, ack 1, win 5840, length 1460
00:00:00.000031 IP 192.168.0.3.42685 > 192.168.0.29.23: Flags [.], ack 5840, win 52560, length 0
00:00:00.383288 IP 192.168.0.29.23 > 192.168.0.3.42685: Flags [P.], seq 5840:7300, ack 1, win 5840, length 1460
00:00:00.000031 IP 192.168.0.3.42685 > 192.168.0.29.23: Flags [.], ack 7300, win 55480, length 0
00:00:00.382253 IP 192.168.0.29.23 > 192.168.0.3.42685: Flags [P.], seq 7300:8760, ack 1, win 5840, length 1460
00:00:00.000031 IP 192.168.0.3.42685 > 192.168.0.29.23: Flags [.], ack 8760, win 58400, length 0
00:00:00.363807 IP 192.168.0.29.23 > 192.168.0.3.42685: Flags [P.], seq 8760:10220, ack 1, win 5840, length 1460
00:00:00.000031 IP 192.168.0.3.42685 > 192.168.0.29.23: Flags [.], ack 10220, win 61320, length 0
00:00:00.385324 IP 192.168.0.29.23 > 192.168.0.3.42685: Flags [P.], seq 10220:11680, ack 1, win 5840, length 1460
00:00:00.000031 IP 192.168.0.3.42685 > 192.168.0.29.23: Flags [.], ack 11680, win 64240, length 0
00:00:00.520872 IP 192.168.0.29.23 > 192.168.0.3.42685: Flags [P.], seq 11680:13140, ack 1, win 5840, length 1460
00:00:00.000031 IP 192.168.0.3.42685 > 192.168.0.29.23: Flags [.], ack 13140, win 64240, length 0

Look at the timestamps: unchanged! The packet rate is still the same. Of course now the packets are 1460 bytes long thanks to buffering. So this helps bandwidth but it doesn't help round-trip times, which is the original problem I've been having. The esp still can't respond to a tcp ack in under ~0.3 seconds!

The original problem I've been having is that I can't program an Arduino via an esp8266 configured as transparent bridge because the round-trip time between avrdude and the arduino is too long due to the above TCP ack problem.

[tve]

Mhh, there seems to be a new bug triggered by the combination of using the write_finish callback and the NODELAY set_opt. I made a single change to my previous test program, which uses the write_finish callback: I added the ESPCONN_NODELAY option (in addition to the ESPCONN_COPY option) using two calls to espconn_set_opt to circumvent the bug that only one flag is taken into account at a time. The result is that the sending stalls after 6 packets. Here's how I initialize the connection in the connect callback:

Code: Select all

static void ICACHE_FLASH_ATTR serverConnectCb(void *conn) {
  os_printf("Connection accepted\n");
  espconn_regist_recvcb(conn, serverRecvCb);
  espconn_regist_reconcb(conn, serverReconCb);
  espconn_regist_disconcb(conn, serverDisconCb);
  espconn_regist_write_finish(conn, serverSentCb);
  espconn_set_opt(conn, ESPCONN_NODELAY);
  espconn_set_opt(conn, ESPCONN_COPY);
  sendpacket(conn);
}


The write_finish callback simply calls espconn_sent with a 60-character string. Here's the tcpdump:

Code: Select all

00:00:00.000000 IP 192.168.0.3.42707 > 192.168.0.29.23: Flags [S], seq 980389593, win 29200, options [mss 1460,sackOK,TS val 1172545111 ecr 0,nop,wscale 7], length 0
00:00:00.424886 IP 192.168.0.29.23 > 192.168.0.3.42707: Flags [S.], seq 6548, ack 980389594, win 5840, options [mss 1460], length 0
00:00:00.000044 IP 192.168.0.3.42707 > 192.168.0.29.23: Flags [.], ack 1, win 29200, length 0
00:00:00.025956 IP 192.168.0.29.23 > 192.168.0.3.42707: Flags [P.], seq 1:71, ack 1, win 5840, length 70
00:00:00.000034 IP 192.168.0.3.42707 > 192.168.0.29.23: Flags [.], ack 71, win 29200, length 0
00:00:00.001915 IP 192.168.0.29.23 > 192.168.0.3.42707: Flags [P.], seq 71:141, ack 1, win 5840, length 70
00:00:00.000029 IP 192.168.0.3.42707 > 192.168.0.29.23: Flags [.], ack 141, win 29200, length 0
00:00:00.002141 IP 192.168.0.29.23 > 192.168.0.3.42707: Flags [P.], seq 141:211, ack 1, win 5840, length 70
00:00:00.000030 IP 192.168.0.3.42707 > 192.168.0.29.23: Flags [.], ack 211, win 29200, length 0
00:00:00.002227 IP 192.168.0.29.23 > 192.168.0.3.42707: Flags [P.], seq 211:281, ack 1, win 5840, length 70
00:00:00.000037 IP 192.168.0.3.42707 > 192.168.0.29.23: Flags [.], ack 281, win 29200, length 0
00:00:00.002423 IP 192.168.0.29.23 > 192.168.0.3.42707: Flags [P.], seq 281:351, ack 1, win 5840, length 70
00:00:00.000030 IP 192.168.0.3.42707 > 192.168.0.29.23: Flags [.], ack 351, win 29200, length 0


After that, the connection freezes! Most likely a bug causes the write_finish callback not to be called anymore... This behavior is 100% reproducible. Try adding the ESPCONN_NODELAY to the sample you provided. For reference, my code is updated on github with the most relevant section being: https://github.com/jeelabs/ESP8266-band ... .c#L30-L71

[tve]

Sorry for the flurry of posts, but each time I decide to quit and go to bed I come up with another little test....

Here's a packet trace of 3 TCP connection attempts to a port on which the esp8266 app isn't listening (port 24 instead of the port 23 my app is using):

Code: Select all

00:00:00.000000 IP 192.168.0.3.35489 > 192.168.0.29.24: Flags [S], seq 3703311375, win 29200, options [mss 1460,sackOK,TS val 1172963017 ecr 0,nop,wscale 7], length 0
00:00:00.036307 IP 192.168.0.29.24 > 192.168.0.3.35489: Flags [R.], seq 0, ack 3703311376, win 5840, length 0

00:00:14.317474 IP 192.168.0.3.35490 > 192.168.0.29.24: Flags [S], seq 2183312759, win 29200, options [mss 1460,sackOK,TS val 1172966606 ecr 0,nop,wscale 7], length 0
00:00:00.039905 IP 192.168.0.29.24 > 192.168.0.3.35490: Flags [R.], seq 0, ack 2183312760, win 5840, length 0

00:00:07.929081 IP 192.168.0.3.35492 > 192.168.0.29.24: Flags [S], seq 1929625896, win 29200, options [mss 1460,sackOK,TS val 1172968598 ecr 0,nop,wscale 7], length 0
00:00:00.066752 IP 192.168.0.29.24 > 192.168.0.3.35492: Flags [R.], seq 0, ack 1929625897, win 5840, length 0

What's interesting here is that the esp8266 responds to the initial SYN packet (correctly) with a TCP reset in 36ms, 39ms, and 66ms respectively. What this little test shows is that a round-trip from my linux box to the esp8266 lwIP TCP stack and back is possible in under 40ms. (If I ping the esp8266 I get ping times in the same ballpark, which is another confirmation.) So the problem causing >300ms reaction times to TCP ACKs is not at the wireless or device driver level. The problem is somewhere between lwIP and the "espconn" layer...

[Her Majesty]

I tested on SDK_v1.0.0 with demo code provided here http://bbs.espressif.com/viewtopic.php?f=21&t=320

It is even faster than my old one..

SPEED_TEST.png (47.83 KiB) Viewed 3573 times

[ESP_Faye]

Hi, tve ,

Sorry for the inconvenience.

Do you still have this problem with "write_finish_callback" + "DIS_NALGE" + SDK_v1.0.1_b2 ?