ESP32 Forum

mbratch wrote: ↑

Mon Aug 02, 2021 2:05 am

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 wrote: ↑

Thu Jul 29, 2021 5:43 pm

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..

abansal22 wrote: ↑

Fri Aug 13, 2021 4:53 pm

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

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

atlascoder wrote: ↑

Sat Aug 14, 2021 7:26 am

abansal22 wrote: ↑

Fri Aug 13, 2021 4:53 pm

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 wrote: ↑

Sat Aug 14, 2021 8:14 am

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.