rp2: crash and memory corruption with threading

In a use case, where two threads are created and massive UART write happens, various kinds of crashes and memory corruptions occur. Test script:

from machine import UART, Pin
import time
import _thread

uart = UART(1, 115200 , parity=None, stop=1, bits=8, tx=Pin(4), rx=Pin(5), txbuf=32, timeout=10)

def send(command):
        write_buffer = bytearray(len(command) + 3)
        write_buffer[0: len(command)] = bytes(command, 'ASCII')
        write_buffer[-3:] = b'\xff\xff\xff'
        uart.write(write_buffer)

def burst():
    msg="0123456789" * 8 + "\r\n"
    n=0
    while True:
        uart.write("%d: " % n)
        uart.write(msg)
        n += 1

def count_count():
    n = 1
    while True:
        print("Count Count counts", n)
        n += 1
        time.sleep(1)

_thread.start_new_thread(burst, ())

# burst()
count_count()

The function send() is not called, but the behavior changes on whether is is present in the code or commented out. For the test, UART1 tx is connected with a UART/USB bridge to a PC showing the data stream. The following test set-ups were made:

With send() code, thread 0 REPL, thread 1 burst():
Result: memory allocation error at msg 5721, rare character doubling, like:
"MemoryError: memory allocation failed, allocating 875706184 bytes"
"5475: 011223344556677889900112233456789012345678901234567890123456789012345678901234567890123456789"
With send() code, thread 0 count_count(), thread 1 burst():
Result: Lock-up after msg 5721, rare char doubling
Without send() code, thread 0 count_count(), thread 1 burst():
Result: No lock-up, rare char doubling
Without send() code, thread 0 REPL, thread 1 burst()
Result: No lock-up, no transmission errors
With send() code, thread 0 burst(), thread 1 count_count()
Result: sending complete rubbish after msg 5720, like, and freezing both threads after a while:
"43: h5�� 44: h5�� 45: h5�0� 46: h5�P� 47: h5�p� 48: h5�� 49: h5�� 50: h5�� 51: h5{�� 52: h5��" and so on
Without send() code, thread 0 burst(), thread 1 count_count()
Result No problem. stopped after msg 100_000

Using critical section instead of lock does not change the game (not surprising).
Increasing the thread stack size has no effect (expected).

Edit: Using the previous version of machine_uart.c without buffering fails too. Only the character doubling error seems to be gone. But since that was rare, the observation time may have been too short.

My first guess would be that it's something to do with the GC interacting between the two cores/threads. Can you try writing a test that does not do any memory allocations when running (ie only at start up)?

Good guess, indeed. Without allocation it looks much better. Same test, 100_000 cycles w/o crash and strange output only in one mode.
I modified the test code such that the increasing numbers are hand-coded into a bytearray, and sys.stdout.write() is used instead of print.

thread0 REPL, thread1 burst(): No crash, no strange output. Manually stopped at 100_00 cycles
thread0 count_count(), thread1 burst(): No crash, char doubling about every 1000th message. Manually stopped at 50_000 cycles
thread0 burst, thread 1 count_count(): No crash, no strange output. Manually stopped at 50_00 cycles

So there may be two independent problems.

The character doubling in UART only occurs, if data is sent to stdout at the same time in thread 0. It does not matter if doing so by calling print() or by sys.stdout.write(). If I just let the LED blink, or interleave writing to stdout and to UART, everything works well.
interestingly, this character doubling only happens, if UART write is done in thread 1 and stdout write in thread 0. If the threads are swapped, it's fine.

I tried to figure out, whether the twice sent characters weer actually put into the UART FIFO by the code in uart_fill_tx_fifo(). So I modified the message to not set the same character twice in sequence, and checked in the uart_fill_tx_fifo() function, whether the actual character is the same as the previous one (code below). If yes, it would create a short pulse at a GPIO pin, which I then would be able to detect. This trigger happened much more rare that the character doubling. And that puzzles me. In a sequence of 100_000 messages, I had 74 with character duplications, but only one trigger event. b.t.w.: If the trigger happens, the function uart_fill_tx_fifo() was called in a interrupt context.
Edit: These events with trigger differ from the others in that only a single character is sent twice, whereas in the other cases typically a burst of pairs happens.
Edit 2: What puzzles me: To see the event in the output I stop pushing data to the UART after the pair has been detected. So this pair should be at the end of the output stream. But it is not. I have seen up to 18 characters following. And the pulse at P11 is too long, like 1 µs, while usually it is 60ns. That all looks like the order of execution is disturbed.

Modified uart_fill_tx_fifo(). P11 was set in the Python code as output. If the pulse is generated when two consecutive chars are different, it fires well.

uint32_t *PIO_OUT = (uint32_t *)0xd0000010;

// take bytes from the buffer and put them into the UART FIFO
STATIC void uart_fill_tx_fifo(machine_uart_obj_t *self) {
    static int last_char = 0;
    static int do_send = 1;
    while (uart_is_writable(self->uart) && ringbuf_avail(&self->write_buffer) > 0) {
        // get a byte from the buffer and put it into the uart
        int c = ringbuf_get(&(self->write_buffer));
        if (do_send) {
            uart_get_hw(self->uart)->dr = c;
        }
        if (c == last_char) {
            PIO_OUT[0] |= 1 << 11; // set P11
            do_send = 0; // Stop output
        }
        last_char = c;
        PIO_OUT[0] &= ~(1 << 11);  // clear p11
    }
}

That all looks like the order of execution is disturbed.

A high priority interrupt? Can recursive execution of the same ISR occur?

I thought about stacked ISR calls. But that should affect the sequence of bytes in the output. But he order is unchanged, just some bytes are sent twice in a row.

After increasing the output rate in thread0, the pulse width of the trigger pulse created in thread 1 is back to ~60ns. Very strange. And sometimes the ISR seems to last for more than 15ms, falling back to its usual ~20µs soon later. So it seems there is a lot of trouble with ISR and threading.
Edit: It looks as if the ISR is interrupted itself and not restarted again at the proper address, but repeats the interrupted instruction.

Partially solved. After having put aside this problem for a while, I had some progress now. If UART instantiation and UART use happen in the same thread, then the character doubling in the output does not happen. Using a spin lock in the ISR with ISR and UART user on two threads suppresses the character doubling too, but causes a device lock-up after short time.

The crash/lock-up which occurs when memory allocations are used is still present.

The fix #7217 may be related to this, but not quite sure yet. If you have a chance to test that PR with the issue here that would be helpful.

Sorry, it does not fix either of the two problems, I see here. It still stops after a while, if memory is allocated in the second thread. And if not, it still send character doubles if uart IRQ handler and uart send are not located in the same thread.

I too have experienced similar issues in my project. I documented my findings in the raspberry pi pico forum.
https://forums.raspberrypi.com/viewtopic.php?t=326826
https://forums.raspberrypi.com/viewtopic.php?t=324136

other posts:
https://forums.raspberrypi.com/viewtopic.php?t=301156
https://forums.raspberrypi.com/viewtopic.php?p=1889442

I wonder if #7977 is relevant. Interestingly that problem isn't restricted to UART output: SPI behaves identically.

Allow me to piggy back onto this thread with similar findings of corruption when using _thread and UART on RPi Pico. Reported here.
https://forums.raspberrypi.com/viewtopic.php?t=329639
I can provide the complete code if it makes sense.

I was testing this issue and found something interesting.
With following two modifications, I could run above test code successfully (at least for 30 minutes).

modify ports/rp2/mpthreadport.c:59

            //gc_collect_root((void **)core1_stack, core1_stack_num_words);
            gc_collect_root((void **)&core1_stack, core1_stack_num_words);

main.py: put gc.collect() in main loop.

from machine import UART, Pin
import time
import _thread
import gc

uart = UART(0, 115200 , parity=None, stop=1, bits=8, tx=Pin(0), rx=Pin(1), txbuf=32, timeout=10)

def send(command):
        write_buffer = bytearray(len(command) + 3)
        write_buffer[0: len(command)] = bytes(command, 'ASCII')
        write_buffer[-3:] = b'\xff\xff\xff'
        uart.write(write_buffer)

def burst():
    msg="0123456789" * 8 + "\r\n"
    n=0
    while True:
        uart.write("%d: " % n)
        uart.write(msg)
        n += 1

def count_count():
    n = 1
    while True:
        print(gc.mem_free())
        gc.collect()
        print("Count Count counts", n)
        n += 1
        time.sleep(1)

_thread.start_new_thread(burst, ())
count_count()

With these two modifications, it ran successfully.
My test results:

I couldn't explain why this works reading the code: gc_collect_root((void **)&core1_stack, core1_stack_num_words);
without gc.collect() in main thread, the moment GC is out of memory is when thread stops.
gc.collect() in thread stop the thread, same reason with (2)
I did notice character doubling problem very rarely in test cases. I am using master rev. as of today. Instead, without modification (1), uart is sending some garbages when burst() is called from main thread: 930: €Rå0 931: €RdP 932: €Rçp. Only heap data is lost.

After tests, my guess is that GC information (or address) is not properly setup in core1. I will try to look into it later but I am not familiar with micropython source code yet.

A quick note on character doubling problem: When I was reading rp2/machine_uart.c, It was suspicious that write_buffer and read_buffer is not properly protected against IRQ: write_lock and read_lock to be set for all access to read/write_buffer? This might be the cause but didn't verify yet though.

rp2/mpthreadport: Fix memory corruption when thread is created in core1.

Fixed by 2d47020

Merge pull request micropython#7124 from piit79/frood

rp2/mpthreadport: Fix memory corruption when thread is created in core1.

Navigation Menu

Repository navigation

rp2: crash and memory corruption with threading #7124

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

rp2: crash and memory corruption with threading #7124

Description

Activity

dpgeorge commented on Apr 16, 2021

robert-hh commented on Apr 16, 2021

robert-hh commented on Apr 17, 2021

robert-hh commented on Apr 17, 2021

peterhinch commented on Apr 18, 2021

robert-hh commented on Apr 18, 2021

robert-hh commented on Apr 18, 2021

robert-hh commented on Apr 28, 2021

dpgeorge commented on May 4, 2021

robert-hh commented on May 4, 2021

jrullan commented on Dec 1, 2021

peterhinch commented on Dec 1, 2021

helarsen commented on Feb 13, 2022

yjchun commented on Feb 16, 2022

yjchun commented on Feb 16, 2022

dpgeorge commented on Mar 1, 2022

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions