esp-hosted icon indicating copy to clipboard operation
esp-hosted copied to clipboard
verified publisher icon espressif

Very poor performance with SDIO, sporadic SDIO errors

Open mdeneen opened this issue 1 year ago • 9 comments

Checklist

  • [X] Checked the issue tracker for similar issues to ensure this is not a duplicate
  • [X] Read the documentation to confirm the issue is not addressed there and your configuration is set correctly
  • [X] Tested with the latest version to ensure the issue hasn't been fixed

How often does this bug occurs?

always

Expected behavior

I expected reasonable throughput

Actual behavior (suspected bug)

Throughput is about 2 megabits per second, and it stops working entirely after less than 10 megabytes have been transferred.

Error logs or terminal output

root@imx93:~# modprobe esp32_sdio resetpin=608 clockspeed=60
root@imx93:~# wpa_supplicant -i wlan0 -B -c /data/tds/wpa_supplicant.conf 
Successfully initialized wpa_supplicant
nl80211: kernel reports: Registration to specific type not supported
nl80211: kernel reports: Registration to specific type not supported
nl80211: kernel reports: Registration to specific type not supported
nl80211: kernel reports: Registration to specific type not supported
nl80211: kernel reports: Registration to specific type not supported
nl80211: kernel reports: Registration to specific type not supported
nl80211: kernel reports: Registration to specific type not supported
nl80211: kernel reports: Registration to specific type not supported
nl80211: kernel reports: Registration to specific type not supported
nl80211: kernel reports: Registration to specific type not supported
nl80211: kernel reports: Registration to specific type not supported
nl80211: kernel reports: Registration to specific type not supported
nl80211: kernel reports: Registration to specific type not supported
nl80211: kernel reports: Registration to specific type not supported
nl80211: kernel reports: Registration to specific type not supported
nl80211: kernel reports: Registration to specific type not supported
nl80211: kernel reports: Registration to specific type not supported
nl80211: kernel reports: Registration to specific type not supported
nl80211: kernel reports: Registration to specific type not supported
nl80211: kernel reports: Registration to specific type not supported
nl80211: kernel reports: Registration to specific type not supported
nl80211: kernel reports: Registration to specific type not supported
nl80211: kernel reports: Registration to specific type not supported
nl80211: kernel reports: Registration to specific type not supported
nl80211: kernel reports: Registration to specific type not supported
nl80211: kernel reports: Registration to specific type not supported
root@imx93:~# udhcpc -i wlan0
udhcpc: started, v1.36.1
Dropped protocol specifier '.udhcpc' from 'wlan0.udhcpc'. Using 'wlan0' (ifindex=29).
udhcpc: broadcasting discover
udhcpc: broadcasting select for 192.168.2.24, server 192.168.2.1
udhcpc: lease of 192.168.2.24 obtained from 192.168.2.1, lease time 3600
RTNETLINK answers: File exists
/etc/udhcpc.d/50default: Adding DNS 8.8.8.8
Dropped protocol specifier '.udhcpc' from 'wlan0.udhcpc'. Using 'wlan0' (ifindex=29).
root@imx93:~# ip route add xxx.xxx.xxx.xxx/32 via 192.168.2.1
root@imx93:~# iperf -c xxx.xxx.xxx.xxx -p 8000
connect failed: Connection refused
root@imx93:~# iperf -c xxx.xxx.xxx.xxx -p 8000
------------------------------------------------------------
Client connecting to xxx.xxx.xxx.xxx, TCP port 8000
TCP window size: 85.0 KByte (default)
------------------------------------------------------------
[  3] local 192.168.2.24 port 45854 connected with xxx.xxx.xxx.xxx port 8000
[ ID] Interval       Transfer     Bandwidth
[  3]  0.0-11.0 sec  2.00 MBytes  1.52 Mbits/sec



[80642.195719] esp32_sdio: process_esp_bootup_event: Received ESP bootup event
[80642.195731] esp32_sdio: process_event_esp_bootup: Bootup Event tag: 3
[80642.195737] esp32_sdio: esp_validate_chipset: Chipset=ESP32-C6 ID=0d detected over SDIO
[80642.195773] esp32_sdio: process_event_esp_bootup: Bootup Event tag: 0
[80642.195778] esp32_sdio: process_event_esp_bootup: Bootup Event tag: 1
[80642.195782] esp32_sdio: process_fw_data: ESP chipsets last reset cause:
[80642.195786] esp32_sdio: print_reset_reason: POWERON_RESET
[80642.195792] esp32_sdio: check_esp_version: ESP-Hosted Version: NG-1.0.3.0.1
[80642.196112] esp32_sdio: esp_reg_notifier: Driver init is ongoing
[80642.215666] esp32_sdio: tx_process: not ready
[80642.533917] esp32_sdio: init_bt: ESP Bluetooth init
[80642.535044] esp32_sdio: print_capabilities: Capabilities: 0x8d. Features supported are:
[80642.535070] esp32_sdio: print_capabilities: 	* WLAN on SDIO
[80642.535073] esp32_sdio: print_capabilities: 	* BT/BLE
[80642.535077] esp32_sdio: print_capabilities: 	  - HCI over SDIO
[80642.535081] esp32_sdio: print_capabilities: 	  - BLE only
[80642.794724] Bluetooth: MGMT ver 1.22
[80650.470630] esp32_sdio: cmd_auth_request: Authentication request: 24:5a:4c:13:af:69 6 0 0 0
[80650.736522] esp32_sdio: cmd_assoc_request: Association request: 24:5a:4c:13:af:69 6 40
[80650.816828] esp32_sdio: process_assoc_event: Connection status: 0
[80662.574717] esp32_sdio: esp_inetaddr_event: NETDEV_UP interface wlan0 ip changed to  192.168.002.024
[80776.608681] esp32_sdio: read_packet: Failed to read data - -84 [0 - 78]
[80776.633730] esp32_sdio: tx_process: not ready
[80776.653729] esp32_sdio: tx_process: not ready
[80776.673731] esp32_sdio: tx_process: not ready
[80776.693725] esp32_sdio: tx_process: not ready
[80776.713725] esp32_sdio: tx_process: not ready
(this continues)

The esp32c6 side shows no unusual behavior.  Additionally, if I enable wlan path debug on the esp32c6 side I do not receive any SDIO errors, so I suspect timing.

Steps to reproduce the behavior

Load module, configure wlan / acquire IP address, set route, run iperf

Project release version

76bb60975ce4fcbae1434771ee4de6ef09bc2f6b

System architecture

ARM 64-bit (Apple M1/M2, Raspberry Pi 4/5)

Operating system

Linux

Operating system version

6.6.23

Shell

sh

Additional context

Here are the results of the raw throughput test, and they look fantastic.

I (3113) stats: 0-1 sec 0.00 kbits/sec I (4113) stats: 1-2 sec 490.47 kbits/sec I (5113) stats: 2-3 sec 72703.44 kbits/sec I (6113) stats: 3-4 sec 74231.88 kbits/sec I (7113) stats: 4-5 sec 73889.69 kbits/sec I (8113) stats: 5-6 sec 72897.34 kbits/sec I (9113) stats: 6-7 sec 74402.97 kbits/sec I (10113) stats: 7-8 sec 74311.72 kbits/sec I (11113) stats: 8-9 sec 72395.47 kbits/sec I (12113) stats: 9-10 sec 74311.72 kbits/sec I (13113) stats: 10-11 sec 74391.56 kbits/sec I (14113) stats: 11-12 sec 73193.91 kbits/sec I (15113) stats: 12-13 sec 74345.94 kbits/sec I (16113) stats: 13-14 sec 74414.38 kbits/sec I (17113) stats: 14-15 sec 74163.44 kbits/sec I (18113) stats: 15-16 sec 73399.22 kbits/sec I (19113) stats: 16-17 sec 74357.34 kbits/sec I (20113) stats: 17-18 sec 73787.03 kbits/sec I (21113) stats: 18-19 sec 73365.00 kbits/sec I (22113) stats: 19-20 sec 74345.94 kbits/sec I (23113) stats: 20-21 sec 73923.91 kbits/sec I (24113) stats: 21-22 sec 73536.09 kbits/sec I (25113) stats: 22-23 sec 74231.88 kbits/sec I (26113) stats: 23-24 sec 74072.19 kbits/sec I (27113) stats: 24-25 sec 74368.75 kbits/sec I (28113) stats: 25-26 sec 73604.53 kbits/sec I (29113) stats: 26-27 sec 74254.69 kbits/sec I (30113) stats: 27-28 sec 74460.00 kbits/sec I (31113) stats: 28-29 sec 73513.28 kbits/sec I (32113) stats: 29-30 sec 74209.06 kbits/sec I (33113) stats: 30-31 sec 74551.25 kbits/sec I (34113) stats: 31-32 sec 73741.41 kbits/sec I (35113) stats: 32-33 sec 74152.03 kbits/sec I (36113) stats: 33-34 sec 74505.62 kbits/sec I (37113) stats: 34-35 sec 74562.66 kbits/sec I (38113) stats: 35-36 sec 73536.09 kbits/sec I (39113) stats: 36-37 sec 74585.47 kbits/sec I (40113) stats: 37-38 sec 74631.09 kbits/sec I (41113) stats: 38-39 sec 73433.44 kbits/sec I (42113) stats: 39-40 sec 74448.59 kbits/sec I (43113) stats: 40-41 sec 74585.47 kbits/sec I (44113) stats: 41-42 sec 73490.47 kbits/sec I (45113) stats: 42-43 sec 74551.25 kbits/sec I (46113) stats: 43-44 sec 74562.66 kbits/sec I (47113) stats: 44-45 sec 74243.28 kbits/sec I (48113) stats: 45-46 sec 73558.91 kbits/sec I (49113) stats: 46-47 sec 74471.41 kbits/sec I (50113) stats: 47-48 sec 74163.44 kbits/sec

I had previously reported problems with instability in issue https://github.com/espressif/esp-hosted/issues/482, which was related to our linear regulator being insufficient. The output current of the LDO was great, but the transient response was not. It has been replaced with a more capable part -- the esp32c6 is no longer suffering from brownout conditions, but the performance isn't great. This particular SoC has three SDIO interfaces and it can really move some data, so I'm quite trusting in its SDIO abilities.

I have tried many clock speeds, but lower ones don't seem any more stable than high ones.

mdeneen avatar Nov 22 '24 14:11 mdeneen

clockspeed=60

Exceeds the max capacity of slave SDIO for esp32-c6. Screenshot 2024-11-23 at 12 58 04 AM

Worth to check what real frequency Linux released although.

sudo cat /sys/kernel/debug/mmcX/ios

mantriyogesh avatar Nov 22 '24 17:11 mantriyogesh

Considering -84 errors, Did you check the external pull-up register requirements from porting guide?

Also, please note, the SDIO can only work over the PCB, not jumper cables.

Additionally, you have captured the throughput one side, what about reverse direction?

mantriyogesh avatar Nov 22 '24 17:11 mantriyogesh

I hear you, but I have the same behavior with 1, 5, 10, 20, 30, 40, 50, and 60.

At 60, it does this:

clock: 60000000 Hz actual clock: 57142857 Hz vdd: 21 (3.3 ~ 3.4 V) bus mode: 2 (push-pull) chip select: 0 (don't care) power mode: 2 (on) bus width: 2 (4 bits) timing spec: 2 (sd high-speed) signal voltage: 0 (3.30 V) driver type: 0 (driver type B)

I agree that it is out of spec, and perhaps that was the wrong example to paste in here; it just happened to be the last test that I did.

mdeneen avatar Nov 22 '24 17:11 mdeneen

Its better not to exceed 50.

it would be undefined behaviour. For adjusting the timing, there is mention of sdio adjustment timing in porting doc.

You can try changing. but in any case you both side traffic test makes sense.

-84 is worrysome. Can you please send me recent picture for c6 integration?

mantriyogesh avatar Nov 22 '24 17:11 mantriyogesh

Additionally, you have captured the throughput one side, what about reverse direction?

Would these be show in the logs on the host side? If so they looked nearly identical to the messages printed on the esp32c6 side.

Considering -84 errors, Did you check the external pull-up register requirements from porting guide?

I will confirm

Also, please note, the SDIO can only work over the PCB, not jumper cables.

The esp32c6 module is on the PCB, and the traces are ~30mm and length balanced.

mdeneen avatar Nov 22 '24 17:11 mdeneen

Considering -84 errors, Did you check the external pull-up register requirements from porting guide?

Yes, we have pull-ups

mdeneen avatar Nov 22 '24 17:11 mdeneen

Would these be show in the logs on the host side? If so they looked nearly identical to the messages printed on the esp32c6 side.

one direction, suppose esp to host. other direction would be host to esp.

Both need to test in individual test case. check https://github.com/espressif/esp-hosted/blob/master/esp_hosted_ng/docs/Raw_TP_Testing.md. two different test cases / runs with reloads of esp.

mantriyogesh avatar Nov 22 '24 18:11 mantriyogesh

I understand. Here is esp -> host @50MHz:

I (19084) stats: 16-17 sec       31372.00 kbits/sec
I (20084) stats: 17-18 sec       32683.00 kbits/sec
I (21084) stats: 18-19 sec       33120.00 kbits/sec
I (22084) stats: 19-20 sec       33430.50 kbits/sec
I (23084) stats: 20-21 sec       33304.00 kbits/sec
I (24084) stats: 21-22 sec       33074.00 kbits/sec
I (25084) stats: 22-23 sec       32867.00 kbits/sec
I (26084) stats: 23-24 sec       32901.50 kbits/sec
I (27084) stats: 24-25 sec       32890.00 kbits/sec
I (28084) stats: 25-26 sec       32648.50 kbits/sec
I (29084) stats: 26-27 sec       31199.50 kbits/sec
I (30084) stats: 27-28 sec       32614.00 kbits/sec
I (31084) stats: 28-29 sec       32867.00 kbits/sec
I (32084) stats: 29-30 sec       32648.50 kbits/sec
I (33084) stats: 30-31 sec       32591.00 kbits/sec
I (34084) stats: 31-32 sec       33051.00 kbits/sec
I (35084) stats: 32-33 sec       32809.50 kbits/sec
I (36084) stats: 33-34 sec       32510.50 kbits/sec
I (37084) stats: 34-35 sec       32867.00 kbits/sec
I (38084) stats: 35-36 sec       32982.00 kbits/sec
I (39084) stats: 36-37 sec       31556.00 kbits/sec
I (40084) stats: 37-38 sec       32993.50 kbits/sec
I (41084) stats: 38-39 sec       33051.00 kbits/sec
I (42084) stats: 39-40 sec       32568.00 kbits/sec
I (43084) stats: 40-41 sec       32901.50 kbits/sec
I (44084) stats: 41-42 sec       32625.50 kbits/sec
I (45084) stats: 42-43 sec       32913.00 kbits/sec
I (46084) stats: 43-44 sec       32809.50 kbits/sec

mdeneen avatar Nov 22 '24 18:11 mdeneen

any updates ?

mantriyogesh avatar Mar 25 '25 05:03 mantriyogesh