Circuitpython: CircuitPython completely freezes upon button click

[c-k-dillard]

While using the cpx, the two buttons crash the entire board after playing a sound. There is no error message and the REPL and serial monitor crash. The buttons are supposed to play a sound when they're pressed. Here is the video of the serial monitor crash: https://imgur.com/O1GLBwN. The board crash is also recorded: https://youtu.be/53wDuqXmbi8. The code that seems to be causing the crash is below

while True:
    if cpx.button_a:
        cpx.play_file("foo.wav")
    elif cpx.button_b:
        cpx.play_file("bar.wav")

[kevinjwalters]

Worth attaching the whole code and all the sound samples too if you're ok with that. Worth a mention of the specific version of CircuitPython and the library bundle you are using too.

[c-k-dillard]

The entire codebase is here: https://pastebin.com/NT34K32T

The versions of CircuitPython we tried are 3.1 and 4.0.

[tannewt]

I was able to replicate this. It is a hang rather than a crash.

Unfortunately, it's a bit of a complicated example. It'd be great to whittle it down a bit.

Anyone have a CircuitPlayground Express with an SWD attachment?

[DavePutz]

I think this may be related to memory management. I added an "import gc" and made some calls to gc.mem_free to note that the memory was quite low just before the hang. I put in a call to gc.collect() after the 'cpx.pixels.show()' line in the while loop and ran successfully for several minutes ( as opposed to several seconds without the patch). It did, however, eventually hang. I do have a Jlink debugger which I will hook up to the CircuitPlayground Express and see what can be seen.

[DavePutz]

Circuitpython-hang-stack.txt

Attached is a stack from the hang state. Apparently we hang while reading a WAV file. Single stepping thru, it looks like the issue is in shared_dma_transfer at the following lines:
// Channels cycle between Suspend -> Pending -> Busy and back while transfering. So, we check
// the channels transfer status for an error or completion.
if (rx_active) {
while ((dma_transfer_status(SHARED_RX_CHANNEL) & 0x3) == 0) {}
}
if (tx_active) {
while ((dma_transfer_status(SHARED_TX_CHANNEL) & 0x3) == 0) {}
}

rx_active is true, so it looks like the dma_transfer_status & 0x3 is always staying at 0. I'll try looking at the relevant code to see if I can spot why that might be.

[kevinjwalters]

I had a glance at your stack trace. I know nothing about this so bare in mind this is a very uninformed comment but one argument to sercom_dma_read looks odd, uint8_t * buffer = 0x5 "\002" is a value that's very low, isn't anything-aligned (possibly irrelevant), isn't in the memory address range of other pointers seen in the trace and hasn't been passed in.

common_hal_busio_spi_read also appears twice for some reason?

    firmware.elf! common_hal_mcu_enable_interrupts Line: 53 
>   firmware.elf! dma_transfer_status (uint8_t channel_number  = 4 '\004') Line: 107    
    firmware.elf! shared_dma_transfer (void * peripheral  = 0x42001400, void * peripheral@entry  = 0x42001400, const uint8_t * buffer_out  = 0x0, const uint8_t * buffer_out@entry  = 0x0, volatile uint32_t * dest  = 0x42001428, volatile uint32_t * dest@entry  = 0x42001428, volatile uint32_t * src  = 0x42001428, volatile uint32_t * src@entry  = 0x42001428, uint8_t * buffer_in  = <optimized out>, uint8_t * buffer_in@entry  = 0x5 "\002", uint32_t length  = <optimized out>, uint32_t length@entry  = 512, uint8_t tx  = <optimized out>) Line: 189    
    firmware.elf! sercom_dma_read (uint8_t tx  = 255 ' ', uint32_t length  = 512, uint8_t * buffer  = 0x5 "\002", Sercom * sercom  = 0x42001400) Line: 229  
    firmware.elf! common_hal_busio_spi_read (busio_spi_obj_t * self  = 0x20001854 <spi>, busio_spi_obj_t * self@entry  = 0x20001854 <spi>, uint8_t * data  = 0x20000860 <_internal_vfs+116> "", uint8_t * data@entry  = 0x20000860 <_internal_vfs+116> "", size_t len  = 512, size_t len@entry  = 512, uint8_t write_value  = 255 ' ', uint8_t write_value@entry  = 255 ' ') Line: 332  
    firmware.elf! common_hal_busio_spi_read (uint8_t write_value  = 255 ' ', size_t len  = 512, uint8_t * data  = 0x20000860 <_internal_vfs+116> "", busio_spi_obj_t * self  = 0x20001854 <spi>) Line: 327  
    firmware.elf! spi_flash_read_data (uint32_t data_length  = 512, uint8_t * data  = 0x20000860 <_internal_vfs+116> "", uint32_t address  = <optimized out>) Line: 128 
    firmware.elf! read_flash (uint32_t data_length  = 512, uint8_t * data  = 0x20000860 <_internal_vfs+116> "", uint32_t address  = <optimized out>) Line: 82   
    firmware.elf! read_flash (uint32_t address  = <optimized out>, uint8_t * data  = <optimized out>, uint32_t data_length  = <optimized out>) Line: 75 

Is this the code in question https://github.com/adafruit/circuitpython/blob/master/ports/atmel-samd/common-hal/busio/SPI.c#L325-L342 ? It looks like the data passed in should be buffer? Is the optimiser messing with us here or are bad-things-happening(tm)?

[Added later] I was reading https://learn.adafruit.com/adafruit-circuit-playground-express/adapting-sketches-to-m0#storing-data-in-flash-7-18 and it talks about memory layout:

If the address is $2000000 or larger, its in SRAM. If the address is between $0000 and $3FFFF Then it is in FLASH

Perhaps when it says $2000000 it means $20000000.

[DavePutz]

I think I may have spotted the issue, but would like some other
eyes to take a look if possible.
Here's what I see:
When playing .wav files, in audio_dma_setup_playback(), we find a free DMA channel (usually
channel 0) and store it in the dma structure. So, whenever we call audio_dma_load_next_block()
we use that stored channel. Now, when using the microphone we call
common_hal_audiobusio_pdmin_record_to_buffer(), which also looks for a free DMA channel
(again, it seems to always get channel 0). The problem occurs when I see a stack like this fragment:

HardFault_Handler Line: 294
Line: 294
audio_dma_load_next_block (audio_dma_t * dma = 0x20005488, audio_dma_t * dma@entry = 0x20005488) Line: 119
audio_dma_background Line: 332
run_background_tasks Line: 60
run_background_tasks Line: 51
common_hal_audiobusio_pdmin_record_to_buffer (uint32_t output_buffer_length = , uint16_t * output_buffer = , audiobusio_pdmin_obj_t * self = ) Line: 412

The code at line 412 in common_hal_audiobusio_pdmin_record_to_buffer() seems to have started a DMA
operation and is waiting for completion:

    // If wait_counts exceeds the max count, buffer has probably stopped filling;
    // DMA may have missed an I2S trigger event.
    while (!event_interrupt_active(event_channel) && ++wait_counts < MAX_WAIT_COUNTS) {
        #ifdef MICROPY_VM_HOOK_LOOP
            MICROPY_VM_HOOK_LOOP
        #endif
    }

So, we have an active DMA operation on channel 0 from the PDM code, and the background code
now uses the channel 0 which was stored in the dma structure. Contention/.confusion? I have seen both loops and
hard faults - maybe depends on what data gets dumped where??
I end up with two questions:
1) What can we do to avoid this contention on channel 0?
2) I am not sure why the background code is calling audio_dma_load_next_block(). The Python
script looks to be waiting for completion when it plays a sound - calling cpx.play_file which
waits for audio to finish playing:

      if sys.implementation.version[0] >= 3:
        with audioio.AudioOut(board.SPEAKER) as audio:
            wavefile = audioio.WaveFile(open(file_name, "rb"))
            audio.play(wavefile)
            while audio.playing:
                pass

So - what would be left for audio_dma_load_next_block() to do?

[tannewt]

Sounds suspicious @DavePutz ! I think you are right about contention.

1. I think we'll want to use channel 0 for recording and 1 for playback because lower numbers get higher priority. I'm not sure what has to happen for that though.

2. Load next block is loading more of the sound from the filesystem so the sound keeps playing because we can't store it all in memory.

Perhaps @jepler and @deshipu have ideas of how to fix this too.

[jepler]

I think @DavePutz is on the right track, if both devices ever try to use the same channel at the same time, something bad will happen. Why isn't the expected protection against this working?

I started looking into this with debugging prints and the first thing I noticed is that dma_disable_channel can be called with an out-of-range channel number if audio_dma_stop is called twice, and it frequently is.
However, this doesn't seem to be leading to this behavior.

Next, I started tracking how dma_channel_enabled tracked with calls to dma_{en,dis}able_channel. I found that, contrary to what the code in find_free_audio_dma_channel requires, it appears that channel->CHCTRLA.bit.ENABLE can be set to false asynchronously.

When this happens, it's possible for both AudioOut and PDMIn to simultaneously believe they have been allocated the same DMA channel, and to make conflicting uses of it.

I did not find any other sites in circuitpython that look like they would reset ENABLE, and the datasheet at best fails to state clearly that this bit can be reset automatically at the end of a DMA operation, but one of these two things must be happening.

My recommendation, and I can clean up and PR my local code that is doing this (there are also a lot of inappropriate print statements and so on), is to add a new array of bool that tracks whether CP believes the DMA channels are in use, and use that in find_free_audio_dma_channel. This involves creating new wrapper functions audio_dma_enable_channel and audio_dma_disable_channel that call the SDK functions but also manipulate the new variable: f9e4b99b19bf8ccc45d9d051ffd77ec38220fe19

However, I have to note that I did NOT reproduce the original problem of a freeze, I just found with debugging statements that both AudioOut and PDMIn were trying to use channel 0 at the same time.

My testing python code was:
import audiobusio import audiocore import audioio import board s = audiocore.RawSample(b'\0' * 256, sample_rate=8000) a = audioio.AudioOut(board.A0) b = bytearray(200) for i in range(10): print(i) a.play(s) with audiobusio.PDMIn(board.MICROPHONE_CLOCK, board.MICROPHONE_DATA, sample_rate=16000) as mic: print(mic.record(b, len(b))) print(a.playing) a.stop() print(a.playing) print() a.stop() print("end of main.py")

[DavePutz]

Here is some python code that reproduces reliably for me. Note that I think the use of the Neopixel code may be needed, as in my tests that generated a lot of gc_allocs and gc_frees - possibly related??

import array
import math
import time
import microcontroller
import audiobusio
import board
import gc
from adafruit_circuitplayground.express import cpx

# Exponential scaling factor.
# Should probably be in range -10 .. 10 to be reasonable.
CURVE = 2
SCALE_EXPONENT = math.pow(10, CURVE * -0.1)

PEAK_COLOR = (100, 0, 255)
NUM_PIXELS = 10

# Number of samples to read at once.
NUM_SAMPLES = 80

cpx.pixels.auto_write = False


# Restrict value to be between floor and ceiling.


def constrain(value, floor, ceiling):
    return max(floor, min(value, ceiling))


# Scale input_value between output_min and output_max, exponentially.


def log_scale(input_value, input_min, input_max, output_min, output_max):
    normalized_input_value = (input_value - input_min) / \
                             (input_max - input_min)
    return output_min + \
        math.pow(normalized_input_value, SCALE_EXPONENT) \
        * (output_max - output_min)


# Remove DC bias before computing RMS.


def normalized_rms(values):
    minbuf = int(mean(values))
    samples_sum = sum(
        float(sample - minbuf) * (sample - minbuf)
        for sample in values
    )

    return math.sqrt(samples_sum / len(values))


def mean(values):
    return sum(values) / len(values)


def volume_color(volume):
    return 200, volume * (255 // NUM_PIXELS), 0


# Main program


# Set up NeoPixels and turn them all off.
cpx.pixels.brightness=0.1
cpx.pixels.fill(0)
cpx.pixels.show()

"""
# For CircuitPython 2.x:
mic = audiobusio.PDMIn(board.MICROPHONE_CLOCK, board.MICROPHONE_DATA,
                      frequency=16000, bit_depth=16)
# For Circuitpython 3.0 and up, "frequency" is now called "sample_rate".
# Comment the lines above and uncomment the lines below.
"""
mic = audiobusio.PDMIn(board.MICROPHONE_CLOCK, board.MICROPHONE_DATA,
                       sample_rate=16000, bit_depth=16)

# Record an initial sample to calibrate. Assume it's quiet when we start.
samples = array.array('H', [0] * NUM_SAMPLES)
mic.record(samples, len(samples))
# Set lowest level to expect, plus a little.
input_floor = normalized_rms(samples) + 10
# OR: used a fixed floor
# input_floor = 50

# You might want to print the input_floor to help adjust other values.
# print(input_floor)

# Corresponds to sensitivity: lower means more pixels light up with lower sound
# Adjust this as you see fit.
input_ceiling = input_floor + 500

peak = 0
cnt = 0

while True:
    mic.record(samples, len(samples))
    magnitude = normalized_rms(samples)
    # You might want to print this to see the values.
    # print(magnitude)

    # Compute scaled logarithmic reading in the range 0 to NUM_PIXELS
    c = log_scale(constrain(magnitude, input_floor, input_ceiling),
                  input_floor, input_ceiling, 0, NUM_PIXELS)
    # print("Before1:" + str(gc.mem_free()))
    # Light up pixels that are below the scaled and interpolated magnitude.
    cpx.pixels.fill(0)
    for i in range(NUM_PIXELS):
        if i < c:
            cpx.pixels[i] = volume_color(i)
        # Light up the peak pixel and animate it slowly dropping.
        if c >= peak:
            peak = min(c, NUM_PIXELS - 1)
        elif peak > 0:
            peak = peak - 1
        if peak > 0:
            cpx.pixels[int(peak)] = PEAK_COLOR
    cpx.pixels.show()
    # audio portion

    cpx.red_led = cpx.switch
    if cnt > 20:
        cpx.play_file("batman_theme_x.wav")
        cnt = 0
    cnt += 1

[jepler]

Unfortunately, I still get hard crashes with my earlier debugging and potential fix code.

[jepler]

next guess, which it looks like has solved the problem, but not sure if it's cumulative with other local changes:

@@ -292,6 +296,7 @@ void audio_dma_stop(audio_dma_t* dma) {
         audio_dma_disable_channel(dma->dma_channel);
         disable_event_channel(dma->event_channel);
     }
+    audio_dma_state[dma->dma_channel] = NULL;
     MP_STATE_PORT(playing_audio)[dma->dma_channel] = NULL;
     dma->dma_channel = AUDIO_DMA_CHANNEL_COUNT;
 }

Theory: nothing is clearing out audio_dma_state for this channel (except reset); this leads to audio_dma_load_next_block being called when it shouldn't have been, which is exactly what has been described.

[DavePutz]

I can confirm that your fix takes care of both the original code by c-k-dillard and my repro code above. My only question would be if we could still have a dma channel conflict should someone actually be playing a wav file asynchronously with using the microphone (or is that really not possible)?

[jepler]

@DavePutz Yes, my analysis of how the channel->CHCTRLA.bit.ENABLE value work seem to indicate that there's a further risk of accidentally re-using a DMA channel too soon when the playback (or, hypothetically, the recording) are asynchronous.

[tannewt]

@jepler Care to make a PR for that audio_dma_state fix?