search

zephyrproject-rtos / zephyr

Primary Git Repository for the Zephyr Project. Zephyr is a new generation, scalable, optimized, secure RTOS for multiple hardware architectures.
https://docs.zephyrproject.org
Apache License 2.0
9.98k stars 6.15k forks source link

ESP32-S3 WiFi Triggers ASSERT in do_swap() due to interrupts being disabled #74277

Closed EricNRS closed 1 day ago

EricNRS commented 2 weeks ago

Describe the bug If asserts are enabled globally (CONFIG_ASSERT=y), then connecting to a WiFi access point will result in a failed assertion. With asserts disabled, the connection is successful.

To Reproduce Build and run the example on an ESP32-S3. No SPIRAM is used here, so this should apply to all targets.

west build --pristine -b xiao_esp32s3/esp32s3/procpu samples/net/wifi -DCONFIG_ASSERT=y -DCONFIG_HEAP_MEM_POOL_SIZE=85000 && west flash && west espressif monitor Connect to WiFi and notice that the system crashes:

*** Booting Zephyr OS build v3.6.0-5736-gd78a9429450f ***
uart:~$ wifi connect -s "SSID" -p PASSWORD -k 1
Connection requested
[00:02:04.100,000] <err> os:  **  PC 0x40378c4f VADDR 0
0x40378c4f: xtensa_arch_except_epc at /home/work/zephyrproject-3.6/zephyr/arch/xtensa/core/xtensa_asm2_util.S:209

[00:02:04.101,000] <err> os:  ** A12 0x3fc9f640 A13 0x4 A14 0 A15 0x3fc9f720
[00:02:04.103,000] <err> os:  ** A12 0x3fc9f428 A13 0x4 A14 0x3fc9f438 A15 0xc
[00:02:04.105,000] <err> os:  ** A12 0x3fc9f230 A13 0x4 A14 0xff0000 A15 0xff000000
[00:02:04.107,000] <err> os:  ** A12 0x3fc9f038 A13 0x4 A14 0xff0000 A15 0xff000000
[00:02:04.109,000] <err> os:  ** A12 0x3fc9ee40 A13 0x4 A14 0xff0000 A15 0xff000000
[00:02:04.111,000] <err> os:  ** A12 0x3fc9ec48 A13 0x4 A14 0xff0000 A15 0xff000000
[00:02:04.113,000] <err> os:  ** A12 0x3fc9ea50 A13 0x4 A14 0xff0000 A15 0xff000000
[00:02:04.115,000] <err> os:  ** A12 0x3fc9e858 A13 0x4 A14 0xff0000 A15 0xff000000
[00:02:04.117,000] <err> os:  ** A12 0x3fc9e660 A13 0x4 A14 0xff0000 A15 0xff000000
[00:02:04.119,000] <err> os:  ** A12 0x3fc9e468 A13 0x4 A14 0xff0000 A15 0xff000000
[00:02:04.121,000] <err> os:  ** A12 0x3fc9e270 A13 0x4 A14 0xff0000 A15 0xff000000
[00:02:04.123,000] <err> os:  ** A12 0x3fc9e078 A13 0x4 A14 0xff0000 A15 0xff000000
[00:02:04.125,000] <err> os:  ** A12 0x3fc9de80 A13 0x4 A14 0xff0000 A15 0xff000000
[00:02:04.127,000] <err> os:  ** A12 0x3fc9dc88 A13 0x4 A14 0xff0000 A15 0xff000000
[00:02:04.129,000] <err> os:  ** A12 0x3fc9da90 A13 0x4 A14 0xff0000 A15 0xff000000
[00:02:04.131,000] <err> os:  ** A12 0x3fc9d898 A13 0x4 A14 0xff0000 A15 0xff000000
[00:02:04.133,000] <err> os:  ** A12 0x3fc9d6a0 A13 0x4 A14 0xff0000 A15 0xff000000
[00:02:04.135,000] <err> os:  ** A12 0x3fc9d4a8 A13 0x4 A14 0xff0000 A15 0xff000000
[00:02:04.137,000] <err> os:  ** A12 0x3fc9d2b0 A13 0x4 A14 0xff0000 A15 0xff000000
[00:02:04.139,000] <err> os:  ** A12 0x3fc9d0b8 A13 0x4 A14 0xff0000 A15 0xff000000
[00:02:04.141,000] <err> os:  ** A12 0x3fc9cec0 A13 0x4 A14 0xff0000 A15 0xff000000
[00:02:04.143,000] <err> os:  ** A12 0x3fc9ccc8 A13 0x4 A14 0xff0000 A15 0xff000000
[00:02:04.145,000] <err> os:  ** A12 0x3fc9cad0 A13 0x4 A14 0xff0000 A15 0xff000000
[00:02:04.147,000] <err> os:  ** A12 0x3fc9c8d8 A13 0x4 A14 0xff0000 A15 0xff000000
[00:02:04.149,000] <err> os:  ** A12 0x3fc9c6e0 A13 0x4 A14 0xff0000 A15 0xff000000
[00:02:04.151,000] <err> os:  ** A12 0x3fc9c4e8 A13 0x4 A14 0xff0000 A15 0xff000000
[00:02:04.153,000] <err> os:  ** A12 0x3fc9c2f0 A13 0x4 A14 0xff0000 A15 0xff000000
[00:02:04.155,000] <err> os:  ** A12 0x3fc9c0f8 A13 0x4 A14 0xff0000 A15 0xff000000
[00:02:04.157,000] <err> os:  ** A12 0x3fc9bf00 A13 0x4 A14 0xff0000 A15 0xff000000
[00:02:04.159,000] <err> os:  ** A12 0x3fc9bd08 A13 0x4 A14 0xff0000 A15 0xff000000
[00:02:04.161,000] <err> os:  ** A12 0x3fc9bb10 A13 0x4 A14 0xff0000 A15 0xff000000
[00:02:04.163,000] <err> os:  ** A12 0x3fc9b918 A13 0x4 A14 0xff0000 A15 0xff000000
[00:02:04.165,000] <err> os:  ** A12 0x3fc9b720 A13 0x4 A14 0xff0000 A15 0xff000000
[00:02:04.167,000] <err> os:  ** A12 0x3fc9b528 A13 0x4 A14 0xff0000 A15 0xff000000
[00:02:04.169,000] <err> os:  ** A12 0x3fc9b330 A13 0x4 A14 0xff0000 A15 0xff000000
[00:02:04.171,000] <err> > > > > > > > > > > > > > > > :  ** A12 0x3fc9b138 A13 0x4 A14 0xff0000 A15 0xff000000

With verbose asserts enabled and debug code enabled: ASSERTION FAIL [arch_irq_unlocked(key) || _kernel.cpus[0].current->base.thread_state & (((1UL << (0))) | ((1UL << (3))))] @ WEST_TOPDIR/zephyr/kernel/include/kswap.h:99

Here is the do_swap() code that triggers the assertion.

static ALWAYS_INLINE unsigned int do_swap(unsigned int key,
                      struct k_spinlock *lock,
                      bool is_spinlock)
{
    ARG_UNUSED(lock);
    struct k_thread *new_thread, *old_thread;

#ifdef CONFIG_SPIN_VALIDATE
    /* Make sure the key acts to unmask interrupts, if it doesn't,
     * then we are context switching out of a nested lock
     * (i.e. breaking the lock of someone up the stack) which is
     * forbidden!  The sole exception are dummy threads used
     * during initialization (where we start with interrupts
     * masked and switch away to begin scheduling) and the case of
     * a dead current thread that was just aborted (where the
     * damage was already done by the abort anyway).
     *
     * (Note that this is disabled on ARM64, where system calls
     * can sometimes run with interrupts masked in ways that don't
     * represent lock state.  See #35307)
     */
# ifndef CONFIG_ARM64
    __ASSERT(arch_irq_unlocked(key) ||
         _current->base.thread_state & (_THREAD_DUMMY | _THREAD_DEAD),
         "Context switching while holding lock!");
# endif /* CONFIG_ARM64 */
#endif /* CONFIG_SPIN_VALIDATE */

The same test without the assert works: west build --pristine -b xiao_esp32s3/esp32s3/procpu samples/net/wifi -DCONFIG_HEAP_MEM_POOL_SIZE=85000 && west flash && west espressif monitor

Expected behavior Connecting to WiFi should be possible with debug ASSERTs enabled.

Impact This is a showstopper since it is causing the system to crash whenever ASSERTS are enabled. If the ASSERT is disabled, then the system crashes in other places randomly.

Environment (please complete the following information): Zephyr 3.6.99 at commit d78a9429450f89de7829c8af7efe41fdb692fd50

EricNRS commented 2 weeks ago

Adding a breakpoint to the failed assertion provides the bracktrace below. Note that the ppTask() function that appears to be holding the lock is in the ESP32-S3 ROM, so I am not able to do any further debugging.

Thread 7 "wifi" received signal SIGTRAP, Trace/breakpoint trap.
[Switching to Thread 1070403216]
(gdb) bt
#0  do_swap (is_spinlock=true, lock=0x3fcbe2cc <_sched_spinlock>, key=396579)
    at /home/work/zephyrproject-3.6/zephyr/kernel/include/kswap.h:101
#1  z_swap (lock=0x3fcbe2cc <_sched_spinlock>, key=...) at /home/work/zephyrproject-3.6/zephyr/kernel/include/kswap.h:192
#2  0x4037bb71 in z_pend_curr (lock=0x3fca1298 <kheap.system_heap+2936>, key=..., wait_q=0x3fca1290 <kheap.system_heap+2928>, timeout=...)
    at /home/work/zephyrproject-3.6/zephyr/kernel/sched.c:696
#3  0x40379fb8 in z_impl_k_msgq_get (msgq=0x3fca1290 <kheap.system_heap+2928>, data=0x3fc9c4e0 <wifi_stack+3520>, timeout=...)
    at /home/work/zephyrproject-3.6/zephyr/kernel/msg_q.c:272
#4  0x42009abc in k_msgq_get (timeout=..., data=<optimized out>, msgq=<optimized out>)
    at /home/work/zephyrproject-3.6/zephyr/build/zephyr/include/generated/zephyr/syscalls/kernel.h:1207
#5  queue_recv_wrapper (queue=0x3fca1290 <kheap.system_heap+2928>, item=0x3fc9c4e0 <wifi_stack+3520>, block_time_tick=4294967295)
    at /home/work/zephyrproject-3.6/modules/hal/espressif/zephyr/esp32s3/src/wifi/esp_wifi_adapter.c:386
#6  0x4038564c in ppTask ()
#7  0x42003618 in z_thread_entry (entry=0x40385620 <ppTask>, p1=0x0, p2=0x0, p3=0x0)
    at /home/work/zephyrproject-3.6/zephyr/lib/os/thread_entry.c:48
EricNRS commented 2 weeks ago

@sylvioalves

EricNRS commented 1 week ago

Just ran into another assert in the I2C code which may be related to this. In this case, the assertion for arch_is_in_isr() failed since the timeout option is a compile-time constant of 500ms.

Line being executed that fails: ret = k_sem_take(&data->cmd_sem, K_MSEC(I2C_TRANSFER_TIMEOUT_MSEC));

Backtrace:

ASSERTION FAIL [((arch_is_in_isr() == 0) || ((timeout).ticks == (((k_timeout_t) {0})).ticks))] @ WEST_TOPDIR/zephyr/kernel/sem.c:136

Line 136 of "/home/work/zephyrproject-3.6/zephyr/kernel/sem.c" starts at address 0x4037f0d9 <z_impl_k_sem_take+21>
   and ends at 0x4037f108 <z_impl_k_sem_take+68>.
Line 1103 of "/home/work/zephyrproject-3.6/zephyr/build/zephyr/include/generated/zephyr/syscalls/kernel.h"
   starts at address 0x40378ce3 <i2c_esp32_transmit+59> and ends at 0x40378ce9 <i2c_esp32_transmit+65>.
Line 453 of "/home/work/zephyrproject-3.6/zephyr/drivers/i2c/i2c_esp32.c" starts at address 0x40378e08 <i2c_esp32_write_addr+212>
   and ends at 0x40378e0b <i2c_esp32_write_addr+215>.
Line 516 of "/home/work/zephyrproject-3.6/zephyr/drivers/i2c/i2c_esp32.c" starts at address 0x40378ffb <i2c_esp32_read_msg+39>
   and ends at 0x40379004 <i2c_esp32_read_msg+48>.
Line 690 of "/home/work/zephyrproject-3.6/zephyr/drivers/i2c/i2c_esp32.c" starts at address 0x4037942f <i2c_esp32_transfer+243>
   and ends at 0x4037943a <i2c_esp32_transfer+254>.
Line 788 of "/home/work/zephyrproject-3.6/zephyr/include/zephyr/drivers/i2c.h" starts at address 0x4207a012 <i2c_write_read+50>
   and ends at 0x4207a015 <i2c_write_read+53>.
Line 1387 of "/home/work/zephyrproject-3.6/zephyr/include/zephyr/drivers/i2c.h" starts at address 0x4207a04b <i2c_burst_read_dt+31>
   and ends at 0x4207a051 <i2c_burst_read_dt+37>.
Line 31 of "/home/work/zephyrproject-3.6/zephyr/drivers/sensor/ti/ina23x/ina23x_common.c"
   starts at address 0x4207a0c8 <ina23x_reg_read_16+16> and ends at 0x4207a0d4 <ina23x_reg_read_16+28>.
Line 150 of "/home/work/zephyrproject-3.6/zephyr/drivers/sensor/ti/ina23x/ina237.c" starts at address 0x4207aae2 <ina237_read_data+46>
   and ends at 0x4207aaed <ina237_read_data+57>.
Line 218 of "/home/work/zephyrproject-3.6/zephyr/drivers/sensor/ti/ina23x/ina237.c"
   starts at address 0x4207ae2c <ina237_sample_fetch+96> and ends at 0x4207ae33 <ina237_sample_fetch+103>.
. . .
EricNRS commented 4 days ago

Just had another I2C failure due to __ASSERT(arch_is_in_isr() == false) failing. I was able to capture a TRAX trace from this and going through each line, I didn't see any place where locks were not being properly released and the code was not being called in ISR context.

Percepio Tracealyzer shows that the esp_timer was active just before this sequence, so this looks to be the same WiFi issue where interrupts are getting disabled in the WiFi blob libpp.a or somewhere else in the sequence.

i2c_esp32_read_msg()
 -> i2c_esp32_master_read()
     -> i2c_esp32_transmit()

Line 337 of "/home/work/zephyrproject-3.6/zephyr/arch/xtensa/core/vector_handlers.c" starts at address 0x4037c81c <xtensa_int1_c+20> and ends at 0x4037c81f <xtensa_int1_c+23>.
Line 337 of "/home/work/zephyrproject-3.6/zephyr/arch/xtensa/core/vector_handlers.c" starts at address 0x4037c825 <xtensa_int1_c+29> and ends at 0x4037c838 <xtensa_int1_c+48>.
Line 121 of "/home/work/zephyrproject-3.6/zephyr/soc/espressif/common/include/_soc_inthandlers.h" starts at address 0x4037c538 <_xtensa_handle_one_int1> and ends at 0x4037c53b <_xtensa_handle_one_int1+3>.
Line 167 of "/home/work/zephyrproject-3.6/zephyr/soc/espressif/common/include/_soc_inthandlers.h" starts at address 0x4037c57c <_xtensa_handle_one_int1+68> and ends at 0x4037c57f <_xtensa_handle_one_int1+71>.
Line 192 of "/home/work/zephyrproject-3.6/zephyr/soc/espressif/common/include/_soc_inthandlers.h" starts at address 0x4037c5a0 <_xtensa_handle_one_int1+104> and ends at 0x4037c5a3 <_xtensa_handle_one_int1+107>.
Line 204 of "/home/work/zephyrproject-3.6/zephyr/soc/espressif/common/include/_soc_inthandlers.h" starts at address 0x4037c5b1 <_xtensa_handle_one_int1+121> and ends at 0x4037c5b4 <_xtensa_handle_one_int1+124>.
Line 211 of "/home/work/zephyrproject-3.6/zephyr/soc/espressif/common/include/_soc_inthandlers.h" starts at address 0x4037c5ba <_xtensa_handle_one_int1+130> and ends at 0x4037c5bc <_xtensa_handle_one_int1+132>.
Line 219 of "/home/work/zephyrproject-3.6/zephyr/soc/espressif/common/include/_soc_inthandlers.h" starts at address 0x4037c62b <_xtensa_handle_one_int1+243> and ends at 0x4037c631 <_xtensa_handle_one_int1+249>.
Line 706 of "/home/work/zephyrproject-3.6/zephyr/drivers/i2c/i2c_esp32.c" starts at address 0x40379854 <i2c_esp32_isr> and ends at 0x40379857 <i2c_esp32_isr+3>.
Line 713 of "/home/work/zephyrproject-3.6/zephyr/drivers/i2c/i2c_esp32.c" starts at address 0x40379880 <i2c_esp32_isr+44> and ends at 0x40379886 <i2c_esp32_isr+50>.
Line 33 of "/home/work/zephyrproject-3.6/modules/hal/espressif/components/hal/i2c_hal_iram.c" starts at address 0x4038c67c <i2c_hal_master_handle_rx_event> and ends at 0x4038c67f <i2c_hal_master_handle_rx_event+3>.
Line 808 of "/home/work/zephyrproject-3.6/modules/hal/espressif/zephyr/esp32s3/../../components/hal/esp32s3/include/hal/i2c_ll.h" starts at address 0x4038c6b0 <i2c_hal_master_handle_rx_event+52> and ends at 0x4038c6b5 <i2c_hal_master_handle_rx_event+57>.
Line 810 of "/home/work/zephyrproject-3.6/modules/hal/espressif/zephyr/esp32s3/../../components/hal/esp32s3/include/hal/i2c_ll.h" starts at address 0x4038c6c0 <i2c_hal_master_handle_rx_event+68> and ends at 0x4038c6c5 <i2c_hal_master_handle_rx_event+73>.
Line 812 of "/home/work/zephyrproject-3.6/modules/hal/espressif/zephyr/esp32s3/../../components/hal/esp32s3/include/hal/i2c_ll.h" starts at address 0x4038c6d0 <i2c_hal_master_handle_rx_event+84> and ends at 0x4038c6d5 <i2c_hal_master_handle_rx_event+89>.
Line 38 of "/home/work/zephyrproject-3.6/modules/hal/espressif/components/hal/i2c_hal_iram.c" starts at address 0x4038c6f2 <i2c_hal_master_handle_rx_event+118> and ends at 0x4038c6f4 <i2c_hal_master_handle_rx_event+120>.
Line 42 of "/home/work/zephyrproject-3.6/modules/hal/espressif/components/hal/i2c_hal_iram.c" starts at address 0x4038c72c <i2c_hal_master_handle_rx_event+176> and ends at 0x4038c72f <i2c_hal_master_handle_rx_event+179>.
Line 46 of "/home/work/zephyrproject-3.6/modules/hal/espressif/components/hal/i2c_hal_iram.c" starts at address 0x4038c737 <i2c_hal_master_handle_rx_event+187> and ends at 0x4038c74c <wdt_hal_init>.
Line 717 of "/home/work/zephyrproject-3.6/zephyr/drivers/i2c/i2c_esp32.c" starts at address 0x40379891 <i2c_esp32_isr+61> and ends at 0x40379893 <i2c_esp32_isr+63>.
Line 719 of "/home/work/zephyrproject-3.6/zephyr/drivers/i2c/i2c_esp32.c" starts at address 0x403798a0 <i2c_esp32_isr+76> and ends at 0x403798a3 <i2c_esp32_isr+79>.
Line 721 of "/home/work/zephyrproject-3.6/zephyr/drivers/i2c/i2c_esp32.c" starts at address 0x403798ad <i2c_esp32_isr+89> and ends at 0x403798b0 <i2c_esp32_isr+92>.
Line 723 of "/home/work/zephyrproject-3.6/zephyr/drivers/i2c/i2c_esp32.c" starts at address 0x403798bc <i2c_esp32_isr+104> and ends at 0x403798bf <i2c_esp32_isr+107>.
Line 727 of "/home/work/zephyrproject-3.6/zephyr/drivers/i2c/i2c_esp32.c" starts at address 0x403798c6 <i2c_esp32_isr+114> and ends at 0x403798c9 <i2c_esp32_isr+117>.
Line 97 of "/home/work/zephyrproject-3.6/zephyr/kernel/sem.c" starts at address 0x4037f850 <z_impl_k_sem_give> and ends at 0x4037f853 <z_impl_k_sem_give+3>.
Line 10 of "/home/work/zephyrproject-3.6/zephyr/kernel/spinlock_validate.c" starts at address 0x403836a4 <z_spin_lock_valid> and ends at 0x403836a7 <z_spin_lock_valid+3>.
Line 18 of "/home/work/zephyrproject-3.6/zephyr/kernel/spinlock_validate.c" starts at address 0x403836c9 <z_spin_lock_valid+37> and ends at 0x403836cb <z_spin_lock_valid+39>.
Line 19 of "/home/work/zephyrproject-3.6/zephyr/kernel/spinlock_validate.c" starts at address 0x403836d1 <z_spin_lock_valid+45> and ends at 0x403836e6 <z_spin_lock_valid+66>.
Line 19 of "/home/work/zephyrproject-3.6/zephyr/kernel/spinlock_validate.c" starts at address 0x403836e6 <z_spin_lock_valid+66> and ends at 0x403836e8 <z_spin_unlock_valid>.
Line 136 of "/home/work/zephyrproject-3.6/zephyr/include/zephyr/spinlock.h" starts at address 0x4037f863 <z_impl_k_sem_give+19> and ends at 0x4037f86b <z_impl_k_sem_give+27>.
Line 147 of "/home/work/zephyrproject-3.6/zephyr/include/zephyr/spinlock.h" starts at address 0x4037f896 <z_impl_k_sem_give+70> and ends at 0x4037f89c <z_impl_k_sem_give+76>.
Line 38 of "/home/work/zephyrproject-3.6/zephyr/kernel/spinlock_validate.c" starts at address 0x40383744 <z_spin_lock_set_owner> and ends at 0x40383747 <z_spin_lock_set_owner+3>.
Line 40 of "/home/work/zephyrproject-3.6/zephyr/kernel/spinlock_validate.c" starts at address 0x40383764 <z_spin_lock_set_owner+32> and ends at 0x40383776.
Line 102 of "/home/work/zephyrproject-3.6/zephyr/kernel/sem.c" starts at address 0x4037f89c <z_impl_k_sem_give+76> and ends at 0x4037f8a4 <z_impl_k_sem_give+84>.
. . .

# Validate spinlock, arch irq unlock and switch to I2C thread
Line 146 of "/home/work/zephyrproject-3.6/zephyr/include/zephyr/arch/xtensa/irq.h" starts at address 0x40381c13 <z_ready_thread+151> and ends at 0x40381c19 <z_ready_thread+157>.
Line 406 of "/home/work/zephyrproject-3.6/zephyr/kernel/sched.c" starts at address 0x40381c1e <z_ready_thread+162> and ends at 0x40381c33.
Line 108 of "/home/work/zephyrproject-3.6/zephyr/kernel/sem.c" starts at address 0x4037f8b4 <z_impl_k_sem_give+100> and ends at 0x4037f8b8 <z_impl_k_sem_give+104>.
Line 115 of "/home/work/zephyrproject-3.6/zephyr/kernel/sem.c" starts at address 0x4037f8d3 <z_impl_k_sem_give+131> and ends at 0x4037f8db <z_impl_k_sem_give+139>.
Line 813 of "/home/work/zephyrproject-3.6/zephyr/kernel/sched.c" starts at address 0x40382914 <z_reschedule> and ends at 0x40382917 <z_reschedule+3>.
Line 305 of "/home/work/zephyrproject-3.6/zephyr/include/zephyr/spinlock.h" starts at address 0x40382948 <z_reschedule+52> and ends at 0x40382951 <z_reschedule+61>.
Line 22 of "/home/work/zephyrproject-3.6/zephyr/kernel/spinlock_validate.c" starts at address 0x403836e8 <z_spin_unlock_valid> and ends at 0x403836eb <z_spin_unlock_valid+3>.
Line 31 of "/home/work/zephyrproject-3.6/zephyr/kernel/spinlock_validate.c" starts at address 0x40383711 <z_spin_unlock_valid+41> and ends at 0x40383717 <z_spin_unlock_valid+47>.
Line 35 of "/home/work/zephyrproject-3.6/zephyr/kernel/spinlock_validate.c" starts at address 0x4038372c <z_spin_unlock_valid+68> and ends at 0x40383732 <z_spin_unlock_valid+74>.
Line 35 of "/home/work/zephyrproject-3.6/zephyr/kernel/spinlock_validate.c" starts at address 0x40383732 <z_spin_unlock_valid+74> and ends at 0x40383743.
Line 305 of "/home/work/zephyrproject-3.6/zephyr/include/zephyr/spinlock.h" starts at address 0x40382948 <z_reschedule+52> and ends at 0x40382951 <z_reschedule+61>.
Line 146 of "/home/work/zephyrproject-3.6/zephyr/include/zephyr/arch/xtensa/irq.h" starts at address 0x4038297b <z_reschedule+103> and ends at 0x40382981 <z_reschedule+109>.
Line 820 of "/home/work/zephyrproject-3.6/zephyr/kernel/sched.c" starts at address 0x40382989 <z_reschedule+117> and ends at 0x40382996.
Line 120 of "/home/work/zephyrproject-3.6/zephyr/kernel/sem.c" starts at address 0x4037f8db <z_impl_k_sem_give+139> and ends at 0x4037f8f0 <z_impl_k_sem_take>.
Line 120 of "/home/work/zephyrproject-3.6/zephyr/kernel/sem.c" starts at address 0x4037f8db <z_impl_k_sem_give+139> and ends at 0x4037f8f0 <z_impl_k_sem_take>.
*** Exception occurred ***
Line 162 of "/home/work/zephyrproject-3.6/zephyr/arch/xtensa/core/window_vectors.S" starts at address 0x403740c0 <_WindowUnderflow8> and ends at 0x403740c3 <_WindowUnderflow8+3>.
Line 120 of "/home/work/zephyrproject-3.6/zephyr/kernel/sem.c" starts at address 0x4037f8db <z_impl_k_sem_give+139> and ends at 0x4037f8f0 <z_impl_k_sem_take>.
Line 728 of "/home/work/zephyrproject-3.6/zephyr/drivers/i2c/i2c_esp32.c" starts at address 0x403798cc <i2c_esp32_isr+120> and ends at 0x403798d5 <i2c_esp32_isr+129>.
Line 728 of "/home/work/zephyrproject-3.6/zephyr/drivers/i2c/i2c_esp32.c" starts at address 0x403798d5 <i2c_esp32_isr+129> and ends at 0x403798e2.
*** Exception occurred ***
Line 162 of "/home/work/zephyrproject-3.6/zephyr/arch/xtensa/core/window_vectors.S" starts at address 0x403740c0 <_WindowUnderflow8> and ends at 0x403740c3 <_WindowUnderflow8+3>.

# i2c_esp32_isr():  k_sem_give(&data->cmd_sem) call complete
Line 728 of "/home/work/zephyrproject-3.6/zephyr/drivers/i2c/i2c_esp32.c" starts at address 0x403798d5 <i2c_esp32_isr+129> and ends at 0x403798e2.
Line 220 of "/home/work/zephyrproject-3.6/zephyr/soc/espressif/common/include/_soc_inthandlers.h" starts at address 0x4037c638 <_xtensa_handle_one_int1+256> and ends at 0x4037c63c <_xtensa_handle_one_int1+260>.
Line 221 of "/home/work/zephyrproject-3.6/zephyr/soc/espressif/common/include/_soc_inthandlers.h" starts at address 0x4037c63f <_xtensa_handle_one_int1+263> and ends at 0x4037c656.
Line 221 of "/home/work/zephyrproject-3.6/zephyr/soc/espressif/common/include/_soc_inthandlers.h" starts at address 0x4037c63f <_xtensa_handle_one_int1+263> and ends at 0x4037c656.
*** Exception occurred ***
Line 162 of "/home/work/zephyrproject-3.6/zephyr/arch/xtensa/core/window_vectors.S" starts at address 0x403740c0 <_WindowUnderflow8> and ends at 0x403740c3 <_WindowUnderflow8+3>.
Line 221 of "/home/work/zephyrproject-3.6/zephyr/soc/espressif/common/include/_soc_inthandlers.h" starts at address 0x4037c63f <_xtensa_handle_one_int1+263> and ends at 0x4037c656.
Line 337 of "/home/work/zephyrproject-3.6/zephyr/arch/xtensa/core/vector_handlers.c" starts at address 0x4037c825 <xtensa_int1_c+29> and ends at 0x4037c838 <xtensa_int1_c+48>.
Line 337 of "/home/work/zephyrproject-3.6/zephyr/arch/xtensa/core/vector_handlers.c" starts at address 0x4037c825 <xtensa_int1_c+29> and ends at 0x4037c838 <xtensa_int1_c+48>.
Line 121 of "/home/work/zephyrproject-3.6/zephyr/soc/espressif/common/include/_soc_inthandlers.h" starts at address 0x4037c538 <_xtensa_handle_one_int1> and ends at 0x4037c53b <_xtensa_handle_one_int1+3>.
Line 167 of "/home/work/zephyrproject-3.6/zephyr/soc/espressif/common/include/_soc_inthandlers.h" starts at address 0x4037c57c <_xtensa_handle_one_int1+68> and ends at 0x4037c57f <_xtensa_handle_one_int1+71>.
Line 192 of "/home/work/zephyrproject-3.6/zephyr/soc/espressif/common/include/_soc_inthandlers.h" starts at address 0x4037c5a0 <_xtensa_handle_one_int1+104> and ends at 0x4037c5a3 <_xtensa_handle_one_int1+107>.
Line 204 of "/home/work/zephyrproject-3.6/zephyr/soc/espressif/common/include/_soc_inthandlers.h" starts at address 0x4037c5b1 <_xtensa_handle_one_int1+121> and ends at 0x4037c5b4 <_xtensa_handle_one_int1+124>.
Line 217 of "/home/work/zephyrproject-3.6/zephyr/soc/espressif/common/include/_soc_inthandlers.h" starts at address 0x4037c63c <_xtensa_handle_one_int1+260> and ends at 0x4037c63f <_xtensa_handle_one_int1+263>.
Line 221 of "/home/work/zephyrproject-3.6/zephyr/soc/espressif/common/include/_soc_inthandlers.h" starts at address 0x4037c63f <_xtensa_handle_one_int1+263> and ends at 0x4037c656.
Line 337 of "/home/work/zephyrproject-3.6/zephyr/arch/xtensa/core/vector_handlers.c" starts at address 0x4037c825 <xtensa_int1_c+29> and ends at 0x4037c838 <xtensa_int1_c+48>.

# 
Line 917 of "/home/work/zephyrproject-3.6/zephyr/kernel/sched.c" starts at address 0x40382a54 <z_get_next_switch_handle> and ends at 0x40382a57 <z_get_next_switch_handle+3>.
Line 327 of "/home/work/zephyrproject-3.6/zephyr/kernel/thread.c" starts at address 0x40380e98 <z_check_stack_sentinel> and ends at 0x40380e9b <z_check_stack_sentinel+3>.
Line 338 of "/home/work/zephyrproject-3.6/zephyr/kernel/thread.c" starts at address 0x40380ec8 <z_check_stack_sentinel+48> and ends at 0x40380ee0 <z_impl_k_thread_start>.
Line 338 of "/home/work/zephyrproject-3.6/zephyr/kernel/thread.c" starts at address 0x40380ec8 <z_check_stack_sentinel+48> and ends at 0x40380ee0 <z_impl_k_thread_start>.
Line 984 of "/home/work/zephyrproject-3.6/zephyr/kernel/sched.c" starts at address 0x40382a68 <z_get_next_switch_handle+20> and ends at 0x40382a6e <z_get_next_switch_handle+26>.
Line 100 of "/home/work/zephyrproject-3.6/zephyr/kernel/usage.c" starts at address 0x40385a18 <z_sched_usage_stop> and ends at 0x40385a1b <z_sched_usage_stop+3>.
Line 10 of "/home/work/zephyrproject-3.6/zephyr/kernel/spinlock_validate.c" starts at address 0x403836a4 <z_spin_lock_valid> and ends at 0x403836a7 <z_spin_lock_valid+3>.
Line 18 of "/home/work/zephyrproject-3.6/zephyr/kernel/spinlock_validate.c" starts at address 0x403836c9 <z_spin_lock_valid+37> and ends at 0x403836cb <z_spin_lock_valid+39>.
Line 19 of "/home/work/zephyrproject-3.6/zephyr/kernel/spinlock_validate.c" starts at address 0x403836d1 <z_spin_lock_valid+45> and ends at 0x403836e6 <z_spin_lock_valid+66>.
Line 19 of "/home/work/zephyrproject-3.6/zephyr/kernel/spinlock_validate.c" starts at address 0x403836e6 <z_spin_lock_valid+66> and ends at 0x403836e8 <z_spin_unlock_valid>.
Line 136 of "/home/work/zephyrproject-3.6/zephyr/include/zephyr/spinlock.h" starts at address 0x40385a2d <z_sched_usage_stop+21> and ends at 0x40385a35 <z_sched_usage_stop+29>.
Line 147 of "/home/work/zephyrproject-3.6/zephyr/include/zephyr/spinlock.h" starts at address 0x40385a61 <z_sched_usage_stop+73> and ends at 0x40385a67 <z_sched_usage_stop+79>.
Line 38 of "/home/work/zephyrproject-3.6/zephyr/kernel/spinlock_validate.c" starts at address 0x40383744 <z_spin_lock_set_owner> and ends at 0x40383747 <z_spin_lock_set_owner+3>.
Line 40 of "/home/work/zephyrproject-3.6/zephyr/kernel/spinlock_validate.c" starts at address 0x40383764 <z_spin_lock_set_owner+32> and ends at 0x40383776.
Line 105 of "/home/work/zephyrproject-3.6/zephyr/kernel/usage.c" starts at address 0x40385a67 <z_sched_usage_stop+79> and ends at 0x40385a6d <z_sched_usage_stop+85>.
Line 117 of "/home/work/zephyrproject-3.6/zephyr/kernel/usage.c" starts at address 0x40385a8d <z_sched_usage_stop+117> and ends at 0x40385a94 <z_sched_usage_stop+124>.
Line 22 of "/home/work/zephyrproject-3.6/zephyr/kernel/spinlock_validate.c" starts at address 0x403836e8 <z_spin_unlock_valid> and ends at 0x403836eb <z_spin_unlock_valid+3>.
Line 31 of "/home/work/zephyrproject-3.6/zephyr/kernel/spinlock_validate.c" starts at address 0x40383711 <z_spin_unlock_valid+41> and ends at 0x40383717 <z_spin_unlock_valid+47>.
Line 35 of "/home/work/zephyrproject-3.6/zephyr/kernel/spinlock_validate.c" starts at address 0x4038372c <z_spin_unlock_valid+68> and ends at 0x40383732 <z_spin_unlock_valid+74>.
Line 35 of "/home/work/zephyrproject-3.6/zephyr/kernel/spinlock_validate.c" starts at address 0x40383732 <z_spin_unlock_valid+74> and ends at 0x40383743.
Line 305 of "/home/work/zephyrproject-3.6/zephyr/include/zephyr/spinlock.h" starts at address 0x40385a94 <z_sched_usage_stop+124> and ends at 0x40385a9c <z_sched_usage_stop+132>.
Line 146 of "/home/work/zephyrproject-3.6/zephyr/include/zephyr/arch/xtensa/irq.h" starts at address 0x40385ac7 <z_sched_usage_stop+175> and ends at 0x40385acd <z_sched_usage_stop+181>.
Line 119 of "/home/work/zephyrproject-3.6/zephyr/kernel/usage.c" starts at address 0x40385acd <z_sched_usage_stop+181> and ends at 0x40385ae2.
Line 303 of "/home/work/zephyrproject-3.6/zephyr/kernel/include/ksched.h" starts at address 0x40382a71 <z_get_next_switch_handle+29> and ends at 0x40382a76 <z_get_next_switch_handle+34>.
Line 75 of "/home/work/zephyrproject-3.6/zephyr/kernel/usage.c" starts at address 0x4038595c <z_sched_usage_start> and ends at 0x4038595f <z_sched_usage_start+3>.
Line 10 of "/home/work/zephyrproject-3.6/zephyr/kernel/spinlock_validate.c" starts at address 0x403836a4 <z_spin_lock_valid> and ends at 0x403836a7 <z_spin_lock_valid+3>.
Line 18 of "/home/work/zephyrproject-3.6/zephyr/kernel/spinlock_validate.c" starts at address 0x403836c9 <z_spin_lock_valid+37> and ends at 0x403836cb <z_spin_lock_valid+39>.
Line 19 of "/home/work/zephyrproject-3.6/zephyr/kernel/spinlock_validate.c" starts at address 0x403836d1 <z_spin_lock_valid+45> and ends at 0x403836e6 <z_spin_lock_valid+66>.
Line 19 of "/home/work/zephyrproject-3.6/zephyr/kernel/spinlock_validate.c" starts at address 0x403836e6 <z_spin_lock_valid+66> and ends at 0x403836e8 <z_spin_unlock_valid>.
Line 136 of "/home/work/zephyrproject-3.6/zephyr/include/zephyr/spinlock.h" starts at address 0x40385971 <z_sched_usage_start+21> and ends at 0x40385979 <z_sched_usage_start+29>.
Line 147 of "/home/work/zephyrproject-3.6/zephyr/include/zephyr/spinlock.h" starts at address 0x403859a4 <z_sched_usage_start+72> and ends at 0x403859aa <z_sched_usage_start+78>.
Line 38 of "/home/work/zephyrproject-3.6/zephyr/kernel/spinlock_validate.c" starts at address 0x40383744 <z_spin_lock_set_owner> and ends at 0x40383747 <z_spin_lock_set_owner+3>.
Line 40 of "/home/work/zephyrproject-3.6/zephyr/kernel/spinlock_validate.c" starts at address 0x40383764 <z_spin_lock_set_owner+32> and ends at 0x40383776.
Line 81 of "/home/work/zephyrproject-3.6/zephyr/kernel/usage.c" starts at address 0x403859aa <z_sched_usage_start+78> and ends at 0x403859ad <z_sched_usage_start+81>.
Line 22 of "/home/work/zephyrproject-3.6/zephyr/kernel/usage.c" starts at address 0x40385928 <usage_now> and ends at 0x4038592b <usage_now+3>.
Line 111 of "/home/work/zephyrproject-3.6/zephyr/drivers/timer/xtensa_sys_timer.c" starts at address 0x403877c0 <sys_clock_cycle_get_32> and ends at 0x403877c3 <sys_clock_cycle_get_32+3>.
Line 36 of "/home/work/zephyrproject-3.6/zephyr/drivers/timer/xtensa_sys_timer.c" starts at address 0x403874e4 <ccount> and ends at 0x403874e7 <ccount+3>.
Line 40 of "/home/work/zephyrproject-3.6/zephyr/drivers/timer/xtensa_sys_timer.c" starts at address 0x403874f9 <ccount+21> and ends at 0x4038750c <sys_clock_driver_init>.
Line 113 of "/home/work/zephyrproject-3.6/zephyr/drivers/timer/xtensa_sys_timer.c" starts at address 0x403877d3 <sys_clock_cycle_get_32+19> and ends at 0x403877e8 <log_msg_generic_get_wlen>.
Line 113 of "/home/work/zephyrproject-3.6/zephyr/drivers/timer/xtensa_sys_timer.c" starts at address 0x403877d3 <sys_clock_cycle_get_32+19> and ends at 0x403877e8 <log_msg_generic_get_wlen>.
Line 32 of "/home/work/zephyrproject-3.6/zephyr/kernel/usage.c" starts at address 0x4038593c <usage_now+20> and ends at 0x40385940 <usage_now+24>.
Line 33 of "/home/work/zephyrproject-3.6/zephyr/kernel/usage.c" starts at address 0x40385940 <usage_now+24> and ends at 0x4038595a.
Line 33 of "/home/work/zephyrproject-3.6/zephyr/kernel/usage.c" starts at address 0x40385940 <usage_now+24> and ends at 0x4038595a.
Line 81 of "/home/work/zephyrproject-3.6/zephyr/kernel/usage.c" starts at address 0x403859ad <z_sched_usage_start+81> and ends at 0x403859b2 <z_sched_usage_start+86>.
Line 22 of "/home/work/zephyrproject-3.6/zephyr/kernel/spinlock_validate.c" starts at address 0x403836e8 <z_spin_unlock_valid> and ends at 0x403836eb <z_spin_unlock_valid+3>.
Line 31 of "/home/work/zephyrproject-3.6/zephyr/kernel/spinlock_validate.c" starts at address 0x40383711 <z_spin_unlock_valid+41> and ends at 0x40383717 <z_spin_unlock_valid+47>.
Line 35 of "/home/work/zephyrproject-3.6/zephyr/kernel/spinlock_validate.c" starts at address 0x4038372c <z_spin_unlock_valid+68> and ends at 0x40383732 <z_spin_unlock_valid+74>.
Line 35 of "/home/work/zephyrproject-3.6/zephyr/kernel/spinlock_validate.c" starts at address 0x40383732 <z_spin_unlock_valid+74> and ends at 0x40383743.
Line 305 of "/home/work/zephyrproject-3.6/zephyr/include/zephyr/spinlock.h" starts at address 0x403859c7 <z_sched_usage_start+107> and ends at 0x403859cf <z_sched_usage_start+115>.
Line 146 of "/home/work/zephyrproject-3.6/zephyr/include/zephyr/arch/xtensa/irq.h" starts at address 0x403859fb <z_sched_usage_start+159> and ends at 0x40385a01 <z_sched_usage_start+165>.
Line 97 of "/home/work/zephyrproject-3.6/zephyr/kernel/usage.c" starts at address 0x40385a09 <z_sched_usage_start+173> and ends at 0x40385a16.
Line 985 of "/home/work/zephyrproject-3.6/zephyr/kernel/sched.c" starts at address 0x40382a76 <z_get_next_switch_handle+34> and ends at 0x40382a78 <z_get_next_switch_handle+36>.
Line 934 of "/home/work/zephyrproject-3.6/zephyr/kernel/thread.c" starts at address 0x40381288 <z_thread_mark_switched_out> and ends at 0x4038128b <z_thread_mark_switched_out+3>.
Line 396 of "/home/work/zephyrproject-3.6/modules/debug/percepio/TraceRecorder/kernelports/Zephyr/trcKernelPort.c" starts at address 0x4208a2f8 <sys_trace_k_thread_switched_out> and ends at 0x4208a2fb <sys_trace_k_thread_switched_out+3>.
Line 397 of "/home/work/zephyrproject-3.6/modules/debug/percepio/TraceRecorder/kernelports/Zephyr/trcKernelPort.c" starts at address 0x4208a308 <sys_trace_k_thread_switched_out+16> and ends at 0x4208a31e.
Line 946 of "/home/work/zephyrproject-3.6/zephyr/kernel/thread.c" starts at address 0x4038129f <z_thread_mark_switched_out+23> and ends at 0x403812b2.
Line 946 of "/home/work/zephyrproject-3.6/zephyr/kernel/thread.c" starts at address 0x4038129f <z_thread_mark_switched_out+23> and ends at 0x403812b2.
Line 882 of "/home/work/zephyrproject-3.6/zephyr/kernel/sched.c" starts at address 0x40382a80 <z_get_next_switch_handle+44> and ends at 0x40382a82 <z_get_next_switch_handle+46>.
Line 989 of "/home/work/zephyrproject-3.6/zephyr/kernel/sched.c" starts at address 0x40382a85 <z_get_next_switch_handle+49> and ends at 0x40382a97.
Line 276 of "/home/work/zephyrproject-3.6/zephyr/arch/xtensa/core/vector_handlers.c" starts at address 0x4037c844 <xtensa_int1_c+60> and ends at 0x4037c849 <xtensa_int1_c+65>.
Line 337 of "/home/work/zephyrproject-3.6/zephyr/arch/xtensa/core/vector_handlers.c" starts at address 0x4037c849 <xtensa_int1_c+65> and ends at 0x4037c85e.
*** Exception occurred ***
Line 162 of "/home/work/zephyrproject-3.6/zephyr/arch/xtensa/core/window_vectors.S" starts at address 0x403740c0 <_WindowUnderflow8> and ends at 0x403740c3 <_WindowUnderflow8+3>.
Line 337 of "/home/work/zephyrproject-3.6/zephyr/arch/xtensa/core/vector_handlers.c" starts at address 0x4037c849 <xtensa_int1_c+65> and ends at 0x4037c85e.
Line 369 of "/home/work/zephyrproject-3.6/zephyr/arch/xtensa/core/vector_handlers.c" starts at address 0x4037ceff <xtensa_excint1_c+35> and ends at 0x4037cf09 <xtensa_excint1_c+45>.
Line 505 of "/home/work/zephyrproject-3.6/zephyr/arch/xtensa/core/vector_handlers.c" starts at address 0x4037cfff <xtensa_excint1_c+291> and ends at 0x4037d007 <xtensa_excint1_c+299>.
Line 505 of "/home/work/zephyrproject-3.6/zephyr/arch/xtensa/core/vector_handlers.c" starts at address 0x4037d007 <xtensa_excint1_c+299> and ends at 0x4037d016.
*** Exception occurred ***
Line 78 of "/home/work/zephyrproject-3.6/zephyr/arch/xtensa/core/window_vectors.S" starts at address 0x40374040 <_WindowUnderflow4> and ends at 0x40374043 <_WindowUnderflow4+3>.
Line 505 of "/home/work/zephyrproject-3.6/zephyr/arch/xtensa/core/vector_handlers.c" starts at address 0x4037d007 <xtensa_excint1_c+299> and ends at 0x4037d016.
Line 320 of "/home/work/zephyrproject-3.6/zephyr/arch/xtensa/core/xtensa_asm2_util.S" starts at address 0x4037c300 <_handle_excint> and ends at 0x4037c3d4 <z_irq_spurious>.
*** Exception occurred ***
Line 78 of "/home/work/zephyrproject-3.6/zephyr/arch/xtensa/core/window_vectors.S" starts at address 0x40374040 <_WindowUnderflow4> and ends at 0x40374043 <_WindowUnderflow4+3>.
Line 320 of "/home/work/zephyrproject-3.6/zephyr/arch/xtensa/core/xtensa_asm2_util.S" starts at address 0x4037c300 <_handle_excint> and ends at 0x4037c3d4 <z_irq_spurious>.
Line 320 of "/home/work/zephyrproject-3.6/zephyr/arch/xtensa/core/xtensa_asm2_util.S" starts at address 0x4037c300 <_handle_excint> and ends at 0x4037c3d4 <z_irq_spurious>.
Line 320 of "/home/work/zephyrproject-3.6/zephyr/arch/xtensa/core/xtensa_asm2_util.S" starts at address 0x4037c300 <_handle_excint> and ends at 0x4037c3d4 <z_irq_spurious>.
Line 152 of "/home/work/zephyrproject-3.6/zephyr/arch/xtensa/core/xtensa_asm2_util.S" starts at address 0x4037c251 <_restore_context> and ends at 0x4037c254 <_restore_context+3>.
Line 103 of "/home/work/zephyrproject-3.6/zephyr/arch/xtensa/core/xtensa_asm2_util.S" starts at address 0x4037c21c <xtensa_restore_high_regs> and ends at 0x4037c21e <xtensa_restore_high_regs+2>.
Line 154 of "/home/work/zephyrproject-3.6/zephyr/arch/xtensa/core/xtensa_asm2_util.S" starts at address 0x4037c254 <_restore_context+3> and ends at 0x4037c256 <_restore_context+5>.
Line 312 of "/home/work/zephyrproject-3.6/zephyr/arch/xtensa/core/xtensa_asm2_util.S" starts at address 0x4037c2fb <_switch_restore_pc> and ends at 0x4037c300 <_handle_excint>.
*** Exception occurred ***
Line 162 of "/home/work/zephyrproject-3.6/zephyr/arch/xtensa/core/window_vectors.S" starts at address 0x403740c0 <_WindowUnderflow8> and ends at 0x403740c3 <_WindowUnderflow8+3>.
Line 312 of "/home/work/zephyrproject-3.6/zephyr/arch/xtensa/core/xtensa_asm2_util.S" starts at address 0x4037c2fb <_switch_restore_pc> and ends at 0x4037c300 <_handle_excint>.
Line 85 of "/home/work/zephyrproject-3.6/zephyr/arch/xtensa/include/kernel_arch_func.h" starts at address 0x40382621 <z_swap+249> and ends at 0x40382625 <z_swap+253>.
Line 146 of "/home/work/zephyrproject-3.6/zephyr/include/zephyr/arch/xtensa/irq.h" starts at address 0x4038265b <z_swap+307> and ends at 0x40382661 <z_swap+313>.
Line 189 of "/home/work/zephyrproject-3.6/zephyr/kernel/include/kswap.h" starts at address 0x40382669 <z_swap+321> and ends at 0x4038267e.
*** Exception occurred ***
Line 162 of "/home/work/zephyrproject-3.6/zephyr/arch/xtensa/core/window_vectors.S" starts at address 0x403740c0 <_WindowUnderflow8> and ends at 0x403740c3 <_WindowUnderflow8+3>.
Line 189 of "/home/work/zephyrproject-3.6/zephyr/kernel/include/kswap.h" starts at address 0x40382669 <z_swap+321> and ends at 0x4038267e.
Line 696 of "/home/work/zephyrproject-3.6/zephyr/kernel/sched.c" starts at address 0x403828f3 <z_pend_curr+179> and ends at 0x403828fd <z_pend_curr+189>.
Line 697 of "/home/work/zephyrproject-3.6/zephyr/kernel/sched.c" starts at address 0x403828fd <z_pend_curr+189> and ends at 0x40382912.
*** Exception occurred ***
Line 162 of "/home/work/zephyrproject-3.6/zephyr/arch/xtensa/core/window_vectors.S" starts at address 0x403740c0 <_WindowUnderflow8> and ends at 0x403740c3 <_WindowUnderflow8+3>.
Line 697 of "/home/work/zephyrproject-3.6/zephyr/kernel/sched.c" starts at address 0x403828fd <z_pend_curr+189> and ends at 0x40382912.
Line 158 of "/home/work/zephyrproject-3.6/zephyr/kernel/sem.c" starts at address 0x4037fa26 <z_impl_k_sem_take+310> and ends at 0x4037fa36 <z_impl_k_sem_take+326>.
Line 725 of "/home/work/zephyrproject-3.6/modules/debug/percepio/TraceRecorder/kernelports/Zephyr/trcKernelPort.c" starts at address 0x4208ab3c <sys_trace_k_sem_take_exit> and ends at 0x4208ab43 <sys_trace_k_sem_take_exit+7>.
Line 726 of "/home/work/zephyrproject-3.6/modules/debug/percepio/TraceRecorder/kernelports/Zephyr/trcKernelPort.c" starts at address 0x4208ab50 <sys_trace_k_sem_take_exit+20> and ends at 0x4208ab62 <sys_trace_k_sem_take_exit+38>.
Line 169 of "/home/work/zephyrproject-3.6/modules/debug/percepio/TraceRecorder/trcEvent.c" starts at address 0x4208c660 <xTraceEventCreate3> and ends at 0x4208c663 <xTraceEventCreate3+3>.
Line 176 of "/home/work/zephyrproject-3.6/modules/debug/percepio/TraceRecorder/trcEvent.c" starts at address 0x4208c67b <xTraceEventCreate3+27> and ends at 0x4208c68e <xTraceEventCreate3+46>.
Line 138 of "/home/work/zephyrproject-3.6/zephyr/include/zephyr/arch/xtensa/irq.h" starts at address 0x4208c68e <xTraceEventCreate3+46> and ends at 0x4208c691 <xTraceEventCreate3+49>.
Line 94 of "/home/work/zephyrproject-3.6/modules/debug/percepio/TraceRecorder/trcEventBuffer.c" starts at address 0x4208cad4 <xTraceEventBufferAlloc> and ends at 0x4208cad7 <xTraceEventBufferAlloc+3>.
Line 120 of "/home/work/zephyrproject-3.6/modules/debug/percepio/TraceRecorder/trcEventBuffer.c" starts at address 0x4208caee <xTraceEventBufferAlloc+26> and ends at 0x4208caf0 <xTraceEventBufferAlloc+28>.
Line 154 of "/home/work/zephyrproject-3.6/modules/debug/percepio/TraceRecorder/trcEventBuffer.c" starts at address 0x4208cb3d <xTraceEventBufferAlloc+105> and ends at 0x4208cb40 <xTraceEventBufferAlloc+108>.
Line 176 of "/home/work/zephyrproject-3.6/modules/debug/percepio/TraceRecorder/trcEventBuffer.c" starts at address 0x4208cb66 <xTraceEventBufferAlloc+146> and ends at 0x4208cb6b <xTraceEventBufferAlloc+151>.
Line 69 of "/home/work/zephyrproject-3.6/modules/debug/percepio/TraceRecorder/trcEventBuffer.c" starts at address 0x4208ca38 <prvTraceEventBufferAllocPop> and ends at 0x4208ca3b <prvTraceEventBufferAllocPop+3>.
Line 84 of "/home/work/zephyrproject-3.6/modules/debug/percepio/TraceRecorder/trcEventBuffer.c" starts at address 0x4208ca5c <prvTraceEventBufferAllocPop+36> and ends at 0x4208ca68 <prvTraceEventBufferAllocPop+48>.
Line 91 of "/home/work/zephyrproject-3.6/modules/debug/percepio/TraceRecorder/trcEventBuffer.c" starts at address 0x4208ca78 <prvTraceEventBufferAllocPop+64> and ends at 0x4208ca8a.
Line 177 of "/home/work/zephyrproject-3.6/modules/debug/percepio/TraceRecorder/trcEventBuffer.c" starts at address 0x4208cb6b <xTraceEventBufferAlloc+151> and ends at 0x4208cb75 <xTraceEventBufferAlloc+161>.
Line 187 of "/home/work/zephyrproject-3.6/modules/debug/percepio/TraceRecorder/trcEventBuffer.c" starts at address 0x4208cb80 <xTraceEventBufferAlloc+172> and ends at 0x4208cb82 <xTraceEventBufferAlloc+174>.
Line 256 of "/home/work/zephyrproject-3.6/modules/debug/percepio/TraceRecorder/trcEventBuffer.c" starts at address 0x4208cc06 <xTraceEventBufferAlloc+306> and ends at 0x4208cc0e <xTraceEventBufferAlloc+314>.
Line 256 of "/home/work/zephyrproject-3.6/modules/debug/percepio/TraceRecorder/trcEventBuffer.c" starts at address 0x4208cc0e <xTraceEventBufferAlloc+314> and ends at 0x4208cc1e.
Line 185 of "/home/work/zephyrproject-3.6/modules/debug/percepio/TraceRecorder/trcEvent.c" starts at address 0x4208c6ac <xTraceEventCreate3+76> and ends at 0x4208c6af <xTraceEventCreate3+79>.
Line 191 of "/home/work/zephyrproject-3.6/modules/debug/percepio/TraceRecorder/trcEvent.c" starts at address 0x4208c6b9 <xTraceEventCreate3+89> and ends at 0x4208c6bc <xTraceEventCreate3+92>.
Line 111 of "/home/work/zephyrproject-3.6/zephyr/drivers/timer/xtensa_sys_timer.c" starts at address 0x403877c0 <sys_clock_cycle_get_32> and ends at 0x403877c3 <sys_clock_cycle_get_32+3>.
Line 36 of "/home/work/zephyrproject-3.6/zephyr/drivers/timer/xtensa_sys_timer.c" starts at address 0x403874e4 <ccount> and ends at 0x403874e7 <ccount+3>.
Line 40 of "/home/work/zephyrproject-3.6/zephyr/drivers/timer/xtensa_sys_timer.c" starts at address 0x403874f9 <ccount+21> and ends at 0x4038750c <sys_clock_driver_init>.
Line 113 of "/home/work/zephyrproject-3.6/zephyr/drivers/timer/xtensa_sys_timer.c" starts at address 0x403877d3 <sys_clock_cycle_get_32+19> and ends at 0x403877e8 <log_msg_generic_get_wlen>.
Line 113 of "/home/work/zephyrproject-3.6/zephyr/drivers/timer/xtensa_sys_timer.c" starts at address 0x403877d3 <sys_clock_cycle_get_32+19> and ends at 0x403877e8 <log_msg_generic_get_wlen>.
Line 191 of "/home/work/zephyrproject-3.6/modules/debug/percepio/TraceRecorder/trcEvent.c" starts at address 0x4208c6de <xTraceEventCreate3+126> and ends at 0x4208c6e0 <xTraceEventCreate3+128>.
Line 191 of "/home/work/zephyrproject-3.6/modules/debug/percepio/TraceRecorder/trcEvent.c" starts at address 0x4208c6e0 <xTraceEventCreate3+128> and ends at 0x4208c6fb <xTraceEventCreate3+155>.
Line 259 of "/home/work/zephyrproject-3.6/modules/debug/percepio/TraceRecorder/trcEventBuffer.c" starts at address 0x4208cc20 <xTraceEventBufferAllocCommit> and ends at 0x4208cc23 <xTraceEventBufferAllocCommit+3>.
Line 272 of "/home/work/zephyrproject-3.6/modules/debug/percepio/TraceRecorder/trcEventBuffer.c" starts at address 0x4208cc52 <xTraceEventBufferAllocCommit+50> and ends at 0x4208cc56.
Line 146 of "/home/work/zephyrproject-3.6/zephyr/include/zephyr/arch/xtensa/irq.h" starts at address 0x4208c710 <xTraceEventCreate3+176> and ends at 0x4208c716 <xTraceEventCreate3+182>.
Line 206 of "/home/work/zephyrproject-3.6/modules/debug/percepio/TraceRecorder/trcEvent.c" starts at address 0x4208c723 <xTraceEventCreate3+195> and ends at 0x4208c728 <xTraceEventCreate3+200>.
Line 206 of "/home/work/zephyrproject-3.6/modules/debug/percepio/TraceRecorder/trcEvent.c" starts at address 0x4208c728 <xTraceEventCreate3+200> and ends at 0x4208c73d.
Line 727 of "/home/work/zephyrproject-3.6/modules/debug/percepio/TraceRecorder/kernelports/Zephyr/trcKernelPort.c" starts at address 0x4208ab62 <sys_trace_k_sem_take_exit+38> and ends at 0x4208ab7c <sys_trace_k_sem_reset>.
Line 727 of "/home/work/zephyrproject-3.6/modules/debug/percepio/TraceRecorder/kernelports/Zephyr/trcKernelPort.c" starts at address 0x4208ab62 <sys_trace_k_sem_take_exit+38> and ends at 0x4208ab7c <sys_trace_k_sem_reset>.

# i2c_esp32_transmit() successfully acquires k_sem_take(&data->cmd_sem, K_MSEC(I2C_TRANSFER_TIMEOUT_MSEC));
Line 163 of "/home/work/zephyrproject-3.6/zephyr/kernel/sem.c" starts at address 0x4037fa44 <z_impl_k_sem_take+340> and ends at 0x4037fa49 <z_impl_k_sem_take+345>.
Line 164 of "/home/work/zephyrproject-3.6/zephyr/kernel/sem.c" starts at address 0x4037fa4c <z_impl_k_sem_take+348> and ends at 0x4037fa5c <z_impl_k_sem_reset>.
*** Exception occurred ***
Line 162 of "/home/work/zephyrproject-3.6/zephyr/arch/xtensa/core/window_vectors.S" starts at address 0x403740c0 <_WindowUnderflow8> and ends at 0x403740c3 <_WindowUnderflow8+3>.
Line 164 of "/home/work/zephyrproject-3.6/zephyr/kernel/sem.c" starts at address 0x4037fa4c <z_impl_k_sem_take+348> and ends at 0x4037fa5c <z_impl_k_sem_reset>.

Line 383 of "/home/work/zephyrproject-3.6/zephyr/drivers/i2c/i2c_esp32.c" starts at address 0x40379009 <i2c_esp32_transmit+69> and ends at 0x4037900b <i2c_esp32_transmit+71>.
Line 391 of "/home/work/zephyrproject-3.6/zephyr/drivers/i2c/i2c_esp32.c" starts at address 0x40379018 <i2c_esp32_transmit+84> and ends at 0x4037901d <i2c_esp32_transmit+89>.
Line 394 of "/home/work/zephyrproject-3.6/zephyr/drivers/i2c/i2c_esp32.c" starts at address 0x4037902e <i2c_esp32_transmit+106> and ends at 0x40379033 <i2c_esp32_transmit+111>.
Line 399 of "/home/work/zephyrproject-3.6/zephyr/drivers/i2c/i2c_esp32.c" starts at address 0x40379038 <i2c_esp32_transmit+116> and ends at 0x4037903d <i2c_esp32_transmit+121>.
Line 399 of "/home/work/zephyrproject-3.6/zephyr/drivers/i2c/i2c_esp32.c" starts at address 0x4037903d <i2c_esp32_transmit+121> and ends at 0x40379052.
*** Exception occurred ***
Line 162 of "/home/work/zephyrproject-3.6/zephyr/arch/xtensa/core/window_vectors.S" starts at address 0x403740c0 <_WindowUnderflow8> and ends at 0x403740c3 <_WindowUnderflow8+3>.
Line 399 of "/home/work/zephyrproject-3.6/zephyr/drivers/i2c/i2c_esp32.c" starts at address 0x4037903d <i2c_esp32_transmit+121> and ends at 0x40379052.
Line 493 of "/home/work/zephyrproject-3.6/zephyr/drivers/i2c/i2c_esp32.c" starts at address 0x403791e0 <i2c_esp32_master_read+148> and ends at 0x403791e3 <i2c_esp32_master_read+151>.
Line 583 of "/home/work/zephyrproject-3.6/modules/hal/espressif/zephyr/esp32s3/../../components/hal/esp32s3/include/hal/i2c_ll.h" starts at address 0x40379203 <i2c_esp32_master_read+183> and ends at 0x40379206 <i2c_esp32_master_read+186>.
Line 584 of "/home/work/zephyrproject-3.6/modules/hal/espressif/zephyr/esp32s3/../../components/hal/esp32s3/include/hal/i2c_ll.h" starts at address 0x403791ec <i2c_esp32_master_read+160> and ends at 0x403791f1 <i2c_esp32_master_read+165>.

# Return to i2c_esp32_read_msg()
Line 503 of "/home/work/zephyrproject-3.6/zephyr/drivers/i2c/i2c_esp32.c" starts at address 0x40379218 <i2c_esp32_master_read+204> and ends at 0x4037922a.
*** Exception occurred ***
Line 162 of "/home/work/zephyrproject-3.6/zephyr/arch/xtensa/core/window_vectors.S" starts at address 0x403740c0 <_WindowUnderflow8> and ends at 0x403740c3 <_WindowUnderflow8+3>.
Line 503 of "/home/work/zephyrproject-3.6/zephyr/drivers/i2c/i2c_esp32.c" starts at address 0x40379218 <i2c_esp32_master_read+204> and ends at 0x4037922a.

Line 523 of "/home/work/zephyrproject-3.6/zephyr/drivers/i2c/i2c_esp32.c" starts at address 0x403793a0 <i2c_esp32_read_msg+156> and ends at 0x403793aa <i2c_esp32_read_msg+166>.
Line 529 of "/home/work/zephyrproject-3.6/zephyr/drivers/i2c/i2c_esp32.c" starts at address 0x40379418 <i2c_esp32_read_msg+276> and ends at 0x4037941b <i2c_esp32_read_msg+279>.
Line 530 of "/home/work/zephyrproject-3.6/zephyr/drivers/i2c/i2c_esp32.c" starts at address 0x40379421 <i2c_esp32_read_msg+285> and ends at 0x40379426 <i2c_esp32_read_msg+290>.
Line 413 of "/home/work/zephyrproject-3.6/zephyr/drivers/i2c/i2c_esp32.c" starts at address 0x40378d40 <i2c_esp32_master_stop> and ends at 0x40378d43 <i2c_esp32_master_stop+3>.
Line 421 of "/home/work/zephyrproject-3.6/zephyr/drivers/i2c/i2c_esp32.c" starts at address 0x40378d6d <i2c_esp32_master_stop+45> and ends at 0x40378d7f.
Line 531 of "/home/work/zephyrproject-3.6/zephyr/drivers/i2c/i2c_esp32.c" starts at address 0x40379426 <i2c_esp32_read_msg+290> and ends at 0x4037942d <i2c_esp32_read_msg+297>.
Line 531 of "/home/work/zephyrproject-3.6/zephyr/drivers/i2c/i2c_esp32.c" starts at address 0x40379426 <i2c_esp32_read_msg+290> and ends at 0x4037942d <i2c_esp32_read_msg+297>.

# i2c_esp32_transmit() line "ret = k_sem_take(&data->cmd_sem, K_MSEC(I2C_TRANSFER_TIMEOUT_MSEC));" fails assert:
#   __ASSERT(((arch_is_in_isr() == false) || K_TIMEOUT_EQ(timeout, K_NO_WAIT)), "");

Line 373 of "/home/work/zephyrproject-3.6/zephyr/drivers/i2c/i2c_esp32.c" starts at address 0x40378fc4 <i2c_ll_write_cmd_reg> and ends at 0x40378fc7 <i2c_esp32_transmit+3>.
Line 133 of "/home/work/zephyrproject-3.6/zephyr/kernel/sem.c" starts at address 0x4037f8f0 <z_impl_k_sem_take> and ends at 0x4037f8f3 <z_impl_k_sem_take+3>.
Line 48 of "/home/work/zephyrproject-3.6/zephyr/lib/os/assert.c" starts at address 0x4201c4a8 <assert_print> and ends at 0x4201c4ab <assert_print+3>.
EricNRS commented 4 days ago

@sylvioalves Can you or someone on the EspressIf team comment on whether the code in libpp.a disables interrupts anywhere -- especially when calling the queue_recv_wrapper()? It seems odd that it would do that since it has function calls such as _wifi_int_disable(), _wifi_int_restore(), _ints_on(), and _ints_off() for that and logging is showing that those functions are being called correctly.

sylvioalves commented 4 days ago

@EricNRS I am able to reproduce it here and have been checking how to solve this. However, I can't reply to your question above (yet).

EricNRS commented 4 days ago

Awesome, thanks @sylvioalves, I sincerely appreciate the help. I have been going through the TRM and code to determine exactly how the interrupts work to see if I can find any clues such as maybe the arch_irq_lock() XCHAL_EXCM_LEVEL isn't masking an interrupt correctly or something similar.

Let me know if you need me to run any tests.

EricNRS commented 3 days ago

@sylvioalves - I found the issue!

I added the following code to grab the PS.INTLEVEL to all of the interface functions in modules/hal/espressif/zephyr/esp32s3/src/wifi/esp_wifi_adapter.c and found that the cause of the interrupts being incorrectly enabled is actually the call to timer_disarm_wrapper() which we do have code for!

/**
 * Return the PS.INTLEVEL which is active interrupt mask level.
 * 
 * 0 means all interrupts enabled, 3 is XCHAL_EXCM_LEVEL and means
 * interrupts disabled. 
 */
static unsigned is_lock_held(void)
{
    unsigned int key;

    __asm__ volatile("rsr.ps %0" : "=r"(key) :: "memory");

    // interrupt level is the lower 4-bits of PS
    return key & 0x0F;
}

// Added the before and after checks to all functions
static void IRAM_ATTR timer_disarm_wrapper(void *timer)
{
    unsigned before = is_lock_held();
    ets_timer_disarm(timer);
    unsigned after = is_lock_held();

    if (before != after) {
        __asm__ volatile("break 1, 4");
    }
}

That identified the location of the issue and stepping through the debugger finally revealed the issue. Here is the call sequence:

Turns out the issue is the irq_lock() key is getting overwritten because timer_list_lock() is being called twice.

timer_disarm_wrapper()
 -> esp_timer_stop()
      -> timer_list_lock()
      -> timer_remove()
            -> timer_list_lock()   <=== this overwrites the PS key returned by irq_lock()
            . . .
      -> timer_list_unlock()  <== wrong interrupt key restored

I just removed the lock and ran tests for an hour and it is working great. I will cleanup the code and upload for review.

EricNRS commented 3 days ago

Fix PR: https://github.com/zephyrproject-rtos/hal_espressif/pull/290

EricNRS commented 3 days ago

It looks like some of the timer functionality isn't used, so I wonder if the entire esp_timer.c task could be replaced by Zephyr timers. That would save 4KB of RAM used for the timer stack. May be something to consider as a lower-priority task once things are stable.