I2S on 2.0.0-alpha.175 causing panic

Toit

#I2S on 2.0.0-alpha.175 causing panic

Thread channel in help

Rikke 03/18/2025 11:20 AM

I have updated my toit sdk to 175, and I have changed the use of I2S to match the new syntax:

i2s_bus = i2s.Bus --tx=pin --sample_rate=100_000 --bits_per_sample=32 --buffer_size=(buf.size + reset.size) --use-apll=false

i2s_bus = i2s.Bus
      --master=true
      --mclk=null
      --tx=pin
      --sck=null
      --ws=null

    i2s_bus.configure
      --sample_rate=100_000 
      --bits_per_sample=32 

    i2s_bus.start

But in 1 out of 20 reboots(ish) I get a panic when starting up the i2s:

Guru Meditation Error: Core  1 panic'ed (Cache disabled but cached memory region accessed). 

Core  1 register dump:
PC      : 0x400d5904  PS      : 0x00060035  A0      : 0x80088c96  A1      : 0x3ffb2b50  
A2      : 0x3ffd48e8  A3      : 0x3ffb2b70  A4      : 0x3ffd4810  A5      : 0x3ffaf960  
A6      : 0x00000003  A7      : 0x00060723  A8      : 0x80080eef  A9      : 0x00060923  
A10     : 0x3ffd4810  A11     : 0x00000002  A12     : 0x00000000  A13     : 0x3ffb4484  
A14     : 0x00000001  A15     : 0x3ffafa84  SAR     : 0x00000001  EXCCAUSE: 0x00000007  
EXCVADDR: 0x00000000  LBEG    : 0x00000000  LEND    : 0x00000000  LCOUNT  : 0x00000000  



*******************************************
Decoding by `jag`, device has version <2.0.0-alpha.175>
*******************************************
Crash in native code:
Backtrace: 0x400d5901:0x3ffb2b50 0x40088c93:0x3ffb2b70 0x40087079:0x3ffb2bb0 0x40089b39:0x3ffb2bd0 0x4008544a:0x3ffaf9b0 0x4008558b:0x3ffaf9d0
0x400d5901: toit::primitive_toit_callback_deinit(toit::Process*, toit::Object**) + 0x15
0x40088c93: i2s_dma_rx_callback + 0x8b
0x40087079: esp_random + 0x15
0x40089b39: interrupt_hlevel_restore + 0x11
0x4008544a: spi_flash_disable_cache$constprop$0 + 0x6
0x4008558b: spi_flash_guard_set + 0x3
*******************************************

I am using i2s_bus.write to write to the pin. It works fine most of the time, but am I starting up the I2S too early?

floitsch 03/18/2025 11:26 AM

Not good...

floitsch 03/18/2025 11:26 AM

I'm having a look.

floitsch 03/18/2025 11:27 AM

Are you sure it's during startup?

floitsch 03/18/2025 11:27 AM

(there is a deinit-callback)

Rikke 03/18/2025 11:28 AM

I am not 100% sure no, but I can try and reproduce with more debugging messages

floitsch 03/18/2025 11:28 AM

The ideal would be something I can reproduce, but I'm looking at the code too.

floitsch 03/18/2025 11:28 AM

Could also be that the stacktrace isn't correct.

floitsch 03/18/2025 11:28 AM

I don't see how the dma_rx_callback can call the deinit.

floitsch 03/18/2025 11:29 AM

Do you have external (spiram) ram?

Rikke 03/18/2025 11:29 AM

That is possible, I have problems with building jag. It does not put the sdk under .cache/jaguar so i move it manually. I am not using external spiram

Rikke 03/18/2025 11:29 AM

So maybe its using default sdk

floitsch 03/18/2025 11:30 AM

Ok. So this is on a standard esp32 without any spiram.

Rikke 03/18/2025 11:30 AM

Correct

floitsch 03/18/2025 11:32 AM

Looking at the error message it's likely I forgot to add an IRAM attribute.

floitsch 03/18/2025 11:32 AM

Do you build your envelope yourself, or do you use a published one?

Rikke 03/18/2025 11:32 AM

I am building myself

floitsch 03/18/2025 11:33 AM

Ok. In that case try to disable I2S_ISR_IRAM_SAFE.

Rikke 03/18/2025 11:34 AM

I2S INIT 1
I2S INIT 2
I2S INIT 3
I2S INIT 4
debug: (1970-01-01T00:00:00Z) Watchdog: started led_control 
Guru Meditation Error: Core  0 panic'ed (Cache disabled but cached memory region accessed). 

Core  0 register dump:
PC      : 0x400d5904  PS      : 0x00060035  A0      : 0x80088c96  A1      : 0x3ffb2550  
A2      : 0x3ffd4900  A3      : 0x3ffb2570  A4      : 0x3ffd4828  A5      : 0x3ffaf3d0  
A6      : 0x00000003  A7      : 0x00060f23  A8      : 0x80080eef  A9      : 0x00060123  
A10     : 0x3ffd4828  A11     : 0x00000002  A12     : 0x00000000  A13     : 0x3ffb4484  
A14     : 0x00000000  A15     : 0x3ffaf4f4  SAR     : 0x0000001b  EXCCAUSE: 0x00000007  
EXCVADDR: 0x00000000  LBEG    : 0x4000c46c  LEND    : 0x4000c477  LCOUNT  : 0xffffffff  



******************************************************************************
Decoding by `jag`, device has version <2.0.0-alpha.175>
******************************************************************************
Crash in native code:
Backtrace: 0x400d5901:0x3ffb2550 0x40088c93:0x3ffb2570 0x40087079:0x3ffb25b0 0x40089b39:0x3ffb25d0 0x40085450:0x3ffaf420 0x4008558b:0x3ffaf440
0x400d5901: toit::primitive_toit_callback_deinit(toit::Process*, toit::Object**) + 0x15
0x40088c93: i2s_dma_rx_callback + 0x8b
0x40087079: esp_random + 0x15
0x40089b39: interrupt_hlevel_restore + 0x11
0x40085450: spi_flash_disable_cache$constprop$0 + 0xc
0x4008558b: spi_flash_guard_set + 0x3
******************************************************************************

so after init 4

print "I2S INIT 1"
    i2s_bus = i2s.Bus
      --master=true
      --mclk=null
      --tx=pin
      --sck=null
      --ws=null
    print "I2S INIT 2"

    i2s_bus.configure
      --sample_rate=100_000 
      --bits_per_sample=32 
    print "I2S INIT 3"

    i2s_bus.start
    print "I2S INIT 4"

before i start writing

floitsch 03/18/2025 11:35 AM

I'm pretty sure the crash happens because the interrupt is trying to call one of our callbacks, but that callback isn't in IRAM.

floitsch 03/18/2025 11:35 AM

I need to find the place where I forgot the IRAM attribute.

Rikke 03/18/2025 11:35 AM

I will rebuild and try to reproduce

floitsch 03/18/2025 11:36 AM

If you disable I2S_ISR_IRAM_SAFE you tell the esp-idf that it shouldn't call the callback when it might not be in IRAM. So in theory that should work around the issue.

floitsch 03/18/2025 11:39 AM

I just realized I have an appointment in a few minutes.
I will be (mostly) offline, but once I come back I will look into this.

Rikke 03/18/2025 11:39 AM

Its fine, i will just test this for now

Rikke 03/18/2025 12:09 PM

I have not been able to reproduce the error, but I got another panic now

looks like i got error messages when trying to configure, and the panic itself before starting the i2s.

I2S INIT 1
I2S INIT 2
E (26638) i2s_common: i2s_alloc_dma_desc(431): allocate DMA buffer failed
E (26638) i2s_std: i2s_std_set_slot(106): allocate memory for dma descriptor failed
E (26638) i2s_std: i2s_channel_init_std_mode(217): initialize channel failed while setting slot
I2S INIT 3
Guru Meditation Error: Core  1 panic'ed (LoadProhibited). Exception was unhandled.

Core  1 register dump:
PC      : 0x401005ca  PS      : 0x00060030  A0      : 0x801012c2  A1      : 0x3ffc5da0  
A2      : 0x3ffebe50  A3      : 0xffffffff  A4      : 0x0000000a  A5      : 0x00000000  
A6      : 0x00000000  A7      : 0x3ffefc84  A8      : 0x3ff4f000  A9      : 0x00000000  
A10     : 0x00000000  A11     : 0x00000002  A12     : 0x00060020  A13     : 0x00060023  
A14     : 0x3ffaeb6c  A15     : 0x3ffb01b8  SAR     : 0x00000010  EXCCAUSE: 0x0000001c  
EXCVADDR: 0x00000000  LBEG    : 0x4000c349  LEND    : 0x4000c36b  LCOUNT  : 0xffffffff

Rikke 03/18/2025 12:09 PM

*************
Decoding by `jag`, device has version <2.0.0-alpha.175>
*************
Crash in native code:
Backtrace: 0x401005c7:0x3ffc5da0 0x401012bf:0x3ffc5dc0 0x400d5bfe:0x3ffc5df0 0x40081d3e:0x3ffc5e10 0x400f2771:0x3ffc5ea0 0x400f29f1:0x3ffc5ef0 0x400f2a11:0x3ffc5f20 0x400e58fa:0x3ffc5f40 0x400e5921:0x3ffc5f60
0x401005c7: nvs::Storage::writeItem(unsigned char, nvs::ItemType, char const*, void const*, unsigned int) + 0x13
0x401012bf: nvs::NVSPartitionManager::init_partition(char const*) + 0x53
0x400d5bfe: toit::primitive_set_characteristic_notify(toit::Process*, toit::Object**) + 0x4e
0x40081d3e: toit::Interpreter::run() + 0x9e6
0x400f2771: toit::primitive_region_open(toit::Process*, toit::Object**) + 0xd5
0x400f29f1: toit::primitive_partition_find(toit::Process*, toit::Object**) + 0x161
0x400f2a11: toit::primitive_region_is_erased(toit::Process*, toit::Object**) + 0xd
0x400e58fa: toit::FlashRegistry::write_chunk(void const*, int, int) + 0x1e
0x400e5921: toit::FlashRegistry::find_next(int, LinkedList<toit::Reservation, 1>::Iterator*) + 0x9
*************

Rikke 03/18/2025 12:10 PM

It looks like a out of memory issue, but it shouldnt really cause a panic. I got a OOM message right before this, 55k free with largest free being 16k (trying to connect to MQTT with TLS)

OPRikke

I have not been able to reproduce the error, but I got another panic now

looks like i got error messages when trying to configure, and the panic itself before starting the i2s....

floitsch 03/18/2025 01:53 PM

I wonder if this is related to https://github.com/toitlang/toit/issues/2714

BLE + WiFi Scan + UDP = crash · Issue #2714 · toitlang/toit

The Provision example currently crashes (with pretty high probability): https://github.com/toitware/toit-provision/blob/53b6c211e3ea34de6ca090c3533e95cf164a3cc6/examples/ble-provision.toit Use http...

floitsch 03/18/2025 01:53 PM

Basically, we are sometimes running out of DMA buffers.

floitsch 03/18/2025 01:53 PM

So far we have only seen this from the wifi-stack, which made it really hard to investigate, as that code is closed source.

floitsch 03/18/2025 01:54 PM

Seeing a similar error in a different part of the system is interesting.

floitsch 03/18/2025 01:57 PM

Do you think the stacktrace is trustworthy?
Could you try to decode it with the SDK that you used to build your envelope?

echo Backtrace: 0x401005c7:0x3ffc5da0 0x401012bf:0x3ffc5dc0 0x400d5bfe:0x3ffc5df0 0x40081d3e:0x3ffc5e10 0x400f2771:0x3ffc5ea0 0x400f29f1:0x3ffc5ef0 0x400f2a11:0x3ffc5f20 0x400e58fa:0x3ffc5f40 0x400e5921:0x3ffc5f60 | build/host/sdk/tools/stacktrace build/esp32/toit.elf

Rikke 03/18/2025 01:58 PM

I have not been able to reproduce the dma/oom error since I posted the last message. I will try and decode

Rikke 03/18/2025 01:58 PM

echo Backtrace: 0x401005c7:0x3ffc5da0 0x401012bf:0x3ffc5dc0 0x400d5bfe:0x3ffc5df0 0x40081d3e:0x3ffc5e10 0x400f2771:0x3ffc5ea0 0x400f29f1:0x3ffc5ef0 0x400f2a11:0x3ffc5f20 0x400e58fa:0x3ffc5f40 0x400e5921:0x3ffc5f60 | build/host/sdk/tools/stacktrace build/esp32/toit.elf
0x401005c7: i2s_tx_channel_start + 0xb3
0x401012bf: i2s_channel_enable + 0x7f
0x400d5bfe: toit::primitive_start(toit::Process*, toit::Object**) + 0x5a
0x40081d3e: toit::Interpreter::run() + 0xa42
0x400f2771: toit::Scheduler::run_process(toit::Locker&, toit::Process*, toit::SchedulerThread*) + 0x5d
0x400f29f1: toit::Scheduler::run(toit::SchedulerThread*) + 0x5d
0x400f2a11: toit::SchedulerThread::entry() + 0x9
0x400e58fa: toit::Thread::_boot() + 0x22
0x400e5921: toit::esp_thread_start(void*) + 0x5

floitsch 03/18/2025 01:59 PM

Perfect. Thanks. That makes much more sense.

Rikke 03/18/2025 01:59 PM

Yeah as i thought. The jaguar sdk is not the correct one

floitsch 03/18/2025 01:59 PM

The DMA error is something we have been chasing, but so far has elluded us. I also have a small hope that upgrading the ESP-IDF to an even newer version could help.
Unfortunately, we don't know when it will get fixed.

floitsch 03/18/2025 01:59 PM

But with your error report we have a new angle to look at it.

Rikke 03/18/2025 02:00 PM

I did the same for first panic message:

echo Backtrace: 0x400d5901:0x3ffb2b50 0x40088c93:0x3ffb2b70 0x40087079:0x3ffb2bb0 0x40089b39:0x3ffb2bd0 0x4008544a:0x3ffaf9b0 0x4008558b:0x3ffaf9d0 | build/host/sdk/tools/stacktrace build/esp32/toit.elf
0x400d5901: toit::I2sResource::adjust_pending_event(int) + 0x9
0x40088c93: i2s_dma_tx_callback + 0x4f
0x40087079: shared_intr_isr + 0x35
0x40089b39: _xt_lowint1 + 0x89
0x4008544a: spi_flash_op_block_func + 0x22
0x4008558b: ipc_task + 0x53

floitsch 03/18/2025 02:00 PM

ah nice.

floitsch 03/18/2025 02:00 PM

Thanks.

OPRikke

It looks like a out of memory issue, but it shouldnt really cause a panic. I got a OOM message right before this, 55k free with largest free being 16k (trying to connect to MQTT wi...

floitsch 03/18/2025 02:08 PM

do you still have the message?
it shouldn't matter, but just in case.

Rikke 03/18/2025 02:09 PM

I do not

floitsch 03/18/2025 02:09 PM

np.

Rikke 03/18/2025 02:10 PM

Okay but I just got the same i2s dma buffer alloc error again, this time without any OOM messages

floitsch 03/18/2025 02:10 PM

ok. good to know.

floitsch 03/18/2025 02:10 PM

out of curiosity: what are you using the i2s for?

Rikke 03/18/2025 02:11 PM

To control our leds, we ran out of UARTs

floitsch 03/18/2025 02:12 PM

is it the pixel-strip?(edited)

Rikke 03/18/2025 02:13 PM

Yes

Rikke 03/18/2025 02:13 PM

W2812B

floitsch 03/18/2025 02:13 PM

how many leds do you have there?

Rikke 03/18/2025 02:14 PM

We are using 4, but they always use same color all 4 of them

floitsch 03/18/2025 02:16 PM

I wonder if we could use the RMT peripheral or the SPI interface instead.
Clearly, we need to fix this, but it might be an easy work-around for now.

floitsch 03/18/2025 02:16 PM

I will continue looking, but if I can't find anything soon (within a day or so), I might write an RMT/SPI version.

floitsch 03/18/2025 02:16 PM

Do you use the RMT for anything so far?

floitsch 03/18/2025 02:17 PM

(it is used behind your back for the DHT11, and one-wire bus)

Rikke 03/18/2025 02:17 PM

Its not really a rush for us, we turn off the leds after 2 minutes anyway, so its only really a problem when it boots. But boot time is super quick anyway

floitsch 03/18/2025 02:18 PM

good to know.
As I said: having crashes is really not nice, so we do want to fix this.
If it ever becomes more urgent to you, please ping us. It is already relatively high priority, but still.

Rikke 03/18/2025 02:19 PM

Yes I fully understand, but you dont have to write another driver for this, unless its a big issue for other people ofc

floitsch 03/18/2025 02:19 PM

Shouldn't be too hard and a challenge that sounds fun. But yes; I probably have other things to do

floitsch 03/19/2025 11:40 AM

@Rikke

: I couldn't resist. I just released a new version of the pixel-strip package that supports RMT. I think it should work nicely with the few pixels you have.(edited)

bitphlipphar 03/19/2025 12:13 PM

@floitsch

I think there is a missing null check here: https://github.com/toitware/esp-idf/blob/patch-head-5.3.1/components/esp_driver_i2s/i2s_common.c#L419. Could that explain the crash if we're really unlucky?

esp-idf/components/esp_driver_i2s/i2s_common.c at patch-head-5.3.1 ...

Espressif IoT Development Framework. Official development framework for ESP32. - toitware/esp-idf

bitphlipphar 03/19/2025 12:24 PM

Filed https://github.com/espressif/esp-idf/issues/15607.

Issues · espressif/esp-idf

Espressif IoT Development Framework. Official development framework for Espressif SoCs. - Issues · espressif/esp-idf

bitphlipphar 03/19/2025 02:16 PM

@Rikke

We've just released v2.0.0-alpha.176 with a few fixes. There still may be more work for us, but we wanted to make the new bits available as quickly as possible

(edited)

Rikke 03/20/2025 07:30 AM

Thanks

will try the new release today

Rikke 03/24/2025 12:20 PM

Looks like espressif added your line for null check, but I am still able to reproduce the panic when using I2S. I did not notice you've already added the line in alpha 176, so we might have to swap LED driver for now

bitphlipphar 03/24/2025 12:22 PM

Yeah, it was a bit of a long shot - and I wasn't convinced that it would solve the issue. More work for us, but do give the RMT-based LED driver a spin

OPRikke

Looks like espressif added your line for null check, but I am still able to reproduce the panic when using I2S. I did not notice you've already added the line in alpha 176, so we m...

floitsch 03/24/2025 12:23 PM

Is the stack trace still the same?

Rikke 03/24/2025 12:24 PM

I tried to decode but it cant find the xtensa-esp32-elf-objdump

echo Backtrace: 0x40101b83:0x3ffc3da0 0x4010294b:0x3ffc3dc0 0x400d5d32:0x3ffc3df0 0x40081d86:0x3ffc3e10 0x400f299d:0x3ffc3ea0 0x400f2c1d:0x3ffc3ef0 0x400f2c3d:0x3ffc3f20 0x400e5b3e:0x3ffc3f40 0x400e5b65:0x3ffc3f60 | build/host/sdk/tools/stacktrace build/esp32/toit.elf
EXCEPTION error. 
Error trying to run 'xtensa-esp32-elf-objdump' using $PATH: No such file or directory: xtensa-esp32-elf-objdump
  0: decode-stacktrace         /home/vsts/staging/toit/tools/stacktrace.toit:66:5
  1: build-command.<lambda>    /home/vsts/staging/toit/tools/stacktrace.toit:38:16
  2: Command.run.<block>       <pkg:pkg-cli>/cli.toit:308:40
  3: Parser_.parse             <pkg:pkg-cli>/parser_.toit:212:5
  4: Command.run               <pkg:pkg-cli>/cli.toit:306:12
  5: main                      /home/vsts/staging/toit/tools/stacktrace.toit:27:7

Rikke 03/24/2025 12:25 PM

But i am getting the same errors from i2s driver:

E (3711657) i2s_common: i2s_alloc_dma_desc(432): allocate DMA buffer failed
E (3711657) i2s_std: i2s_std_set_slot(106): allocate memory for dma descriptor failed
E (3711667) i2s_std: i2s_channel_init_std_mode(217): initialize channel failed while setting slot

Rikke 03/24/2025 12:30 PM

Okay i rebuild, reflashed and reproduced:

echo Backtrace: 0x40101b83:0x3ffc5da0 0x4010294b:0x3ffc5dc0 0x400d5d32:0x3ffc5df0 0x40081d86:0x3ffc5e10 0x400f299d:0x3ffc5ea0 0x400f2c1d:0x3ffc5ef0 0x400f2c3d:0x3ffc5f20 0x400e5b3e:0x3ffc5f40 0x400e5b65:0x3ffc5f60 | build/host/sdk/tools/stacktrace build/esp32/toit.elf
0x40101b83: i2s_tx_channel_start + 0xb3
0x4010294b: i2s_channel_enable + 0x7b
0x400d5d32: toit::primitive_start(toit::Process*, toit::Object**) + 0x5a
0x40081d86: toit::Interpreter::run() + 0xa42
0x400f299d: toit::Scheduler::run_process(toit::Locker&, toit::Process*, toit::SchedulerThread*) + 0x5d
0x400f2c1d: toit::Scheduler::run(toit::SchedulerThread*) + 0x5d
0x400f2c3d: toit::SchedulerThread::entry() + 0x9
0x400e5b3e: toit::Thread::_boot() + 0x22
0x400e5b65: toit::esp_thread_start(void*) + 0x5

Same error as before(edited)

floitsch 03/24/2025 12:35 PM

Thanks

Rikke 03/24/2025 12:47 PM

Well. I added a info log message when allocating the 6 DMA buffers, to check if its the first, last or just random buffer that fails. And so far I have not been able to reproduce

I am printing the info log messages to console(edited)

Rikke 03/24/2025 12:51 PM

Now Ive written 50 times in a row with no errors, I wonder if its a weird yield issue

floitsch 03/24/2025 12:51 PM

How did you instrument the code?

Rikke 03/24/2025 12:53 PM

I added ESP_LOGI(TAG, "DMA malloc info: dma_desc_num = %d", i); right before the line ESP_GOTO_ON_FALSE(handle->dma.bufs[i], ESP_ERR_NO_MEM, err, TAG, "allocate DMA buffer failed"); in the file third_party/esp-idf/components/esp_driver_i2s/i2s_common.c and rebuild, reflash and command the device to write to the LEDs with i2s over and over again

floitsch 03/24/2025 12:54 PM

weird. Clearly that should not change whether the thing crashes or not.
There is, of course, the possibility that cache lines are different, changing the timing, but I would hope that doesn't matter that much.

Rikke 03/24/2025 12:55 PM

Its really odd yes..

OPRikke

Its really odd yes..

bitphlipphar 03/24/2025 01:01 PM

Can you share the build/esp32/toit.elf file with me somehow? I'd like to take a look at the assembly code around 0x40101b83.

Rikke 03/24/2025 01:03 PM

How do you want me to send it to you?

bitphlipphar 03/24/2025 01:03 PM

Email perhaps? Maybe it is so big that I'll need to download it from somewhere?

Rikke 03/24/2025 01:04 PM

20M hmm

Rikke 03/24/2025 01:06 PM

Looks like I can send it over mail

Rikke 03/24/2025 01:07 PM

Do you have a support mail?

floitsch 03/24/2025 01:07 PM

Just send it to [email protected]

Rikke 03/24/2025 01:09 PM

Ah okay, it got decliend because it is too big

Rikke 03/24/2025 01:12 PM

The .zip mightve worked

bitphlipphar 03/24/2025 01:12 PM

Got it! Thanks

bitphlipphar 03/24/2025 01:17 PM

Found the load that is causing the crash. Now I have to try to figure out what it corresponds to in the C++ code

bitphlipphar 03/24/2025 01:17 PM

Good fun on a Monday!

Rikke 03/24/2025 01:20 PM

Okay I was finally able to make it crash with info log message, and it crashed when allocating the 3rd dma buffer

I (285857) i2s_common: DMA malloc info: dma_desc_num = 0
I (285857) i2s_common: DMA malloc info: dma_desc_num = 1
I (285857) i2s_common: DMA malloc info: dma_desc_num = 2
E (285857) i2s_common: i2s_alloc_dma_desc(433): allocate DMA buffer failed
E (285867) i2s_std: i2s_std_set_slot(106): allocate memory for dma descriptor failed
E (285877) i2s_std: i2s_channel_init_std_mode(217): initialize channel failed while setting slot

(edited)

floitsch 03/24/2025 01:38 PM

And then crashed immediately afterwards?

Rikke 03/24/2025 01:38 PM

Yes, it always crashes after the 3 i2s errors

floitsch 03/24/2025 01:39 PM

Kasper is already looking into the esp-idf to figure out where they don't handle null-pointers correctly.

floitsch 03/24/2025 01:39 PM

Normally, when the esp-idf can't allocate something it returns with an ERR_NO_MEM (or something like that).

floitsch 03/24/2025 01:39 PM

The Toit VM then does a GC and tries again.

floitsch 03/24/2025 01:40 PM

However, here the ESP_IDF isn't return correctly, and we don't get a chance to do any GC.

floitsch 03/24/2025 01:40 PM

For most users this isn't really an issue, since they can't do anything once the memory is tight.

floitsch 03/24/2025 01:40 PM

It's mostly interesting for systems that actually can find memory somewhere, like the Toit VM.

floitsch 03/24/2025 01:41 PM

We have plans to do a GC immediately inside a malloc, so that bugs like these don't affect the Toit VM, but that requires some refactoring in our primitives.

bitphlipphar 03/24/2025 02:51 PM

So the crash is definitely loading from dma.desc even though it is NULL. Maybe there is a missing failure check in the code that calls i2s_alloc_dma_desc, so it still tries to start the tx even though it is out of memory.

bitphlipphar 03/25/2025 06:37 AM

I think I've found another subtle bug in esp-idf.

bitphlipphar 03/25/2025 06:42 AM

/* The DMA buffer need to re-allocate if the buffer size changed */
    if (handle->dma.buf_size != buf_size) {
        handle->dma.buf_size = buf_size;
        ESP_RETURN_ON_ERROR(i2s_free_dma_desc(handle), TAG, "failed to free the old dma descriptor");
        ESP_RETURN_ON_ERROR(i2s_alloc_dma_desc(handle, handle->dma.desc_num, buf_size),
                            TAG, "allocate memory for dma descriptor failed");
    }

bitphlipphar 03/25/2025 06:43 AM

It seems completely broken to update handle->dma.buf_size before making sure that the allocations succeed. If we fail the allocation and retry, we will not try to re-allocate the structures.

bitphlipphar 03/25/2025 06:52 AM

Filed https://github.com/espressif/esp-idf/issues/15648.

bitphlipphar 03/25/2025 07:12 AM

Will try to patch this in our own fork of the esp-idf and get a new build out.

Rikke 03/25/2025 08:09 AM

Nice job! I can try and patch myself to test

bitphlipphar 03/25/2025 08:09 AM

You probably only need the changes in i2s_std.c.(edited)

bitphlipphar 03/25/2025 08:11 AM

You should still expect to see the error logs (E (285857) i2s_common: i2s_alloc_dma_desc(433): allocate DMA buffer failed), but at least now there should be a chance that it will not lead to a crash on the retry.

Rikke 03/25/2025 08:11 AM

Okay so move the size change till after it has been allocated

bitphlipphar 03/25/2025 08:12 AM

/* The DMA buffer need to re-allocate if the buffer size changed */
     if (handle->dma.buf_size != buf_size) {
-        handle->dma.buf_size = buf_size;
         ESP_RETURN_ON_ERROR(i2s_free_dma_desc(handle), TAG, "failed to free the old dma descriptor");
         ESP_RETURN_ON_ERROR(i2s_alloc_dma_desc(handle, handle->dma.desc_num, buf_size),
                             TAG, "allocate memory for dma descriptor failed");
+        handle->dma.buf_size = buf_size;
     }

bitphlipphar 03/25/2025 08:12 AM

Yes.

Rikke 03/25/2025 08:36 AM

I still got a panic :/

Rikke 03/25/2025 08:37 AM

Same errors, same backtrace

bitphlipphar 03/25/2025 08:38 AM

Probably just means more work for me, but can you post your git diff from the esp-idf directory?

Rikke 03/25/2025 08:39 AM

Yes let me clean up some logs and reproduce again

Rikke 03/25/2025 08:42 AM

diff --git a/components/esp_driver_i2s/i2s_common.c b/components/esp_driver_i2s/i2s_common.c
index ca7332e32..695a7a30e 100644
--- a/components/esp_driver_i2s/i2s_common.c
+++ b/components/esp_driver_i2s/i2s_common.c
@@ -417,7 +417,7 @@ esp_err_t i2s_alloc_dma_desc(i2s_chan_handle_t handle, uint32_t num, uint32_t bu
     handle->dma.desc = (lldesc_t **)heap_caps_calloc(num, sizeof(lldesc_t *), I2S_MEM_ALLOC_CAPS);
     ESP_GOTO_ON_FALSE(handle->dma.desc, ESP_ERR_NO_MEM, err, TAG, "create I2S DMA descriptor array failed");
     handle->dma.bufs = (uint8_t **)heap_caps_calloc(num, sizeof(uint8_t *), I2S_MEM_ALLOC_CAPS);
-    ESP_GOTO_ON_FALSE(handle->dma.bufs, ESP_ERR_NO_MEM, err, TAG, "create I2S DMA buffers array failed");
+    ESP_GOTO_ON_FALSE(handle->dma.bufs, ESP_ERR_NO_MEM, err, TAG, "create I2S DMA buffer array failed");
     for (int i = 0; i < num; i++) {
         /* Allocate DMA descriptor */
         handle->dma.desc[i] = (lldesc_t *) i2s_dma_calloc(handle, 1, sizeof(lldesc_t));

Rikke 03/25/2025 08:42 AM

@@ -429,6 +429,7 @@ esp_err_t i2s_alloc_dma_desc(i2s_chan_handle_t handle, uint32_t num, uint32_t bu
         handle->dma.desc[i]->size = bufsize;
         handle->dma.desc[i]->offset = 0;
         handle->dma.bufs[i] = (uint8_t *) i2s_dma_calloc(handle, 1, bufsize * sizeof(uint8_t));
+        // ESP_LOGI(TAG, "DMA malloc info: dma_desc_num = %d", i);
         ESP_GOTO_ON_FALSE(handle->dma.bufs[i], ESP_ERR_NO_MEM, err, TAG,  "allocate DMA buffer failed");
 #if SOC_CACHE_INTERNAL_MEM_VIA_L1CACHE
         esp_cache_msync(handle->dma.bufs[i], bufsize * sizeof(uint8_t), ESP_CACHE_MSYNC_FLAG_DIR_C2M);
diff --git a/components/esp_driver_i2s/i2s_std.c b/components/esp_driver_i2s/i2s_std.c
index c3ef0c046..878b1845c 100644
--- a/components/esp_driver_i2s/i2s_std.c
+++ b/components/esp_driver_i2s/i2s_std.c
@@ -101,10 +101,10 @@ static esp_err_t i2s_std_set_slot(i2s_chan_handle_t handle, const i2s_std_slot_c
     uint32_t buf_size = i2s_get_buf_size(handle, slot_cfg->data_bit_width, handle->dma.frame_num);
     /* The DMA buffer need to re-allocate if the buffer size changed */
     if (handle->dma.buf_size != buf_size) {
-        handle->dma.buf_size = buf_size;
         ESP_RETURN_ON_ERROR(i2s_free_dma_desc(handle), TAG, "failed to free the old dma descriptor");
         ESP_RETURN_ON_ERROR(i2s_alloc_dma_desc(handle, handle->dma.desc_num, buf_size),
                             TAG, "allocate memory for dma descriptor failed");
+        handle->dma.buf_size = buf_size;
     }
     bool is_slave = handle->role == I2S_ROLE_SLAVE;
     /* Share bck and ws signal in full-duplex mode */

bitphlipphar 03/25/2025 08:43 AM

Yeah, I just found another bug.

Rikke 03/25/2025 08:43 AM

Another one okay

bitphlipphar 03/25/2025 08:44 AM

So i2s_alloc_dma_desc updates buf_size too and it does it wrong.

bitphlipphar 03/25/2025 08:51 AM

esp_err_t i2s_free_dma_desc(i2s_chan_handle_t handle)
 {
     I2S_NULL_POINTER_CHECK(TAG, handle);
+    uint32_t desc_num = handle->dma.desc_num;
+
+    handle->dma.desc_num = 0;
+    handle->dma.buf_size = 0;
+
     if (!handle->dma.desc) {
         return ESP_OK;
     }
-    for (int i = 0; i < handle->dma.desc_num; i++) {
+    for (int i = 0; i < desc_num; i++) {
         if (handle->dma.bufs[i]) {

bitphlipphar 03/25/2025 08:52 AM

That is my next attempt. Also I'm dropping all the updates to buf_size outside of i2s_alloc_dma_desc, but I don't think it matters much.

Rikke 03/25/2025 08:54 AM

Testing changes to free dma desc

Rikke 03/25/2025 08:55 AM

E (971) i2s_common: i2s_alloc_dma_desc(423): create I2S DMA descriptor array failed
E (971) i2s_std: i2s_std_set_slot(105): allocate memory for dma descriptor failed
E (971) i2s_std: i2s_channel_init_std_mode(217): initialize channel failed while setting slot
E (981) i2s_common: i2s_alloc_dma_desc(423): create I2S DMA descriptor array failed
E (991) i2s_std: i2s_std_set_slot(105): allocate memory for dma descriptor failed
E (1001) i2s_std: i2s_channel_init_std_mode(217): initialize channel failed while setting slot
E (1011) i2s_common: i2s_alloc_dma_desc(423): create I2S DMA descriptor array failed
E (1011) i2s_std: i2s_std_set_slot(105): allocate memory for dma descriptor failed
E (1021) i2s_std: i2s_channel_init_std_mode(217): initialize channel failed while setting slot

Rikke 03/25/2025 08:55 AM

Heap report @ out of memory in primitive 7:2:
  ┌───────────┬──────────┬─────────────────────────────────────────────────────┐
  │   Bytes   │  Count   │  Type                                               │
  ├───────────┼──────────┼─────────────────────────────────────────────────────┤
  │       8   │      1   │  external byte array                                │
  │   32768   │     10   │  toit processes                                     │
  │     16384 │        4 │    system    0 ba2bb6f3-b6cd-d9c6-621d-7632ae3d2f0c │
  │     16384 │        4 │    current   1 8de635b4-126e-3003-f980-e3a3ec6281c5 │
  │   20480   │      1   │  heap metadata                                      │
  │    4096   │      1   │  spare new-space                                    │
  │    5352   │     13   │  lwip                                               │
  │    4720   │    326   │  heap overhead                                      │
  │    2104   │     33   │  event source                                       │
  │    9424   │    126   │  thread/other                                       │
  │   26400   │     21   │  thread/spawn                                       │
  │   22696   │    100   │  untagged                                           │
  └───────────┴──────────┴─────────────────────────────────────────────────────┘
  Total: 128048 bytes in 304 allocations (43%), largest free 108k, total free 165k
E (1201) i2s_common: i2s_alloc_dma_desc(423): create I2S DMA descriptor array failed
E (1211) i2s_std: i2s_std_set_slot(105): allocate memory for dma descriptor failed
E (1221) i2s_std: i2s_channel_init_std_mode(217): initialize channel failed while setting slot

Rikke 03/25/2025 08:58 AM

diff --git a/components/esp_driver_i2s/i2s_common.c b/components/esp_driver_i2s/i2s_common.c
index ca7332e32..f0fd7483f 100644
--- a/components/esp_driver_i2s/i2s_common.c
+++ b/components/esp_driver_i2s/i2s_common.c
@@ -380,10 +380,15 @@ uint32_t i2s_get_buf_size(i2s_chan_handle_t handle, uint32_t data_bit_width, uin
 esp_err_t i2s_free_dma_desc(i2s_chan_handle_t handle)
 {
     I2S_NULL_POINTER_CHECK(TAG, handle);
+    uint32_t desc_num = handle->dma.desc_num;
+
+    handle->dma.desc_num = 0;
+    handle->dma.buf_size = 0;
+
     if (!handle->dma.desc) {
         return ESP_OK;
     }
-    for (int i = 0; i < handle->dma.desc_num; i++) {
+    for (int i = 0; i < desc_num; i++) {
         if (handle->dma.bufs[i]) {
             free(handle->dma.bufs[i]);
             handle->dma.bufs[i] = NULL;

bitphlipphar 03/25/2025 08:58 AM

So no crash in native code?

Rikke 03/25/2025 08:58 AM

Nope

Rikke 03/25/2025 08:59 AM

******************************************************************************
Decoding by `jag`, device has version <2.0.0-alpha.176>
******************************************************************************
MALLOC_FAILED error.
  0: Bus.configure             <sdk>/i2s.toit:475:5
  1: LedI2S                    /home/vsts/--/src/i2s_led_driver.toit:96:13
  2: led-task                  /home/vsts/--/src/led_handler.toit:91:13
  3: setup-gpio                /home/vsts/--/src/pinout.toit:130:5
  4: main                      /home/vsts/--/src/gateway.toit:25:3
******************************************************************************

but reset because of [toit] WARN: entering deep sleep for 1s due to error(edited)

bitphlipphar 03/25/2025 09:00 AM

That is progress!

bitphlipphar 03/25/2025 09:05 AM

Now we have to figure out why the three attempts to initialize the i2s subsystem with GCs in between isn't enough to make this work.

Rikke 03/25/2025 09:10 AM

But it fails on i2s.bus configure now, not i2s.bus start like before

Rikke 03/25/2025 09:11 AM

And it crashed when trying to start a i2s.bus with dma allocation fail

floitsch 03/25/2025 09:12 AM

Does your code (up to this point) depend on specific hardware?

floitsch 03/25/2025 09:12 AM

Or do you think we could maybe reproduce it locally?

Rikke 03/25/2025 09:14 AM

Should be easy to reproduce locally, i set up the i2s:

i2s_bus = i2s.Bus
      --master=true
      --mclk=null
      --tx=pin
      --sck=null
      --ws=null

    i2s_bus.configure
      --sample_rate=100_000 
      --bits_per_sample=32 

    i2s_bus.start

and write written := i2s_bus.write buf.copy + reset.copy

OPRikke

But it fails on i2s.bus configure now, not i2s.bus start like before

bitphlipphar 03/25/2025 09:14 AM

Yeah, so we now notice that we failed to allocate the buffers, so the primitive fails. Before it would claim to succeed leading to a crash down the line.

bitphlipphar

Yeah, so we now notice that we failed to allocate the buffers, so the primitive fails. Before it would claim to succeed leading to a crash down the line.

Rikke 03/25/2025 09:14 AM

Ah true

OPRikke

Should be easy to reproduce locally, i set up the i2s: ``` i2s_bus = i2s.Bus --master=true --mclk=null --tx=pin --sck=null --ws=null i2s_bus....

floitsch 03/25/2025 09:14 AM

Is that all you do?
no other hardware/drivers started before?

Rikke 03/25/2025 09:15 AM

Its a part of our code, but I can see if I can run and reproduce on a simple esp devkit

Rikke 03/25/2025 09:16 AM

import i2s
import bytes
import gpio
import encoding.hex
import system.storage

the imports we use for driver

floitsch 03/25/2025 09:18 AM

Interesting. I did a lot of i2s tests, but never encountered this error. That said, I never used 100_000 samples. So maybe that's why.
I just assumed it was dependent on other code you had run before. I will give it a try in a few minutes and see if I can reproduce.

Rikke 03/25/2025 09:20 AM

Hm not sure how to flash a dev kit through jag with my own build sdk

floitsch 03/25/2025 09:20 AM

You need to have a local checkout of Jaguar.

Rikke 03/25/2025 09:21 AM

When building jag it does not put in the sdk under .cache

floitsch 03/25/2025 09:21 AM

But let me test first. If I can reproduce you don't need to go through the trouble.

floitsch 03/25/2025 09:21 AM

If you have a local Jaguar, you need to set JAG_TOIT_REPO_PATH to the root of the SDK checkout

floitsch 03/25/2025 09:22 AM

Then you can just make and it also builds the envelope.

Rikke 03/25/2025 09:23 AM

This is our jag build command JAG_TOIT_REPO_PATH=~/staging/toit make -C staging/jaguar JAG_BUILD_RELEASE=1(edited)

floitsch 03/25/2025 09:23 AM

I described my workflow a few days ago: https://discord.com/channels/918498540232253480/1351095805624188983/1351244613096312922(edited)

bitphlipphar 03/25/2025 09:24 AM

You probably don't want to pass JAG_BUILD_RELEASE=1 because that will give you a binary that only looks in ~/.cache/ if I am not mistaken.

Rikke 03/25/2025 09:24 AM

Ah okay, will try without

OPRikke

Should be easy to reproduce locally, i set up the i2s: ``` i2s_bus = i2s.Bus --master=true --mclk=null --tx=pin --sck=null --ws=null i2s_bus....

floitsch 03/25/2025 09:49 AM

looks like that on its own isn't enough.

floitsch 03/25/2025 09:49 AM

import i2s
import bytes
import gpio
import encoding.hex
import system.storage

main:
  pin := gpio.Pin 32

  i2s_bus := i2s.Bus
    --master=true
    --mclk=null
    --tx=pin
    --sck=null
    --ws=null

  i2s_bus.configure
    --sample_rate=100_000
    --bits_per_sample=32

  i2s_bus.start

  bytes := ByteArray 1024
  i2s_bus.write bytes

Rikke 03/25/2025 09:50 AM

We open it everytime we write and close it again afterwards

Rikke 03/25/2025 09:51 AM

So everytime we write to the leds. we have to open the i2s.bus and that means allocating the 6 dma buffers

floitsch 03/25/2025 09:52 AM

This is my code now:

import i2s
import bytes
import gpio
import encoding.hex
import system.storage

main:
  while true:
    pin := gpio.Pin 32

    i2s_bus := i2s.Bus
      --master=true
      --mclk=null
      --tx=pin
      --sck=null
      --ws=null

    i2s_bus.configure
      --sample_rate=100_000
      --bits_per_sample=32

    i2s_bus.start

    bytes := ByteArray 1024
    i2s_bus.write bytes
    i2s_bus.stop
    i2s_bus.close
    pin.close

Still no crash.

Rikke 03/25/2025 09:54 AM

Dont know if its a actual memory issue, because we have high traffic in our dev area that has to be passed and sent on mqtt. This often leads to low memory so bad timing is prob what causes the allocation error

Rikke 03/25/2025 09:56 AM

Not sure what other drivers are using dma

floitsch 03/25/2025 09:56 AM

could be general memory pressure as well.

Rikke 03/25/2025 09:57 AM

I tried following the other thread and the jaguar github but it wont work. heres a attempt to jag flash

Error: Failed to open '' for reading (FILE_NOT_FOUND: "").
Error: exit status 1

JAG_TOIT_REPO_PATH=/home/vsts/staging/toit

(edited)

floitsch 03/25/2025 09:58 AM

can you show a bit more output (the lines before).

Rikke 03/25/2025 09:59 AM

vsts@rikke:~/staging/jaguar$ build/jag flash
Enter WiFi network (SSID): WiFi_QA_3
Enter WiFi password for 'WiFi_QA_3': 
Error: Failed to open '' for reading (FILE_NOT_FOUND: "").
Error: exit status 1

floitsch 03/25/2025 09:59 AM

That just seems to indicate that it doesn't find the usb-port

floitsch 03/25/2025 10:01 AM

btw: if you are frequently flashing, you can avoid typing the wifi credentials by

build/jag config wifi set --wifi-password="WiFi_QA_3" --wifi-ssid="WiFi_QA_3"

Rikke 03/25/2025 10:01 AM

Odd when jag monitor works

bitphlipphar 03/25/2025 10:01 AM

Could be that you can't find the tools for flashing.

floitsch 03/25/2025 10:02 AM

that's right. you might not have esptool.py where we try to find it.

floitsch 03/25/2025 10:04 AM

Kasper and I have the esptool.py in our PATH.

floitsch 03/25/2025 10:04 AM

Try to source the export.sh from the esp-idf.

Rikke 03/25/2025 10:04 AM

I will add that to the build process

Rikke 03/25/2025 10:05 AM

This docker container does not have access to esptool.py i think

floitsch 03/25/2025 10:05 AM

Since you are on Windows, you might need export.bat.

Rikke 03/25/2025 10:06 AM

I am on linux

floitsch 03/25/2025 10:06 AM

No idea where I got that from. Sorry.
Then source $JAG_TOIT_REPO_PATH/third_party/esp-idf/export.sh should do it.

Rikke 03/25/2025 10:09 AM

Okay it is there ./toit/third_party/esp-idf/components/esptool_py/esptool/esptool.pybut its not added with the exports.. Guess i will manually add it

floitsch 03/25/2025 10:10 AM

weird. For me it added it.

floitsch 03/25/2025 10:11 AM

ᐅ source ../opentoit/third_party/esp-idf/export.sh
Setting IDF_PATH to '/home/flo/work/opentoit/third_party/esp-idf'
...
ᐅ which esptool.py
/home/flo/.espressif/python_env/idf5.3_py3.13_env/bin/esptool.py

Rikke 03/25/2025 10:13 AM

Yeah I just give up

floitsch 03/25/2025 10:13 AM

no worries

floitsch 03/25/2025 10:59 AM

[jaguar] INFO: program cbaa7f18-0910-cf8a-ed22-16dbb4a5f3b7 started
E (9020) i2s_common: i2s_alloc_dma_desc(432): allocate DMA buffer failed
E (9020) i2s_std: i2s_std_set_slot(106): allocate memory for dma descriptor failed
E (9020) i2s_std: i2s_channel_init_std_mode(217): initialize channel failed while setting slot
Guru Meditation Error: Core  0 panic'ed (LoadProhibited). Exception was unhandled.

Core  0 register dump:
PC      : 0x40105292  PS      : 0x00060930  A0      : 0x80106092  A1      : 0x3ffd1da0  
A2      : 0x3ffef9f8  A3      : 0xffffffff  A4      : 0x00000000  A5      : 0x00000000  
A6      : 0x00000000  A7      : 0x3fff547c  A8      : 0x3ff4f000  A9      : 0x00000000  
A10     : 0x00000000  A11     : 0x00000002  A12     : 0x00060920  A13     : 0x00060923  
A14     : 0x00000001  A15     : 0x3ffbdd28  SAR     : 0x00000018  EXCCAUSE: 0x0000001c  
EXCVADDR: 0x00000000  LBEG    : 0x4000c349  LEND    : 0x4000c36b  LCOUNT  : 0xffffffff  



******************************************************************************
Decoding by `jag`, device has version <2.0.0-alpha.176.4+floitsch-i2c.registers.slave.a63ae902>
******************************************************************************
Crash in native code:
Backtrace: 0x4010528f:0x3ffd1da0 0x4010608f:0x3ffd1dc0 0x400d99f6:0x3ffd1df0 0x40081e72:0x3ffd1e10 0x400f63d4:0x3ffd1ea0 0x400f665d:0x3ffd1ef0 0x400f667d:0x3ffd1f20 0x400e97c6:0x3ffd1f40 0x400e97ed:0x3ffd1f60
0x4010528f: i2s_tx_channel_start + 0xb3
0x4010608f: i2s_channel_enable + 0x7f

First step in reproducing.
This is still without Kasper's patch.

bitphlipphar 03/25/2025 10:59 AM

Nice!

floitsch 03/25/2025 11:02 AM

I'm just running a second container that does https stuff in a loop.

floitsch 03/25/2025 11:09 AM

[jaguar] INFO: program 5243ce0f-2715-f465-ab36-1119f0d306ca started
E (54350) i2s_common: i2s_alloc_dma_desc(422): create I2S DMA descriptor array failed
E (54350) i2s_std: i2s_std_set_slot(105): allocate memory for dma descriptor failed
E (54350) i2s_std: i2s_channel_init_std_mode(216): initialize channel failed while setting slot
E (54370) i2s_common: i2s_alloc_dma_desc(422): create I2S DMA descriptor array failed
E (54370) i2s_std: i2s_std_set_slot(105): allocate memory for dma descriptor failed
E (54370) i2s_std: i2s_channel_init_std_mode(216): initialize channel failed while setting slot
E (54390) i2s_common: i2s_alloc_dma_desc(422): create I2S DMA descriptor array failed
E (54400) i2s_std: i2s_std_set_slot(105): allocate memory for dma descriptor failed
E (54400) i2s_std: i2s_channel_init_std_mode(216): initialize channel failed while setting slot
Heap report @ out of memory in primitive 7:2:
  ┌───────────┬──────────┬─────────────────────────────────────────────────────┐
...
  └───────────┴──────────┴─────────────────────────────────────────────────────┘
  Total: 198768 bytes in 475 allocations (83%), largest free 24k, total free 42k
E (54610) i2s_common: i2s_alloc_dma_desc(422): create I2S DMA descriptor array failed
E (54610) i2s_std: i2s_std_set_slot(105): allocate memory for dma descriptor failed
E (54620) i2s_std: i2s_channel_init_std_mode(216): initialize channel failed while setting slot

******************************************************************************
Decoding by `jag`, device has version <2.0.0-alpha.176.5+f1a00000>
******************************************************************************
MALLOC_FAILED error.
  0: Bus.configure             <sdk>/i2s.toit:473:5
  1: main                      /home/flo/tmp/i2s-dma/main.toit:18:13
******************************************************************************

I can reproduce.

Rikke 03/25/2025 11:15 AM

So it is also related to low memory

floitsch 03/25/2025 11:28 AM

Or memory pressure

floitsch 03/25/2025 11:28 AM

And memory churn

bitphlipphar 03/25/2025 11:40 AM

One theory is that it is two containers that fight for the same memory, unable to coordinate their efforts well enough.

Rikke 03/25/2025 11:40 AM

Okay a rebuild of jag without release flag fixed all my problems. stacktrace is now correct and I can use jag flash

bitphlipphar

One theory is that it is two containers that fight for the same memory, unable to coordinate their efforts well enough.

Rikke 03/25/2025 11:56 AM

We are only running 2 containers, the "system" and our program

OPRikke

We are only running 2 containers, the "system" and our program

bitphlipphar 03/25/2025 12:22 PM

So the MQTT activity is from the same container that tries to use the LEDs via I2S?

Rikke 03/25/2025 12:23 PM

Yes, we run everything from same container. We are starting a new container for modem connectivity, but I am currently testing on wifi

OPRikke

Yes, we run everything from same container. We are starting a new container for modem connectivity, but I am currently testing on wifi

bitphlipphar 03/25/2025 12:33 PM

That's good news. I think that will make it easier for us to debug and fix.

bitphlipphar 03/25/2025 03:34 PM

Looks like we found and fixed the issue.

bitphlipphar 03/25/2025 03:34 PM

https://github.com/toitlang/toit/commit/1790b3c4077a06a10c9e4d271bd216a6150085a7

Roll esp-idf again (#2751) · toitlang/toit@1790b3c

bitphlipphar 03/26/2025 11:20 AM

@Rikke

Let me know if you're able to update to HEAD of the master branch and try the fix

I'll be preparing a new SDK release if things look good to you.

Rikke 03/26/2025 11:26 AM

I would have to manually patch it with the changes in the commit above, our build system is based on specific sdk versions, gonna test it now

bitphlipphar 03/26/2025 11:27 AM

Thank you!

bitphlipphar 03/26/2025 11:28 AM

My original fix made the i2s subsystem ask for zero bytes on retry (a clear bug) and the allocator always responds with null in that case. When the allocator returns null, we assume we're out of memory and try to clean up and retry, but we just kept asking for zero bytes repeatedly thus eventually concluding that there was no memory left. Woops.(edited)

Rikke 03/26/2025 11:29 AM

Haha

Rikke 03/26/2025 11:39 AM

It no longer panics on i2s error!

E (13649) i2s_common: i2s_alloc_dma_desc(434): allocate DMA buffer failed
E (13649) i2s_std: i2s_std_set_slot(106): allocate memory for dma descriptor failed
E (13659) i2s_std: i2s_channel_init_std_mode(217): initialize channel failed while setting slot
E (13669) i2s_common: i2s_alloc_dma_desc(434): allocate DMA buffer failed
E (13669) i2s_std: i2s_std_set_slot(106): allocate memory for dma descriptor failed
E (13679) i2s_std: i2s_channel_init_std_mode(217): initialize channel failed while setting slot

no reset(edited)

bitphlipphar 03/26/2025 11:40 AM

So it works better for you?

Rikke 03/26/2025 11:40 AM

Yes, im pretty sure it just retries because leds are correct after error

bitphlipphar 03/26/2025 11:40 AM

I get the feeling you don't like panics

floitsch 03/26/2025 11:41 AM

fwiw, I would still switch to the RMT implementation. It should use less memory for the 4 LEDs.

Rikke 03/26/2025 11:42 AM

It wasnt really a problem until i tested on our other devices. We have a device controlling machinery by toggling a relay, and we light up when we are controlling. This device might end up in a restart loop because it restarts and toggles led to indicate its controlling etc

floitsch

fwiw, I would still switch to the RMT implementation. It should use less memory for the 4 LEDs.

Rikke 03/26/2025 11:42 AM

I did notice that. I like the RMT implementation

Rikke 03/26/2025 11:45 AM

I would 100% prefer just retrying instead of full chip reboot, and I am sure I am not the only one

211 messages in total