esp-idf: MQTT publish outside of mqtt handler takes up to couple of seconds - now entirely stopped working (ESP32-S2) (IDFGH-4439)

Environment

• Development Kit: ESP32-S2 Saola-1
• Kit version: v1.2
• Module or chip used: ESP32-S2-WROVER
• IDF version: ESP-MDF with ESP-IDF v4.2-dev-2084-g98d5b5dfd-dirty ESP-IDF v4.3-dev-2136-gb0150615d
• Build System: idf.py
• Compiler version: xtensa-esp32-elf-gcc (crosstool-NG esp-2020r2) 8.2.0 xtensa-esp32-elf-gcc (crosstool-NG esp-2020r3) 8.4.0
• Operating System: Linux
• Using an IDE?: No
• Power Supply: USB or external 5V

Problem Description

The time of MQTT publish via esp_mqtt_client_publish() outside MQTT event handler varies between instant to a couple of seconds with weird repeating message in idf.py monitor. The repeating message is variation of

I (7592040) phy: pll_cap_ext 10

Expected Behavior

Instant or almost instant mqtt message publish without weird messages appearing on idf.py monitor.

Steps to reproduce

1. Configure MQTT broker URL & WiFi credentials in idf.py menuconfig
2. Build, flash & monitor the program
3. Make interrupt on GPIO pin 17
4. Watch the idf.py monitor

Code to reproduce this issue

GIST UPDATED

Debug Logs

--- idf_monitor on /dev/ttyUSB0 115200 ---
--- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H ---
�x�x��x����x����������x�x��ESP-ROM:esp32s2-rc4-20191025
Build:Oct 25 2019
rst:0x1 (POWERON),boot:0x8 (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:1
load:0x3ffe6100,len:0x8
load:0x3ffe6108,len:0x17f0
load:0x4004c000,len:0x9d8
load:0x40050000,len:0x2e08
entry 0x4004c1ec
I (46) boot: ESP-IDF v4.3-dev-2136-gb0150615d 2nd stage bootloader
I (46) boot: compile time 06:38:21
I (46) boot: chip revision: 0
I (49) boot.esp32s2: SPI Speed      : 80MHz
I (54) boot.esp32s2: SPI Mode       : DIO
I (59) boot.esp32s2: SPI Flash Size : 2MB
I (63) boot: Enabling RNG early entropy source...
I (69) boot: Partition Table:
I (72) boot: ## Label            Usage          Type ST Offset   Length
I (80) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (87) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (94) boot:  2 factory          factory app      00 00 00010000 00100000
I (102) boot: End of partition table
I (106) esp_image: segment 0: paddr=00010020 vaddr=3f000020 size=1e874h (125044) map
I (141) esp_image: segment 1: paddr=0002e89c vaddr=3ffc8860 size=0177ch (  6012) load
I (143) esp_image: segment 2: paddr=00030020 vaddr=40080020 size=88878h (559224) map
I (263) esp_image: segment 3: paddr=000b88a0 vaddr=3ffc9fdc size=02314h (  8980) load
I (266) esp_image: segment 4: paddr=000babbc vaddr=40024000 size=00404h (  1028) load
I (269) esp_image: segment 5: paddr=000bafc8 vaddr=40024404 size=14450h ( 83024) load
I (311) boot: Loaded app from partition at offset 0x10000
I (311) boot: Disabling RNG early entropy source...
I (323) cache: Instruction cache 	: size 8KB, 4Ways, cache line size 32Byte
I (323) cpu_start: Pro cpu up.
I (376) cpu_start: Pro cpu start user code
I (376) cpu_start: cpu freq: 160000000
I (377) cpu_start: Application information:
I (379) cpu_start: Project name:     imp
I (384) cpu_start: App version:      1
I (388) cpu_start: Compile time:     Dec 15 2020 06:38:13
I (394) cpu_start: ELF file SHA256:  ee539ffa585b5eea...
I (400) cpu_start: ESP-IDF:          v4.3-dev-2136-gb0150615d
I (407) heap_init: Initializing. RAM available for dynamic allocation:
I (414) heap_init: At 3FF9E000 len 00002000 (8 KiB): RTCRAM
I (420) heap_init: At 3FFD0058 len 0002BFA8 (175 KiB): DRAM
I (426) heap_init: At 3FFFC000 len 00003A10 (14 KiB): DRAM
I (433) spi_flash: detected chip: generic
I (437) spi_flash: flash io: dio
W (441) spi_flash: Detected size(4096k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (458) cpu_start: Starting scheduler on PRO CPU.
I (460) IMP Motion sensor: [APP] Startup..
I (460) IMP Motion sensor: [APP] Free memory: 186212 bytes
I (470) IMP Motion sensor: [APP] IDF version: v4.3-dev-2136-gb0150615d
I (490) gpio: GPIO[17]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 1| Intr:1 
I (500) wifi:wifi driver task: 3ffd6fe0, prio:23, stack:6656, core=0
I (500) system_api: Base MAC address is not set
I (500) system_api: read default base MAC address from EFUSE
I (520) wifi:wifi firmware version: e1e57aa
I (520) wifi:wifi certification version: v7.0
I (520) wifi:config NVS flash: enabled
I (520) wifi:config nano formating: disabled
I (520) wifi:Init data frame dynamic rx buffer num: 32
I (530) wifi:Init management frame dynamic rx buffer num: 32
I (530) wifi:Init management short buffer num: 32
I (540) wifi:Init dynamic tx buffer num: 32
I (540) wifi:Init static rx buffer size: 1600
I (550) wifi:Init static rx buffer num: 10
I (550) wifi:Init dynamic rx buffer num: 32
I (550) wifi_init: rx ba win: 6
I (560) wifi_init: tcpip mbox: 32
I (560) wifi_init: udp mbox: 6
I (560) wifi_init: tcp mbox: 6
I (570) wifi_init: tcp tx win: 5744
I (570) wifi_init: tcp rx win: 5744
I (580) wifi_init: tcp mss: 1440
I (580) wifi_init: WiFi IRAM OP enabled
I (590) wifi_init: WiFi RX IRAM OP enabled
I (590) example_connect: Connecting to WIFI...
I (710) phy: phy_version: 603, 72dfd77, Jul  7 2020, 19:57:05, 0, 2
I (710) wifi:mode : sta (7c:df:a1:05:fc:d2)
I (710) wifi:enable tsf
I (710) example_connect: Waiting for IP(s)
I (840) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
I (2180) wifi:state: init -> auth (b0)
I (2200) wifi:state: auth -> assoc (0)
I (2200) wifi:state: assoc -> run (10)
I (2210) wifi:connected with WIFI, aid = 3, channel 1, BW20, bssid = 18:e8:29:fb:0d:4e
I (2210) wifi:security: WPA2-PSK, phy: bgn, rssi: -43
I (2210) wifi:pm start, type: 1

W (2220) wifi:<ba-add>idx:0 (ifx:0, 18:e8:29:fb:0d:4e), tid:0, ssn:0, winSize:64
I (2280) wifi:AP's beacon interval = 102400 us, DTIM period = 3
I (3190) esp_netif_handlers: example_connect: sta ip: 192.168.0.154, mask: 255.255.255.0, gw: 192.168.0.1
I (3190) example_connect: Got IPv4 event: Interface "example_connect: sta" address: 192.168.0.154
I (3480) example_connect: Got IPv6 event: Interface "example_connect: sta" address: fe80:0000:0000:0000:7edf:a1ff:fe05:fcd2, type: ESP_IP6_ADDR_IS_LINK_LOCAL
I (3480) example_connect: Connected to example_connect: sta
I (3490) example_connect: - IPv4 address: 192.168.0.154
I (3490) example_connect: - IPv6 address: fe80:0000:0000:0000:7edf:a1ff:fe05:fcd2, type: ESP_IP6_ADDR_IS_LINK_LOCAL
I (3510) Motion sensor: Other event id:7
I (4440) Motion sensor: MQTT_EVENT_CONNECTED
I (4440) Motion sensor: sent publish successful, msg_id=23729
I (4450) Motion sensor: sent subscribe successful, msg_id=21965
I (4470) Motion sensor: MQTT_EVENT_PUBLISHED, msg_id=23729
I (4510) Motion sensor: MQTT_EVENT_SUBSCRIBED, msg_id=21965
I (13510) Motion sensor: [GPIO] sent publish successful, msg_id=58815
GPIO[17] intr, val: 1
I (13510) phy: pll_cap_ext 10
I (13520) phy: pll_cap_ext 10
I (13530) phy: pll_cap_ext 10
I (13540) phy: pll_cap_ext 10
I (13550) phy: pll_cap_ext 10
I (13560) phy: pll_cap_ext 10
I (13560) phy: pll_cap_ext 10
I (13570) phy: pll_cap_ext 10
I (13570) phy: pll_cap_ext 10

... // many times repeats

I (15250) phy: pll_cap_ext 10
I (15250) phy: pll_cap_ext 10
I (15260) phy: pll_cap_ext 10
I (15260) phy: pll_cap_ext 10
I (15260) phy: pll_cap_ext 10
I (15320) Motion sensor: MQTT_EVENT_PUBLISHED, msg_id=58815
I (19510) Motion sensor: [GPIO] sent publish successful, msg_id=8655