https://toitlang.org/ logo
Powered by
I2S on 2.0.0-alpha.175 causing panic
# help
r
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
to
Copy code
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:
Copy code
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?
f
Not good...
I'm having a look.
Are you sure it's during startup?
(there is a 
deinit-callback
)
r
I am not 100% sure no, but I can try and reproduce with more debugging messages
f
The ideal would be something I can reproduce, but I'm looking at the code too.
Could also be that the stacktrace isn't correct.
I don't see how the 
dma_rx_callback
can call the deinit.
Do you have external (spiram) ram?
r
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
So maybe its using default sdk
f
Ok. So this is on a standard esp32 without any spiram.
r
Correct
f
Looking at the error message it's likely I forgot to add an 
IRAM
attribute.
Do you build your envelope yourself, or do you use a published one?
r
I am building myself
f
Ok. In that case try to disable 
I2S_ISR_IRAM_SAFE
.
r
Copy code
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
Copy code
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
f
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.
I need to find the place where I forgot the IRAM attribute.
r
I will rebuild and try to reproduce
f
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.
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.
r
Its fine, i will just test this for now
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.
Copy code
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
Copy code
*************
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
*************
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)
f
I wonder if this is related to https://github.com/toitlang/toit/issues/2714
Basically, we are sometimes running out of DMA buffers.
So far we have only seen this from the wifi-stack, which made it really hard to investigate, as that code is closed source.
Seeing a similar error in a different part of the system is interesting.
Do you think the stacktrace is trustworthy? Could you try to decode it with the SDK that you used to build your envelope?
Copy code
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
r
I have not been able to reproduce the dma/oom error since I posted the last message. I will try and decode
Copy code
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
f
Perfect. Thanks. That makes much more sense.
r
Yeah as i thought. The jaguar sdk is not the correct one
f
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.
But with your error report we have a new angle to look at it.
r
I did the same for first panic message:
Copy code
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
f
ah nice.
Thanks.
do you still have the message? it shouldn't matter, but just in case.
r
I do not 😦
f
np.
r
Okay but I just got the same i2s dma buffer alloc error again, this time without any OOM messages
f
ok. good to know.
out of curiosity: what are you using the i2s for?
r
To control our leds, we ran out of UARTs
f
is it the pixel-strip?
r
Yes
W2812B
f
how many leds do you have there?
r
We are using 4, but they always use same color all 4 of them
f
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.
I will continue looking, but if I can't find anything soon (within a day or so), I might write an RMT/SPI version.
Do you use the RMT for anything so far?
(it is used behind your back for the DHT11, and one-wire bus)
r
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
f
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.
r
Yes I fully understand, but you dont have to write another driver for this, unless its a big issue for other people ofc
f
Shouldn't be too hard and a challenge that sounds fun. But yes; I probably have other things to do 🙂
@User : 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.
k
@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?
@User 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 🙂
r
Thanks 🙂 will try the new release today
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
k
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 🙂
f
Is the stack trace still the same?
r
I tried to decode but it cant find the 
xtensa-esp32-elf-objdump
Copy code
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
But i am getting the same errors from i2s driver:
Copy code
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
Okay i rebuild, reflashed and reproduced:
Copy code
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
f
Thanks
r
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
Now Ive written 50 times in a row with no errors, I wonder if its a weird yield issue
f
How did you instrument the code?
r
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
f
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.
r
Its really odd yes..
k
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.
r
How do you want me to send it to you?
k
Email perhaps? Maybe it is so big that I'll need to download it from somewhere?
r
20M hmm
Looks like I can send it over mail
Do you have a support mail?
f
Just send it to kasper@toit.io
r
Ah okay, it got decliend because it is too big
The .zip mightve worked
k
Got it! Thanks 🙂
Found the load that is causing the crash. Now I have to try to figure out what it corresponds to in the C++ code 🙂
Good fun on a Monday!
r
Okay I was finally able to make it crash with info log message, and it crashed when allocating the 3rd dma buffer 🤷
Copy code
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
f
And then crashed immediately afterwards?
r
Yes, it always crashes after the 3 i2s errors
f
Kasper is already looking into the esp-idf to figure out where they don't handle null-pointers correctly.
Normally, when the esp-idf can't allocate something it returns with an ERR_NO_MEM (or something like that).
The Toit VM then does a GC and tries again.
However, here the ESP_IDF isn't return correctly, and we don't get a chance to do any GC.
For most users this isn't really an issue, since they can't do anything once the memory is tight.
It's mostly interesting for systems that actually can find memory somewhere, like the Toit VM.
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.
k
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.
I think I've found another subtle bug in esp-idf.
Copy code
/* 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");
    }
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.
Will try to patch this in our own fork of the esp-idf and get a new build out.
r
Nice job! I can try and patch myself to test
k
You probably only need the changes in 
i2s_std.c
.
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.
r
Okay so move the size change till after it has been allocated
k
Copy code
/* 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;
     }
Yes.
r
I still got a panic :/
Same errors, same backtrace
k
Probably just means more work for me, but can you post your 
git diff
from the esp-idf directory? 🙂
r
Yes let me clean up some logs and reproduce again
Copy code
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));
Copy code
@@ -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 */
k
Yeah, I just found another bug.
r
Another one okay
k
So i2s_alloc_dma_desc updates 
buf_size
too and it does it wrong.
Copy code
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]) {
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.
r
Testing changes to free dma desc
Copy code
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
Copy code
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
Copy code
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;
k
So no crash in native code?
r
Nope
Copy code
******************************************************************************
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
k
That is progress!
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.
r
But it fails on i2s.bus configure now, not i2s.bus start like before
And it crashed when trying to start a i2s.bus with dma allocation fail
f
Does your code (up to this point) depend on specific hardware?
Or do you think we could maybe reproduce it locally?
r
Should be easy to reproduce locally, i set up the i2s:
Copy code
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
k
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.
r
Ah true
f
Is that all you do? no other hardware/drivers started before?
r
Its a part of our code, but I can see if I can run and reproduce on a simple esp devkit
Copy code
import i2s
import bytes
import gpio
import encoding.hex
import system.storage
the imports we use for driver
f
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.
r
Hm not sure how to flash a dev kit through jag with my own build sdk
f
You need to have a local checkout of Jaguar.
r
When building jag it does not put in the sdk under .cache
f
But let me test first. If I can reproduce you don't need to go through the trouble.
If you have a local Jaguar, you need to set 
JAG_TOIT_REPO_PATH
to the root of the SDK checkout
Then you can just 
make
and it also builds the envelope.
r
This is our jag build command 
JAG_TOIT_REPO_PATH=~/staging/toit make -C staging/jaguar JAG_BUILD_RELEASE=1
f
k
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.
r
Ah okay, will try without
f
looks like that on its own isn't enough.
Copy code
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
r
We open it everytime we write and close it again afterwards
So everytime we write to the leds. we have to open the i2s.bus and that means allocating the 6 dma buffers
f
This is my code now:
Copy code
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.
r
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
Not sure what other drivers are using dma
f
could be general memory pressure as well.
r
I tried following the other thread and the jaguar github but it wont work. heres a attempt to jag flash
Copy code
Error: Failed to open '' for reading (FILE_NOT_FOUND: "").
Error: exit status 1
JAG_TOIT_REPO_PATH=/home/vsts/staging/toit
f
can you show a bit more output (the lines before).
r
Copy code
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
f
That just seems to indicate that it doesn't find the usb-port
btw: if you are frequently flashing, you can avoid typing the wifi credentials by
Copy code
build/jag config wifi set --wifi-password="WiFi_QA_3" --wifi-ssid="WiFi_QA_3"
r
Odd when jag monitor works
k
Could be that you can't find the tools for flashing.
f
that's right. you might not have esptool.py where we try to find it.
Kasper and I have the esptool.py in our PATH.
Try to source the export.sh from the esp-idf.
r
I will add that to the build process
This docker container does not have access to esptool.py i think
f
Since you are on Windows, you might need export.bat.
r
I am on linux
f
No idea where I got that from. Sorry. Then 
source $JAG_TOIT_REPO_PATH/third_party/esp-idf/export.sh
should do it.
r
Okay it is there `./toit/third_party/esp-idf/components/esptool_py/esptool/esptool.py`but its not added with the exports.. Guess i will manually add it
f
weird. For me it added it.
Copy code
ᐅ 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
r
Yeah I just give up 🙃
f
no worries 🙂
Copy code
[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.
k
Nice!
f
I'm just running a second container that does https stuff in a loop.
Copy code
[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.
r
So it is also related to low memory
f
Or memory pressure
And memory churn
k
One theory is that it is two containers that fight for the same memory, unable to coordinate their efforts well enough.
r
Okay a rebuild of jag without release flag fixed all my problems. stacktrace is now correct and I can use jag flash 👍
We are only running 2 containers, the "system" and our program
k
So the MQTT activity is from the same container that tries to use the LEDs via I2S?
r
Yes, we run everything from same container. We are starting a new container for modem connectivity, but I am currently testing on wifi
k
That's good news. I think that will make it easier for us to debug and fix.
Looks like we found and fixed the issue.
@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.
r
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
k
Thank you!
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.
r
Haha 😄
It no longer panics on i2s error!
Copy code
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
k
So it works better for you?
r
Yes, im pretty sure it just retries because leds are correct after error
k
I get the feeling you don't like panics 😅
f
fwiw, I would still switch to the RMT implementation. It should use less memory for the 4 LEDs.
r
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
I did notice that. I like the RMT implementation
I would 100% prefer just retrying instead of full chip reboot, and I am sure I am not the only one 🙂
PreviousNext
Powered by