search

espressif / esp-idf

Espressif IoT Development Framework. Official development framework for Espressif SoCs.
Apache License 2.0
13.44k stars 7.25k forks source link

ESP Mesh per-hop latency is rose up to hundreds of ms (IDFGH-5576) #7299

Closed JirkoPS closed 2 years ago

JirkoPS commented 3 years ago

Environment

Problem Description

I used two modules (master and slave)for testing. The master sends message to the slave and the slave retransmit the message back to the master. The master measures time of each message from sending this message by the slave to receiving it by the master (ping time). The master and the slave both measure how long take esp_mesh_send function. Esp documentation specifies per-hop latency: 10 to 30 milliseconds. But my measuring shows that latency is small at the beginning (~5ms) but after few messages are sent, the latency rose up to hundreds of ms. At the same time, the esp_mesh_send function starts to be blocking.

I find out that this problem is related to the mesh PS (power save) function. When PS is disabled everything is working correctly.

The problem is probably related to issues: #4475, #4407, #3472 These issues are closed and without a solution.

Expected Behavior

Esp documentation specify per-hop latency: 10 to 30 milliseconds.

Actual Behavior

Measured per-hop latency rose up to hundreds of ms. See debug logs.

Steps to reproduce

  1. Import example internal communication
  2. Use my mesh_main.c file
  3. Set mac addr
  4. Set wifi and rtos tick time to 1000
  5. Comment for slave #define MASTER_NODE TRUE

Code to reproduce this issue

https://github.com/JirkoPS/ESP32.git

Debug Logs

Enabled mesh PS function

ts Jun  8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0030,len:7248
load:0x40078000,len:14292
ho 0 tail 12 room 4
load:0x40080400,len:3688
entry 0x40080678
I (28) boot: ESP-IDF v4.3-dirty 2nd stage bootloader
I (28) boot: compile time 12:05:11
I (28) boot: chip revision: 1
I (31) boot_comm: chip revision: 1, min. bootloader chip revision: 0
I (38) boot.esp32: SPI Speed      : 40MHz
I (43) boot.esp32: SPI Mode       : DIO
I (48) boot.esp32: SPI Flash Size : 2MB
I (52) boot: Enabling RNG early entropy source...
I (57) boot: Partition Table:
I (61) boot: ## Label            Usage          Type ST Offset   Length
I (68) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (76) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (83) boot:  2 factory          factory app      00 00 00010000 00100000
I (91) boot: End of partition table
I (95) boot_comm: chip revision: 1, min. application chip revision: 0
I (102) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=218a0h (137376) map
I (162) esp_image: segment 1: paddr=000318c8 vaddr=3ffb0000 size=04544h ( 17732) load
I (170) esp_image: segment 2: paddr=00035e14 vaddr=40080000 size=0a204h ( 41476) load
I (188) esp_image: segment 3: paddr=00040020 vaddr=400d0020 size=9f1d8h (651736) map
I (434) esp_image: segment 4: paddr=000df200 vaddr=4008a204 size=0b4a8h ( 46248) load
I (454) esp_image: segment 5: paddr=000ea6b0 vaddr=50000000 size=00010h (    16) load
I (466) boot: Loaded app from partition at offset 0x10000
I (466) boot: Disabling RNG early entropy source...
I (478) cpu_start: Pro cpu up.
I (478) cpu_start: Starting app cpu, entry point is 0x400812fc
I (0) cpu_start: App cpu up.
I (494) cpu_start: Pro cpu start user code
I (494) cpu_start: cpu freq: 160000000
I (494) cpu_start: Application information:
I (499) cpu_start: Project name:     internal_communication
I (505) cpu_start: App version:      1
I (509) cpu_start: Compile time:     Jul 20 2021 10:05:13
I (515) cpu_start: ELF file SHA256:  3141639fd42f2fa3...
I (521) cpu_start: ESP-IDF:          v4.3-dirty
I (527) heap_init: Initializing. RAM available for dynamic allocation:
I (534) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (540) heap_init: At 3FFB9D48 len 000262B8 (152 KiB): DRAM
I (546) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (552) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (559) heap_init: At 400956AC len 0000A954 (42 KiB): IRAM
I (566) spi_flash: detected chip: generic
I (570) spi_flash: flash io: dio
W (574) spi_flash: Detected size(4096k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (588) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (696) wifi:wifi driver task: 3ffc3b34, prio:23, stack:6656, core=0
I (697) system_api: Base MAC address is not set
I (697) system_api: read default base MAC address from EFUSE
I (723) wifi:wifi firmware version: c7d0450
I (724) wifi:wifi certification version: v7.0
I (724) wifi:config NVS flash: enabled
I (724) wifi:config nano formating: disabled
I (728) wifi:Init data frame dynamic rx buffer num: 32
I (733) wifi:Init management frame dynamic rx buffer num: 32
I (738) wifi:Init management short buffer num: 32
I (743) wifi:Init dynamic tx buffer num: 32
I (747) wifi:Init static rx buffer size: 1600
I (751) wifi:Init static rx buffer num: 10
I (754) wifi:Init dynamic rx buffer num: 32
I (759) wifi_init: rx ba win: 6
I (762) wifi_init: tcpip mbox: 32
I (766) wifi_init: udp mbox: 6
I (770) wifi_init: tcp mbox: 6
I (774) wifi_init: tcp tx win: 5744
I (778) wifi_init: tcp rx win: 5744
I (782) wifi_init: tcp mss: 1440
I (786) wifi_init: WiFi IRAM OP enabled
I (790) wifi_init: WiFi RX IRAM OP enabled
I (796) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
I (903) wifi:mode : sta (24:0a:c4:ef:bd:48) + softAP (24:0a:c4:ef:bd:49)
I (904) wifi:enable tsf
I (907) wifi:Total power save buffer number: 16
I (908) wifi:Init max length of beacon: 752/752
I (910) wifi:Init max length of beacon: 752/752
E (915) wifi:ioctl_register type:0
E (917) wifi:ioctl_register type:0
E (920) wifi:ioctl_register type:0
I (928) mesh: <nvs>read layer:0
I (929) mesh: <nvs>read assoc:0
I (930) wifi:Set ps type: 1

I (944) wifi:Total power save buffer number: 16
I (1696) wifi:mode : sta (24:0a:c4:ef:bd:48)
I (1700) mesh: <MESH_NWK_LOOK_FOR_NETWORK>need_scan:0x3, need_scan_router:0x0, look_for_nwk_count:1
I (1702) master: <MESH_EVENT_MESH_STARTED>ID:77:77:77:77:77:77
I (1706) master: mesh starts successfully, heap:170024, root not fixed<0>(tree), ps:1

I (5609) mesh: [S1]linksys2, 00:1f:1f:0a:4e:12, channel:11, rssi:-38
I (5609) mesh: find router:[ssid_len:8]linksys2, rssi:-38, 00:1f:1f:0a:4e:12(encrypted), new channel:11, old channel:0
I (5615) mesh: [FIND][ch:0]AP:2, otherID:0, MAP:0, idle:0, candidate:0, root:0[00:1f:1f:0a:4e:12]router found
I (5624) mesh: [FIND:1]find a network, channel:11, cfg<channel:0, router:linksys2, 00:00:00:00:00:00>

I (5635) wifi:mode : sta (24:0a:c4:ef:bd:48) + softAP (24:0a:c4:ef:bd:49)
W (5641) wifi:<MESH AP>adjust channel:1, secondary channel offset:1(40U)
I (5649) wifi:Total power save buffer number: 16
I (5634) master: <MESH_EVENT_FIND_NETWORK>new channel:11, router BSSID:00:00:00:00:00:00
W (5662) wifi:<MESH AP>adjust channel:11, secondary channel offset:2(40D)
I (5669) wifi:Total power save buffer number: 16
I (5973) mesh: [SCAN][ch:11]AP:1, other(ID:0, RD:0), MAP:0, idle:0, candidate:1, root:0, topMAP:0[c:0,i:0][00:1f:1f:0a:4e:12]router found<>
I (5975) mesh: 1330[SCAN]init rc[24:0a:c4:ef:bd:49,-39], mine:0, voter:0
I (5981) mesh: 1368, vote myself, router rssi:-39 > voted rc_rssi:-120
I (5988) mesh: [SCAN:1/10]rc[128][24:0a:c4:ef:bd:49,-39], self[24:0a:c4:ef:bd:48,-39,reason:0,votes:1,idle][mine:1,voter:1(1.00)percent:1.00][128,1,24:0a:c4:ef:bd:49]

I (6304) mesh: [SCAN][ch:11]AP:1, other(ID:0, RD:0), MAP:0, idle:0, candidate:1, root:0, topMAP:0[c:0,i:1][00:1f:1f:0a:4e:12]router found<>
I (6306) mesh: 1330[SCAN]init rc[24:0a:c4:ef:bd:49,-39], mine:0, voter:0
I (6312) mesh: [SCAN:2/10]rc[128][24:0a:c4:ef:bd:49,-39], self[24:0a:c4:ef:bd:48,-39,reason:0,votes:1,idle][mine:1,voter:1(1.00)percent:1.00][128,1,24:0a:c4:ef:bd:49]

I (6628) mesh: [SCAN][ch:11]AP:1, other(ID:0, RD:0), MAP:0, idle:0, candidate:1, root:0, topMAP:0[c:0,i:1][00:1f:1f:0a:4e:12]router found<>
I (6630) mesh: 1330[SCAN]init rc[24:0a:c4:ef:bd:49,-39], mine:0, voter:0
I (6636) mesh: [SCAN:3/10]rc[128][24:0a:c4:ef:bd:49,-39], self[24:0a:c4:ef:bd:48,-39,reason:0,votes:1,idle][mine:1,voter:1(1.00)percent:1.00][128,1,24:0a:c4:ef:bd:49]

I (6952) mesh: [SCAN][ch:11]AP:1, other(ID:0, RD:0), MAP:0, idle:0, candidate:1, root:0, topMAP:0[c:0,i:1][00:1f:1f:0a:4e:12]router found<>
I (6954) mesh: 1330[SCAN]init rc[24:0a:c4:ef:bd:49,-37], mine:0, voter:0
I (6961) mesh: [SCAN:4/10]rc[128][24:0a:c4:ef:bd:49,-38], self[24:0a:c4:ef:bd:48,-37,reason:0,votes:1,idle][mine:1,voter:1(1.00)percent:1.00][128,1,24:0a:c4:ef:bd:49]

I (7276) mesh: [SCAN][ch:11]AP:1, other(ID:0, RD:0), MAP:0, idle:0, candidate:1, root:0, topMAP:0[c:0,i:1][00:1f:1f:0a:4e:12]router found<>
I (7278) mesh: 1330[SCAN]init rc[24:0a:c4:ef:bd:49,-38], mine:0, voter:0
I (7285) mesh: [SCAN:5/10]rc[128][24:0a:c4:ef:bd:49,-38], self[24:0a:c4:ef:bd:48,-38,reason:0,votes:1,idle][mine:1,voter:1(1.00)percent:1.00][128,1,24:0a:c4:ef:bd:49]

I (7601) mesh: [SCAN][ch:11]AP:1, other(ID:0, RD:0), MAP:0, idle:0, candidate:1, root:0, topMAP:0[c:0,i:1][00:1f:1f:0a:4e:12]router found<>
I (7602) mesh: 1330[SCAN]init rc[24:0a:c4:ef:bd:49,-37], mine:0, voter:0
I (7609) mesh: [SCAN:6/10]rc[128][24:0a:c4:ef:bd:49,-37], self[24:0a:c4:ef:bd:48,-37,reason:0,votes:1,idle][mine:1,voter:1(1.00)percent:1.00][128,1,24:0a:c4:ef:bd:49]

I (7926) mesh: [SCAN][ch:11]AP:2, other(ID:0, RD:0), MAP:1, idle:1, candidate:1, root:0, topMAP:0[c:0,i:1][00:1f:1f:0a:4e:12]router found<>
I (7928) mesh: [SCAN:7/10]rc[128][24:0a:c4:ef:bd:49,-37], self[24:0a:c4:ef:bd:48,-38,reason:0,votes:1,idle][mine:1,voter:1(1.00)percent:1.00][128,1,24:0a:c4:ef:bd:49]

I (8244) mesh: [SCAN][ch:11]AP:2, other(ID:0, RD:0), MAP:1, idle:1, candidate:1, root:0, topMAP:0[c:0,i:1][00:1f:1f:0a:4e:12]router found<>
I (8246) mesh: [SCAN:8/10]rc[127][24:0a:c4:ee:a5:c9,-37], self[24:0a:c4:ef:bd:48,-38,reason:0,votes:0,idle][mine:0,voter:2(0.00)percent:1.00][127,1,24:0a:c4:ee:a5:c9]

I (8562) mesh: [SCAN][ch:11]AP:2, other(ID:0, RD:0), MAP:1, idle:1, candidate:1, root:0, topMAP:0[c:0,i:1][00:1f:1f:0a:4e:12]router found<>
I (8564) mesh: [SCAN:9/10]rc[127][24:0a:c4:ee:a5:c9,-37], self[24:0a:c4:ef:bd:48,-38,reason:0,votes:0,idle][mine:0,voter:2(0.00)percent:1.00][127,1,24:0a:c4:ee:a5:c9]

I (8880) mesh: [SCAN][ch:11]AP:2, other(ID:0, RD:0), MAP:1, idle:1, candidate:1, root:0, topMAP:0[c:0,i:1][00:1f:1f:0a:4e:12]router found<>
I (8883) mesh: [SCAN:10/10]rc[127][24:0a:c4:ee:a5:c9,-37], self[24:0a:c4:ef:bd:48,-38,reason:0,votes:0,idle][mine:0,voter:2(0.00)percent:1.00][127,1,24:0a:c4:ee:a5:c9]

I (9199) mesh: [SCAN][ch:11]AP:2, other(ID:0, RD:0), MAP:1, idle:1, candidate:1, root:0, topMAP:0[c:0,i:1][00:1f:1f:0a:4e:12]router found<>
I (9202) mesh: [SCAN:11/10]rc[127][24:0a:c4:ee:a5:c9,-37], self[24:0a:c4:ef:bd:48,-39,reason:0,votes:0,idle][mine:0,voter:2(0.00)percent:1.00][127,2,24:0a:c4:ee:a5:c9]

I (9517) mesh: [SCAN][ch:11]AP:2, other(ID:0, RD:0), MAP:1, idle:1, candidate:1, root:0, topMAP:0[c:0,i:1][00:1f:1f:0a:4e:12]router found<>
I (9519) mesh: [SCAN:12/10]rc[127][24:0a:c4:ee:a5:c9,-37], self[24:0a:c4:ef:bd:48,-39,reason:0,votes:0,idle][mine:0,voter:2(0.00)percent:1.00][127,2,24:0a:c4:ee:a5:c9]

I (9835) mesh: [SCAN][ch:11]AP:2, other(ID:0, RD:0), MAP:1, idle:1, candidate:1, root:0, topMAP:0[c:0,i:1][00:1f:1f:0a:4e:12]router found<>
I (9838) mesh: [SCAN:13/10]rc[127][24:0a:c4:ee:a5:c9,-37], self[24:0a:c4:ef:bd:48,-38,reason:0,votes:0,idle][mine:0,voter:2(0.00)percent:1.00][127,2,24:0a:c4:ee:a5:c9]

I (10154) mesh: [SCAN][ch:11]AP:2, other(ID:0, RD:0), MAP:1, idle:1, candidate:1, root:0, topMAP:0[c:0,i:1][00:1f:1f:0a:4e:12]router found<>
I (10156) mesh: [SCAN:14/10]rc[127][24:0a:c4:ee:a5:c9,-37], self[24:0a:c4:ef:bd:48,-38,reason:0,votes:0,idle][mine:0,voter:2(0.00)percent:1.00][127,2,24:0a:c4:ee:a5:c9]

I (10472) mesh: [SCAN][ch:11]AP:2, other(ID:0, RD:0), MAP:1, idle:1, candidate:1, root:0, topMAP:0[c:0,i:1][00:1f:1f:0a:4e:12]router found<>
I (10475) mesh: [SCAN:15/10]rc[127][24:0a:c4:ee:a5:c9,-37], self[24:0a:c4:ef:bd:48,-38,reason:0,votes:0,idle][mine:0,voter:2(0.00)percent:1.00][127,2,24:0a:c4:ee:a5:c9]

I (10791) mesh: [SCAN][ch:11]AP:2, other(ID:0, RD:0), MAP:1, idle:1, candidate:1, root:0, topMAP:0[c:0,i:1][00:1f:1f:0a:4e:12]router found<>
I (10793) mesh: [SCAN:16/10]rc[127][24:0a:c4:ee:a5:c9,-37], self[24:0a:c4:ef:bd:48,-38,reason:0,votes:0,idle][mine:0,voter:2(0.00)percent:1.00][127,2,24:0a:c4:ee:a5:c9]

I (11110) mesh: [SCAN][ch:11]AP:2, other(ID:0, RD:0), MAP:1, idle:1, candidate:1, root:0, topMAP:0[c:0,i:1][00:1f:1f:0a:4e:12]router found<>
I (11112) mesh: [SCAN:17/10]rc[127][24:0a:c4:ee:a5:c9,-37], self[24:0a:c4:ef:bd:48,-38,reason:0,votes:0,idle][mine:0,voter:2(0.00)percent:1.00][127,2,24:0a:c4:ee:a5:c9]

I (11428) mesh: [SCAN][ch:11]AP:2, other(ID:0, RD:0), MAP:1, idle:1, candidate:1, root:0, topMAP:0[c:0,i:1][00:1f:1f:0a:4e:12]router found<>
I (11430) mesh: [SCAN:18/10]rc[0][00:00:00:00:00:00,-37], self[24:0a:c4:ef:bd:48,-38,reason:0,votes:0,idle][mine:0,voter:1(0.00)percent:1.00][0,0,00:00:00:00:00:00]

I (11746) mesh: [SCAN][ch:11]AP:2, other(ID:0, RD:0), MAP:1, idle:1, candidate:1, root:0, topMAP:0[c:0,i:1][00:1f:1f:0a:4e:12]router found<>
I (11748) mesh: 6890[SCAN]init rc[ttl:127/votes:1][24:0a:c4:ee:a5:c9,-36]
I (11755) mesh: [SCAN:19/10]rc[127][24:0a:c4:ee:a5:c9,-37], self[24:0a:c4:ef:bd:48,-38,reason:0,votes:0,idle][mine:0,voter:2(0.00)percent:1.00][127,1,24:0a:c4:ee:a5:c9]

I (12071) mesh: [SCAN][ch:11]AP:2, other(ID:0, RD:0), MAP:1, idle:0, candidate:1, root:1, topMAP:0[c:0,i:0][00:1f:1f:0a:4e:12]router found<>
I (12073) mesh: 7364[selection]try rssi_threshold:-78, backoff times:0, max:5<-78,-82,-85>
I (12082) mesh: [DONE]connect to parent:ESPM_EEA5C8, channel:11, rssi:-36, 24:0a:c4:ee:a5:c9[layer:1, assoc:0], my_vote_num:0/voter_num:0, rc[00:00:00:00:00:00/-37/0]
I (12096) mesh: set router bssid:00:1f:1f:0a:4e:12
I (12221) wifi:new:<11,2>, old:<11,2>, ap:<11,2>, sta:<11,2>, prof:11
I (12222) wifi:state: init -> auth (b0)
I (12231) wifi:state: auth -> assoc (0)
I (12244) wifi:state: assoc -> run (10)
I (12248) mesh: <MESH_NWK_MIE_CHANGE><><><><ROOT ADDR><><><>
I (12248) mesh: <MESH_NWK_ROOT_ADDR>from assoc, layer:2, root_addr:24:0a:c4:ee:a5:c9, root_cap:1
I (12254) mesh: <MESH_NWK_ROOT_ADDR>idle, layer:2, root_addr:24:0a:c4:ee:a5:c9, conflict_roots.num:0<>
I (12256) wifi:connected with ESPM_EEA5C8, aid = 1, channel 11, 40D, bssid = 24:0a:c4:ee:a5:c9
I (12268) wifi:security: WPA2-PSK, phy: bgn, rssi: -36
I (12254) master: <MESH_EVENT_PS_PARENT_DUTY>duty:10
I (12279) master: <MESH_EVENT_ROOT_ADDRESS>root address:24:0a:c4:ee:a5:c9
I (12288) wifi:Set ps type: 1

I (12290) mesh: [scan]new scanning time:600ms, beacon interval:300ms
I (12298) mesh: 2004<arm>parent monitor, my layer:2(cap:6)(node), interval:9422ms, retries:1<normal connected>
I (12305) master: <MESH_EVENT_PARENT_CONNECTED>layer:0-->2, parent:24:0a:c4:ee:a5:c9<layer2>, ID:77:77:77:77:77:77, duty:10
I (12317) master: <MESH_EVENT_TODS_REACHABLE>state:0
W (12824) wifi:<ba-add>idx:0 (ifx:0, 24:0a:c4:ee:a5:c9), tid:5, ssn:0, winSize:64
I (12826) master: sending PacketNumber:0 esp_mesh_send Time:  9ms
I (12838) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:0 Ping time: 21ms
I (12929) master: sending PacketNumber:1 esp_mesh_send Time:  2ms
I (12932) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:1 Ping time:  5ms
I (13032) master: sending PacketNumber:2 esp_mesh_send Time:  2ms
I (13034) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:2 Ping time:  4ms
I (13134) master: sending PacketNumber:3 esp_mesh_send Time:  2ms
I (13144) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:3 Ping time: 12ms
I (13238) master: sending PacketNumber:4 esp_mesh_send Time:  3ms
I (13241) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:4 Ping time:  6ms
I (13340) master: sending PacketNumber:5 esp_mesh_send Time:  2ms
I (13342) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:5 Ping time:  4ms
I (13442) master: sending PacketNumber:6 esp_mesh_send Time:  2ms
I (13452) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:6 Ping time: 12ms
I (13544) master: sending PacketNumber:7 esp_mesh_send Time:  2ms
I (13547) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:7 Ping time:  5ms
I (13647) master: sending PacketNumber:8 esp_mesh_send Time:  2ms
I (13650) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:8 Ping time:  5ms
I (13761) master: sending PacketNumber:9 esp_mesh_send Time: 14ms
I (13764) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:9 Ping time: 17ms
I (13863) master: sending PacketNumber:10 esp_mesh_send Time:  2ms
I (13866) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:10 Ping time:  5ms
I (13965) master: sending PacketNumber:11 esp_mesh_send Time:  2ms
I (13967) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:11 Ping time:  4ms
I (14069) master: sending PacketNumber:12 esp_mesh_send Time:  3ms
I (14073) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:12 Ping time:  7ms
I (14171) master: sending PacketNumber:13 esp_mesh_send Time:  2ms
I (14174) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:13 Ping time:  5ms
I (14273) master: sending PacketNumber:14 esp_mesh_send Time:  2ms
I (14275) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:14 Ping time:  4ms
I (14376) master: sending PacketNumber:15 esp_mesh_send Time:  3ms
I (14379) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:15 Ping time:  6ms
I (14478) master: sending PacketNumber:16 esp_mesh_send Time:  2ms
I (14480) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:16 Ping time:  4ms
I (14580) master: sending PacketNumber:17 esp_mesh_send Time:  2ms
I (14583) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:17 Ping time:  5ms
I (14687) master: sending PacketNumber:18 esp_mesh_send Time:  7ms
I (14690) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:18 Ping time: 10ms
I (14789) master: sending PacketNumber:19 esp_mesh_send Time:  2ms
I (14792) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:19 Ping time:  5ms
I (14891) master: sending PacketNumber:20 esp_mesh_send Time:  2ms
I (14893) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:20 Ping time:  4ms
I (14994) master: sending PacketNumber:21 esp_mesh_send Time:  3ms
I (14997) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:21 Ping time:  6ms
I (15096) master: sending PacketNumber:22 esp_mesh_send Time:  2ms
I (15099) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:22 Ping time:  5ms
I (15198) master: sending PacketNumber:23 esp_mesh_send Time:  2ms
I (15201) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:23 Ping time:  5ms
I (15300) master: sending PacketNumber:24 esp_mesh_send Time:  2ms
I (15303) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:24 Ping time:  5ms
I (15401) master: sending PacketNumber:25 esp_mesh_send Time:  1ms
I (15404) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:25 Ping time:  4ms
I (15504) master: sending PacketNumber:26 esp_mesh_send Time:  2ms
I (15506) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:26 Ping time:  4ms
I (15609) master: sending PacketNumber:27 esp_mesh_send Time:  5ms
I (15611) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:27 Ping time:  7ms
I (15712) master: sending PacketNumber:28 esp_mesh_send Time:  2ms
I (15715) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:28 Ping time:  5ms
I (15814) master: sending PacketNumber:29 esp_mesh_send Time:  2ms
I (15816) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:29 Ping time:  4ms
I (15915) master: sending PacketNumber:30 esp_mesh_send Time:  1ms
I (15918) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:30 Ping time:  4ms
I (16018) master: sending PacketNumber:31 esp_mesh_send Time:  2ms
I (16021) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:31 Ping time:  5ms
I (16119) master: sending PacketNumber:32 esp_mesh_send Time:  1ms
I (16122) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:32 Ping time:  4ms
I (16222) master: sending PacketNumber:33 esp_mesh_send Time:  2ms
I (16225) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:33 Ping time:  5ms
I (16323) master: sending PacketNumber:34 esp_mesh_send Time:  1ms
I (16326) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:34 Ping time:  4ms
I (16426) master: sending PacketNumber:35 esp_mesh_send Time:  2ms
I (16428) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:35 Ping time:  4ms
I (16531) master: sending PacketNumber:36 esp_mesh_send Time:  5ms
I (16533) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:36 Ping time:  7ms
I (16633) master: sending PacketNumber:37 esp_mesh_send Time:  2ms
I (16636) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:37 Ping time:  5ms
I (16735) master: sending PacketNumber:38 esp_mesh_send Time:  2ms
I (16738) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:38 Ping time:  5ms
I (16837) master: sending PacketNumber:39 esp_mesh_send Time:  2ms
I (16840) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:39 Ping time:  5ms
I (16939) master: sending PacketNumber:40 esp_mesh_send Time:  2ms
I (16941) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:40 Ping time:  4ms
I (17041) master: sending PacketNumber:41 esp_mesh_send Time:  2ms
I (17043) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:41 Ping time:  4ms
I (17143) master: sending PacketNumber:42 esp_mesh_send Time:  2ms
I (17146) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:42 Ping time:  5ms
I (17246) master: sending PacketNumber:43 esp_mesh_send Time:  2ms
I (17249) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:43 Ping time:  5ms
I (17347) master: sending PacketNumber:44 esp_mesh_send Time:  1ms
I (17350) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:44 Ping time:  4ms
I (17453) master: sending PacketNumber:45 esp_mesh_send Time:  5ms
I (17455) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:45 Ping time:  7ms
I (17555) master: sending PacketNumber:46 esp_mesh_send Time:  2ms
I (17558) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:46 Ping time:  5ms
I (17657) master: sending PacketNumber:47 esp_mesh_send Time:  2ms
I (17660) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:47 Ping time:  5ms
I (17759) master: sending PacketNumber:48 esp_mesh_send Time:  2ms
I (17762) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:48 Ping time:  5ms
I (17861) master: sending PacketNumber:49 esp_mesh_send Time:  2ms
I (17865) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:49 Ping time:  6ms
I (17963) master: sending PacketNumber:50 esp_mesh_send Time:  2ms
I (17966) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:50 Ping time:  5ms
I (18065) master: sending PacketNumber:51 esp_mesh_send Time:  2ms
I (18069) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:51 Ping time:  6ms
I (18168) master: sending PacketNumber:52 esp_mesh_send Time:  2ms
I (18170) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:52 Ping time:  4ms
I (18269) master: sending PacketNumber:53 esp_mesh_send Time:  1ms
I (18272) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:53 Ping time:  4ms
I (18375) master: sending PacketNumber:54 esp_mesh_send Time:  5ms
I (18378) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:54 Ping time:  8ms
I (18478) master: sending PacketNumber:55 esp_mesh_send Time:  2ms
I (18481) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:55 Ping time:  5ms
I (18580) master: sending PacketNumber:56 esp_mesh_send Time:  2ms
I (18583) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:56 Ping time:  5ms
I (18682) master: sending PacketNumber:57 esp_mesh_send Time:  2ms
I (18685) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:57 Ping time:  5ms
I (18784) master: sending PacketNumber:58 esp_mesh_send Time:  2ms
I (18787) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:58 Ping time:  5ms
I (18885) master: sending PacketNumber:59 esp_mesh_send Time:  1ms
I (18888) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:59 Ping time:  4ms
I (18988) master: sending PacketNumber:60 esp_mesh_send Time:  2ms
I (18991) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:60 Ping time:  5ms
I (19089) master: sending PacketNumber:61 esp_mesh_send Time:  1ms
I (19092) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:61 Ping time:  4ms
I (19192) master: sending PacketNumber:62 esp_mesh_send Time:  2ms
I (19195) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:62 Ping time:  5ms
I (19297) master: sending PacketNumber:63 esp_mesh_send Time:  5ms
I (19299) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:63 Ping time:  7ms
I (19399) master: sending PacketNumber:64 esp_mesh_send Time:  2ms
I (19402) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:64 Ping time:  5ms
I (19501) master: sending PacketNumber:65 esp_mesh_send Time:  2ms
I (19504) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:65 Ping time:  5ms
I (19603) master: sending PacketNumber:66 esp_mesh_send Time:  2ms
I (19606) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:66 Ping time:  5ms
I (19705) master: sending PacketNumber:67 esp_mesh_send Time:  2ms
I (19707) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:67 Ping time:  4ms
I (19807) master: sending PacketNumber:68 esp_mesh_send Time:  2ms
I (19809) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:68 Ping time:  4ms
I (19900) wifi:pm start, type: 1

I (19909) master: sending PacketNumber:69 esp_mesh_send Time:  2ms
I (19913) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:69 Ping time:  6ms
I (20206) wifi:AP's beacon interval = 307200 us, DTIM period = 1
I (20688) master: sending PacketNumber:70 esp_mesh_send Time:678ms
I (20692) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:70 Ping time:682ms
I (21172) master: sending PacketNumber:71 esp_mesh_send Time:383ms
I (21176) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:71 Ping time:387ms
I (21654) master: sending PacketNumber:72 esp_mesh_send Time:382ms
I (21657) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:72 Ping time:385ms
I (21955) mesh: 5151<active>parent layer:1(node), channel:11, rssi:-36, assoc:0(cnx rssi threshold:-120)my_assoc:0
I (23459) mesh: 5942<scan>parent layer:1, rssi:-37, assoc:1(cnx rssi threshold:-120)
I (23459) mesh: [SCAN][ch:11]AP:1, other(ID:0, RD:0), MAP:1, idle:0, candidate:1, root:1, topMAP:0[c:2,i:2][00:1f:1f:0a:4e:12]<weak>
I (23467) mesh: 7364[weak]try rssi_threshold:-120, backoff times:0, max:5<-78,-82,-85>
I (23474) mesh: 716[monitor]no change, parent:24:0a:c4:ee:a5:c9, rssi:-37
I (23481) mesh: 2004<arm>parent monitor, my layer:2(cap:6)(node), interval:9418ms, retries:2<>
I (24069) master: sending PacketNumber:73 esp_mesh_send Time:2314ms
I (24072) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:73 Ping time:2317ms
I (24546) master: sending PacketNumber:74 esp_mesh_send Time:377ms
I (24550) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:74 Ping time:381ms
I (25025) master: sending PacketNumber:75 esp_mesh_send Time:378ms
I (25028) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:75 Ping time:381ms
I (25507) master: sending PacketNumber:76 esp_mesh_send Time:382ms
I (25511) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:76 Ping time:386ms
I (25983) master: sending PacketNumber:77 esp_mesh_send Time:376ms
I (25986) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:77 Ping time:379ms
I (26462) master: sending PacketNumber:78 esp_mesh_send Time:378ms
I (26465) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:78 Ping time:381ms
I (26941) master: sending PacketNumber:79 esp_mesh_send Time:379ms
I (26944) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:79 Ping time:382ms
I (27444) master: sending PacketNumber:80 esp_mesh_send Time:403ms
I (27447) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:80 Ping time:406ms
I (27927) master: sending PacketNumber:81 esp_mesh_send Time:382ms
I (27930) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:81 Ping time:385ms
I (28402) master: sending PacketNumber:82 esp_mesh_send Time:374ms
I (28405) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:82 Ping time:377ms
I (28884) master: sending PacketNumber:83 esp_mesh_send Time:382ms
I (28888) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:83 Ping time:386ms
I (29360) master: sending PacketNumber:84 esp_mesh_send Time:376ms
I (29363) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:84 Ping time:379ms
I (29842) master: sending PacketNumber:85 esp_mesh_send Time:382ms
I (29846) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:85 Ping time:386ms
I (30318) master: sending PacketNumber:86 esp_mesh_send Time:376ms
I (30321) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:86 Ping time:379ms
I (30825) master: sending PacketNumber:87 esp_mesh_send Time:407ms
I (30829) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:87 Ping time:411ms
I (31309) master: sending PacketNumber:88 esp_mesh_send Time:383ms
I (31313) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:88 Ping time:387ms
I (31788) master: sending PacketNumber:89 esp_mesh_send Time:379ms
I (31792) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:89 Ping time:383ms
I (32268) master: sending PacketNumber:90 esp_mesh_send Time:380ms
I (32271) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:90 Ping time:383ms
I (32743) master: sending PacketNumber:91 esp_mesh_send Time:375ms
I (32746) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:91 Ping time:378ms
I (33134) mesh: 5151<active>parent layer:1(node), channel:11, rssi:-36, assoc:1(cnx rssi threshold:-120)my_assoc:0
I (33225) master: sending PacketNumber:92 esp_mesh_send Time:382ms
I (34638) mesh: 5942<scan>parent layer:1, rssi:-37, assoc:1(cnx rssi threshold:-120)
I (34638) mesh: [SCAN][ch:11]AP:1, other(ID:0, RD:0), MAP:1, idle:0, candidate:1, root:1, topMAP:0[c:0,i:2][00:1f:1f:0a:4e:12]<weak>
I (34646) mesh: 7364[weak]try rssi_threshold:-120, backoff times:0, max:5<-78,-82,-85>
I (34648) master: sending PacketNumber:93 esp_mesh_send Time:1322ms
I (34654) mesh: 716[monitor]no change, parent:24:0a:c4:ee:a5:c9, rssi:-37
I (34649) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:92 Ping time:1806ms
I (34667) mesh: 2004<arm>parent monitor, my layer:2(cap:6)(node), interval:11434ms, retries:3<>
I (34676) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:93 Ping time:1350ms
I (35129) master: sending PacketNumber:94 esp_mesh_send Time:368ms
I (35133) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:94 Ping time:372ms
I (35609) master: sending PacketNumber:95 esp_mesh_send Time:380ms
I (35613) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:95 Ping time:384ms
I (36085) master: sending PacketNumber:96 esp_mesh_send Time:376ms
I (36089) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:96 Ping time:380ms
I (36564) master: sending PacketNumber:97 esp_mesh_send Time:379ms
I (36567) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:97 Ping time:382ms

Disabled mesh PS function

I (12456) master: <MESH_EVENT_ROOT_ADDRESS>root address:24:0a:c4:ee:a5:c9
I (12460) mesh: [scan]new scanning time:600ms, beacon interval:300ms
I (12468) mesh: 2004<arm>parent monitor, my layer:2(cap:6)(node), interval:8751ms, retries:1<normal connected>
I (12475) master: <MESH_EVENT_PARENT_CONNECTED>layer:0-->2, parent:24:0a:c4:ee:a5:c9<layer2>, ID:77:77:77:77:77:77, duty:0
I (12486) master: <MESH_EVENT_TODS_REACHABLE>state:0
I (12702) wifi:AP's beacon interval = 307200 us, DTIM period = 1
W (12991) wifi:<ba-add>idx:0 (ifx:0, 24:0a:c4:ee:a5:c9), tid:5, ssn:0, winSize:64
I (12993) master: sending PacketNumber:0 esp_mesh_send Time:  7ms
I (12997) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:0 Ping time: 11ms
I (13097) master: sending PacketNumber:1 esp_mesh_send Time:  2ms
I (13100) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:1 Ping time:  5ms
I (13199) master: sending PacketNumber:2 esp_mesh_send Time:  2ms
I (13201) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:2 Ping time:  4ms
I (13301) master: sending PacketNumber:3 esp_mesh_send Time:  2ms
I (13303) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:3 Ping time:  4ms
I (13403) master: sending PacketNumber:4 esp_mesh_send Time:  2ms
I (13406) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:4 Ping time:  5ms
I (13504) master: sending PacketNumber:5 esp_mesh_send Time:  1ms
I (13507) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:5 Ping time:  4ms
I (13607) master: sending PacketNumber:6 esp_mesh_send Time:  2ms
I (13609) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:6 Ping time:  4ms
I (13709) master: sending PacketNumber:7 esp_mesh_send Time:  2ms
I (13712) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:7 Ping time:  5ms
I (13811) master: sending PacketNumber:8 esp_mesh_send Time:  2ms
I (13813) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:8 Ping time:  4ms
I (13915) master: sending PacketNumber:9 esp_mesh_send Time:  4ms
I (13917) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:9 Ping time:  6ms
I (14018) master: sending PacketNumber:10 esp_mesh_send Time:  2ms
I (14020) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:10 Ping time:  4ms
I (14120) master: sending PacketNumber:11 esp_mesh_send Time:  2ms
I (14122) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:11 Ping time:  4ms
I (14222) master: sending PacketNumber:12 esp_mesh_send Time:  2ms
I (14224) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:12 Ping time:  4ms
I (14324) master: sending PacketNumber:13 esp_mesh_send Time:  2ms
I (14327) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:13 Ping time:  5ms
I (14426) master: sending PacketNumber:14 esp_mesh_send Time:  2ms
I (14428) master: Rx data from:24:0a:c4:ee:a5:c8 size:1460 PacketNumber:14 Ping time:  4ms
shenjun7 commented 2 years ago

wifi:pm start, type: 1; duty:10; -> The node has turned on the power-save mode, wake up 10% time per cycle. So per-hop latency is rose up to hundreds of ms. If there is no need for low power consumption, please turn off the power-save mode to improve real-time performance. Also can adjust the duty to achieve a balance between power consumption and real-time performance.

Alvin1Zhang commented 2 years ago

Thanks for reporting, feel free to reopen.