[Resolved] Is mbedtls on ESP32 particularly slow?

[kolban]

Ive been playing with the mbedtls libraries for SSL and my experiments are still in early days ... however, I seem to be finding that transmissions and receptions appear "slow". In my tests, I am sending an HTTP "GET /get" to "httpbin.org" ... and it is all working ... just with pauses ... here is a trace of the traffic at the ESP32 log level:

Code: Select all

D (21509) ssl: >> js_ssl_write
D (21511) ssl: About to send data over SSL: GET /get HTTP/1.1
Host: www.example.org


D (21521) ssl: >> ssl_send
D (21523) ssl: << ssl_send: fd=0, rc=404
D (21525) ssl: >> ssl_recv: max_length=5
D (27179) ssl: << ssl_recv: fd=0, rc=5
D (27179) ssl: >> ssl_recv: max_length=61
D (27179) ssl: << ssl_recv: fd=0, rc=61
D (27180) ssl: >> ssl_recv: max_length=5
D (27182) ssl: << ssl_recv: fd=0, rc=5
D (27186) ssl: >> ssl_recv: max_length=4327
D (27190) ssl: << ssl_recv: fd=0, rc=4327
D (27197) ssl: >> ssl_recv: max_length=5
D (27197) ssl: << ssl_recv: fd=0, rc=5
D (27201) ssl: >> ssl_recv: max_length=333
D (27204) ssl: << ssl_recv: fd=0, rc=333
V (27210) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (27214) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (27222) intr_alloc: Connected src 51 to int 12 (cpu 0)
D (27320) ssl: >> ssl_recv: max_length=5
D (27320) ssl: << ssl_recv: fd=0, rc=5
D (27320) ssl: >> ssl_recv: max_length=4
D (27320) ssl: << ssl_recv: fd=0, rc=4
D (28416) ssl: >> ssl_send
D (28418) ssl: << ssl_send: fd=0, rc=75
D (28428) ssl: >> ssl_send
D (28429) ssl: << ssl_send: fd=0, rc=6
D (28432) ssl: >> ssl_send
D (28432) ssl: << ssl_send: fd=0, rc=45
D (28432) ssl: >> ssl_recv: max_length=5
D (44911) ssl: << ssl_recv: fd=0, rc=5
D (44912) ssl: >> ssl_recv: max_length=202
D (44912) ssl: << ssl_recv: fd=0, rc=202
D (44912) ssl: >> ssl_recv: max_length=5
D (44915) ssl: << ssl_recv: fd=0, rc=5
D (44918) ssl: >> ssl_recv: max_length=1
D (44922) ssl: << ssl_recv: fd=0, rc=1
D (44928) ssl: >> ssl_recv: max_length=5
D (44929) ssl: << ssl_recv: fd=0, rc=5
D (44933) ssl: >> ssl_recv: max_length=40
D (44936) ssl: << ssl_recv: fd=0, rc=40
D (44941) ssl: >> ssl_send
D (44943) ssl: << ssl_send: fd=0, rc=73
D (44946) ssl: << js_ssl_write: rc=44
D (50001) log: selectResult: {"readfds":[0],"writefds":[],"exceptfds":[]}
D (50002) log: loop: working on ready to read of fd=0
D (50004) ssl: >> js_ssl_read
D (50005) ssl: >> ssl_recv: max_length=5
D (50009) ssl: << ssl_recv: fd=0, rc=5
D (50012) ssl: >> ssl_recv: max_length=383
D (50016) ssl: << ssl_recv: fd=0, rc=383
D (50020) ssl: << js_ssl_read: rc=359
D (50023) log: Length of data from recv: 359
D (50028) log: SSL socket got some data!: HTTP/1.1 200 OK
Server: nginx
Date: Wed, 04 Jan 2017 22:37:26 GMT
Content-Type: application/json
Content-Length: 139
Connection: keep-alive
Access-Control-Allow-Origin: *
Access-Control-Allow-Credentials: true

{
  "args": {}, 
  "headers": {
    "Host": "www.example.org"
  }, 
  "origin": "47.32.225.189", 
  "url": "https://www.example.org/get"
}

What we find is about 30 seconds to get my response back. There are a number of long pauses in this trace ... some as high as 16 seconds. Obviously, when looking at such traces, one has to ask how long the back-end is taking to respond ... and I haven't done that leg work yet. However, the purpose of this post is to see if others have worked with mbedtls and have seen any "slowness" ... if no, then that would point to my environment.

[WiFive]

Did you compare to example 4

[andrew_p]

I'm using example4 with POST request and the correct certificate for my server and it's pretty fast:

Code: Select all

I (41756) example: Starting again!
I (41756) example: Connected to AP
I (41756) example: Connecting to XXXXX.com:443...
I (42036) example: Connected.
I (42036) example: Performing the SSL/TLS handshake...
I (45166) example: Verifying peer X.509 certificate...
I (45166) example: Certificate verified.
I (45166) example: Writing HTTP request...
I (45216) example: 312 bytes written
I (45216) example: Reading HTTP response...
I (45546) example: 511 bytes read
I (45776) example: 7 bytes read
I (45786) example: 5 bytes read
I (45786) example: connection closed

[kolban]

Thank you both for responding. I got the distinct sense that "something" was odd ... my initial thinking was "what changed" and the biggest thing (at this time) was the download last night of the latest "ESP-IDF" ... so I had half convinced myself of a regression. To run some tests, I created a simple socket client that connected to a Windows PC that was running a socket server. The sample socket client source can be seen here:

https://github.com/nkolban/esp32-snippe ... etClient.c

When I ran this client using a fresh ESP template ... I got the following results from a few runs:

Code: Select all

D (8612) event: SYSTEM_EVENT_STA_GOTIP, ip:192.168.1.15, mask:255.255.255.0, gw:192.168.1.1
V (8613) event: enter default callback
I (8613) event: ip: 192.168.1.15, mask: 255.255.255.0, gw: 192.168.1.1
V (8619) event: exit default callback
D (8623) socketClient: start
D (8626) socketClient: socket: rc: 0
I (14389) wifi: pm start, type:0
D (23662) socketClient: connect rc: 0
D (23663) socketClient: send: rc: 11
D (23664) socketClient: close: rc: 0

Code: Select all

D (12173) event: SYSTEM_EVENT_STA_GOTIP, ip:192.168.1.15, mask:255.255.255.0, gw:192.168.1.1
V (12173) event: enter default callback
I (12174) event: ip: 192.168.1.15, mask: 255.255.255.0, gw: 192.168.1.1
V (12180) event: exit default callback
D (12184) socketClient: start
D (12187) socketClient: socket: rc: 0
I (14389) wifi: pm start, type:0
D (19136) socketClient: connect rc: 0
D (19137) socketClient: send: rc: 11
D (19137) socketClient: close: rc: 0

Code: Select all

D (8116) event: SYSTEM_EVENT_STA_GOTIP, ip:192.168.1.15, mask:255.255.255.0, gw:192.168.1.1
V (8116) event: enter default callback
I (8117) event: ip: 192.168.1.15, mask: 255.255.255.0, gw: 192.168.1.1
V (8123) event: exit default callback
D (8127) socketClient: start
D (8129) socketClient: socket: rc: 0
I (14353) wifi: pm start, type:0
D (26385) socketClient: connect rc: -1
D (26385) socketClient: send: rc: -1
D (26386) socketClient: close: rc: 0

As we can hopefully see ... we have long pauses and, in some cases, network failures/timeouts. On a wild hunch, I rebooted my router ... after rebooting ...

Code: Select all

D (7196) event: SYSTEM_EVENT_STA_GOTIP, ip:192.168.1.8, mask:255.255.255.0, gw:192.168.1.1
V (7196) event: enter default callback
I (7197) event: ip: 192.168.1.8, mask: 255.255.255.0, gw: 192.168.1.1
V (7203) event: exit default callback
D (7206) socketClient: start
D (7209) socketClient: socket: rc: 0
D (7366) socketClient: connect rc: 0
D (7367) socketClient: send: rc: 11
D (7368) socketClient: close: rc: 0
I (13909) wifi: pm start, type:0

Code: Select all

D (11178) event: SYSTEM_EVENT_STA_GOTIP, ip:192.168.1.8, mask:255.255.255.0, gw:192.168.1.1
V (11178) event: enter default callback
I (11179) event: ip: 192.168.1.8, mask: 255.255.255.0, gw: 192.168.1.1
V (11185) event: exit default callback
D (11189) socketClient: start
D (11192) socketClient: socket: rc: 0
D (11458) socketClient: connect rc: 0
D (11459) socketClient: send: rc: 11
D (11460) socketClient: close: rc: 0
I (13961) wifi: pm start, type:0

we have beautiful clean, low latency runs with no pauses or timeouts. Before rebooting my router, I checked its stats ... nothing obvious in its logs but I did notice it had been up for "78 days". I'll be watching carefully ... but as of just now, I don't know what may have happened. I'm not a great fan on non-deterministic glitches ... especially those that don't seem to manifest themselves elsewhere. My multiple home PCs, cell phones, tablets etc weren't experiencing any obvious errors ... only my ESP32.

[vitasi]

I think, the delay (at the end of the request) is caused by the keep-alive feature. If I change the keepalive_timeout on the nginx server, then the read function quits at that new time.