ESP32-S3 HTTPS esp_mbedtls_handshake握手平均耗时3s以上

kangzy4
Posts: 6
Joined: Wed Jan 11, 2023 7:18 am

ESP32-S3 HTTPS esp_mbedtls_handshake握手平均耗时3s以上

Postby kangzy4 » Wed Jan 11, 2023 7:24 am

当我使用HTTP POST/GET请求时,每次请求耗时一般在100-300ms左右
更改为HTTPS,并加入服务器证书校验后,每次请求耗时需要3s以上
我尝试过下面这几种配置方式,但是耗时变化不大
1、
esp_tls_cfg_t cfg = {
.use_global_ca_store = true,
};
2、
esp_tls_cfg_t cfg = {
.cacert_buf = (const unsigned char *) server_root_cert_pem_start,
.cacert_bytes = server_root_cert_pem_end - server_root_cert_pem_start,
};
3、
esp_tls_cfg_t cfg = {
.crt_bundle_attach = esp_crt_bundle_attach,
};
然后我跟踪源码运行发现,每次请求耗时主要在esp_mbedtls_handshake内
Then I tracked the source code and ran and found that each request took less than esp_mbedtls_handshake
E (9881) esp-tls-mbedtls: -------start = 9270ms esp_mbedtls_handshake
I (10691) esp-x509-crt-bundle: Certificate validated
E (15741) esp-tls-mbedtls: -------end =15130ms esp_mbedtls_handshake

这是否是正常的HTTPS请求耗时?还是我的配置出现问题?是否有优化请求耗时的方法呢?


下方是完整的启动、请求日志:
entry 0x40080694
I (27) boot: ESP-IDF v4.4.2-378-g9269a536ac-dirty 2nd stage bootloader
I (27) boot: compile time 22:13:45
I (28) boot: chip revision: 3
I (32) boot_comm: chip revision: 3, min. bootloader chip revision: 0
I (39) boot.esp32: SPI Speed : 40MHz
I (44) boot.esp32: SPI Mode : DIO
I (48) boot.esp32: SPI Flash Size : 2MB
I (53) boot: Enabling RNG early entropy source...
I (58) boot: Partition Table:
I (62) boot: ## Label Usage Type ST Offset Length
I (69) boot: 0 nvs WiFi data 01 02 00009000 00006000
I (77) boot: 1 phy_init RF data 01 01 0000f000 00001000
I (84) boot: 2 factory factory app 00 00 00010000 00100000
I (92) boot: End of partition table
I (96) boot_comm: chip revision: 3, min. application chip revision: 0
I (103) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=28eb8h (167608) map
I (172) esp_image: segment 1: paddr=00038ee0 vaddr=3ffb0000 size=03800h ( 14336) load
I (178) esp_image: segment 2: paddr=0003c6e8 vaddr=40080000 size=03930h ( 14640) load
I (184) esp_image: segment 3: paddr=00040020 vaddr=400d0020 size=88158h (557400) map
I (388) esp_image: segment 4: paddr=000c8180 vaddr=40083930 size=10f64h ( 69476) load
I (417) esp_image: segment 5: paddr=000d90ec vaddr=50000000 size=00010h ( 16) load
I (427) boot: Loaded app from partition at offset 0x10000
I (427) boot: Disabling RNG early entropy source...
I (439) cpu_start: Pro cpu up.
I (439) cpu_start: Starting app cpu, entry point is 0x400811a4
0x400811a4: call_start_cpu1 at /home/leo/work/esp/esp-idf/components/esp_system/port/cpu_start.c:148

I (0) cpu_start: App cpu up.
I (456) cpu_start: Pro cpu start user code
I (456) cpu_start: cpu freq: 160000000
I (456) cpu_start: Application information:
I (460) cpu_start: Project name: https_request
I (466) cpu_start: App version: 1
I (470) cpu_start: Compile time: Jan 10 2023 22:13:40
I (476) cpu_start: ELF file SHA256: 3ad1424200dff368...
I (482) cpu_start: ESP-IDF: v4.4.2-378-g9269a536ac-dirty
I (489) heap_init: Initializing. RAM available for dynamic allocation:
I (496) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (502) heap_init: At 3FFB7790 len 00028870 (162 KiB): DRAM
I (508) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (515) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (521) heap_init: At 40094894 len 0000B76C (45 KiB): IRAM
I (529) spi_flash: detected chip: generic
I (532) spi_flash: flash io: dio
W (536) spi_flash: Detected size(4096k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (550) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (671) wifi:wifi driver task: 3ffc01f8, prio:23, stack:6656, core=0
I (671) system_api: Base MAC address is not set
I (671) system_api: read default base MAC address from EFUSE
I (691) wifi:wifi firmware version: f1d33cc
I (691) wifi:wifi certification version: v7.0
I (691) wifi:config NVS flash: enabled
I (691) wifi:config nano formating: disabled
I (701) wifi:Init data frame dynamic rx buffer num: 32
I (701) wifi:Init management frame dynamic rx buffer num: 32
I (711) wifi:Init management short buffer num: 32
I (711) wifi:Init dynamic tx buffer num: 32
I (721) wifi:Init static rx buffer size: 1600
I (721) wifi:Init static rx buffer num: 10
I (731) wifi:Init dynamic rx buffer num: 32
I (731) wifi_init: rx ba win: 6
I (731) wifi_init: tcpip mbox: 32
I (741) wifi_init: udp mbox: 6
I (741) wifi_init: tcp mbox: 6
I (741) wifi_init: tcp tx win: 5744
I (751) wifi_init: tcp rx win: 5744
I (751) wifi_init: tcp mss: 1440
I (761) wifi_init: WiFi IRAM OP enabled
I (761) wifi_init: WiFi RX IRAM OP enabled
I (771) example_connect: Connecting to midea_ceshi_002...
I (771) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
W (781) phy_init: failed to load RF calibration data (0xffffffff), falling back to full calibration
I (1051) wifi:mode : sta (b8:d6:1a:33:d0:e4)
I (1051) wifi:enable tsf
I (1061) example_connect: Waiting for IP(s)
I (3471) wifi:new:<8,0>, old:<1,0>, ap:<255,255>, sta:<8,0>, prof:1
I (4211) wifi:state: init -> auth (b0)
I (4221) wifi:state: auth -> assoc (0)
I (4221) wifi:state: assoc -> run (10)
W (4231) wifi:<ba-add>idx:0 (ifx:0, 34:97:f6:b6:22:a0), tid:0, ssn:0, winSize:64
I (4251) wifi:connected with midea_ceshi_002, aid = 7, channel 8, BW20, bssid = 34:97:f6:b6:22:a0
I (4251) wifi:security: WPA2-PSK, phy: bgn, rssi: -42
I (4251) wifi:pm start, type: 1
I (4331) wifi:AP's beacon interval = 102400 us, DTIM period = 3
I (5661) example_connect: Got IPv6 event: Interface "example_connect: sta" address: fe80:0000:0000:0000:bad6:1aff:fe33:d0e4, type: ESP_IP6_ADDR_IS_LINK_LOCAL
I (9161) esp_netif_handlers: example_connect: sta ip: 192.168.3.137, mask: 255.255.255.0, gw: 192.168.3.1
I (9161) example_connect: Got IPv4 event: Interface "example_connect: sta" address: 192.168.3.137
I (9171) example_connect: Connected to example_connect: sta
I (9171) example_connect: - IPv4 address: 192.168.3.137
I (9181) example_connect: - IPv6 address: fe80:0000:0000:0000:bad6:1aff:fe33:d0e4, type: ESP_IP6_ADDR_IS_LINK_LOCAL
I (9191) example: Start https_request example
I (9201) example: https_request using crt bundle
E (9881) esp-tls-mbedtls: -------start = 9270ms esp_mbedtls_handshake
I (10691) esp-x509-crt-bundle: Certificate validated
E (15741) esp-tls-mbedtls: -------end =15130ms esp_mbedtls_handshake
I (15741) example: Connection established...
I (15751) example: 106 bytes written
I (15751) example: Reading HTTP response...
HTTP/1.1 200 OK
Content-Length: 2091
Access-Control-Allow-Origin: *
Connection: close
Content-Type: application/json
Date: Wed, 11 Jan 2023 06:15:16 GMT
Strict-Transport-Security: max-age=631138519; includeSubdomains; preload
...
I (42881) example: https_request using global ca_store
E (44281) esp-tls-mbedtls: -------start = 43670ms esp_mbedtls_handshake
E (47381) esp-tls-mbedtls: -------end =46770ms esp_mbedtls_handshake
I (47391) example: Connection established...
I (47401) example: 106 bytes written
I (47401) example: Reading HTTP response...
HTTP/1.1 200 OK
Content-Length: 2091
Access-Control-Allow-Origin: *
Connection: close
Content-Type: application/json
Date: Wed, 11 Jan 2023 06:15:48 GMT
Strict-Transport-Security: max-age=631138519; includeSubdomains; preload

ESP_YJM
Posts: 300
Joined: Fri Feb 26, 2021 10:30 am

Re: ESP32-S3 HTTPS esp_mbedtls_handshake握手平均耗时3s以上

Postby ESP_YJM » Wed Jan 11, 2023 11:12 am

能否提供下你的 sdkconfig 以及打开 mbedtls debug 查看下 mbedtls 握手所使用的套件。

kangzy4
Posts: 6
Joined: Wed Jan 11, 2023 7:18 am

Re: ESP32-S3 HTTPS esp_mbedtls_handshake握手平均耗时3s以上

Postby kangzy4 » Sun Jan 15, 2023 12:46 am

好的,这里提供下配置和日志信息如下:

下方是sdkconfig与TLS相关的配置
#
# ESP-TLS
#
CONFIG_ESP_TLS_USING_MBEDTLS=y
CONFIG_ESP_TLS_USE_DS_PERIPHERAL=y
# CONFIG_ESP_TLS_CLIENT_SESSION_TICKETS is not set
# CONFIG_ESP_TLS_SERVER is not set
# CONFIG_ESP_TLS_PSK_VERIFICATION is not set
CONFIG_ESP_TLS_INSECURE=y
CONFIG_ESP_TLS_SKIP_SERVER_CERT_VERIFY=y
# end of ESP-TLS
#
# mbedTLS
#
CONFIG_MBEDTLS_INTERNAL_MEM_ALLOC=y
# CONFIG_MBEDTLS_EXTERNAL_MEM_ALLOC is not set
# CONFIG_MBEDTLS_DEFAULT_MEM_ALLOC is not set
# CONFIG_MBEDTLS_CUSTOM_MEM_ALLOC is not set
CONFIG_MBEDTLS_ASYMMETRIC_CONTENT_LEN=y
CONFIG_MBEDTLS_SSL_IN_CONTENT_LEN=16384
CONFIG_MBEDTLS_SSL_OUT_CONTENT_LEN=4096
# CONFIG_MBEDTLS_DYNAMIC_BUFFER is not set
CONFIG_MBEDTLS_DEBUG=y
# CONFIG_MBEDTLS_DEBUG_LEVEL_WARN is not set
# CONFIG_MBEDTLS_DEBUG_LEVEL_INFO is not set
# CONFIG_MBEDTLS_DEBUG_LEVEL_DEBUG is not set
CONFIG_MBEDTLS_DEBUG_LEVEL_VERBOSE=y
CONFIG_MBEDTLS_DEBUG_LEVEL=4

#
# mbedTLS v2.28.x related
#
# CONFIG_MBEDTLS_SSL_VARIABLE_BUFFER_LENGTH is not set
# CONFIG_MBEDTLS_X509_TRUSTED_CERT_CALLBACK is not set
# CONFIG_MBEDTLS_SSL_CONTEXT_SERIALIZATION is not set
CONFIG_MBEDTLS_SSL_KEEP_PEER_CERTIFICATE=y
# end of mbedTLS v2.28.x related

#
# Certificate Bundle
#
CONFIG_MBEDTLS_CERTIFICATE_BUNDLE=y
CONFIG_MBEDTLS_CERTIFICATE_BUNDLE_DEFAULT_FULL=y
# CONFIG_MBEDTLS_CERTIFICATE_BUNDLE_DEFAULT_CMN is not set
# CONFIG_MBEDTLS_CERTIFICATE_BUNDLE_DEFAULT_NONE is not set
# CONFIG_MBEDTLS_CUSTOM_CERTIFICATE_BUNDLE is not set
CONFIG_MBEDTLS_CERTIFICATE_BUNDLE_MAX_CERTS=200
# end of Certificate Bundle

# CONFIG_MBEDTLS_ECP_RESTARTABLE is not set
# CONFIG_MBEDTLS_CMAC_C is not set
CONFIG_MBEDTLS_HARDWARE_AES=y
CONFIG_MBEDTLS_AES_USE_INTERRUPT=y
CONFIG_MBEDTLS_HARDWARE_MPI=y
CONFIG_MBEDTLS_HARDWARE_SHA=y
CONFIG_MBEDTLS_ROM_MD5=y
# CONFIG_MBEDTLS_ATCA_HW_ECDSA_SIGN is not set
# CONFIG_MBEDTLS_ATCA_HW_ECDSA_VERIFY is not set
CONFIG_MBEDTLS_HAVE_TIME=y
# CONFIG_MBEDTLS_HAVE_TIME_DATE is not set
CONFIG_MBEDTLS_ECDSA_DETERMINISTIC=y
CONFIG_MBEDTLS_SHA512_C=y
CONFIG_MBEDTLS_TLS_SERVER_AND_CLIENT=y
# CONFIG_MBEDTLS_TLS_SERVER_ONLY is not set
# CONFIG_MBEDTLS_TLS_CLIENT_ONLY is not set
# CONFIG_MBEDTLS_TLS_DISABLED is not set
CONFIG_MBEDTLS_TLS_SERVER=y
CONFIG_MBEDTLS_TLS_CLIENT=y
CONFIG_MBEDTLS_TLS_ENABLED=y

#
# TLS Key Exchange Methods
#
# CONFIG_MBEDTLS_PSK_MODES is not set
CONFIG_MBEDTLS_KEY_EXCHANGE_RSA=y
CONFIG_MBEDTLS_KEY_EXCHANGE_DHE_RSA=y
CONFIG_MBEDTLS_KEY_EXCHANGE_ELLIPTIC_CURVE=y
CONFIG_MBEDTLS_KEY_EXCHANGE_ECDHE_RSA=y
CONFIG_MBEDTLS_KEY_EXCHANGE_ECDHE_ECDSA=y
CONFIG_MBEDTLS_KEY_EXCHANGE_ECDH_ECDSA=y
CONFIG_MBEDTLS_KEY_EXCHANGE_ECDH_RSA=y
# end of TLS Key Exchange Methods

CONFIG_MBEDTLS_SSL_RENEGOTIATION=y
# CONFIG_MBEDTLS_SSL_PROTO_SSL3 is not set
CONFIG_MBEDTLS_SSL_PROTO_TLS1=y
CONFIG_MBEDTLS_SSL_PROTO_TLS1_1=y
CONFIG_MBEDTLS_SSL_PROTO_TLS1_2=y
# CONFIG_MBEDTLS_SSL_PROTO_GMTSSL1_1 is not set
# CONFIG_MBEDTLS_SSL_PROTO_DTLS is not set
CONFIG_MBEDTLS_SSL_ALPN=y
CONFIG_MBEDTLS_CLIENT_SSL_SESSION_TICKETS=y
CONFIG_MBEDTLS_X509_CHECK_KEY_USAGE=y
CONFIG_MBEDTLS_X509_CHECK_EXTENDED_KEY_USAGE=y
CONFIG_MBEDTLS_SERVER_SSL_SESSION_TICKETS=y

#
# Symmetric Ciphers
#
CONFIG_MBEDTLS_AES_C=y
# CONFIG_MBEDTLS_CAMELLIA_C is not set
# CONFIG_MBEDTLS_DES_C is not set
CONFIG_MBEDTLS_RC4_DISABLED=y
# CONFIG_MBEDTLS_RC4_ENABLED_NO_DEFAULT is not set
# CONFIG_MBEDTLS_RC4_ENABLED is not set
# CONFIG_MBEDTLS_BLOWFISH_C is not set
# CONFIG_MBEDTLS_XTEA_C is not set
CONFIG_MBEDTLS_CCM_C=y
CONFIG_MBEDTLS_GCM_C=y
# CONFIG_MBEDTLS_NIST_KW_C is not set
# end of Symmetric Ciphers

# CONFIG_MBEDTLS_RIPEMD160_C is not set

#
# Certificates
#
CONFIG_MBEDTLS_PEM_PARSE_C=y
CONFIG_MBEDTLS_PEM_WRITE_C=y
CONFIG_MBEDTLS_X509_CRL_PARSE_C=y
CONFIG_MBEDTLS_X509_CSR_PARSE_C=y
# end of Certificates

CONFIG_MBEDTLS_ECP_C=y
CONFIG_MBEDTLS_ECDH_C=y
CONFIG_MBEDTLS_ECDSA_C=y
# CONFIG_MBEDTLS_ECJPAKE_C is not set
CONFIG_MBEDTLS_ECP_DP_SECP192R1_ENABLED=y
CONFIG_MBEDTLS_ECP_DP_SECP224R1_ENABLED=y
CONFIG_MBEDTLS_ECP_DP_SECP256R1_ENABLED=y
CONFIG_MBEDTLS_ECP_DP_SECP384R1_ENABLED=y
CONFIG_MBEDTLS_ECP_DP_SECP521R1_ENABLED=y
CONFIG_MBEDTLS_ECP_DP_SECP192K1_ENABLED=y
CONFIG_MBEDTLS_ECP_DP_SECP224K1_ENABLED=y
CONFIG_MBEDTLS_ECP_DP_SECP256K1_ENABLED=y
CONFIG_MBEDTLS_ECP_DP_BP256R1_ENABLED=y
CONFIG_MBEDTLS_ECP_DP_BP384R1_ENABLED=y
CONFIG_MBEDTLS_ECP_DP_BP512R1_ENABLED=y
CONFIG_MBEDTLS_ECP_DP_CURVE25519_ENABLED=y
CONFIG_MBEDTLS_ECP_NIST_OPTIM=y
# CONFIG_MBEDTLS_POLY1305_C is not set
# CONFIG_MBEDTLS_CHACHA20_C is not set
# CONFIG_MBEDTLS_HKDF_C is not set
# CONFIG_MBEDTLS_THREADING_C is not set
# CONFIG_MBEDTLS_LARGE_KEY_SOFTWARE_MPI is not set
# CONFIG_MBEDTLS_SECURITY_RISKS is not set
# end of mbedTLS


下面是开启Mbedtls后的日志
I (31829) ms_camera: picture: 1280 x 720 22111byte
I (31834) ms_http_client: picture size = 22111
I (31846) ms_http_client: http_get_task 2
I (31851) ms_http_client: http_loader_len = 22553
I (31855) ms_http_client: HTTP POST:30606
E (31860) TRANSPORT_BASE: -------send time test=30611ms ssl_connect
E (31907) esp-tls: -------send time test3=30658ms tcp_connect
E (31907) esp-tls-mbedtls: -------send time2=30658ms esp_mbedtls_handshake
I (31910) mbedtls: ssl_tls.c:5905 => handshake
I (31922) mbedtls: ssl_cli.c:4483 client state: 0
I (31927) mbedtls: ssl_msg.c:2102 => flush output
I (31933) mbedtls: ssl_msg.c:2114 <= flush output
I (31945) mbedtls: ssl_cli.c:4483 client state: 1
I (31950) mbedtls: ssl_msg.c:2102 => flush output
I (31956) mbedtls: ssl_msg.c:2114 <= flush output
I (31961) mbedtls: ssl_cli.c:999 => write client hello
I (31970) mbedtls: ssl_msg.c:2542 => write handshake message
I (31974) mbedtls: ssl_msg.c:2701 => write record
I (31981) mbedtls: ssl_msg.c:2102 => flush output
I (31985) mbedtls: ssl_msg.c:2122 message length: 244, out_left: 244
I (31994) mbedtls: ssl_msg.c:2127 ssl->f_send() returned 244 (-0xffffff0c)
I (32000) mbedtls: ssl_msg.c:2155 <= flush output
I (32006) mbedtls: ssl_msg.c:2870 <= write record
I (32011) mbedtls: ssl_msg.c:2678 <= write handshake message
I (32018) mbedtls: ssl_cli.c:1467 <= write client hello
I (32030) mbedtls: ssl_cli.c:4483 client state: 2
I (32036) mbedtls: ssl_msg.c:2102 => flush output

I (32041) mbedtls: ssl_msg.c:2114 <= flush output

I (32047) mbedtls: ssl_cli.c:2082 => parse server hello

I (32053) mbedtls: ssl_msg.c:3941 => read record

I (32058) mbedtls: ssl_msg.c:1886 => fetch input

I (32064) mbedtls: ssl_msg.c:2043 in_left: 0, nb_want: 5

I (32070) mbedtls: ssl_msg.c:2068 in_left: 0, nb_want: 5

I (32076) mbedtls: ssl_msg.c:2069 ssl->f_recv(_timeout)() returned 5 (-0xfffffffb)

I (32085) mbedtls: ssl_msg.c:2089 <= fetch input

I (32090) mbedtls: ssl_msg.c:1886 => fetch input

I (32096) mbedtls: ssl_msg.c:2043 in_left: 5, nb_want: 70

I (32102) mbedtls: ssl_msg.c:2068 in_left: 5, nb_want: 70

I (32108) mbedtls: ssl_msg.c:2069 ssl->f_recv(_timeout)() returned 65 (-0xffffffbf)

I (32117) mbedtls: ssl_msg.c:2089 <= fetch input

I (32123) mbedtls: ssl_msg.c:4015 <= read record

I (32128) mbedtls: ssl_cli.c:2385 server hello, total extension length: 21

I (32136) mbedtls: ssl_cli.c:2627 <= parse server hello
I (32148) mbedtls: ssl_cli.c:4483 client state: 3

I (32153) mbedtls: ssl_msg.c:2102 => flush output

I (32159) mbedtls: ssl_msg.c:2114 <= flush output

I (32164) mbedtls: ssl_tls.c:2878 => parse certificate

I (32170) mbedtls: ssl_msg.c:3941 => read record

I (32176) mbedtls: ssl_msg.c:1886 => fetch input

I (32181) mbedtls: ssl_msg.c:2043 in_left: 0, nb_want: 5

I (32188) mbedtls: ssl_msg.c:2068 in_left: 0, nb_want: 5

I (32194) mbedtls: ssl_msg.c:2069 ssl->f_recv(_timeout)() returned 5 (-0xfffffffb)

I (32202) mbedtls: ssl_msg.c:2089 <= fetch input

I (32208) mbedtls: ssl_msg.c:1886 => fetch input

I (32213) mbedtls: ssl_msg.c:2043 in_left: 5, nb_want: 2738

I (32221) mbedtls: ssl_msg.c:2068 in_left: 5, nb_want: 2738

I (32226) mbedtls: ssl_msg.c:2069 ssl->f_recv(_timeout)() returned 2733 (-0xfffff553)

I (32235) mbedtls: ssl_msg.c:2089 <= fetch input

I (32259) mbedtls: ssl_msg.c:4015 <= read record

I (32266) mbedtls: ssl_tls.c:2989 <= parse certificate

I (32268) mbedtls: ssl_cli.c:4483 client state: 4

I (32273) mbedtls: ssl_msg.c:2102 => flush output

I (32279) mbedtls: ssl_msg.c:2114 <= flush output

I (32284) mbedtls: ssl_cli.c:3094 => parse server key exchange

I (32291) mbedtls: ssl_msg.c:3941 => read record

I (32297) mbedtls: ssl_msg.c:1886 => fetch input

I (32302) mbedtls: ssl_msg.c:2043 in_left: 0, nb_want: 5

I (32309) mbedtls: ssl_msg.c:2068 in_left: 0, nb_want: 5

I (32315) mbedtls: ssl_msg.c:2069 ssl->f_recv(_timeout)() returned 5 (-0xfffffffb)

I (32323) mbedtls: ssl_msg.c:2089 <= fetch input

I (32329) mbedtls: ssl_msg.c:1886 => fetch input

I (32334) mbedtls: ssl_msg.c:2043 in_left: 5, nb_want: 305

I (32341) mbedtls: ssl_msg.c:2068 in_left: 5, nb_want: 305

I (32347) mbedtls: ssl_msg.c:2069 ssl->f_recv(_timeout)() returned 300 (-0xfffffed4)

I (32355) mbedtls: ssl_msg.c:2089 <= fetch input

I (32363) mbedtls: ssl_msg.c:4015 <= read record

I (32369) mbedtls: ssl_cli.c:2699 ECDH curve: x25519

I (32372) mbedtls: ssl_cli.c:3018 Server used SignatureAlgorithm 1

I (32379) mbedtls: ssl_cli.c:3020 Server used HashAlgorithm 4

I (32407) mbedtls: ssl_cli.c:3487 <= parse server key exchange

I (32410) mbedtls: ssl_cli.c:4483 client state: 5

I (32415) mbedtls: ssl_msg.c:2102 => flush output

I (32421) mbedtls: ssl_msg.c:2114 <= flush output

I (32427) mbedtls: ssl_cli.c:3522 => parse certificate request

I (32433) mbedtls: ssl_msg.c:3941 => read record

I (32439) mbedtls: ssl_msg.c:1886 => fetch input

I (32444) mbedtls: ssl_msg.c:2043 in_left: 0, nb_want: 5

I (32451) mbedtls: ssl_msg.c:2068 in_left: 0, nb_want: 5

I (32457) mbedtls: ssl_msg.c:2069 ssl->f_recv(_timeout)() returned 5 (-0xfffffffb)

I (32465) mbedtls: ssl_msg.c:2089 <= fetch input

I (32471) mbedtls: ssl_msg.c:1886 => fetch input

I (32476) mbedtls: ssl_msg.c:2043 in_left: 5, nb_want: 9

I (32482) mbedtls: ssl_msg.c:2068 in_left: 5, nb_want: 9

I (32488) mbedtls: ssl_msg.c:2069 ssl->f_recv(_timeout)() returned 4 (-0xfffffffc)

I (32497) mbedtls: ssl_msg.c:2089 <= fetch input

I (32502) mbedtls: ssl_msg.c:4015 <= read record

I (32508) mbedtls: ssl_cli.c:3678 <= parse certificate request

I (32521) mbedtls: ssl_cli.c:4483 client state: 6

I (32526) mbedtls: ssl_msg.c:2102 => flush output

I (32532) mbedtls: ssl_msg.c:2114 <= flush output

I (32537) mbedtls: ssl_cli.c:3689 => parse server hello done

I (32544) mbedtls: ssl_msg.c:3941 => read record

I (32549) mbedtls: ssl_msg.c:4011 reuse previously read message

I (32556) mbedtls: ssl_msg.c:4015 <= read record

I (32562) mbedtls: ssl_cli.c:3719 <= parse server hello done

I (32575) mbedtls: ssl_cli.c:4483 client state: 7

I (32580) mbedtls: ssl_msg.c:2102 => flush output

I (32586) mbedtls: ssl_msg.c:2114 <= flush output

I (32591) mbedtls: ssl_tls.c:2229 => write certificate

I (32597) mbedtls: ssl_tls.c:2243 <= skip write certificate

I (32610) mbedtls: ssl_cli.c:4483 client state: 8

I (32616) mbedtls: ssl_msg.c:2102 => flush output

I (32621) mbedtls: ssl_msg.c:2114 <= flush output

I (32627) mbedtls: ssl_cli.c:3734 => write client key exchange

I (33112) mbedtls: ssl_msg.c:2542 => write handshake message

I (33113) mbedtls: ssl_msg.c:2701 => write record

I (33114) mbedtls: ssl_msg.c:2102 => flush output

I (33119) mbedtls: ssl_msg.c:2122 message length: 42, out_left: 42

I (33127) mbedtls: ssl_msg.c:2127 ssl->f_send() returned 42 (-0xffffffd6)

I (33134) mbedtls: ssl_msg.c:2155 <= flush output

I (33139) mbedtls: ssl_msg.c:2870 <= write record

I (33145) mbedtls: ssl_msg.c:2678 <= write handshake message

I (33151) mbedtls: ssl_cli.c:4151 <= write client key exchange

I (33165) mbedtls: ssl_cli.c:4483 client state: 9

I (33170) mbedtls: ssl_msg.c:2102 => flush output

I (33175) mbedtls: ssl_msg.c:2114 <= flush output

I (33181) mbedtls: ssl_cli.c:4196 => write certificate verify

I (33188) mbedtls: ssl_tls.c:1728 => derive keys

I (33193) mbedtls: ssl_tls.c:1930 => calc verify sha256

I (33200) mbedtls: ssl_tls.c:1938 <= calc verify

I (33212) mbedtls: ssl_tls.c:1807 <= derive keys

I (33213) mbedtls: ssl_cli.c:4221 <= skip write certificate verify

I (33224) mbedtls: ssl_cli.c:4483 client state: 10

I (33229) mbedtls: ssl_msg.c:2102 => flush output

I (33235) mbedtls: ssl_msg.c:2114 <= flush output

I (33240) mbedtls: ssl_msg.c:5012 => write change cipher spec

I (33247) mbedtls: ssl_msg.c:2542 => write handshake message

I (33253) mbedtls: ssl_msg.c:2701 => write record

I (33259) mbedtls: ssl_msg.c:2102 => flush output

I (33265) mbedtls: ssl_msg.c:2122 message length: 6, out_left: 6

I (33272) mbedtls: ssl_msg.c:2127 ssl->f_send() returned 6 (-0xfffffffa)

I (33279) mbedtls: ssl_msg.c:2155 <= flush output

I (33285) mbedtls: ssl_msg.c:2870 <= write record

I (33290) mbedtls: ssl_msg.c:2678 <= write handshake message

I (33297) mbedtls: ssl_msg.c:5026 <= write change cipher spec

I (33310) mbedtls: ssl_cli.c:4483 client state: 11

I (33315) mbedtls: ssl_msg.c:2102 => flush output

I (33321) mbedtls: ssl_msg.c:2114 <= flush output

I (33327) mbedtls: ssl_tls.c:3533 => write finished

I (33332) mbedtls: ssl_tls.c:3323 => calc finished tls sha256

I (33340) mbedtls: ssl_tls.c:3349 <= calc finished

I (33345) mbedtls: ssl_msg.c:2542 => write handshake message

I (33351) mbedtls: ssl_msg.c:2701 => write record

I (33357) mbedtls: ssl_msg.c:632 => encrypt buf

I (33363) mbedtls: ssl_msg.c:1120 <= encrypt buf

I (33368) mbedtls: ssl_msg.c:2102 => flush output

I (33373) mbedtls: ssl_msg.c:2122 message length: 45, out_left: 45

I (33381) mbedtls: ssl_msg.c:2127 ssl->f_send() returned 45 (-0xffffffd3)

I (33388) mbedtls: ssl_msg.c:2155 <= flush output

I (33393) mbedtls: ssl_msg.c:2870 <= write record

I (33399) mbedtls: ssl_msg.c:2678 <= write handshake message

I (33405) mbedtls: ssl_tls.c:3642 <= write finished

I (33418) mbedtls: ssl_cli.c:4483 client state: 12

I (33423) mbedtls: ssl_msg.c:2102 => flush output

I (33429) mbedtls: ssl_msg.c:2114 <= flush output

I (33435) mbedtls: ssl_cli.c:4365 => parse new session ticket

I (33441) mbedtls: ssl_msg.c:3941 => read record

I (33446) mbedtls: ssl_msg.c:1886 => fetch input

I (33452) mbedtls: ssl_msg.c:2043 in_left: 0, nb_want: 5

I (33479) mbedtls: ssl_msg.c:2068 in_left: 0, nb_want: 5

I (33480) mbedtls: ssl_msg.c:2069 ssl->f_recv(_timeout)() returned 5 (-0xfffffffb)

I (33483) mbedtls: ssl_msg.c:2089 <= fetch input

I (33489) mbedtls: ssl_msg.c:1886 => fetch input

I (33494) mbedtls: ssl_msg.c:2043 in_left: 5, nb_want: 191

I (33501) mbedtls: ssl_msg.c:2068 in_left: 5, nb_want: 191

I (33507) mbedtls: ssl_msg.c:2069 ssl->f_recv(_timeout)() returned 186 (-0xffffff46)

I (33516) mbedtls: ssl_msg.c:2089 <= fetch input

I (33523) mbedtls: ssl_msg.c:4015 <= read record

I (33527) mbedtls: ssl_cli.c:4467 <= parse new session ticket

I (33540) mbedtls: ssl_cli.c:4483 client state: 12

I (33545) mbedtls: ssl_msg.c:2102 => flush output

I (33551) mbedtls: ssl_msg.c:2114 <= flush output

I (33556) mbedtls: ssl_msg.c:5035 => parse change cipher spec

I (33563) mbedtls: ssl_msg.c:3941 => read record

I (33568) mbedtls: ssl_msg.c:1886 => fetch input

I (33574) mbedtls: ssl_msg.c:2043 in_left: 0, nb_want: 5

I (33580) mbedtls: ssl_msg.c:2068 in_left: 0, nb_want: 5

I (33586) mbedtls: ssl_msg.c:2069 ssl->f_recv(_timeout)() returned 5 (-0xfffffffb)

I (33595) mbedtls: ssl_msg.c:2089 <= fetch input

I (33600) mbedtls: ssl_msg.c:1886 => fetch input

I (33606) mbedtls: ssl_msg.c:2043 in_left: 5, nb_want: 6

I (33612) mbedtls: ssl_msg.c:2068 in_left: 5, nb_want: 6

I (33618) mbedtls: ssl_msg.c:2069 ssl->f_recv(_timeout)() returned 1 (-0xffffffff)

I (33626) mbedtls: ssl_msg.c:2089 <= fetch input

I (33632) mbedtls: ssl_msg.c:4015 <= read record

I (33637) mbedtls: ssl_msg.c:5099 <= parse change cipher spec

I (33651) mbedtls: ssl_cli.c:4483 client state: 13

I (33656) mbedtls: ssl_msg.c:2102 => flush output

I (33662) mbedtls: ssl_msg.c:2114 <= flush output

I (33667) mbedtls: ssl_tls.c:3659 => parse finished

I (33673) mbedtls: ssl_tls.c:3323 => calc finished tls sha256

I (33681) mbedtls: ssl_tls.c:3349 <= calc finished

I (33685) mbedtls: ssl_msg.c:3941 => read record

I (33691) mbedtls: ssl_msg.c:1886 => fetch input

I (33696) mbedtls: ssl_msg.c:2043 in_left: 0, nb_want: 5

I (33703) mbedtls: ssl_msg.c:2068 in_left: 0, nb_want: 5

I (33709) mbedtls: ssl_msg.c:2069 ssl->f_recv(_timeout)() returned 5 (-0xfffffffb)

I (33717) mbedtls: ssl_msg.c:2089 <= fetch input

I (33723) mbedtls: ssl_msg.c:1886 => fetch input

I (33728) mbedtls: ssl_msg.c:2043 in_left: 5, nb_want: 45

I (33734) mbedtls: ssl_msg.c:2068 in_left: 5, nb_want: 45

I (33740) mbedtls: ssl_msg.c:2069 ssl->f_recv(_timeout)() returned 40 (-0xffffffd8)

I (33749) mbedtls: ssl_msg.c:2089 <= fetch input

I (33755) mbedtls: ssl_msg.c:1144 => decrypt buf

I (33761) mbedtls: ssl_msg.c:1741 <= decrypt buf

I (33766) mbedtls: ssl_msg.c:4015 <= read record

I (33771) mbedtls: ssl_tls.c:3730 <= parse finished

I (33783) mbedtls: ssl_cli.c:4483 client state: 14

I (33789) mbedtls: ssl_msg.c:2102 => flush output

I (33794) mbedtls: ssl_msg.c:2114 <= flush output

I (33800) mbedtls: ssl_cli.c:4594 handshake: done

I (33812) mbedtls: ssl_cli.c:4483 client state: 15

I (33817) mbedtls: ssl_msg.c:2102 => flush output

I (33823) mbedtls: ssl_msg.c:2114 <= flush output

I (33841) mbedtls: ssl_tls.c:5920 <= handshake

E (33846) esp-tls-mbedtls: -------send time3=32597ms esp_mbedtls_handshake
I (33855) mbedtls: ssl_msg.c:5820 => write

I (33859) mbedtls: ssl_msg.c:2701 => write record

I (33864) mbedtls: ssl_msg.c:632 => encrypt buf

I (33873) mbedtls: ssl_msg.c:1120 <= encrypt buf

I (33877) mbedtls: ssl_msg.c:2102 => flush output

I (33881) mbedtls: ssl_msg.c:2122 message length: 238, out_left: 238

I (33889) mbedtls: ssl_msg.c:2127 ssl->f_send() returned 238 (-0xffffff12)

I (33896) mbedtls: ssl_msg.c:2155 <= flush output

I (33901) mbedtls: ssl_msg.c:2870 <= write record

I (33907) mbedtls: ssl_msg.c:5848 <= write

I (33913) mbedtls: ssl_msg.c:5820 => write

I (33917) mbedtls: ssl_msg.c:2701 => write record

I (33922) mbedtls: ssl_msg.c:632 => encrypt buf

I (33970) mbedtls: ssl_msg.c:1120 <= encrypt buf

I (33998) mbedtls: ssl_msg.c:2102 => flush output

I (33998) mbedtls: ssl_msg.c:2122 message length: 4125, out_left: 4125

I (34002) mbedtls: ssl_msg.c:2127 ssl->f_send() returned 4125 (-0xffffefe3)

I (34008) mbedtls: ssl_msg.c:2155 <= flush output

I (34013) mbedtls: ssl_msg.c:2870 <= write record

I (34019) mbedtls: ssl_msg.c:5848 <= write

I (34024) mbedtls: ssl_msg.c:5820 => write

I (34029) mbedtls: ssl_msg.c:2701 => write record

I (34034) mbedtls: ssl_msg.c:632 => encrypt buf

I (34083) mbedtls: ssl_msg.c:1120 <= encrypt buf

I (34112) mbedtls: ssl_msg.c:2102 => flush output

I (34112) mbedtls: ssl_msg.c:2122 message length: 4125, out_left: 4125

I (34116) mbedtls: ssl_msg.c:2127 ssl->f_send() returned 4125 (-0xffffefe3)

I (34122) mbedtls: ssl_msg.c:2155 <= flush output

I (34127) mbedtls: ssl_msg.c:2870 <= write record

I (34133) mbedtls: ssl_msg.c:5848 <= write

I (34138) mbedtls: ssl_msg.c:5820 => write

I (34143) mbedtls: ssl_msg.c:2701 => write record

I (34148) mbedtls: ssl_msg.c:632 => encrypt buf

I (34197) mbedtls: ssl_msg.c:1120 <= encrypt buf

I (34225) mbedtls: ssl_msg.c:2102 => flush output

I (34226) mbedtls: ssl_msg.c:2122 message length: 4125, out_left: 4125

I (34229) mbedtls: ssl_msg.c:2127 ssl->f_send() returned 4125 (-0xffffefe3)

I (34235) mbedtls: ssl_msg.c:2155 <= flush output

I (34241) mbedtls: ssl_msg.c:2870 <= write record

I (34246) mbedtls: ssl_msg.c:5848 <= write

I (34251) mbedtls: ssl_msg.c:5820 => write

I (34256) mbedtls: ssl_msg.c:2701 => write record

I (34262) mbedtls: ssl_msg.c:632 => encrypt buf

I (34310) mbedtls: ssl_msg.c:1120 <= encrypt buf

I (34338) mbedtls: ssl_msg.c:2102 => flush output

I (34339) mbedtls: ssl_msg.c:2122 message length: 4125, out_left: 4125

I (34342) mbedtls: ssl_msg.c:2127 ssl->f_send() returned 4125 (-0xffffefe3)

I (34348) mbedtls: ssl_msg.c:2155 <= flush output

I (34354) mbedtls: ssl_msg.c:2870 <= write record

I (34359) mbedtls: ssl_msg.c:5848 <= write

I (34364) mbedtls: ssl_msg.c:5820 => write

I (34369) mbedtls: ssl_msg.c:2701 => write record

I (34375) mbedtls: ssl_msg.c:632 => encrypt buf

I (34424) mbedtls: ssl_msg.c:1120 <= encrypt buf

I (34452) mbedtls: ssl_msg.c:2102 => flush output

I (34452) mbedtls: ssl_msg.c:2122 message length: 4125, out_left: 4125

I (34456) mbedtls: ssl_msg.c:2127 ssl->f_send() returned 4125 (-0xffffefe3)

I (34462) mbedtls: ssl_msg.c:2155 <= flush output

I (34467) mbedtls: ssl_msg.c:2870 <= write record

I (34473) mbedtls: ssl_msg.c:5848 <= write

I (34478) mbedtls: ssl_msg.c:5820 => write

I (34483) mbedtls: ssl_msg.c:2701 => write record

I (34488) mbedtls: ssl_msg.c:632 => encrypt buf

I (34517) mbedtls: ssl_msg.c:1120 <= encrypt buf

I (34532) mbedtls: ssl_msg.c:2102 => flush output

I (34533) mbedtls: ssl_msg.c:2122 message length: 2102, out_left: 2102

I (34536) mbedtls: ssl_msg.c:2127 ssl->f_send() returned 2102 (-0xfffff7ca)

I (34542) mbedtls: ssl_msg.c:2155 <= flush output

I (34548) mbedtls: ssl_msg.c:2870 <= write record

I (34553) mbedtls: ssl_msg.c:5848 <= write

I (34625) mbedtls: ssl_msg.c:5399 => read

I (34626) mbedtls: ssl_msg.c:3941 => read record

I (34627) mbedtls: ssl_msg.c:1886 => fetch input

I (34631) mbedtls: ssl_msg.c:2043 in_left: 0, nb_want: 5

I (34637) mbedtls: ssl_msg.c:2068 in_left: 0, nb_want: 5

I (34643) mbedtls: ssl_msg.c:2069 ssl->f_recv(_timeout)() returned 5 (-0xfffffffb)

I (34652) mbedtls: ssl_msg.c:2089 <= fetch input

I (34657) mbedtls: ssl_msg.c:1886 => fetch input

I (34662) mbedtls: ssl_msg.c:2043 in_left: 5, nb_want: 994

I (34670) mbedtls: ssl_msg.c:2068 in_left: 5, nb_want: 994

I (34675) mbedtls: ssl_msg.c:2069 ssl->f_recv(_timeout)() returned 989 (-0xfffffc23)

I (34684) mbedtls: ssl_msg.c:2089 <= fetch input

I (34696) mbedtls: ssl_msg.c:1144 => decrypt buf

I (34700) mbedtls: ssl_msg.c:1741 <= decrypt buf

I (34707) mbedtls: ssl_msg.c:4015 <= read record

I (34708) mbedtls: ssl_msg.c:5693 <= read

I (34711) mbedtls: ssl_msg.c:5399 => read

I (34715) mbedtls: ssl_msg.c:5693 <= read

I (34721) HTTP_CLIENT: Body received in fetch header state, 0x3fcb4de2, 177
I (34729) mbedtls: ssl_msg.c:5399 => read

I (34733) mbedtls: ssl_msg.c:3941 => read record

I (34738) mbedtls: ssl_msg.c:1886 => fetch input

I (34744) mbedtls: ssl_msg.c:2043 in_left: 0, nb_want: 5

I (34750) mbedtls: ssl_msg.c:2068 in_left: 0, nb_want: 5

I (34756) mbedtls: ssl_msg.c:2069 ssl->f_recv(_timeout)() returned 5 (-0xfffffffb)

I (34764) mbedtls: ssl_msg.c:2089 <= fetch input

I (34770) mbedtls: ssl_msg.c:1886 => fetch input

I (34775) mbedtls: ssl_msg.c:2043 in_left: 5, nb_want: 34

I (34782) mbedtls: ssl_msg.c:2068 in_left: 5, nb_want: 34

I (34788) mbedtls: ssl_msg.c:2069 ssl->f_recv(_timeout)() returned 29 (-0xffffffe3)

I (34796) mbedtls: ssl_msg.c:2089 <= fetch input

I (34802) mbedtls: ssl_msg.c:1144 => decrypt buf

I (34808) mbedtls: ssl_msg.c:1741 <= decrypt buf

I (34813) mbedtls: ssl_msg.c:4015 <= read record

I (34818) mbedtls: ssl_msg.c:5693 <= read

I (34823) ms_http_client: end_time 2:33574
I (34828) ms_http_client: average_time 2:2111:2999
I (34833) ms_http_client: HTTP POST Status = 200, content_length = -1

kangzy4
Posts: 6
Joined: Wed Jan 11, 2023 7:18 am

Re: ESP32-S3 HTTPS esp_mbedtls_handshake握手平均耗时3s以上

Postby kangzy4 » Mon Jan 16, 2023 9:34 am

您好,
这边重新修改了相关配置,也排除了网络和服务器端的问题后。

目前1000次HTTPS请求(消息体30kB是的图片)平均耗时大概在1.3s左右。
socket init < 1ms
tls init <1ms
tcp_connect 60-80ms
mbedtls_ssl_handshake 800ms
transfer 320ms
使用POSTMAN工具测试耗时在300ms左右。

想了解下:
1.3秒是否属于模组正常请求时间?HTTPS请求耗时是否有参考的数值呢?

ESP_YJM
Posts: 300
Joined: Fri Feb 26, 2021 10:30 am

Re: ESP32-S3 HTTPS esp_mbedtls_handshake握手平均耗时3s以上

Postby ESP_YJM » Tue Jan 17, 2023 12:12 pm

1.3s 的时间算正常。目前日志中没看到握手所使用的加密套件,如果用了椭圆算法就会比较久。你可以参考函数 mbedtls_ssl_get_ciphersuite 打印加密套件(这个需要在握手成功后),看日志是没有套件打印。

kangzy4
Posts: 6
Joined: Wed Jan 11, 2023 7:18 am

Re: ESP32-S3 HTTPS esp_mbedtls_handshake握手平均耗时3s以上

Postby kangzy4 » Mon Jan 30, 2023 2:32 am

验证后发现用的的确是椭圆算法:
esp-tls-mbedtls: Cipher suite is TLS-ECDHE-RSA-WITH-AES-128-GCM-SHA256

如果需要验证RSA或DHE,是否是需要服务端提供对应的密钥交换套件的接口呢?我看官网的例程用的也是ECDHE,不知道官方是否有RSA或DHE的后端接口可以提供验证呢?或者有没有这几种算法在模组上运行效率相关的数据可以提供参考呢?

因为我们目前场景对耗时比较敏感,想综合对比下。

又或者是否有其它可以提高运行效率的地方呢?目前主频已设置在240MHz

ESP_YJM
Posts: 300
Joined: Fri Feb 26, 2021 10:30 am

Re: ESP32-S3 HTTPS esp_mbedtls_handshake握手平均耗时3s以上

Postby ESP_YJM » Mon Jan 30, 2023 3:20 am

我们有 ECDH,DHE 和 RSA 的对比数据,时间消耗上 RSA < DHE < ECDH ,所以你看下服务器是否支持 RSA-WITH-AES,可以在客户端专门设置特定的加密套件,修改该配置,比如设置 TLS_RSA_WITH_AES_128_GCM_SHA256,可以在如下文件 https://github.com/espressif/esp-idf/bl ... ig.h#L2959 加一句 #define MBEDTLS_SSL_CIPHERSUITES MBEDTLS_TLS_RSA_WITH_AES_128_GCM_SHA256。这样有可能导致服务器拒绝连接,可能是服务器不支持该加密套件,你可以再试试其他的加密套件,或者使用 openssl 命令获取服务器支持的加密套件然后挑个非椭圆曲线的加密套件,这样应该可以节省时间。

Who is online

Users browsing this forum: Google [Bot] and 34 guests