High ICMP Ping Latency Under Low Network Traffic Conditions

[Philipansari]

I observed a significant increase in ICMP ping latency after a big file (~100MB) was transferred.

My Setup

• ESP32c3 chip
• OpenWRT v21 linux-host
• First-Generation (latest master)
• WiFi over SPI
• calling esp-interface-cmd softap_start & ifconfig ethap0 192.168.4.5 to host a network
• conncting a linux client to the softap

Steps to reproduce

1. Start SoftAP mode and let a new client (192.168.4.6) connect to it.
2. Check ping latency with ping 192.168.4.5 and observe normal ping (~10ms).
3. Transfer a large file via SCP: scp root@192.168.4.6:/tmp/big_file /dev/null.
4. Check ping latency again and observe high latency (~5000ms).
5. Check again after a while and note no change.

Observation

• Until the large file is transferred, the ping stays low.
• As long as a large file is being transferred, the ping stays low.
• As soon as the large file transfer stops, the ping increases (~1000ms to ~5000ms) but there is no packet loss.
• As soon as a large file is being transferred again, the ping returns to normal.
• Flooding the host with ping packets without transferring a file also brings the ping latency back to normal.
• Any high traffic will bring the ping latency back to normal. As soon as traffic stops, the ping latency increases again.
• if more clients are connected to the station, then the ping from one client to another client is not affected from the high latency

This indicates that during high transfer rates, the packets go through without issue. However, transferring only a few small packets (such as ICMP packets) results in them being held back.

Verify SPI-bus

The same hardware was also used with the next-generation driver, expect that the linux-host connects itself to another station. However, transferring a huge file does not cause any problems afterwards, so the SPI-bus connection should be fine.

Suggestions

• The GPIO handshake/data_ready signals may not be behaving as expected: Data is only transferred to the Linux host when the buffer is full, instead of sending the data as soon as it becomes available, which could hold back the data and cause high latency on low traffic.
• During the transfer of a large file, the internal buffers might adjust to handle high traffic, but after the file transfer, the buffers do not adjust back to normal operation, potentially leading to a buffer bloat problem ?

To mention

This problem does not occur in a Raspberry Pi 4 setup. I tested the same source codes, and the latency was always low. I understand that you might not support other platforms, but perhaps someone has an idea where there might be a misconfiguration in my setup?

I have made no changes to the driver itself except for:

• changing GPIOs to match my hardware
• reduced to 10Mhz SPI-clock also for normal operation
• changed from SPI-mode 2 to SPI-mode 1

[Philipansari]

While investigating this issue i observed that the problem is gone when the interrupt-service-routine of the handshake pin contains a print. Of course this will drastically reduce the speed of the driver and is no option for a work-around.

With the following modification the high latency problem is gone:

esp_spi.c

static irqreturn_t spi_interrupt_handler(int irq, void * dev)
{
    up(&spi_sem);
    esp_info("x"); // added this line here
    esp_verbose("\n");
    return IRQ_HANDLED;
}

It is strange that the problem only arises after the first large data transmission.

[mantriyogesh]

Thank you for all of the details. Understood the issue fully. Thanks a lot for all the details shared, we will try to reproduce this problem (first on Raspberry pi and otherwise some other platform as possible)

Sorry for the long questions ahead, trying to understand the issue better, as you said Raspberry pi doesn't face this issue Can you please help with below info:

1. Git commit used at C3 and host
2. Logs:
   • If you could capture of the commands and their output
   • C3 log
   • host kern.log or dmesg from start
3. Host mpu details (for checking base spi driver on Linux)
4. Linux kernel version
5. Do you also have sdio as transport setup (I think not, but thought to ask if issue is also seen there)
6. Do you also use bluetooth at the same time, when issue occurs (I think not, but thought to clarify as rf time is shared)
7. Do you also observe the same behaviour on station mode? (Preferably bluetooth disabled and power save disabled on C3)
8. Does your Linux allowed to be in sleep or power save?
9. Finally, do you have a logic analyser?

[Philipansari]

Thanks a lot for the support on this issue.

Sorry for the long comment.

1. commit: 3d4f2f7b5913e951a3af2083c117a88d3638e429
2. see below
3. Freescale i.MX6 Ultralite Model name ARMv7 Processor rev 5 (v7l)
4. v5.4.154
5. unfortunately not, sorry
6. bluetooth was never used/tested
7. see below, yes, indeed, it has the same problem
8. the linux itself is not in any sleep or power save mode
9. yes, i have

Ping from linux-host to client, file transfer, ping again

$ ping 192.168.4.6
PING 192.168.4.6 (192.168.4.6): 56 data bytes
64 bytes from 192.168.4.6: seq=0 ttl=64 time=58.120 ms
64 bytes from 192.168.4.6: seq=1 ttl=64 time=81.676 ms
64 bytes from 192.168.4.6: seq=2 ttl=64 time=104.794 ms
64 bytes from 192.168.4.6: seq=3 ttl=64 time=179.349 ms
64 bytes from 192.168.4.6: seq=4 ttl=64 time=263.912 ms
64 bytes from 192.168.4.6: seq=5 ttl=64 time=207.331 ms
64 bytes from 192.168.4.6: seq=6 ttl=64 time=199.862 ms
64 bytes from 192.168.4.6: seq=7 ttl=64 time=18.787 ms
64 bytes from 192.168.4.6: seq=8 ttl=64 time=42.698 ms
64 bytes from 192.168.4.6: seq=9 ttl=64 time=66.202 ms
64 bytes from 192.168.4.6: seq=10 ttl=64 time=89.950 ms
64 bytes from 192.168.4.6: seq=11 ttl=64 time=113.528 ms
64 bytes from 192.168.4.6: seq=12 ttl=64 time=137.109 ms
64 bytes from 192.168.4.6: seq=13 ttl=64 time=162.851 ms
^C
--- 192.168.4.6 ping statistics ---
14 packets transmitted, 14 packets received, 0% packet loss
round-trip min/avg/max = 18.787/123.297/263.912 ms

$ scp philip@192.168.4.6:/tmp/tmp.iso /dev/null
philip@192.168.4.6's password: 
tmp.iso          0% 2224KB 772.9KB/s   33:20 ETA^C

$ ping 192.168.4.6
PING 192.168.4.6 (192.168.4.6): 56 data bytes
64 bytes from 192.168.4.6: seq=0 ttl=64 time=2185.167 ms
64 bytes from 192.168.4.6: seq=1 ttl=64 time=2209.065 ms
64 bytes from 192.168.4.6: seq=2 ttl=64 time=2029.460 ms
64 bytes from 192.168.4.6: seq=3 ttl=64 time=2053.233 ms
64 bytes from 192.168.4.6: seq=4 ttl=64 time=2077.249 ms
64 bytes from 192.168.4.6: seq=5 ttl=64 time=2100.408 ms
64 bytes from 192.168.4.6: seq=6 ttl=64 time=2124.813 ms
64 bytes from 192.168.4.6: seq=7 ttl=64 time=2148.502 ms
64 bytes from 192.168.4.6: seq=8 ttl=64 time=2176.771 ms
64 bytes from 192.168.4.6: seq=9 ttl=64 time=2194.951 ms
64 bytes from 192.168.4.6: seq=10 ttl=64 time=2013.807 ms
64 bytes from 192.168.4.6: seq=11 ttl=64 time=2149.801 ms
64 bytes from 192.168.4.6: seq=12 ttl=64 time=2157.804 ms
64 bytes from 192.168.4.6: seq=13 ttl=64 time=2196.044 ms
^C
--- 192.168.4.6 ping statistics ---
16 packets transmitted, 14 packets received, 12% packet loss
round-trip min/avg/max = 2013.807/2129.791/2209.065 ms

If more data than ~2MB is transferred, then the situation gets even worse:

$ scp philip@192.168.4.6:/tmp/tmp.iso /dev/null
philip@192.168.4.6's password: 
tmp.iso       1%   29MB 785.6KB/s   32:12 ETA^C

$ ping 192.168.4.6
PING 192.168.4.6 (192.168.4.6): 56 data bytes
64 bytes from 192.168.4.6: seq=0 ttl=64 time=11165.752 ms
64 bytes from 192.168.4.6: seq=1 ttl=64 time=11189.200 ms
64 bytes from 192.168.4.6: seq=2 ttl=64 time=12150.178 ms
64 bytes from 192.168.4.6: seq=3 ttl=64 time=12148.721 ms
64 bytes from 192.168.4.6: seq=4 ttl=64 time=12172.253 ms
64 bytes from 192.168.4.6: seq=5 ttl=64 time=12196.058 ms
64 bytes from 192.168.4.6: seq=6 ttl=64 time=12014.980 ms
64 bytes from 192.168.4.6: seq=7 ttl=64 time=12038.422 ms
64 bytes from 192.168.4.6: seq=8 ttl=64 time=12062.286 ms
64 bytes from 192.168.4.6: seq=9 ttl=64 time=12086.010 ms
64 bytes from 192.168.4.6: seq=10 ttl=64 time=12108.923 ms
64 bytes from 192.168.4.6: seq=11 ttl=64 time=12133.523 ms
64 bytes from 192.168.4.6: seq=12 ttl=64 time=12125.347 ms
64 bytes from 192.168.4.6: seq=13 ttl=64 time=11126.848 ms
64 bytes from 192.168.4.6: seq=14 ttl=64 time=10133.052 ms
64 bytes from 192.168.4.6: seq=15 ttl=64 time=10296.940 ms
64 bytes from 192.168.4.6: seq=16 ttl=64 time=10203.496 ms
64 bytes from 192.168.4.6: seq=17 ttl=64 time=10046.928 ms
64 bytes from 192.168.4.6: seq=18 ttl=64 time=10046.498 ms
64 bytes from 192.168.4.6: seq=19 ttl=64 time=10069.749 ms
^C
--- 192.168.4.6 ping statistics ---
30 packets transmitted, 20 packets received, 33% packet loss
round-trip min/avg/max = 10046.498/11375.758/12196.058 ms

Ping from client to linux-host

before the file transmission:

$ ping 192.168.4.5
PING 192.168.4.5 (192.168.4.5) 56(84) bytes of data.
64 bytes from 192.168.4.5: icmp_seq=1 ttl=64 time=8.16 ms
64 bytes from 192.168.4.5: icmp_seq=2 ttl=64 time=8.02 ms
64 bytes from 192.168.4.5: icmp_seq=3 ttl=64 time=8.00 ms
64 bytes from 192.168.4.5: icmp_seq=4 ttl=64 time=10.7 ms
64 bytes from 192.168.4.5: icmp_seq=5 ttl=64 time=8.09 ms
64 bytes from 192.168.4.5: icmp_seq=6 ttl=64 time=8.90 ms
64 bytes from 192.168.4.5: icmp_seq=7 ttl=64 time=8.06 ms
64 bytes from 192.168.4.5: icmp_seq=8 ttl=64 time=7.98 ms
64 bytes from 192.168.4.5: icmp_seq=9 ttl=64 time=16.5 ms

after the file transmission:

$ ping 192.168.4.5
PING 192.168.4.5 (192.168.4.5) 56(84) bytes of data.
From 192.168.4.6 icmp_seq=1 Destination Host Unreachable
From 192.168.4.6 icmp_seq=2 Destination Host Unreachable
From 192.168.4.6 icmp_seq=3 Destination Host Unreachable
From 192.168.4.6 icmp_seq=4 Destination Host Unreachable
From 192.168.4.6 icmp_seq=5 Destination Host Unreachable
From 192.168.4.6 icmp_seq=6 Destination Host Unreachable
From 192.168.4.6 icmp_seq=7 Destination Host Unreachable
From 192.168.4.6 icmp_seq=8 Destination Host Unreachable
From 192.168.4.6 icmp_seq=9 Destination Host Unreachable
64 bytes from 192.168.4.5: icmp_seq=12 ttl=64 time=12296 ms
64 bytes from 192.168.4.5: icmp_seq=13 ttl=64 time=12274 ms
64 bytes from 192.168.4.5: icmp_seq=14 ttl=64 time=12251 ms
64 bytes from 192.168.4.5: icmp_seq=15 ttl=64 time=12228 ms
64 bytes from 192.168.4.5: icmp_seq=16 ttl=64 time=12208 ms
64 bytes from 192.168.4.5: icmp_seq=17 ttl=64 time=12198 ms
64 bytes from 192.168.4.5: icmp_seq=18 ttl=64 time=11187 ms
64 bytes from 192.168.4.5: icmp_seq=19 ttl=64 time=11172 ms
64 bytes from 192.168.4.5: icmp_seq=20 ttl=64 time=10191 ms
64 bytes from 192.168.4.5: icmp_seq=21 ttl=64 time=10088 ms
64 bytes from 192.168.4.5: icmp_seq=22 ttl=64 time=9220 ms
64 bytes from 192.168.4.5: icmp_seq=23 ttl=64 time=9037 ms
64 bytes from 192.168.4.5: icmp_seq=24 ttl=64 time=12072 ms
64 bytes from 192.168.4.5: icmp_seq=25 ttl=64 time=11072 ms
64 bytes from 192.168.4.5: icmp_seq=26 ttl=64 time=10073 ms
64 bytes from 192.168.4.5: icmp_seq=27 ttl=64 time=9073 ms
64 bytes from 192.168.4.5: icmp_seq=28 ttl=64 time=8074 ms
64 bytes from 192.168.4.5: icmp_seq=29 ttl=64 time=7075 ms
64 bytes from 192.168.4.5: icmp_seq=30 ttl=64 time=7066 ms
64 bytes from 192.168.4.5: icmp_seq=31 ttl=64 time=8072 ms
64 bytes from 192.168.4.5: icmp_seq=32 ttl=64 time=9159 ms
64 bytes from 192.168.4.5: icmp_seq=33 ttl=64 time=9127 ms
64 bytes from 192.168.4.5: icmp_seq=34 ttl=64 time=10088 ms
64 bytes from 192.168.4.5: icmp_seq=35 ttl=64 time=11080 ms
64 bytes from 192.168.4.5: icmp_seq=36 ttl=64 time=12072 ms
^C
--- 192.168.4.5 ping statistics ---
48 packets transmitted, 25 received, +9 errors, 47.9167% packet loss, time 47590ms
rtt min/avg/max/mdev = 7066.213/10338.164/12296.315/1667.552 ms, pipe 13

Whole ESP32c3 log output since start

ESP-ROM:esp32c3-api1-20210207
Build:Feb  7 2021
rst:0x1 (POWEIO, clock div:1
load:0x3fcd5820,len:0x1708
load:0x403cc710,len:0x968
load:0x403ce710,len:0x2f68
entry 0x403cc710
I (30) boot: ESP-IDF cbce0) boot: compile time Feb  5 2024 17:06:12
I (30) boot: chip revision: v0.4
I (33) boot.esp32c3: SPI Speed      : 80MHz
I (38) boot.esp32c3: SPI Mode       : DIO
I (43) boot.esp32c3: SPI Flash Size : 4MB
I (48) boot: Enabling RNG early entropy source...
I (53) boot: Partition Table:
I (57) boot: ## Label            Usage          Type ST Offset   Length
I (64) boot:  0 nvs              WiFi data        01 02 00009000 00004000
I (71) boot:  1 otadata          OTA data         01 00 0000d000 00002000
I (79) boot:  2 phy_init         RF data          01 01 0000f000 00001000
I (86) boot:  3 factory          factory app      00 00 00010000 00100000
I (94) boot:  4 ota_0            OTA app          00 10 00110000 00100000
I (101) boot:  5 ota_1            OTA app          00 11 00210000 00100000
I (109) boot: End of partition table
I (113) boot: Defaulting to factory image
I (118) esp_image: segment 0: paddr=00010020 vaddr=3c0a0020 size=27490h (160912) map
I (152) esp_image: segment 1: paddr=000374b8 vaddr=3fc94400 size=030fch ( 12540) load
I (155) esp_image: segment 2: paddr=0003a5bc vaddr=40380000 size=05a5ch ( 23132) load
I (162) esp_image: segment 3: paddr=00040020 vaddr=42000020 size=941a4h (606628) map
I (263) esp_image: segment 4: paddr=000d41cc vaddr=40385a5c size=0e8f4h ( 59636) load
I (281) boot: Loaded app from partition at offset 0x10000
I (281) boot: Disabling RNG early entropy source...
I (292) cpu_start: Unicore app
I (292) cpu_start: Pro cpu up.
I (301) cpu_start: Pro cpu start user code
I (301) cpu_start: cpu freq: 160000000 Hz
I (301) cpu_start: Application information:
I (304) cpu_start: Project name:     network_adapter
I (310) cpu_start: App version:      a06acb7-dirty
I (315) cpu_start: Compile time:     Feb 27 2024 09:14:45
I (321) cpu_start: ELF file SHA256:  c9691572e03cf36a...
I (327) cpu_start: ESP-IDF:          cbce221e
I (332) cpu_start: Min chip rev:     v0.3
I (337) cpu_start: Max chip rev:     v0.99 
I (342) cpu_start: Chip rev:         v0.4
I (347) heap_init: Initializing. RAM available for dynamic allocation:
I (354) heap_init: At 3FC9BF50 len 000407C0 (257 KiB): DRAM
I (360) heap_init: At 3FCDC710 len 00002950 (10 KiB): STACK/DRAM
I (367) heap_init: At 50000020 len 00001FE0 (7 KiB): RTCRAM
I (374) spi_flash: detected chip: generic
I (378) spi_flash: flash io: dio
I (382) sleep: Configure to isolate all GPIO pins in sleep state
I (388) sleep: Enable automatic switching of GPIO sleep configuration
I (396) coexist: coex firmware version: ebddf30
I (401) coexist: coexist rom version 9387209
I (406) app_start: Starting scheduler on CPU0
I (411) main_task: Started on CPU0
I (411) main_task: Calling app_main()
I (411) NETWORK_ADAPTER: *********************************************************************
I (421) NETWORK_ADAPTER:                 ESP-Hosted-FG Firmware version :: 0.0.5                        
I (431) NETWORK_ADAPTER:                 Transport used :: SPI only                      
I (441) NETWORK_ADAPTER: *********************************************************************
I (451) NETWORK_ADAPTER: Supported features are:
I (461) NETWORK_ADAPTER: - WLAN over SPI
I (461) ESP_BT: - BT/BLE
I (461) ESP_BT:    - HCI Over SPI
I (471) ESP_BT:    - BLE only
I (471) NETWORK_ADAPTER: capabilities: 0xe8
I (481) BLE_INIT: BT controller compile version [85b425c]
I (481) phy_init: phy_version 970,1856f88,May 10 2023,17:44:12
I (531) BLE_INIT: Bluetooth MAC: d4:f9:8d:34:35:1a

I (531) NETWORK_ADAPTER: ESP Bluetooth MAC addr: d4:f9:8d:34:35:1a
I (531) SPI_DRIVER: Using SPI interface
I (531) gpio: GPIO[4]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (541) gpio: GPIO[5]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (551) SPI_DRIVER: SPI Ctrl:1 mode: 1, InitFreq: 10MHz, ReqFreq: 10MHz
GPIOs: MOSI: 7, MISO: 2, CS: 10, CLK: 6 HS: 4 DR: 5

I (561) SPI_DRIVER: Hosted SPI queue size: Tx:20 Rx:20
I (571) gpio: GPIO[10]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (581) gpio: GPIO[10]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (591) pp: pp rom version: 9387209
I (591) net80211: net80211 rom version: 9387209
I (611) wifi:wifi driver task: 3fcc20a4, prio:23, stack:6656, core=0
I (611) wifi:wifi firmware version: b2f1f86
I (611) wifi:wifi certification version: v7.0
I (611) wifi:config NVS flash: disabled
I (611) wifi:config nano formating: disabled
I (621) wifi:Init data frame dynamic rx buffer num: 32
I (621) wifi:Init management frame dynamic rx buffer num: 32
I (631) wifi:Init management short buffer num: 32
I (631) wifi:Init dynamic tx buffer num: 32
I (641) wifi:Init static tx FG buffer num: 2
I (641) wifi:Init static rx buffer size: 1600
I (641) wifi:Init static rx buffer num: 10
I (651) wifi:Init dynamic rx buffer num: 32
I (651) wifi_init: rx ba win: 6
I (661) wifi_init: tcpip mbox: 32
I (661) wifi_init: udp mbox: 6
I (661) wifi_init: tcp mbox: 6
I (671) wifi_init: tcp tx win: 5744
I (671) wifi_init: tcp rx win: 5744
I (681) wifi_init: tcp mss: 1440
I (681) wifi_init: WiFi IRAM OP enabled
I 0m
I (691) wifi:mode : null
ial set up done
I (70m
I (701) main_task: RetI (13521) slave_ctrl: HB timer started for 20 sec

I (13531) wifi:mode : softAP (d4:f9:8d:34:35:19)
I (13541) wifi:Total power save buffer number: 16
I (13541) wifi:Init max length of beacon: 752/752
I (13541) wifi:Init max length of beacon: 752/752
I (13541) slave_ctrl: softap mode set
I (13551) slave_ctrl: mac [d4:f9:8d:34:35:19] 
I (13551) slave_ctrl: d4:f9:8d:34:35:19
I (14231) wifi:Total power save buffer number: 16
I (14231) slave_ctrl: ssid ESPWifi pwd ESPWifi@123 authmode 3 ssid_hidden 0 max_conn 4 channel 11
I (14231) slave_ctrl: ESP32 SoftAP is avaliable 
I (14241) NETWORK_ADAPTER: Get softap mac address
I (14241) NETWORK_ADAPTER: AP mac [d4:f9:8d:34:35:19] 
I (14251) slave_ctrl: softap stop handler stop
I (14261) NETWORK_ADAPTER: Get softap mac address
I (14261) NETWORK_ADAPTER: AP mac [d4:f9:8d:34:35:19] 
I (17351) slave_ctrl: Stop Heatbeat
I (17351) slave_ctrl: Stopping HB timer
I (42081) wifi:new:<11,2>, old:<11,2>, ap:<11,2>, sta:<255,255>, prof:11
I (42081) wifi:station: 88:d8:2e:4e:11:64 join, AID=1, bgn, 40D
I (42101) slave_ctrl: station 88:d8:2e:4e:11:64 join, AID=1
I (46241) wifi:<ba-add>idx:2 (ifx:1, 88:d8:2e:4e:11:64), tid:0, ssn:21, winSize:64

Kernel output of linux-host

$ dmesg
[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 5.4.154 (build@***) (gcc version 8.4.0 (OpenWrt GCC 8.4.0 v2.0.9)) #0 Sun Oct 24 09:01:35 2021
[    0.000000] CPU: ARMv7 Processor [410fc075] revision 5 (ARMv7), cr=10c5387d
[    0.000000] CPU: div instructions available: patching division code
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[    0.000000] OF: fdt: Machine model: ***
[    0.000000] Memory policy: Data cache writeback
[    0.000000] On node 0 totalpages: 131072
[    0.000000]   Normal zone: 1152 pages used for memmap
[    0.000000]   Normal zone: 0 pages reserved
[    0.000000]   Normal zone: 131072 pages, LIFO batch:31
[    0.000000] CPU: All CPU(s) started in SVC mode.
[    0.000000] pcpu-alloc: s0 r0 d32768 u32768 alloc=1*32768
[    0.000000] pcpu-alloc: [0] 0 
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 129920
[    0.000000] Kernel command line: root=/dev/mmcblk1p2 rootwait rw init=/sbin/clearOverlay.sh console=ttymxc3,115200 button=long rootPartition=2 pci=nomsi
[    0.000000] Dentry cache hash table entries: 65536 (order: 6, 262144 bytes, linear)
[    0.000000] Inode-cache hash table entries: 32768 (order: 5, 131072 bytes, linear)
[    0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off
[    0.000000] Memory: 508364K/524288K available (6774K kernel code, 297K rwdata, 1804K rodata, 1024K init, 226K bss, 15924K reserved, 0K cma-reserved)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[    0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
[    0.000000] random: get_random_bytes called from start_kernel+0x2e4/0x48c with crng_init=0
[    0.000000] Switching to timer-based delay loop, resolution 41ns
[    0.000016] sched_clock: 32 bits at 24MHz, resolution 41ns, wraps every 89478484971ns
[    0.000051] clocksource: mxc_timer1: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 79635851949 ns
[    0.002074] Console: colour dummy device 80x30
[    0.002153] Calibrating delay loop (skipped), value calculated using timer frequency.. 48.00 BogoMIPS (lpj=240000)
[    0.002184] pid_max: default: 32768 minimum: 301
[    0.002595] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes, linear)
[    0.002626] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes, linear)
[    0.004191] CPU: Testing write buffer coherency: ok
[    0.005320] Setting up static identity map for 0x80100000 - 0x80100060
[    0.016817] VFP support v0.3: implementor 41 architecture 2 part 30 variant 7 rev 5
[    0.017199] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.017239] futex hash table entries: 256 (order: -1, 3072 bytes, linear)
[    0.017400] pinctrl core: initialized pinctrl subsystem
[    0.019642] NET: Registered protocol family 16
[    0.020449] DMA: preallocated 256 KiB pool for atomic coherent allocations
[    0.033349] vdd3p0: supplied by regulator-dummy
[    0.034059] cpu: supplied by regulator-dummy
[    0.035137] vddsoc: supplied by regulator-dummy
[    0.050060] No ATAGs?
[    0.051526] debugfs: Directory 'dummy-iomuxc-gpr@20e4000' with parent 'regmap' already present!
[    0.051945] imx6ul-pinctrl 20e0000.iomuxc: initialized IMX pinctrl driver
[    0.103179] cryptd: max_cpu_qlen set to 1000
[    0.127183] mxs-dma 1804000.dma-apbh: initialized
[    0.129568] SCSI subsystem initialized
[    0.137895] libata version 3.00 loaded.
[    0.138508] usbcore: registered new interface driver usbfs
[    0.138644] usbcore: registered new interface driver hub
[    0.138762] usbcore: registered new device driver usb
[    0.140557] i2c i2c-1: IMX I2C adapter registered
[    0.140971] pps_core: LinuxPPS API ver. 1 registered
[    0.140993] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
[    0.141059] PTP clock support registered
[    0.141639] workqueue: max_active 576 requested for napi_workq is out of range, clamping between 1 and 512
[    0.148977] clocksource: Switched to clocksource mxc_timer1
[    0.160353] thermal_sys: Registered thermal governor 'step_wise'
[    0.160972] NET: Registered protocol family 2
[    0.161298] IP idents hash table entries: 8192 (order: 4, 65536 bytes, linear)
[    0.162716] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 4096 bytes, linear)
[    0.162781] TCP established hash table entries: 4096 (order: 2, 16384 bytes, linear)
[    0.162878] TCP bind hash table entries: 4096 (order: 2, 16384 bytes, linear)
[    0.162979] TCP: Hash tables configured (established 4096 bind 4096)
[    0.163171] UDP hash table entries: 256 (order: 0, 4096 bytes, linear)
[    0.163217] UDP-Lite hash table entries: 256 (order: 0, 4096 bytes, linear)
[    0.163596] NET: Registered protocol family 1
[    0.163662] PCI: CLS 0 bytes, default 64
[    0.185174] workingset: timestamp_bits=14 max_order=17 bucket_order=3
[    0.197983] squashfs: version 4.0 (2009/01/31) Phillip Lougher
[    0.308484] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 249)
[    0.313200] gpio-export gpio-export: 10 gpio(s) exported
[    0.322236] Serial: 8250/16550 driver, 16 ports, IRQ sharing enabled
[    0.326826] 2020000.serial: ttymxc0 at MMIO 0x2020000 (irq = 22, base_baud = 5000000) is a IMX
[    0.328149] 21e8000.serial: ttymxc1 at MMIO 0x21e8000 (irq = 56, base_baud = 5000000) is a IMX
[    0.329231] 21f0000.serial: ttymxc3 at MMIO 0x21f0000 (irq = 57, base_baud = 5000000) is a IMX
[    0.338846] imx-sdma 20ec000.sdma: loaded firmware 3.5
[    0.811333] printk: console [ttymxc3] enabled
[    0.816665] 21f4000.serial: ttymxc4 at MMIO 0x21f4000 (irq = 58, base_baud = 5000000) is a IMX
[    0.834748] loop: module loaded
[    0.837917] Loading iSCSI transport class v2.0-870.
[    0.853255] spi_imx 2008000.spi: probed
[    0.858505] libphy: Fixed MDIO Bus: probed
[    0.884973] pps pps0: new PPS source ptp0
[    0.889568] fec 20b4000.ethernet: Invalid MAC address: 00:00:00:00:00:00
[    0.896310] fec 20b4000.ethernet: Using random MAC address: 3e:5e:5f:66:55:79
[    0.904182] libphy: fec_enet_mii_bus: probed
[    0.912714] fec 20b4000.ethernet eth0: registered PHC device 0
[    0.933899] pps pps1: new PPS source ptp1
[    0.938455] fec 2188000.ethernet: Invalid MAC address: 00:00:00:00:00:00
[    0.945277] fec 2188000.ethernet: Using random MAC address: d2:16:f0:65:16:48
[    0.984022] libphy: fec_enet_mii_bus: probed
[    0.989394] fec 2188000.ethernet eth1: registered PHC device 1
[    0.995632] e1000e: Intel(R) PRO/1000 Network Driver - 3.2.6-k
[    1.001539] e1000e: Copyright(c) 1999 - 2015 Intel Corporation.
[    1.007620] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    1.014203] ehci-pci: EHCI PCI platform driver
[    1.018746] ehci-mxc: Freescale On-Chip EHCI Host driver
[    1.027134] imx_usb 2184000.usb: 2184000.usb supply vbus not found, using dummy regulator
[    1.041811] ci_hdrc ci_hdrc.0: EHCI Host Controller
[    1.046785] ci_hdrc ci_hdrc.0: new USB bus registered, assigned bus number 1
[    1.079008] ci_hdrc ci_hdrc.0: USB 2.0 started, EHCI 1.00
[    1.085815] hub 1-0:1.0: USB hub found
[    1.090213] hub 1-0:1.0: 1 port detected
[    1.095655] imx_usb 2184200.usb: 2184200.usb supply vbus not found, using dummy regulator
[    1.108736] ci_hdrc ci_hdrc.1: EHCI Host Controller
[    1.113776] ci_hdrc ci_hdrc.1: new USB bus registered, assigned bus number 2
[    1.149013] ci_hdrc ci_hdrc.1: USB 2.0 started, EHCI 1.00
[    1.155848] hub 2-0:1.0: USB hub found
[    1.160257] hub 2-0:1.0: 1 port detected
[    1.166280] i2c /dev entries driver
[    1.171990] imx2-wdt 20bc000.wdog: timeout 60 sec (nowayout=0)
[    1.179126] sdhci: Secure Digital Host Controller Interface driver
[    1.185323] sdhci: Copyright(c) Pierre Ossman
[    1.189728] sdhci-pltfm: SDHCI platform and OF driver helper
[    1.233673] mmc0: SDHCI controller on 2190000.usdhc [2190000.usdhc] using ADMA
[    1.277159] mmc1: SDHCI controller on 2194000.usdhc [2194000.usdhc] using ADMA
[    1.288922] caam 2140000.caam: Entropy delay = 3200
[    1.293952] caam 2140000.caam: Instantiated RNG4 SH0
[    1.354715] caam 2140000.caam: Instantiated RNG4 SH1
[    1.359730] caam 2140000.caam: device ID = 0x0a16030000000000 (Era 8)
[    1.366186] caam 2140000.caam: job rings = 3, qi = 0
[    1.392031] random: fast init done
[    1.396508] caam algorithms registered in /proc/crypto
[    1.406092] caam 2140000.caam: caam pkc algorithms registered in /proc/crypto
[    1.415583] caam_jr 2141000.jr0: registering rng-caam
[    1.425010] NET: Registered protocol family 10
[    1.437901] Segment Routing with IPv6
[    1.441862] NET: Registered protocol family 17
[    1.446408] bridge: filtering via arp/ip/ip6tables is no longer available by default. Update your scripts to load br_netfilter if you need this.
[    1.460900] 8021q: 802.1Q VLAN Support v1.8
[    1.467412] Registering SWP/SWPB emulation handler
[    1.475536] Key type ._fscrypt registered
[    1.479639] Key type .fscrypt registered
[    1.491672] Key type encrypted registered
[    1.516449] imx_thermal tempmon: Industrial CPU temperature grade - max:105C critical:100C passive:95C
[    1.528881] hctosys: unable to open rtc device (rtc0)
[    1.542478] mmc1: new DDR MMC card at address 0001
[    1.549074] mmcblk1: mmc1:0001 8GTF4R 7.28 GiB 
[    1.554080] mmcblk1boot0: mmc1:0001 8GTF4R partition 1 4.00 MiB
[    1.560544] mmcblk1boot1: mmc1:0001 8GTF4R partition 2 4.00 MiB
[    1.566733] mmcblk1rpmb: mmc1:0001 8GTF4R partition 3 512 KiB, chardev (248:0)
[    1.576085]  mmcblk1: p1 p2 p3
[    1.594683] EXT4-fs (mmcblk1p2): mounted filesystem with ordered data mode. Opts: (null)
[    1.602975] VFS: Mounted root (ext4 filesystem) on device 179:2.
[    1.610956] Freeing unused kernel memory: 1024K
[    1.617909] Run /sbin/clearOverlay.sh as init process
[    1.793736] EXT4-fs (mmcblk1p3): recovery complete
[    1.799269] EXT4-fs (mmcblk1p3): mounted filesystem with ordered data mode. Opts: (null)
[    1.836315] EXT4-fs (mmcblk1p2): re-mounted. Opts: (null)
[    2.026756] init: Console is alive
[    2.030706] init: - watchdog -
[    2.268556] kmodloader: loading kernel modules from /etc/modules-boot.d/*
[    2.324476] ehci-fsl: Freescale EHCI Host controller driver
[    2.352075] ehci-platform: EHCI generic platform driver
[    2.372146] uhci_hcd: USB Universal Host Controller Interface driver
[    2.409661] usbcore: registered new interface driver usb-storage
[    2.423609] kmodloader: done loading kernel modules from /etc/modules-boot.d/*
[    2.454314] init: - preinit -
[    2.761111] random: procd: uninitialized urandom read (4 bytes read)
[    2.814744] mount_root: mounting /dev/root
[    2.839203] urandom-seed: Seeding with /etc/urandom.seed
[    2.883783] procd: - early -
[    2.886888] procd: - watchdog -
[    3.777915] procd: - watchdog -
[    3.796133] procd: - ubus -
[    3.836073] random: ubusd: uninitialized urandom read (4 bytes read)
[    3.860320] random: ubusd: uninitialized urandom read (4 bytes read)
[    3.879308] random: ubusd: uninitialized urandom read (4 bytes read)
[    3.902959] procd: - init -
[    5.793412] urngd: v1.0.2 started.
[    5.819449] kmodloader: loading kernel modules from /etc/modules.d/*
[    5.975803] NET: Registered protocol family 38
[    6.111009] device-mapper: ioctl: 4.41.0-ioctl (2019-09-16) initialised: dm-devel@redhat.com
[    6.184066] Key type dns_resolver registered
[    6.194230] random: crng init done
[    6.197654] random: 6 urandom warning(s) missed due to ratelimiting
[    6.269671] RPC: Registered named UNIX socket transport module.
[    6.275610] RPC: Registered udp transport module.
[    6.280384] RPC: Registered tcp transport module.
[    6.285097] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    6.403840] NET: Registered protocol family 15
[    6.450632] Initializing XFRM netlink socket
[    6.605673] tun: Universal TUN/TAP device driver, 1.6
[    6.782102] l2tp_core: L2TP core driver, V2.0
[    6.812378] l2tp_netlink: L2TP netlink interface
[    6.989109] Installing knfsd (copyright (C) 1996 okir@monad.swb.de).
[    7.049047] NFS: Registering the id_resolver key type
[    7.054177] Key type id_resolver registered
[    7.058368] Key type id_legacy registered
[    7.262599] hidraw: raw HID events driver (C) Jiri Kosina
[    7.374870] fuse: init (API version 7.31)
[    7.822880] at24 1-0050: 8192 byte 24c64 EEPROM, writable, 1 bytes/write
[    7.902948] Bluetooth: Core ver 2.22
[    7.906723] NET: Registered protocol family 31
[    7.911251] Bluetooth: HCI device and connection manager initialized
[    7.917635] Bluetooth: HCI socket layer initialized
[    7.922559] Bluetooth: L2CAP socket layer initialized
[    7.927648] Bluetooth: SCO socket layer initialized
[    8.033134] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[    8.038470] Bluetooth: BNEP filters: protocol multicast
[    8.043815] Bluetooth: BNEP socket layer initialized
[    8.121135] usbcore: registered new interface driver btusb
[    8.153512] can: controller area network core (rev 20170425 abi 9)
[    8.159947] NET: Registered protocol family 29
[    8.213488] CAN device driver interface
[    8.240863] can: SAE J1939
[    8.260468] can: raw protocol (rev 20170425)
[    8.300729] usbcore: registered new interface driver cdc_wdm
[    8.320481] Loading modules backported from Linux version v5.10.68-0-g4d8524048a35
[    8.328074] Backport generated by backports.git v5.10.68-1-0-ga4f9ba32
[    8.410739] usbcore: registered new interface driver gs_usb
[    8.454221] Bluetooth: HCI UART driver ver 2.3
[    8.458691] Bluetooth: HCI UART protocol H4 registered
[    8.463929] Bluetooth: HCI UART protocol BCSP registered
[    8.469275] Bluetooth: HCI UART protocol ATH3K registered
[    8.543916] Bluetooth: HIDP (Human Interface Emulation) ver 1.2
[    8.549965] Bluetooth: HIDP socket layer initialized
[    8.691286] usbcore: registered new interface driver peak_usb
[    8.731936] Bluetooth: RFCOMM TTY layer initialized
[    8.736857] Bluetooth: RFCOMM socket layer initialized
[    8.742111] Bluetooth: RFCOMM ver 1.11
[    8.825727] usbcore: registered new interface driver ums-alauda
[    8.842335] usbcore: registered new interface driver ums-cypress
[    8.877859] usbcore: registered new interface driver ums-datafab
[    8.939237] usbcore: registered new interface driver ums-freecom
[    8.962783] usbcore: registered new interface driver ums-isd200
[    8.972357] usbcore: registered new interface driver ums-jumpshot
[    9.001540] usbcore: registered new interface driver ums-karma
[    9.025550] usbcore: registered new interface driver ums-sddr09
[    9.046403] usbcore: registered new interface driver ums-sddr55
[    9.085040] usbcore: registered new interface driver ums-usbat
[    9.135520] usbcore: registered new interface driver usbserial_generic
[    9.142249] usbserial: USB Serial support registered for generic
[    9.196552] vcan: Virtual CAN interface driver
[    9.213155] Driver for 1-wire Dallas network protocol.
[    9.299825] xt_time: kernel timezone is -0000
[    9.326026] usbcore: registered new interface driver cdc_ncm
[    9.502286] usbcore: registered new interface driver ch341
[    9.507907] usbserial: USB Serial support registered for ch341-uart
[    9.562944] usbcore: registered new interface driver cp210x
[    9.568633] usbserial: USB Serial support registered for cp210x
[    9.640359] usbcore: registered new interface driver ftdi_sio
[    9.646226] usbserial: USB Serial support registered for FTDI USB Serial Device
[    9.851073] usbcore: registered new interface driver pl2303
[    9.856776] usbserial: USB Serial support registered for pl2303
[    9.898168] PPP generic driver version 2.4.2
[    9.921101] NET: Registered protocol family 24
[    9.951212] usbcore: registered new interface driver qmi_wwan
[   10.009562] wireguard: WireGuard 1.0.0 loaded. See www.wireguard.com for information.
[   10.017410] wireguard: Copyright (C) 2015-2019 Jason A. Donenfeld <Jason@zx2c4.com>. All Rights Reserved.
[   10.125763] usbcore: registered new interface driver cdc_mbim
[   10.162795] l2tp_ppp: PPPoL2TP kernel driver, V2.0
[   10.195732] usbcore: registered new interface driver option
[   10.201551] usbserial: USB Serial support registered for GSM modem (1-port)
[   10.269428] kmodloader: done loading kernel modules from /etc/modules.d/*
[   29.239087] Micrel KSZ8081 or KSZ8091 20b4000.ethernet-1:01: attached PHY driver [Micrel KSZ8081 or KSZ8091] (mii_bus:phy_addr=20b4000.ethernet-1:01, irq=188)
[   29.282938] br-lan: port 1(eth0) entered blocking state
[   29.288192] br-lan: port 1(eth0) entered disabled state
[   29.293958] device eth0 entered promiscuous mode
[   29.439524] Micrel KSZ8081 or KSZ8091 20b4000.ethernet-1:02: attached PHY driver [Micrel KSZ8081 or KSZ8091] (mii_bus:phy_addr=20b4000.ethernet-1:02, irq=187)
[   29.522326] br-lan: port 2(eth1) entered blocking state
[   29.527581] br-lan: port 2(eth1) entered disabled state
[   29.533337] device eth1 entered promiscuous mode
[   32.085051] fec 20b4000.ethernet eth0: Link is Up - 100Mbps/Full - flow control rx/tx
[   32.093042] br-lan: port 1(eth0) entered blocking state
[   32.098285] br-lan: port 1(eth0) entered forwarding state
[   32.140273] IPv6: ADDRCONF(NETDEV_CHANGE): br-lan: link becomes ready
[   32.153905] fec 20b4000.ethernet eth0: Link is Down
[   33.129499] br-lan: port 1(eth0) entered disabled state
[   34.942704] fec 20b4000.ethernet eth0: Link is Up - 100Mbps/Full - flow control rx/tx
[   34.950693] br-lan: port 1(eth0) entered blocking state
[   34.955937] br-lan: port 1(eth0) entered forwarding state
[   42.079581] NFSD: Using /var/lib/nfs/v4recovery as the NFSv4 state recovery directory
[   42.087483] NFSD: Using legacy client tracking operations.
[   42.093063] NFSD: starting 10-second grace period (net f000001b)
[   99.450309] esp_interface_fg: esp_reset: Triggering ESP reset.
[   99.456510] esp_interface_fg: spi_init: ESP: SPI host config: GPIOs: Handshake[88] DataReady[81]
[   99.465835] esp_interface_fg: spi_dev_init: ESP host driver claiming SPI bus [0],chip select [0] with init SPI Clock [10]
[   99.487765] esp_interface_fg: esp_spi_thread: esp spi thread created
[  100.156144] esp_interface_fg: process_event: INIT event rcvd from ESP
[  100.162755] esp_interface_fg: process_init_event: EVENT: 2
[  100.168291] esp_interface_fg: process_init_event: EVENT: 1
[  100.173849] esp_interface_fg: process_init_event: EVENT: 0
[  100.179396] esp_interface_fg: process_init_event: EVENT: 3
[  100.187199] esp_interface_fg: process_capabilities: ESP peripheral capabilities: 0xe8
[  100.409611] esp_interface_fg: process_init_event: esp boot-up event processed

Testing same problem in station mode

Ping before (from linux-host to device behind connected station)

$ ping 10.8.4.4
PING 10.8.4.4 (10.8.4.4): 56 data bytes
64 bytes from 10.8.4.4: seq=0 ttl=64 time=7.884 ms
64 bytes from 10.8.4.4: seq=1 ttl=64 time=7.769 ms
64 bytes from 10.8.4.4: seq=2 ttl=64 time=36.129 ms
^C
--- 10.8.4.4 ping statistics ---
3 packets transmitted, 3 packets received, 0% packet loss
round-trip min/avg/max = 7.769/17.260/36.129 ms

$ scp philip@10.8.4.4:/tmp/tmp.iso /dev/null
philip@10.8.4.4's password: 
tmp.iso     0%   15MB 792.4KB/s   32:14 ETA
^C

$ ping 10.8.4.4
PING 10.8.4.4 (10.8.4.4): 56 data bytes
64 bytes from 10.8.4.4: seq=0 ttl=64 time=593.283 ms
64 bytes from 10.8.4.4: seq=1 ttl=64 time=1018.539 ms
64 bytes from 10.8.4.4: seq=2 ttl=64 time=838.238 ms
64 bytes from 10.8.4.4: seq=3 ttl=64 time=1271.463 ms
64 bytes from 10.8.4.4: seq=4 ttl=64 time=281.996 ms
64 bytes from 10.8.4.4: seq=5 ttl=64 time=1319.891 ms
64 bytes from 10.8.4.4: seq=6 ttl=64 time=429.727 ms
64 bytes from 10.8.4.4: seq=7 ttl=64 time=862.875 ms
64 bytes from 10.8.4.4: seq=8 ttl=64 time=1007.921 ms
64 bytes from 10.8.4.4: seq=9 ttl=64 time=1108.313 ms
64 bytes from 10.8.4.4: seq=10 ttl=64 time=1008.716 ms
64 bytes from 10.8.4.4: seq=11 ttl=64 time=438.860 ms
64 bytes from 10.8.4.4: seq=12 ttl=64 time=974.666 ms
64 bytes from 10.8.4.4: seq=13 ttl=64 time=1201.375 ms
64 bytes from 10.8.4.4: seq=14 ttl=64 time=304.147 ms
64 bytes from 10.8.4.4: seq=15 ttl=64 time=1007.910 ms
64 bytes from 10.8.4.4: seq=16 ttl=64 time=659.758 ms
64 bytes from 10.8.4.4: seq=17 ttl=64 time=379.681 ms
64 bytes from 10.8.4.4: seq=18 ttl=64 time=1422.231 ms
64 bytes from 10.8.4.4: seq=19 ttl=64 time=1007.975 ms
64 bytes from 10.8.4.4: seq=20 ttl=64 time=548.048 ms
^C
--- 10.8.4.4 ping statistics ---
21 packets transmitted, 21 packets received, 0% packet loss
round-trip min/avg/max = 281.996/842.172/1422.231 ms

[mantriyogesh]

We might need to reproduce this case, but it might take some time to address, as some other Linux like imx to be setup for this.

Is there any anomaly you observe on logic analyser? Possible to share the dumps?

[Philipansari]

I tried to spot the root of this error by adding some prints and looking at the logs.

Adding this log function to the skb buffer which is passed to the kernel via netif_rx()

void print_skb_data(struct sk_buff *skb) {
    // Ensure skb is not NULL
    if (!skb) return;
    printk(KERN_INFO "skb length: %u\n", skb->len);
    print_hex_dump(KERN_INFO, "", DUMP_PREFIX_NONE, 16, 1, skb->data, min(skb->len, 100U), true);
}

and logging ICMP reply/requests at kernel logs with this command

sudo iptables -I INPUT -p icmp --icmp-type echo-request -j LOG --log-prefix "ICMP Echo Request: "

gave me some insight where the problem occurred:

Even if the high latency problem occurs after a large file transfer, i am able to immediately send out anything without any delay. I verified it by sending single ICMP packages to a connected client and looking at the ICMP Echo request on its kernel logs.

ping 192.168.4.6 -c 1
PING 192.168.4.6 (192.168.4.6): 56 data bytes

--- 192.168.4.6 ping statistics ---
1 packets transmitted, 0 packets received, 100% packet loss

On the client side i observed an immediate print of

[18534.237240] ICMP Echo Request: IN=wlp0s20f3 OUT= MAC=88:d8:2e:4e:11:64:d4:f9:8d:34:35:19:08:00 SRC=192.168.4.5 DST=192.168.4.6 LEN=84 TOS=0x00 PREC=0x00 TTL=64 ID=35024 DF PROTO=ICMP TYPE=8 CODE=0 ID=5077 SEQ=0

So the problem doesn't occur at sending data, it occurs during receive.

Putting the skb log function in place gave me an interesting insight: the SPI-transaction (read_data) is happening right on point without any delay. As soon as a clients sends an ICMP request, the skb-buffer print on the linux-host side will be dumped out. But looking at the length of the buffer we can see that the package is obviously not a ICMP request, it is more like a delayed package from the data transfer:

... running file transmission (scp command)
[13043.078140] skb length: 1500
[13043.081274] 45 08 05 dc 57 54 40 00 40 06 54 64 c0 a8 04 06  E...WT@.@.Td....
[13043.088425] c0 a8 04 05 00 16 eb 6a bc 2d 51 20 a2 05 09 38  .......j.-Q ...8
[13043.095629] 80 10 01 f5 be 2b 00 00 01 01 08 0a f1 23 57 33  .....+.......#W3
[13043.102800] 4a ff d7 99 13 a1 9f eb eb 5c 87 1b 5c 5d 7c 6b  J........\..\]|k
[13043.109965] b1 5f 5e b4 d6 9f bd db 1c 71 82 d3 9a c4 15 49  ._^......q.....I
[13043.117108] 39 ec 70 0a 7c 22 e6 27 7a 6f bc 42 4b 98 44 44  9.p.|".'zo.BK.DD
[13043.124267] 1a 9c c8 87                                      ....
[13043.144277] skb length: 1500
[13043.147426] 45 08 05 dc 57 55 40 00 40 06 54 63 c0 a8 04 06  E...WU@.@.Tc....
[13043.154657] c0 a8 04 05 00 16 eb 6a bc 2d 56 c8 a2 05 09 38  .......j.-V....8
[13043.161829] 80 18 01 f5 4c 25 00 00 01 01 08 0a f1 23 57 33  ....L%.......#W3
[13043.168975] 4a ff d7 99 dd 1a 84 c1 46 e2 34 53 1a 09 77 0a  J.......F.4S..w.
[13043.176136] df cc 24 89 96 3c 4f 85 3b 84 95 fd 60 a7 a5 7a  ..$..<O.;...`..z
[13043.183296] 93 e9 2d cd 72 33 b9 46 99 12 45 67 f6 70 aa df  ..-.r3.F..Eg.p..
[13043.190454] 8c 1b 44 24                                      ..D$
[13043.202096] skb length: 1500
[13043.205008] 45 08 05 dc 57 56 40 00 40 06 54 62 c0 a8 04 06  E...WV@.@.Tb....
[13043.212222] c0 a8 04 05 00 16 eb 6a bc 2d 5c 70 a2 05 09 38  .......j.-\p...8
[13043.219393] 80 10 01 f5 eb c4 00 00 01 01 08 0a f1 23 57 33  .............#W3
[13043.226536] 4a ff d7 d0 bd 8e ca 75 68 ce c6 6a ba 16 8f 1e  J......uh..j....
[13043.233701] 23 9c ba 2e 9c 41 f4 d9 a9 76 5d b6 e0 dd bc 93  #....A...v].....
[13043.240863] a9 bf 41 9c 0f a3 93 f2 c9 a1 b9 cb cb 12 3f 00  ..A...........?.    # interrupted file-transmission with Ctrl+C (note the kernel-tick)
[13043.248002] f3 3d 5c ea                                      .=\.
[13045.633492] skb length: 1500
[13045.636542] 45 08 05 dc 57 57 40 00 40 06 54 61 c0 a8 04 06  E...WW@.@.Ta....    # executing ICMP requests manually in various intervals (look at the ticks), but data is still from file-transmission
[13045.643770] c0 a8 04 05 00 16 eb 6a bc 2d 62 18 a2 05 09 38  .......j.-b....8
[13045.650941] 80 18 01 f5 ae ac 00 00 01 01 08 0a f1 23 57 33  .............#W3
[13045.658083] 4a ff d7 d0 f1 f3 1d a7 58 a0 19 5c 49 5a 97 3d  J.......X..\IZ.=
[13045.665244] a9 c7 54 77 b7 a3 20 c7 34 20 c0 0f ba 0a 27 bf  ..Tw.. .4 ....'.
[13045.672403] 81 28 93 0d bb 61 73 b0 c2 ac d0 88 9e 79 3c c1  .(...as......y<.
[13045.679560] f0 fb df 9c                                      ....
[13048.505135] skb length: 1500
[13048.508198] 45 08 05 dc 57 58 40 00 40 06 54 60 c0 a8 04 06  E...WX@.@.T`....    # on each new ICMP request a new data-set of the file transmission will be transferred.
[13048.515420] c0 a8 04 05 00 16 eb 6a bc 2d 67 c0 a2 05 09 38  .......j.-g....8
[13048.522591] 80 10 01 f5 65 29 00 00 01 01 08 0a f1 23 57 57  ....e).......#WW
[13048.529756] 4a ff d8 06 e5 b3 a0 c7 78 58 e5 55 88 4d 43 9a  J.......xX.U.MC.
[13048.536896] 7e cd 65 a1 14 79 b2 c0 94 1f 85 b9 1d a9 1e e8  ~.e..y..........
[13048.544060] 85 d1 b1 ee 9e f8 0e 27 7f ab 8f e9 d4 fc a8 8a  .......'........
[13048.551216] 30 a0 bb e6                                      0...
[13049.986684] skb length: 1500
[13049.989830] 45 08 05 dc 57 59 40 00 40 06 54 5f c0 a8 04 06  E...WY@.@.T_....    # here again
[13049.996981] c0 a8 04 05 00 16 eb 6a bc 2d 6d 68 a2 05 09 38  .......j.-mh...8
[13050.004183] 80 18 01 f5 c2 c7 00 00 01 01 08 0a f1 23 57 57  .............#WW
[13050.011354] 4a ff d8 06 28 e1 3c b9 f7 c2 5f f4 1c 3c cf b7  J...(.<..._..<..
[13050.018519] 63 d3 0f c6 53 fb 39 a3 e1 c6 c3 50 d3 0e b7 c4  c...S.9....P....
[13050.025684] ab 0f 0e c4 3e ad 7d 68 63 60 db 1a f0 fa 65 1d  ....>.}hc`....e.
[13050.032844] eb 39 85 f1                                      .9..
[13054.859293] skb length: 1500
[13054.862352] 45 08 05 dc 57 5a 40 00 40 06 54 5e c0 a8 04 06  E...WZ@.@.T^....    #  (if you look at the ticks you see that the trigger comes from the manual ICMP request, but the data is still from the aborted file transfer)
[13054.869565] c0 a8 04 05 00 16 eb 6a bc 2d 73 10 a2 05 09 38  .......j.-s....8
[13054.876712] 80 10 01 f5 ba ab 00 00 01 01 08 0a f1 23 57 8d  .............#W.
[13054.883879] 4a ff d8 3d ae 9b 50 59 ec b5 a4 f1 b8 58 70 c7  J..=..PY.....Xp.
[13054.891042] 70 6e c7 fe 36 c0 a4 25 be c8 42 60 df a5 65 e5  pn..6..%..B`..e.
[13054.898184] af e5 b5 f8 75 74 52 97 eb 85 d7 25 86 af ba 41  ....utR....%...A
[13054.905346] a7 ba 65 3c                                      ..e<
[13058.433100] skb length: 1500
[13058.436303] 45 08 05 dc 57 5b 40 00 40 06 54 5d c0 a8 04 06  E...W[@.@.T]....
[13058.443547] c0 a8 04 05 00 16 eb 6a bc 2d 78 b8 a2 05 09 38  .......j.-x....8
[13058.450721] 80 18 01 f5 5d c8 00 00 01 01 08 0a f1 23 57 8d  ....]........#W.
[13058.457866] 4a ff d8 3d a4 1c b7 c9 0d ac be 90 18 3f c9 2d  J..=.........?.-
[13058.465029] e2 b9 cb 04 62 fa b2 c2 ad 71 06 43 cb c5 ec 1f  ....b....q.C....
[13058.472187] 05 7a 5e d6 cb cd 61 af 8f 93 60 a7 f0 f0 b3 76  .z^...a...`....v
[13058.479342] 08 e7 9e 18                                      ....
[13062.021630] skb length: 1500
[13062.024770] 45 08 05 dc 57 5c 40 00 40 06 54 5c c0 a8 04 06  E...W\@.@.T\....
[13062.032000] c0 a8 04 05 00 16 eb 6a bc 2d 7e 60 a2 05 09 38  .......j.-~`...8
[13062.039169] 80 10 01 f5 3e 80 00 00 01 01 08 0a f1 23 57 92  ....>........#W.
[13062.046312] 4a ff d8 75 12 fa c9 ab 62 d3 24 61 d7 22 a7 be  J..u....b.$a."..
[13062.053485] fc 3c 56 d2 e1 33 c7 b6 7f b6 4c 24 04 6a d3 5a  .<V..3....L$.j.Z
[13062.060650] c4 10 3b f7 b5 e9 5e bd 85 de f1 09 81 47 b0 77  ..;...^......G.w
[13062.067790] 90 71 ea dc                                      .q..
[13069.277359] skb length: 1500
[13069.280470] 45 08 05 dc 57 5d 40 00 40 06 54 5b c0 a8 04 06  E...W]@.@.T[....
[13069.287621] c0 a8 04 05 00 16 eb 6a bc 2d 84 08 a2 05 09 38  .......j.-.....8
[13069.294826] 80 18 01 f5 64 a9 00 00 01 01 08 0a f1 23 57 92  ....d........#W.
[13069.301997] 4a ff d8 75 1b 8a 8b 75 50 5e bc d9 a5 05 40 ba  J..u...uP^....@.
[13069.309164] c5 5d 22 de cb c2 ef db 6d 63 be a1 3c d6 45 fa  .]".....mc..<.E.
[13069.316306] c7 e5 75 75 2e 12 77 19 18 fc 78 fa d5 65 ad 62  ..uu..w...x..e.b
[13069.323464] 0b f4 7d cc                                      ..}.
[13074.304356] skb length: 1500
[13074.307483] 45 08 05 dc 57 5e 40 00 40 06 54 5a c0 a8 04 06  E...W^@.@.TZ....
[13074.314714] c0 a8 04 05 00 16 eb 6a bc 2d 89 b0 a2 05 09 38  .......j.-.....8
[13074.321888] 80 10 01 f5 0b 9d 00 00 01 01 08 0a f1 23 58 67  .............#Xg
[13074.329055] 4a ff d8 b9 8e ab 1c 5f 22 6d 2e 95 8b d7 b7 ae  J......_"m......
[13074.336198] 4f 5c 08 d6 8b 37 85 c0 e4 ee 33 36 77 42 3a b7  O\...7....36wB:.
[13074.343360] 64 f2 cf 3d b2 19 a4 ff eb c4 7a ef 99 f9 18 dd  d..=......z.....
[13074.350519] 9f 91 85 11                                      ....
[13074.417083] skb length: 1500
[13074.420192] 45 08 05 dc 57 5f 40 00 40 06 54 59 c0 a8 04 06  E...W_@.@.TY....
[13074.427343] c0 a8 04 05 00 16 eb 6a bc 2d 8f 58 a2 05 09 38  .......j.-.X...8
[13074.434540] 80 18 01 f5 05 89 00 00 01 01 08 0a f1 23 58 67  .............#Xg
[13074.441712] 4a ff d8 b9 c2 57 2a 79 1c 72 07 a3 10 e7 85 98  J....W*y.r......
[13074.448854] 49 c3 d8 35 35 04 6f b3 f5 6d cd ea 8a 94 3b 57  I..55.o..m....;W
[13074.456015] 5d f0 79 5c 7b 5c 9b 27 8d cd 2c 2d f4 57 45 0f  ].y\{\.'..,-.WE.
[13074.463171] cd f7 b2 b3                                      ....
[13075.330798] skb length: 1500
[13075.334007] 45 08 05 dc 57 60 40 00 40 06 54 58 c0 a8 04 06  E...W`@.@.TX....
[13075.341250] c0 a8 04 05 00 16 eb 6a bc 2d 95 00 a2 05 09 38  .......j.-.....8
[13075.348394] 80 10 01 f5 17 5c 00 00 01 01 08 0a f1 23 58 67  .....\.......#Xg
[13075.355562] 4a ff d8 ef 51 8f 19 64 92 58 2e 5d 56 c7 9b 2e  J...Q..d.X.]V...
[13075.362730] 80 f5 08 11 a6 2b 77 03 d8 da 26 f5 78 b3 61 45  .....+w...&.x.aE
[13075.369892] 11 b4 c5 e3 a5 8c 58 ca 7f 20 d9 a5 aa 82 01 ec  ......X.. ......
[13075.377032] 61 6e eb 06                                      an..
[13075.457032] skb length: 1500
[13075.460141] 45 08 05 dc 57 61 40 00 40 06 54 57 c0 a8 04 06  E...Wa@.@.TW....
[13075.467291] c0 a8 04 05 00 16 eb 6a bc 2d 9a a8 a2 05 09 38  .......j.-.....8
[13075.474489] 80 18 01 f5 88 a4 00 00 01 01 08 0a f1 23 58 67  .............#Xg
[13075.481657] 4a ff d8 ef ea 8d 36 ee 0c 85 4b b6 ed ff 54 43  J.....6...K...TC
[13075.488800] 3e 27 cf b1 ce 03 c4 c2 ca 61 98 97 81 4b 29 a9  >'.......a...K).
[13075.495963] db fe ff 62 d0 a0 6c 24 94 25 4f 3c a4 b3 96 74  ...b..l$.%O<...t
[13075.503122] a9 f7 dc e1                                      ....
[13076.352125] skb length: 1500
[13076.355329] 45 08 05 dc 57 62 40 00 40 06 54 56 c0 a8 04 06  E...Wb@.@.TV....
[13076.362576] c0 a8 04 05 00 16 eb 6a bc 2d a0 50 a2 05 09 38  .......j.-.P...8
[13076.369747] 80 10 01 f5 e3 11 00 00 01 01 08 0a f1 23 58 77  .............#Xw
[13076.376889] 4a ff d9 26 a0 1f eb a0 31 bf 1c 5c 76 d2 78 da  J..&....1..\v.x.
[13076.384053] 18 03 05 3b 97 15 26 c0 4a 71 86 80 a4 f1 7e 88  ...;..&.Jq....~.
[13076.391212] 3b 50 c4 09 f6 55 97 20 66 c1 82 f6 56 f2 dc d2  ;P...U. f...V...
[13076.398351] c7 73 84 bf                                      .s..
[13076.496727] skb length: 1500
[13076.499931] 45 08 05 dc 57 63 40 00 40 06 54 55 c0 a8 04 06  E...Wc@.@.TU....
[13076.507082] c0 a8 04 05 00 16 eb 6a bc 2d a5 f8 a2 05 09 38  .......j.-.....8
[13076.514287] 80 18 01 f5 7e 44 00 00 01 01 08 0a f1 23 58 77  ....~D.......#Xw
[13076.521459] 4a ff d9 26 01 41 a5 b3 2c e6 b6 d4 59 dc c9 63  J..&.A..,...Y..c
[13076.528600] 6b f3 df 17 f4 c3 4d 46 b2 ed f6 9f 2b b4 65 2e  k.....MF....+.e.
[13076.535761] 23 33 32 c5 b8 67 b3 20 8b 8b 0b 9a ed c4 2a a3  #32..g. ......*.
[13076.542922] 95 06 26 ec                                      ..&.
[13076.977002] skb length: 1500
[13076.980119] 45 08 05 dc 57 64 40 00 40 06 54 54 c0 a8 04 06  E...Wd@.@.TT....
[13076.987269] c0 a8 04 05 00 16 eb 6a bc 2d ab a0 a2 05 09 38  .......j.-.....8
[13076.994470] 80 10 01 f5 1b 2d 00 00 01 01 08 0a f1 23 58 79  .....-.......#Xy
[13077.001640] 4a ff d9 5d a1 3c ef d3 13 9b be b0 32 8e 44 e4  J..].<......2.D.
[13077.008784] 87 11 93 96 9f b6 e5 b4 5b 25 0f 73 b3 a7 c5 9c  ........[%.s....
[13077.015948] 29 f5 cc 5e 57 35 4e 9c 17 24 09 91 be 7d 45 0e  )..^W5N..$...}E.
[13077.023108] a4 91 54 1f                                      ..T.
[13082.756172] skb length: 1500
[13082.759288] 45 08 05 dc 57 65 40 00 40 06 54 53 c0 a8 04 06  E...We@.@.TS....
[13082.766437] c0 a8 04 05 00 16 eb 6a bc 2d b1 48 a2 05 09 38  .......j.-.H...8
[13082.773636] 80 18 01 f5 a5 df 00 00 01 01 08 0a f1 23 58 79  .............#Xy
[13082.780806] 4a ff d9 5d c7 bb 20 62 a7 c3 8c ca dc 55 e6 c0  J..].. b.....U..
[13082.787949] 2a 6b be 7c 50 0d 6e 11 ac f1 cf 9c 91 f5 9d b1  *k.|P.n.........
[13082.795112] 3c 3d b5 d2 8f ab 47 09 52 3b f0 fe da 60 6d 07  <=....G.R;...`m.
[13082.802271] 88 20 93 f5                                      . ..
[13082.912530] skb length: 1500
[13082.915735] 45 08 05 dc 57 66 40 00 40 06 54 52 c0 a8 04 06  E...Wf@.@.TR....
[13082.922976] c0 a8 04 05 00 16 eb 6a bc 2d b6 f0 a2 05 09 38  .......j.-.....8
[13082.930145] 80 10 01 f5 f6 2c 00 00 01 01 08 0a f1 23 59 33  .....,.......#Y3
[13082.937290] 4a ff d9 d4 ef 19 93 e8 fd a3 7b 1d 30 40 e6 9e  J.........{.0@..
[13082.944451] 9d b2 e8 c0 8b d6 a1 8f 0a 5e 03 3a 17 d7 f8 ee  .........^.:....
[13082.951612] 1a 55 9b c7 8f 25 be 45 12 fb 23 cd 16 7a db f6  .U...%.E..#..z..
[13082.958752] 72 80 e8 2e                                      r...
[13083.936981] skb length: 1500
[13083.940097] 45 08 05 dc 57 67 40 00 40 06 54 51 c0 a8 04 06  E...Wg@.@.TQ....
[13083.947248] c0 a8 04 05 00 16 eb 6a bc 2d bc 98 a2 05 09 38  .......j.-.....8
[13083.954447] 80 10 01 f5 f0 7c 00 00 01 01 08 0a f1 23 5a 00  .....|.......#Z.
[13083.961620] 4a ff da b0 6b f2 7e 00 5e d3 07 24 fc 6e 78 69  J...k.~.^..$.nxi
[13083.968762] 69 3b e1 e6 ca 89 1e 76 68 9e 17 c6 20 55 cb f6  i;.....vh... U..
[13083.975925] dc f5 07 2f ad 1a 51 7b 42 6e e0 c0 12 e2 1a 07  .../..Q{Bn......
[13083.983081] 4f 8c 9e bb                                      O...
[13084.961090] skb length: 1500
[13084.964140] 45 08 05 dc 57 68 40 00 40 06 54 50 c0 a8 04 06  E...Wh@.@.TP....
[13084.971375] c0 a8 04 05 00 16 eb 6a bc 2d c2 40 a2 05 09 38  .......j.-.@...8
[13084.978521] 80 10 01 f5 b1 cc 00 00 01 01 08 0a f1 23 5b 34  .............#[4
[13084.985689] 4a ff db b4 70 e5 2c d3 43 4a 59 05 b3 a7 62 fd  J...p.,.CJY...b.
[13084.992855] dc d1 a1 b9 98 1b 35 7c 41 7a 5b 1b 5e 01 49 86  ......5|Az[.^.I.
[13085.000013] f2 5d c8 16 c2 49 69 7a ad f7 9b 3d dc 29 17 0c  .]...Iiz...=.)..
[13085.007152] 05 58 36 6a                                      .X6j
[13087.708246] skb length: 1500
[13087.711519] 45 08 05 dc 57 69 40 00 40 06 54 4f c0 a8 04 06  E...Wi@.@.TO....
[13087.718876] c0 a8 04 05 00 16 eb 6a bc 2d c7 e8 a2 05 09 38  .......j.-.....8
[13087.726085] 80 10 01 f5 4d 2e 00 00 01 01 08 0a f1 23 5c 66  ....M........#\f
[13087.733255] 4a ff dc ea d8 d1 27 d8 ab 79 10 c3 78 81 e0 3b  J.....'..y..x..;
[13087.740420] 25 7a 4c 47 07 ec a3 f6 8c ce cc a8 79 66 dc 62  %zLG........yf.b
[13087.747561] 2b 6b 7b bc fa 3b c5 91 6c 1c 80 40 2b ba a2 1b  +k{..;..l..@+...
[13087.754719] 75 13 a5 31                                      u..1
[13087.764756] skb length: 1500
[13087.767846] 45 08 05 dc 57 6a 40 00 40 06 54 4e c0 a8 04 06  E...Wj@.@.TN....
[13087.775074] c0 a8 04 05 00 16 eb 6a bc 2d cd 90 a2 05 09 38  .......j.-.....8
[13087.782246] 80 10 01 f5 31 8a 00 00 01 01 08 0a f1 23 5d 33  ....1........#]3
[13087.789413] 4a ff de 16 8e 4d 44 ef 86 3e c7 84 d0 49 77 af  J....MD..>...Iw.
[13087.796555] d5 4a 17 b9 17 87 b7 77 4f a3 a0 a7 ed 1d a0 6f  .J.....wO......o
[13087.803718] 86 dd 22 dd fb 13 4c 0c 35 5b b1 09 40 2c 2a 19  .."...L.5[..@,*.
[13087.810876] 40 c7 c5 61                                      @..a
[13087.827527] skb length: 1500
[13087.830673] 45 08 05 dc 57 6b 40 00 40 06 54 4d c0 a8 04 06  E...Wk@.@.TM....
[13087.837822] c0 a8 04 05 00 16 eb 6a bc 2d d3 38 a2 05 09 38  .......j.-.8...8
[13087.845022] 80 10 01 f5 31 75 00 00 01 01 08 0a f1 23 5e 67  ....1u.......#^g
[13087.852190] 4a ff de e8 02 02 9b 9b 32 c6 e9 cf 3a 01 72 f2  J.......2...:.r.
[13087.859355] 79 cf e2 1a bf 9f ac 06 05 74 b9 8e aa cb 85 93  y........t......
[13087.866497] ed 91 75 94 ed b5 82 6f 5e f5 61 e9 63 5f f0 fd  ..u....o^.a.c_..
[13087.873653] c3 93 46 a8                                      ..F.
[13088.857711] skb length: 1500
[13088.860912] 45 08 05 dc 57 6c 40 00 40 06 54 4c c0 a8 04 06  E...Wl@.@.TL....
[13088.868062] c0 a8 04 05 00 16 eb 6a bc 2d d8 e0 a2 05 09 74  .......j.-.....t
[13088.875270] 80 10 01 f5 c6 3a 00 00 01 01 08 0a f1 23 5e ab  .....:.......#^.
[13088.882442] 4a ff df 8c 9b 7f 9d 8f 14 dc a9 73 b5 3a d9 ef  J..........s.:..
[13088.889607] 62 11 9e 1b 67 a7 6d 8c 47 88 b4 ab 73 ec 03 3d  b...g.m.G...s..=
[13088.896750] 89 6e d0 0c 30 50 c1 8a f9 16 a3 e4 0e 11 eb fe  .n..0P..........
[13088.903909] cc 22 37 f8                                      ."7.
[13089.876813] skb length: 52
[13089.879746] 45 08 00 34 57 6d 40 00 40 06 59 f3 c0 a8 04 06  E..4Wm@.@.Y.....
[13089.886896] c0 a8 04 05 00 16 eb 6a bc 2d de 88 a2 05 09 75  .......j.-.....u
[13089.894095] 80 10 01 f5 3f 2b 00 00 01 01 08 0a f1 23 5e dd  ....?+.......#^.
[13089.901264] 4a ff df 8e

Additionally i added prints on the ESP32 firmware side to see the length of the buffer that is sent out:

    ESP_LOGI("LEN", "%d", tx_buf_handle.payload_len);

resulting in the logs:

... running file transmission (scp command)
I (104881) LEN: 1528    # interrupted file-transmission with Ctrl+C
I (105191) LEN: 1528    # ICMP reply are triggering SPI-communication immediately, data is too large to be ICMP reply
I (105501) LEN: 1528    # again
I (105701) LEN: 1528    # again 
I (106011) LEN: 1528    # ...
I (106081) LEN: 1528
I (106131) LEN: 80
I (108571) LEN: 1528
I (111441) LEN: 112
I (112921) LEN: 1528
I (117791) LEN: 112
I (121371) LEN: 1528
I (124951) LEN: 112
I (132211) LEN: 112
I (137241) LEN: 56    # here the first ICMP reply goes through (but package's TTL is outdated)
I (137351) LEN: 56    # again ...
I (138261) LEN: 56
I (138261) LEN: 1528
I (138391) LEN: 56    # even if the buffer length is only 56 bytes, the skb buffer length will be interpreted as 1500 (without header). why?
I (139291) LEN: 56
I (139431) LEN: 56
I (139911) LEN: 112
I (145691) LEN: 76
I (145851) LEN: 56
I (146871) LEN: 56
I (147891) LEN: 56
I (150641) LEN: 100
I (150651) LEN: 120
I (150761) LEN: 56
I (151791) LEN: 56
I (152811) LEN: 56
I (173081) LEN: 1528
I (173141) LEN: 56
I (174311) LEN: 56
I (175341) LEN: 56
I (178201) LEN: 56
I (178261) LEN: 56
I (179221) LEN: 56
I (179301) LEN: 56
I (184561) LEN: 56

Note: the tick offset of the ESP32 and the linux-kernel logs is 12937.065 seconds

Note: the ESP is sending out short packages than the linux-host is interpreting. For example looking at the package sent from ESP side at 151.791 and arrived at 13088.857 on the linux side is 56 bytes long (including 28 byte header) and the skb-buffer (removed header) is still 1500 bytes long. How can it be? Did i mixed up receiving and sending buffers?

Note: adding prints everywhere can also create strange behaviors since timings can not be adhered

I will check the transmissions again with a logic analyzer the next days, but i want to share the current results with you. Maybe you have an idea whats going wrong?

[mantriyogesh]

Okay. Thank you again for all the logs. Understood the scenario, great debug. Wifi sniffer will solve a lot of questions and get clear understanding, what is this 1500 byte packet.

Some responses-

1. The length 1500 is confusing, what is the real packet? Can only check through the wifi sniffer. Also, what is the packet type (header->if_type) of this big packet?

2. There is always one extra packets from slave to host, for new session. Let me try to explain some design considerations for spi. A. SPI is driven by the host always. B. The SPI should be full duplex C. As being full duplex, even when either terminal (host or slave) doesn't hold a valid data (nothing to tx), it would send dummy data, with non valid if_type, the receiver terminal would discard this packet. D. Slave needs to be always ready, as host can send data any time. Due to this, if slave doesn't have next valid tx, it will create a dummy packet and keep the spi driver queue ready. But the dummy packet length is always zero. So I don't think this 1500 length is dummy packet. E. We need to idle the spi bus, when there is no valid data at either terminal F. When slave has some new data to tx to host, data ready interrupt will be triggered. This is interrupt at host, which will schedule new spi transfer. Data ready will be high until all packets are drained from slave to host (and host to slave also) G. As the duration of ping would be 1 sec, which is very high, generally there would be one packet as dummy (last time we had to put in spi driver queue for slave spi readiness, when spi bus was going idle) followed by real data packet response H. Dummy packet is just 1 packet after spi idle, should not much hog the spi as such and harmless.

3. As you are aware, I think you can cut down logs a bit, either side and print only necessary, as it will cause additional delays (I understand for debug, logs are easiest to do)

4. If the packets (header-if_type) is of type ESP_AP_IF and length unexpected, I think we need to understand what these messages are from the wifi sniffer capture.

5. Bluetooth and station mode is disabled ? Also, add back this dropping logic https://github.com/espressif/esp-hosted/commit/e4ee1a33514fd219b228b844205f499d5b7ee49f#diff-93cd143561776b7c16d5588f4e64301ed06856fc08b7df7a72630acf286d6ec4L224 for any broadcast /multicast data received at AP interface?

[Philipansari]

Hi, i was able to track down the problem a bit further.

I adjust the test case: Instead of calling scp (which encrypts data and uses TCP) with a large binary file, i am using a self-written UDP stream of 0xFF bytes without encryption. This way i do not need a wifi-sniffer to interpret the data. Additionally i observed whats happening on the SPI-bus by connecting a logic analyzer:

It clearly shows that the SPI-bus transmission itself is completely fine and there is no delay or buffered data written to the bus. But the kernel-prints on the linux-host are showing outdated (buffered) data on the kernel-logs right on the receiving function. This means i probably have an issue with the SPI-driver of my linux?

For clarification i made a small graphic to illustrate the setup:

Here you can take a look at the kernel logs (i wrote some comments what actually should happen): kernel.log

And here is the capture of my logic analyzer (recorded with Saleae Logic 2) The capture itself is taken on another transmission than shown in the kernel logs, because i disabled the kernel-prints for it) [EDIT: Fileupload as *.zip] udp_stream_ff_then_f0.sal.zip

The situation i observed also relates to the symptoms i found: removing and reloading the kernel-module (esp-hosted driver) does not solve the buffer problem, which is interesting because it will:

1. re-initialize the allocated SPI-peripheral from the kernel
2. restart the whole ESP32

without any effect.

Last to mention, the next-generation does not have this problem, even though the SPI-driver on my linux seems to have a problem. Does the implementation of the SPI-transmission layer differentiate significantly in the FG/NG? Can i merge the SPI-transmission layer from the NG into the FG as a workaround for my case?

[mantriyogesh]

Well, this looks very confusing & much worrisome.

There are two differences,

1. https://github.com/espressif/esp-hosted/blob/ee0b7414fadd6d255291059618929832bb23bf64/esp_hosted_fg/esp/esp_driver/network_adapter/main/spi_slave_api.c#L545C23-L545C50
2. spi_sem is used as semaphore instead of the spi as work queue. Anyway, you can change this one by one or can also move to older commit.

Do let us know the result, just curious.

[Philipansari]

Finally found the problem: DMA was disabled on the linux-system, which caused the SPI-transmission to be interrupted all the time. The unexpected interrupts caused the buffer-bloat situation.

For anyone who is curious if they have the same problem: You have to watch for idle-times of the CLK line during SPI transmissions, which can look like this: (first package is an ICMP ping request and the second one is the pong response)

After enabling DMA the CLK line does not idle during the transmission:

It seems the next-generation SPI-transmission layer is more robust against such cases.