Low performance with SDIO (iperf)

[zavdimka]

Checklist

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

How often does this bug occurs?

always

Expected behavior

Expect to get at last 15Mbits in iperf3 test

Actual behavior (suspected bug)

For TCP connection I get 5.55 Mbits/sec
For UDP connection I get 1.05 Mbits/sec

Error logs or terminal output

Steps to reproduce the behavior

1. Set up router close to the board.
2. Check that signal level is good - not less then -15dBm
3. Run iperf3 server
4. Run iperf3 clien ( iperf3 -c 192.168.1.2)

Project release version

master

System architecture

ARM 32-bit (Raspberry Pi 32-bit)

Operating system

Linux

Operating system version

Buildroot

Shell

Bash

Additional context

Platform - RockChip RV1106
SDIO section in DTS file

/**********SDIO-WIFI**********/
&sdmmc {
        max-frequency = <5000000>;
        bus-width = <4>;
        cap-sd-highspeed;
        cap-sdio-irq;
        keep-power-in-suspend;
        non-removable;
        //rockchip,default-sample-phase = <90>;
        no-sd;
        no-mmc;
        supports-sdio;
        //mmc-pwrseq = <&sdio_pwrseq>;
        pinctrl-names = "default";
        pinctrl-0 = <&sdmmc0_clk &sdmmc0_cmd &sdmmc0_bus4 &sdmmc0_det>;
		no-prescan-powerup;
        post-power-on-delay-ms = <0>;
        status = "okay";
};

 dmesg | grep mmc1
[    0.168413] mmc_host mmc1: card is non-removable.
[    0.168900] mmc_host mmc1: Bus speed (slot 0) = 400000Hz (slot req 400000Hz, actual 400000HZ d)
[    0.205196] mmc1: queuing unknown CIS tuple 0x01 (3 bytes)
[    0.212248] mmc1: queuing unknown CIS tuple 0x1a (5 bytes)
[    0.215324] mmc1: queuing unknown CIS tuple 0x1b (8 bytes)
[    0.216300] mmc_host mmc1: Bus speed (slot 0) = 4950000Hz (slot req 5000000Hz, actual 4950000H)
[    0.222139] mmc1: queuing unknown CIS tuple 0x80 (1 bytes)
[    0.222257] mmc1: queuing unknown CIS tuple 0x81 (1 bytes)
[    0.222360] mmc1: queuing unknown CIS tuple 0x82 (1 bytes)
[    0.224200] mmc1: queuing unknown CIS tuple 0x80 (1 bytes)
[    0.224302] mmc1: queuing unknown CIS tuple 0x81 (1 bytes)
[    0.224401] mmc1: queuing unknown CIS tuple 0x82 (1 bytes)
[    0.224601] mmc1: new high speed SDIO card at address 0001

dmesg | grep esp32
[   32.809365] esp32_sdio: esp_init: init_adapter
[   32.809397] esp32_sdio: esp_init: esp_init_interface_layer
[   32.809646] esp32_sdio: esp_probe: esp_probe
[   32.809651] esp32_sdio: esp_probe: ESP network device detected
[   32.809894] esp32_sdio: get_firmware_data: Rx Pre ====== 0
[   32.809905] esp32_sdio: get_firmware_data: Rx Pos ======  0
[   32.809954] esp32_sdio: get_firmware_data: Tx Pre ======  0
[   32.809962] esp32_sdio: get_firmware_data: Tx Pos ======  10
[   32.810225] esp32_sdio: esp_init: esp_init_interface_layer pass
[   32.814318] esp32_sdio: process_esp_bootup_event: Received ESP bootup event
[   32.814344] esp32_sdio: process_event_esp_bootup: Bootup Event tag: 3
[   32.814356] esp32_sdio: esp_validate_chipset: Chipset=ESP32-C6 ID=0d detected over SDIO
[   32.814363] esp32_sdio: process_event_esp_bootup: Bootup Event tag: 0
[   32.814371] esp32_sdio: process_event_esp_bootup: Bootup Event tag: 1
[   32.814378] esp32_sdio: process_fw_data: ESP chipset's last reset cause:
[   32.814385] esp32_sdio: print_reset_reason: POWERON_RESET
[   32.814396] esp32_sdio: check_esp_version: ESP-Hosted Version: NG-1.0.3.0.9
[   32.815753] esp32_sdio: esp_reg_notifier: Driver init is ongoing
[   32.839362] esp32_sdio: tx_process: not ready
[   33.179363] esp32_sdio: init_bt: ESP Bluetooth init
[   33.179683] esp32_sdio: print_capabilities: Capabilities: 0xd. Features supported are:
[   33.179697] esp32_sdio: print_capabilities:   * WLAN on SDIO
[   33.179706] esp32_sdio: print_capabilities:   * BT/BLE
[   33.179712] esp32_sdio: print_capabilities:     - HCI over SDIO
[   33.179718] esp32_sdio: print_capabilities:     - BLE only
[   59.038540] esp32_sdio: cmd_auth_request: Authentication request: 6c:b0:ce:ff:5c:d2 1 0 0 0
[   59.285542] esp32_sdio: cmd_assoc_request: Association request: 6c:b0:ce:ff:5c:d2 1 42
[   59.390258] esp32_sdio: process_assoc_event: Connection status: 0
[   67.155800] esp32_sdio: esp_inetaddr_event: NETDEV_UP interface wlan0 ip changed to  192.168.03

[mantriyogesh]

What is effective clock in use?

sudo cat /sys/kernel/debug/mmc1/ios

Also, please check the raw transport throughput first in both directions using this

[zavdimka]

Interface test give about 53Mbps.

cat /sys/kernel/debug/mmc1/ios
clock:          50000000 Hz
actual clock:   49500000 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)

Signal is -8 dBm
sdkconfig.txt - confign file, maybe it will help.
Maybe it's bad cristal? Is there any way to check it?

[mantriyogesh]

I couldn't see any obvious issue in sdkconfig. you would need to test 'raw' throughput test (tx and rx both half duplex) to understand if something wrong in the sdio first.

[mantriyogesh]

1. C6 XTAL is 40MHz. Which is fine.

2. Raw throughput would let us know the link capacity. If it is less than desired, you cannot get correct throughput.
   Please attach the textual raw throughput test results.

3. Please confirm if you have added the $\text{external pull up}$ of $\text{desired value}$ and on $\text{desired GPIOs}$. Details

4. Please share the camera picture of your set-up, showing the connections clearly.

[zavdimka]

insmod esp32_sdio.ko raw_tp_mode=2 give

[ 1121.179603] esp32_sdio: process_test_capabilities: start testing of ESP->Host raw throughput
[ 1121.202194] esp32_sdio: print_capabilities: Capabilities: 0xd. Features supported are:
[ 1121.202217] esp32_sdio: print_capabilities:   * WLAN on SDIO
[ 1121.202225] esp32_sdio: print_capabilities:   * BT/BLE
[ 1121.202232] esp32_sdio: print_capabilities:     - HCI over SDIO
[ 1121.202239] esp32_sdio: print_capabilities:     - BLE only
[ 1122.249300] esp32_sdio: log_raw_tp_stats_timer_cb: 0-1 sec       51065 kbits/sec
[ 1122.249300]
[ 1123.289292] esp32_sdio: log_raw_tp_stats_timer_cb: 1-2 sec       52913 kbits/sec
[ 1123.289292]
[ 1124.329302] esp32_sdio: log_raw_tp_stats_timer_cb: 2-3 sec       52970 kbits/sec
[ 1124.329302]
[ 1125.369295] esp32_sdio: log_raw_tp_stats_timer_cb: 3-4 sec       52605 kbits/sec
[ 1125.369295]
r[ 1126.409296] esp32_sdio: log_raw_tp_stats_timer_cb: 4-5 sec       52993 kbits/sec
[ 1126.409296]
mmod[ 1127.449300] esp32_sdio: log_raw_tp_stats_timer_cb: 5-6 sec       53027 kbits/sec

But insmod esp32_sdio.ko raw_tp_mode=1 hangs and don't working.
Pull up are 4.7k on all SDIO lines except CLK. On the fist version of the board we forgot about pull up and solder them using wires. Also there pull up enabled in esp. It doesn't metter if the board has pull up or not - behavior is the same.

[mantriyogesh]

Pull up are 4.7k on all SDIO lines except CLK

From logs it looks to be C6 SDIO.

Pull-up are specific values and should be applied on specific lines : check https://docs.espressif.com/projects/esp-idf/en/latest/esp32c6/api-reference/peripherals/sd_pullup_requirements.html for details. We use 51K ohm external pulls for CMD and DATA (DAT0 - DAT3).

Please ensure the trace length is the same. Generally, this kind of issues would be faced for poor grounding and high signal interference experienced on SDIO. The jumpers put the cherry on the cake (in a sarcastic way).

We do not recommend using jumpers manually for SDIO, instead you get SDIO as with jumper cables, it is not stable.

Apart from this, please also check the voltage received on SD lines. It should be 3v3.

If you just wish to evaluate, you can also try using SPI with jumper cables or SDIO 1-bit mode, instead of 4-bit mode.

[zavdimka]

First, I decided to verify the hardware. To do this, I took this example from the IDF and uploaded it to my board. I connected to a Wi-Fi router and ran iperf as a server, and got a stable 30.8 Mbit/sec. Therefore, I assumed that there was no problem with the crystal or power supply of my PCB design.

Next, I dropped the SDIO frequency to 20 MHz and captured the SDIO communication with my 100 MHz logic analyzer.

cat /sys/kernel/debug/mmc1/ios
clock:          20000000 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)

Then, I loaded the kernel module with raw_tp_mode=2 and got 36,950 kbps. The log of the communication (Kingston Vis logic analyzer).

Next, I loaded the kernel module with the raw_tp_mode=1 and the system hung. No kernel panic, just a hang. The screenshot below shows the last comunication on the bus before the hang.

Log

[  441.824787] esp32_sdio: esp_init: esp_init_interface_layer
[  441.824987] Probing SDIO device...
[  441.825006] esp32_sdio: esp_probe: esp_probe
[  441.825012] esp32_sdio: esp_probe: ESP network device detected
[  441.825130] esp32_sdio: get_firmware_data: Rx Pre ====== 0
[  441.825140] esp32_sdio: get_firmware_data: Rx Pos ======  0
[  441.825170] esp32_sdio: get_firmware_data: Tx Pre ======  0
[  441.825179] esp32_sdio: get_firmware_data: Tx Pos ======  10
[  441.825450] esp32_sdio: esp_init: esp_init_interface_layer pass
[  441.828951] esp32_sdio: process_esp_bootup_event: Received ESP bootup event
[  441.828979] esp32_sdio: process_event_esp_bootup: Bootup Event tag: 3
[  441.828990] esp32_sdio: esp_validate_chipset: Chipset=ESP32-C6 ID=0d detected over SDIO
[  441.828998] esp32_sdio: process_event_esp_bootup: Bootup Event tag: 0
[  441.829006] esp32_sdio: process_event_esp_bootup: Bootup Event tag: 1
[  441.829013] esp32_sdio: process_fw_data: ESP chipset's last reset cause:
[  441.829022] esp32_sdio: print_reset_reason: POWERON_RESET
[  441.829032] esp32_sdio: check_esp_version: ESP-Hosted Version: NG-1.0.3.0.9
[  441.831947] esp32_sdio: esp_reg_notifier: Driver init is ongoing
[  441.836796] esp32_sdio: tx_process: not ready
[  442.216747] esp32_sdio: init_bt: ESP Bluetooth init
[  442.217064] esp32_sdio: process_test_capabilities: start testing of Host->ESP raw throughput
[  442.220052] bt_tx: 391062cc: 03 0c 00                                         ...
[  442.224691] bt_tx: 898299f1: 03 10 00                                         ...
[  442.225070] esp32_sdio: print_capabilities: Capabilities: 0xd. Features supported are:
[  442.225081] esp32_sdio: print_capabilities:   * WLAN on SDIO
[  442.225089] esp32_sdio: print_capabilities:   * BT/BLE
[  442.225095] esp32_sdio: print_capabilities:     - HCI over SDIO
[  442.225102] esp32_sdio: print_capabilities:     - BLE only
[  442.226848] bt_tx: 838e8a59: 01 10 00                                         ...
[  442.229798] bt_tx: da0171fb: 09 10 00                                         ...
[  442.232852] bt_tx: b1ed3437: 02 20 00                                         . .
[  442.235812] bt_tx: 71510259: 03 20 00                                         . .
[  442.238848] bt_tx: 2660217e: 1c 20 00                                         . .
[  442.241785] bt_tx: 838e8a59: 02 10 00                                         ...
[  442.244831] bt_tx: da0171fb: 01 0c 08 90 e0 04 02 00 80 00 20                 ..........
[  442.247792] bt_tx: 898299f1: 01 20 08 7f 1e 0a 00 00 00 00 00                 . .........
[  442.250793] bt_tx: cfd04b04: 0f 20 00                                         . .
[  442.253793] bt_tx: aa0c4c3d: 10 20 00                                         . .
[  442.256792] bt_tx: bf93b23c: 2a 20 00                                         * .
[  442.259790] bt_tx: 3780981f: 29 20 00                                         ) .
[  442.262794] bt_tx: 391062cc: 2e 20 02 84 03                                   . ...
[  442.265787] bt_tx: e25ad38b: 2f 20 00                                         / .
[  442.268791] bt_tx: aad6535e: 23 20 00                                         # .
[  442.271835] bt_tx: 2660217e: 3b 20 00                                         ; .
[  442.274806] bt_tx: 71510259: 24 20 04 fb 00 90 42                             $ ....B
[  442.277789] bt_tx: b1ed3437: 31 20 03 00 01 01                                1 ....
[  443.232750] esp32_sdio: log_raw_tp_stats_timer_cb: 0-1 sec       0 kbits/sec
[  443.232750]

KingstVis logs google disk ( 300+MB)
But driver work (raw_tp_mode = 0) but iperf still gives about 9Mbits/sec.
Can you kindly suggest how can I use logic analyzer to find bottle neck?
update: Parsed SDIO comunication before hang

time 0.45298484, dt 29.1us, ->CMD53, 0x1400B004 :  RW 0 func 1 Block 0 Inc 1 Addr 0x00058 Data 0x004 INT_ST
time 0.45298799, dt 3.2us, <-R1-53, 0x1000 
time 0.45303142, dt 43.4us, ->CMD53, 0x9401A804 :  RW 1 func 1 Block 0 Inc 1 Addr 0x000D4 Data 0x004 INT_CLR
time 0.45303457, dt 3.2us, <-R1-53, 0x1000 
time 0.45504971, dt 2015.1us, ->CMD53, 0x97EC0000 :  RW 1 func 1 Block 0 Inc 1 Addr 0x1F600 Data 0x000 addr: 512
time 0.45505286, dt 3.2us, <-R1-53, 0x1000 
time 0.45587398, dt 821.1us, ->CMD53, 0x1400B004 :  RW 0 func 1 Block 0 Inc 1 Addr 0x00058 Data 0x004 INT_ST
time 0.45587713, dt 3.2us, <-R1-53, 0x1000 
time 0.45589853, dt 21.4us, ->CMD53, 0x9401A804 :  RW 1 func 1 Block 0 Inc 1 Addr 0x000D4 Data 0x004 INT_CLR
time 0.45590168, dt 3.1us, <-R1-53, 0x1000 
time 0.45591955, dt 17.9us, ->CMD53, 0x1400C004 :  RW 0 func 1 Block 0 Inc 1 Addr 0x00060 Data 0x004 PKT_LEN
time 0.45592270, dt 3.2us, <-R1-53, 0x1000 
time 0.45594527, dt 22.6us, ->CMD53, 0x17EFDA14 :  RW 0 func 1 Block 0 Inc 1 Addr 0x1F7ED Data 0x014 addr: 19
time 0.45594842, dt 3.2us, <-R1-53, 0x1000 
time 0.45597599, dt 27.6us, ->CMD53, 0x1400B004 :  RW 0 func 1 Block 0 Inc 1 Addr 0x00058 Data 0x004 INT_ST
time 0.45597914, dt 3.2us, <-R1-53, 0x1000 
time 0.45756375, dt 1584.6us, ->CMD53, 0x9401A804 :  RW 1 func 1 Block 0 Inc 1 Addr 0x000D4 Data 0x004 INT_CLR
time 0.45756690, dt 3.2us, <-R1-53, 0x1000