Slow HTTP server response

[atlascoder]

Hello guys!

I am facing strange issue with ESP HTTP server.. I am testing several boards and different firmware and facing the same trouble. I think that esp32-cam would be very goo example to explain. So, I am facing very, very slow responses from HTTP server, when ESP is running in STA mode. Below is a dump showing transferring 125KB in 25862ms !!!

From another side, when I run ESP in SoftAP mode - it works just fine, less than a second!

I tried to create manual HTTP server implementation using Socket API - result is the same..

I changed WiFi channel on my router, suspecting that maybe WiFi channel is too busy - no significant changes.

I also tried different boards - nothing helps.

I turned of AMPDU, changed WiFi channel witdh, played with other params and just can't get a good result.

Code: Select all

D (2944081) httpd: httpd_server: processing listen socket 54
D (2944081) httpd: httpd_accept_conn: newfd = 57
D (2944091) httpd_sess: httpd_sess_new: fd = 57
D (2944091) httpd: httpd_accept_conn: complete
D (2944091) httpd: httpd_server: doing select maxfd+1 = 58
D (2944101) httpd: httpd_server: processing socket 57
D (2944101) httpd_sess: httpd_sess_process: httpd_req_new
D (2944111) httpd_txrx: httpd_recv_with_opt: requested length = 128
D (2944111) httpd_txrx: httpd_recv_with_opt: received length = 128
D (2944121) httpd_parse: read_block: received HTTP request block size = 128
D (2944131) httpd_parse: cb_url: message begin
D (2944131) httpd_parse: cb_url: processing url = /jpg
D (2944141) httpd_parse: verify_url: received URI = /jpg
D (2944141) httpd_parse: cb_header_field: headers begin
D (2944151) httpd_txrx: httpd_unrecv: length = 109
D (2944151) httpd_parse: pause_parsing: paused
D (2944161) httpd_parse: cb_header_field: processing field = Host
D (2944161) httpd_txrx: httpd_recv_with_opt: requested length = 128
D (2944171) httpd_txrx: httpd_recv_with_opt: pending length = 109
D (2944181) httpd_parse: read_block: received HTTP request block size = 109
D (2944181) httpd_parse: continue_parsing: skip pre-parsed data of size = 5
D (2944191) httpd_parse: continue_parsing: un-paused
D (2944201) httpd_parse: cb_header_value: processing value = 192.168.0.124
D (2944201) httpd_parse: cb_header_field: processing field = Connection
D (2944211) httpd_parse: cb_header_value: processing value = keep-alive
D (2944221) httpd_parse: cb_header_field: processing field = Cache-Control
D (2944221) httpd_parse: cb_header_value: processing value = max-age=0
D (2944231) httpd_parse: cb_header_field: processing field = Upgrade-Insecure-Requests
D (2944241) httpd_parse: cb_header_value: processing value = 1
D (2944241) httpd_parse: cb_header_field: processing field = User-Age
D (2944251) httpd_parse: parse_block: parsed block size = 109
D (2944261) httpd_txrx: httpd_recv_with_opt: requested length = 128
D (2944261) httpd_txrx: httpd_recv_with_opt: received length = 128
D (2944271) httpd_parse: read_block: received HTTP request block size = 128
D (2944271) httpd_parse: cb_header_field: processing field = nt
D (2944281) httpd_parse: cb_header_value: processing value = Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/91.0.4472.164 Safari/537.36
D (2944301) httpd_parse: cb_header_field: processing field = Accept
D (2944301) httpd_parse: cb_header_value: processing value = text/html
D (2944311) httpd_parse: parse_block: parsed block size = 237
D (2944311) httpd_txrx: httpd_recv_with_opt: requested length = 128
D (2944321) httpd_txrx: httpd_recv_with_opt: received length = 128
D (2944331) httpd_parse: read_block: received HTTP request block size = 128
D (2944331) httpd_parse: cb_header_value: processing value = ,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9
D (2944351) httpd_parse: parse_block: parsed block size = 365
D (2944361) httpd_txrx: httpd_recv_with_opt: requested length = 128
D (2944361) httpd_txrx: httpd_recv_with_opt: received length = 76
D (2944371) httpd_parse: read_block: received HTTP request block size = 76
D (2944381) httpd_parse: cb_header_field: processing field = Accept-Encoding
D (2944381) httpd_parse: cb_header_value: processing value = gzip, deflate
D (2944391) httpd_parse: cb_header_field: processing field = Accept-Language
D (2944401) httpd_parse: cb_header_value: processing value = en-US,en;q=0.9,uk;q=0.8
D (2944411) httpd_parse: cb_headers_complete: bytes read     = 462
D (2944411) httpd_parse: cb_headers_complete: content length = 0
D (2944421) httpd_parse: pause_parsing: paused
D (2944421) httpd_parse: cb_no_body: message complete
D (2944431) httpd_parse: httpd_parse_req: parsing complete
D (2944431) httpd_uri: httpd_uri: request for /jpg with type 1
D (2944441) httpd_uri: httpd_find_uri_handler: [0] = /jpg
D (2944441) httpd_txrx: httpd_resp_set_hdr: new header = Content-Disposition: inline; filename=capture.jpg
D (2944461) httpd_txrx: httpd_send_all: sent = 67
D (2944461) httpd_txrx: httpd_send_all: sent = 19
D (2944461) httpd_txrx: httpd_send_all: sent = 2
D (2944471) httpd_txrx: httpd_send_all: sent = 28
D (2944471) httpd_txrx: httpd_send_all: sent = 2
D (2944481) httpd_txrx: httpd_send_all: sent = 2
D (2950311) httpd_txrx: httpd_send_all: sent = 11451
D (2955311) httpd_txrx: httpd_send_all: sent = 2880
D (2960311) httpd_txrx: httpd_send_all: sent = 14400
D (2965311) httpd_txrx: httpd_send_all: sent = 1424
W (2970311) httpd_txrx: httpd_sock_err: error in send : 11
D (2970311) httpd_txrx: httpd_send_all: error in send_fn
I (2970311) example:http_jpg: JPG: 125KB 25862ms

The next step I am going to try - is maybe to implement HTTP server using low level API - lwip "raw" or "netconn" API, but I have doubts that this can help. It looks like some issue with WiFi...

Also, I monitored load on CPU and there are not problems as well - IDLE is around 90% for both CPUs.

I am relly confused.......

Any ideas?

Thanks in advance!

PS// I use IDF in from docker image release-v4.3.

UPDATE

I also ran iperf from idf/examples and measured transmission trough the AP. I'vw got 15Mbps when ESP is ip server, and 25 Mbps when it's iperf client.
Now it looks like the problem is located in HTTP Server or LwIP..

[atlascoder]

UPDATE

It looks like this is some trouble in WiFi or LWIP..

Using Wireshark I see a loot of TCP retransmissions - see attachments.

I'll try to survey on lower layers.

I still hope that this post was read by somebody from Espresiff...

[atlascoder]

Another update.

After hours of testing with esp32_cam firmware, I've got really unstable results. I tried IDF 4.1 and 4.3 - no remarkable difference.

Sometimes, it sends ~100 KB in 300 ms, sometimes in 11000 ms!!! I can't measure actual WiFi readio-channel load, but it looks very strange, because I tried with usage other devices in the same network, doing yotube watching, online gaming, files downloading - via WiFi, and I couldn't detect clear corellation.

But I've found another interesting point - it looks like ESP doesn't receive some TCP packets. An example from the attached picture: the packet with seq=66200 - ACK was sent by ESP (ESP has 192.168.0.124) in #114216, but immediately it also was repeated in retransmissions in #114220 and #114222. After, it was ACKed to ESP by host in #114226, and also with duplication.

Time between #114216 and #114226 is 34 us. Why was this retransmission happened?

The router is Tp-Link Archer C2 v.3 with original FW (EU version). Placen in 4 meters, behind thin wall (10 cm gipsum wall).

The screenshot was taken from Wireshark being runned on a macbook whick was placed in 20 cm from ESP. WiFi radio levels are pretty good close to ESP:
Signal: -33 dBm
Noise: -90 dBm
SNR: 57 dBm

The packets were captured while transmission of a shot with ~100KB in ~3000 ms.

What's happening??...

[mbratch]

I'm reading your posts with great interest since I am experiencing the same problem. Sometimes, for no apparent reason, a response which usually takes about 1 sec (in human perception terms) will take up to 30 seconds. I am running ESP32 Pico Kit. Your test data is more thorough and detailed than what I currently have. I will continue testing to see if I can get some useful data.

Meanwhile, I posted my observation as Issue #7328.

[atlascoder]

I'm reading your posts with great interest since I am experiencing the same problem. Sometimes, for no apparent reason, a response which usually takes about 1 sec (in human perception terms) will take up to 30 seconds. I am running ESP32 Pico Kit. Your test data is more thorough and detailed than what I currently have. I will continue testing to see if I can get some useful data.

Meanwhile, I posted my observation as Issue #7328.

Thanks for joining, mbratch! I thought that this is maybe my router trouble, or local WiFi interferences, but as more I try to survey - then I get more doubts in this. Other confirmations, like your ones, enforce my doubts..

[atlascoder]

Tried to add

Code: Select all

esp_wifi_set_ps(WIFI_PS_NONE);

- nothing changed.

Created an issue https://github.com/espressif/esp-idf/issues/7415

[abansal22]

Hello guys!

I am facing strange issue with ESP HTTP server.. I am testing several boards and different firmware and facing the same trouble. I think that esp32-cam would be very goo example to explain. So, I am facing very, very slow responses from HTTP server, when ESP is running in STA mode. Below is a dump showing transferring 125KB in 25862ms !!!

From another side, when I run ESP in SoftAP mode - it works just fine, less than a second!

I tried to create manual HTTP server implementation using Socket API - result is the same..

I changed WiFi channel on my router, suspecting that maybe WiFi channel is too busy - no significant changes.

I also tried different boards - nothing helps.

I turned of AMPDU, changed WiFi channel witdh, played with other params and just can't get a good result.

Code: Select all

D (2944081) httpd: httpd_server: processing listen socket 54
D (2944081) httpd: httpd_accept_conn: newfd = 57
D (2944091) httpd_sess: httpd_sess_new: fd = 57
D (2944091) httpd: httpd_accept_conn: complete
D (2944091) httpd: httpd_server: doing select maxfd+1 = 58
D (2944101) httpd: httpd_server: processing socket 57
D (2944101) httpd_sess: httpd_sess_process: httpd_req_new
D (2944111) httpd_txrx: httpd_recv_with_opt: requested length = 128
D (2944111) httpd_txrx: httpd_recv_with_opt: received length = 128
D (2944121) httpd_parse: read_block: received HTTP request block size = 128
D (2944131) httpd_parse: cb_url: message begin
D (2944131) httpd_parse: cb_url: processing url = /jpg
D (2944141) httpd_parse: verify_url: received URI = /jpg
D (2944141) httpd_parse: cb_header_field: headers begin
D (2944151) httpd_txrx: httpd_unrecv: length = 109
D (2944151) httpd_parse: pause_parsing: paused
D (2944161) httpd_parse: cb_header_field: processing field = Host
D (2944161) httpd_txrx: httpd_recv_with_opt: requested length = 128
D (2944171) httpd_txrx: httpd_recv_with_opt: pending length = 109
D (2944181) httpd_parse: read_block: received HTTP request block size = 109
D (2944181) httpd_parse: continue_parsing: skip pre-parsed data of size = 5
D (2944191) httpd_parse: continue_parsing: un-paused
D (2944201) httpd_parse: cb_header_value: processing value = 192.168.0.124
D (2944201) httpd_parse: cb_header_field: processing field = Connection
D (2944211) httpd_parse: cb_header_value: processing value = keep-alive
D (2944221) httpd_parse: cb_header_field: processing field = Cache-Control
D (2944221) httpd_parse: cb_header_value: processing value = max-age=0
D (2944231) httpd_parse: cb_header_field: processing field = Upgrade-Insecure-Requests
D (2944241) httpd_parse: cb_header_value: processing value = 1
D (2944241) httpd_parse: cb_header_field: processing field = User-Age
D (2944251) httpd_parse: parse_block: parsed block size = 109
D (2944261) httpd_txrx: httpd_recv_with_opt: requested length = 128
D (2944261) httpd_txrx: httpd_recv_with_opt: received length = 128
D (2944271) httpd_parse: read_block: received HTTP request block size = 128
D (2944271) httpd_parse: cb_header_field: processing field = nt
D (2944281) httpd_parse: cb_header_value: processing value = Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/91.0.4472.164 Safari/537.36
D (2944301) httpd_parse: cb_header_field: processing field = Accept
D (2944301) httpd_parse: cb_header_value: processing value = text/html
D (2944311) httpd_parse: parse_block: parsed block size = 237
D (2944311) httpd_txrx: httpd_recv_with_opt: requested length = 128
D (2944321) httpd_txrx: httpd_recv_with_opt: received length = 128
D (2944331) httpd_parse: read_block: received HTTP request block size = 128
D (2944331) httpd_parse: cb_header_value: processing value = ,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9
D (2944351) httpd_parse: parse_block: parsed block size = 365
D (2944361) httpd_txrx: httpd_recv_with_opt: requested length = 128
D (2944361) httpd_txrx: httpd_recv_with_opt: received length = 76
D (2944371) httpd_parse: read_block: received HTTP request block size = 76
D (2944381) httpd_parse: cb_header_field: processing field = Accept-Encoding
D (2944381) httpd_parse: cb_header_value: processing value = gzip, deflate
D (2944391) httpd_parse: cb_header_field: processing field = Accept-Language
D (2944401) httpd_parse: cb_header_value: processing value = en-US,en;q=0.9,uk;q=0.8
D (2944411) httpd_parse: cb_headers_complete: bytes read     = 462
D (2944411) httpd_parse: cb_headers_complete: content length = 0
D (2944421) httpd_parse: pause_parsing: paused
D (2944421) httpd_parse: cb_no_body: message complete
D (2944431) httpd_parse: httpd_parse_req: parsing complete
D (2944431) httpd_uri: httpd_uri: request for /jpg with type 1
D (2944441) httpd_uri: httpd_find_uri_handler: [0] = /jpg
D (2944441) httpd_txrx: httpd_resp_set_hdr: new header = Content-Disposition: inline; filename=capture.jpg
D (2944461) httpd_txrx: httpd_send_all: sent = 67
D (2944461) httpd_txrx: httpd_send_all: sent = 19
D (2944461) httpd_txrx: httpd_send_all: sent = 2
D (2944471) httpd_txrx: httpd_send_all: sent = 28
D (2944471) httpd_txrx: httpd_send_all: sent = 2
D (2944481) httpd_txrx: httpd_send_all: sent = 2
D (2950311) httpd_txrx: httpd_send_all: sent = 11451
D (2955311) httpd_txrx: httpd_send_all: sent = 2880
D (2960311) httpd_txrx: httpd_send_all: sent = 14400
D (2965311) httpd_txrx: httpd_send_all: sent = 1424
W (2970311) httpd_txrx: httpd_sock_err: error in send : 11
D (2970311) httpd_txrx: httpd_send_all: error in send_fn
I (2970311) example:http_jpg: JPG: 125KB 25862ms

The next step I am going to try - is maybe to implement HTTP server using low level API - lwip "raw" or "netconn" API, but I have doubts that this can help. It looks like some issue with WiFi...

Also, I monitored load on CPU and there are not problems as well - IDLE is around 90% for both CPUs.

I am relly confused.......

Any ideas?

Thanks in advance!

PS// I use IDF in from docker image release-v4.3.

UPDATE

I also ran iperf from idf/examples and measured transmission trough the AP. I'vw got 15Mbps when ESP is ip server, and 25 Mbps when it's iperf client.
Now it looks like the problem is located in HTTP Server or LwIP..

I think there is some mistake in the http header. Checkout this. In debug log
D (2944441) httpd_txrx: httpd_resp_set_hdr: new header = Content-Disposition: inline; filename=capture.jpg

You are responding to the jpg request as inline, but not mentioning the content type as image/jpeg. Either set correct content type or set the value of content-disposition to attachment. So it could be downloaded.
Thanks

[atlascoder]

I think there is some mistake in the http header. Checkout this. In debug log
D (2944441) httpd_txrx: httpd_resp_set_hdr: new header = Content-Disposition: inline; filename=capture.jpg

You are responding to the jpg request as inline, but not mentioning the content type as image/jpeg. Either set correct content type or set the value of content-disposition to attachment. So it could be downloaded.
Thanks

Hello, abansal22, the problem is not on the Application (HTTP) level - it is somewhere below, lower from the Session level.

I'd rather pay attention to these lines in logs(in brackets is system time in ms):

Code: Select all

D (2944461) httpd_txrx: httpd_send_all: sent = 67
D (2944461) httpd_txrx: httpd_send_all: sent = 19
D (2944461) httpd_txrx: httpd_send_all: sent = 2
D (2944471) httpd_txrx: httpd_send_all: sent = 28
D (2944471) httpd_txrx: httpd_send_all: sent = 2
D (2944481) httpd_txrx: httpd_send_all: sent = 2
D (2950311) httpd_txrx: httpd_send_all: sent = 11451
D (2955311) httpd_txrx: httpd_send_all: sent = 2880
D (2960311) httpd_txrx: httpd_send_all: sent = 14400
D (2965311) httpd_txrx: httpd_send_all: sent = 1424

so, what's strange, is that sending 11451 bytes takes 2950311 - 2944481 = 5830 ms = 5.83 seconds

[abansal22]

I think there is some mistake in the http header. Checkout this. In debug log
D (2944441) httpd_txrx: httpd_resp_set_hdr: new header = Content-Disposition: inline; filename=capture.jpg

You are responding to the jpg request as inline, but not mentioning the content type as image/jpeg. Either set correct content type or set the value of content-disposition to attachment. So it could be downloaded.
Thanks

Hello, abansal22, the problem is not on the Application (HTTP) level - it is somewhere below, lower from the Session level.

I'd rather pay attention to these lines in logs(in brackets is system time in ms):

Code: Select all

D (2944461) httpd_txrx: httpd_send_all: sent = 67
D (2944461) httpd_txrx: httpd_send_all: sent = 19
D (2944461) httpd_txrx: httpd_send_all: sent = 2
D (2944471) httpd_txrx: httpd_send_all: sent = 28
D (2944471) httpd_txrx: httpd_send_all: sent = 2
D (2944481) httpd_txrx: httpd_send_all: sent = 2
D (2950311) httpd_txrx: httpd_send_all: sent = 11451
D (2955311) httpd_txrx: httpd_send_all: sent = 2880
D (2960311) httpd_txrx: httpd_send_all: sent = 14400
D (2965311) httpd_txrx: httpd_send_all: sent = 1424

so, what's strange, is that sending 11451 bytes takes 2950311 - 2944481 = 5830 ms = 5.83 seconds

The thing is when we set the log level to debug, actually the whole system tries to print on the Console. Printing on consoles itself is a time and memory consuming task. My advice is to change the header, log the time taken while entering in the function and while leaving the function. Set the esp log level to error.

[atlascoder]

The thing is when we set the log level to debug, actually the whole system tries to print on the Console. Printing on consoles itself is a time and memory consuming task. My advice is to change the header, log the time taken while entering in the function and while leaving the function. Set the esp log level to error.

Well.. I am aware all these performance things, thank you.

Maybe I was not clear enough in my initial post, but I do debugging AFTER facing the issue. And here is just an example, based on the ESP32-CAM project, which is very close to my project.

If you believe in your advice, please, explain, how HTTP header can impact on data transmission speed?