ESP32-S3 HTTPS esp_mbedtls_handshake握手平均耗时3s以上
Posted: 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<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
更改为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<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