printf deadlock usb using two tasks #1453

adri-sass · 2023-07-07T18:48:43Z

Hello, I've a deadlock using the printf in two differents thread with the usb stdio configured.
I'm using:

FreeRTOS on "smp" branch
Pico sdk 1.5.1

A simple main that causes the issue is the following:

#include <stdio.h>
#include "pico/stdlib.h"
#include "FreeRTOS-Kernel/include/FreeRTOS.h"
#include "FreeRTOS-Kernel/include/task.h"

void TaskA(void*)
{
    int VAL = 0;   
    while(true)
    {
        printf("TaskA VAL = %d\n", VAL++);
    }
}

void TaskB(void*)
{
    int VAL = 0;
    while(true)
    {
        printf("TaskB VAL = %d\n", VAL++);
    }
}


int main() {
    stdio_init_all();
    sleep_ms(1000);
    printf("STARTING\n");
    #ifdef LIB_PICO_MULTICORE
        printf("LIB_PICO_MULTICORE defined\n");
    #else
        printf("LIB_PICO_MULTICORE not defined\n");
    #endif
    xTaskCreate(TaskA, "Bouncing Task1", configMINIMAL_STACK_SIZE, nullptr, 1, nullptr);
    xTaskCreate(TaskB, "Bouncing Task2", configMINIMAL_STACK_SIZE, nullptr, 1, nullptr);
    
    
    vTaskStartScheduler();
    
    printf("Error\n");
    while(true)
    {
        ;;
        sleep_ms(1000);
    }
}

The CMake is the following:

cmake_minimum_required(VERSION 3.13)

set(PICO_BOARD pico_w)
set(FREERTOS_KERNEL_PATH ./FreeRTOS-Kernel)
# initialize pico-sdk from submodule
# note: this must happen before project()
include(pico-sdk/pico_sdk_init.cmake)
include(pico_FreeRTOS_Kernel_import.cmake)

project(PICO_OS_TEST)

# initialize the Raspberry Pi Pico SDK
pico_sdk_init()

add_executable(pico_usb_print_deadlock_test main_issue_poc.cpp)

target_include_directories(pico_usb_print_deadlock_test PRIVATE ${CMAKE_CURRENT_LIST_DIR} )
target_include_directories(pico_usb_print_deadlock_test PRIVATE ${FREERTOS_KERNEL_PATH}/${FREERTOS_KERNEL_RP2040_RELATIVE_PATH}/include )
target_link_libraries(pico_usb_print_deadlock_test pico_stdlib pico_multicore FreeRTOS-Kernel FreeRTOS-Kernel-Heap4)

pico_enable_stdio_usb(pico_usb_print_deadlock_test 1)
pico_enable_stdio_uart(pico_usb_print_deadlock_test 0)
pico_add_extra_outputs(pico_usb_print_deadlock_test)

Using OpenOCD and another pico, I've debugged the code, and it seems to be blocked on the same spinlock handle (see the attached image for the stack)

Here I was able to check that deadlock was on the same handle:

Is there a workaround? Thanks for any help

peterharperuk · 2023-07-07T19:59:36Z

Does it happen with stdio uart?

adri-sass · 2023-07-08T08:28:19Z

@peterharperuk with the usb stdio the problem occurs within seconds, using the uart stdio after 10 minutes everything was working fine, so the answer to your question is "probably not"

kilograham · 2023-07-08T20:26:38Z

urgggh. this is nasty, and one root cause is a bug in our RP2040 SMP FreeRTOS port; which doesn't look at all trivial to fix in general.

note the manifestation you are probably hitting (which is also easier to fix), can actually be worked around by disabling RTOS asserts (i.e. set configASSERT(x) to not reference x), or if that is defined to be assert(x), then set NDEBUG=1 or do a Release build.

Really, the pico_stdio_usb code should now use pico_asyc_context and thus use a more sensible (than IRQ) mechanism for background work under FreeRTOS.

adri-sass · 2023-07-09T12:25:11Z

@kilograham thank you for your analisys, but the workaround you suggest, delays only the deadlock.

I've tried the following steps:

In my FreeRTOSConfig.h I've changed the configASSERT define like this:

#include <assert.h>
/* Define to trap errors during development. */
//#define configASSERT(x)                         assert(x)
#define configASSERT(x)

Using the debugger, I've checked that a "configASSERT(0)" didn't throw a breakpoint (the debugger skips the instruction correctly)

At this point the issue still shows up.

So I've tried a Release build, but the result is the same.
A "RelWithDebInfo" build type was useful to see the stack, almost the one in the first snapshot I've posted. Also the spinlocks in the two threads, still show the same handles value

I hope this test helps, let me know if you need more info or if there is a more effective workaround/fix.

Thank you in advance

kilograham · 2023-07-09T21:59:05Z

yes, this fixed only one possible place the issue occurred, and i left it running and it seemed happier, but yeah mine hung too.

daveythacher · 2023-08-12T17:32:54Z

Increase stack size please.

daveythacher · 2023-08-12T17:38:00Z

urgggh. this is nasty, and one root cause is a bug in our RP2040 SMP FreeRTOS port

Can you explain?

adri-sass · 2023-09-13T17:43:51Z

Hi @daveythacher, sorry for the late reply. I've doubled the stack size, but the issue still shows up

daveythacher · 2023-11-11T17:46:09Z

@kilograham Is the entire mutex implementation bad?

Edit: What happens to owner?

kilograham · 2023-11-11T19:39:24Z

it is lower level than that

on the FreeRTOS port, either lock_internal_spin_unlock_with_wait or lock_internal_spin_unlock_with_notify(i forget which or both off the top of my head) are actually not guaranteed to be "atomic" as per their documentation (because IRQs are enabled on one FreeRTOS path, and a task switch can occur if an IRQ is taken)

daveythacher · 2023-11-11T21:27:11Z

That should not cause an issue if the mutex is atomic. It creates blocking logic but that itself is designed to be fine from my understanding of the stdio and usb implementation. (They are designed to back off (yield) and come back in a polling task.)

However my understanding of the mutex implementation is that they are not atomic. The spin lock is atomic however the owner flag can be duplicated in multiple places. (Declare as volatile?)

Another issue is the USB ISR (USB and timer) calls directly into tinyUSB. However this may be okay on ARM if it implements the reserved context for ISRs which is shared. This context would need to be large.

Why do you mutex guard tinyUSB?

Edit: In hindsight the tinyUSB guard is somewhat self evident.

daveythacher · 2023-11-12T04:52:19Z

Here is a hack which may work around the problem. This is not an ideal solution due to the overhead.

#include <stdio.h>
#include <stdint.h>
#include "pico/stdlib.h"
#include "FreeRTOS-Kernel/include/FreeRTOS.h"
#include "FreeRTOS-Kernel/include/task.h"
#include "FreeRTOS-Kernel/include/queue.h"

static xQueueHandle queue;
static TaskHandle_t task;

void TaskA(void*)
{
    uint16_t VAL = 0;   
    while(true)
    {
        uint32_t data = (1 << 16) | VAL;
        while(xQueueSend(queue, &data, portMAX_DELAY) != pdPASS);
        ++VAL;
    }
}

void TaskB(void*)
{
    uint16_t VAL = 0;
    while(true)
    {
        uint32_t data = (2 << 16) | VAL;
        while(xQueueSend(queue, &data, portMAX_DELAY) != pdPASS);
        ++VAL;
    }
}

void TaskC(void*)
{
    while(true)
    {
        uint32_t data;
        while(xQueueReceive(queue, &data, portMAX_DELAY) != pdPASS);

        if ((data >> 16) == 1)
            printf("TaskA NUM = %d\n", data & 0xFFFF);
        else
            printf("TaskB NUM = %d\n", data & 0xFFFF);
    }
}


int main() {
    stdio_init_all();
    sleep_ms(1000);
    printf("STARTING\n");
    #ifdef LIB_PICO_MULTICORE
        printf("LIB_PICO_MULTICORE defined\n");
    #else
        printf("LIB_PICO_MULTICORE not defined\n");
    #endif

    queue = xQueueCreate(5, sizeof(uint32_t));

    xTaskCreate(TaskA, "Bouncing Task1", configMINIMAL_STACK_SIZE, nullptr, 1, nullptr);
    xTaskCreate(TaskB, "Bouncing Task2", configMINIMAL_STACK_SIZE, nullptr, 1, nullptr);
    xTaskCreate(TaskC, "Bouncing Task3", configMINIMAL_STACK_SIZE, nullptr, 1, &task);

    vTaskCoreAffinitySet( task, 1 << 0 );
    
    vTaskStartScheduler();
    
    printf("Error\n");
    while(true)
    {
        ;;
        sleep_ms(1000);
    }
}

daveythacher · 2023-11-12T04:59:34Z

Note I was not able to pin TaskC to core 1. I can only pin it to core 0. It does not like core 1.

Again I do not know how owner is protected in multicore!

daveythacher · 2023-11-12T21:04:11Z

I looked into it some.

Core 1 goes for stdio_usb_mutex and gets it.
Core 0 goes for stdio_usb_mutex but only gets spin lock.
Core 0 goes for portGET_ISR_LOCK or portGET_TASK_LOCK in xEventGroupWaitBits
Core 0 releases spin lock in vPortEnableInterrupts
Core 1 releases stdio_usb_mutex
ISR is allowed to run and goes for stdio_usb_mutex (gets it it on core 0)
ISR releases spin lock
Core 1 goes for stdio_usb_mutex but only gets spin lock
Core 1 goes for portGET_ISR_LOCK or portGET_TASK_LOCK in xEventGroupWaitBits
ISR goes for stdio_usb_mutex but cannot get spin lock

Core 1 is dead locking the ISR on core 0
Core 0 is dead locking core 1

If true, core 1 must never go for stdio_usb_mutex or ditch immediately. Without FreeRTOS it normally ditches instantly which I proved does fix it. Looks like xEventGroupWaitBits allows a nested locked which can be split into a deadlock.

I am not sure I understand how stdio_usb_mutex needs to be submitted to xEventGroupWaitBits. The SDK promote stdio_usb_mutex to cover the mutex internal state and the event group bits. The notion of the two seem similar but different. I am not sure the SDK should manage FreeRTOS's internal state.

Edit:
This looks to do the trick.

#define configSUPPORT_PICO_SYNC_INTEROP 0

This like lowers the performance, but it should be stable. So you have two workarounds currently, but they both come with performance trade offs.

I think you could make an argument for saying this fix belongs in the FreeRTOS side not the SDK. If this is the direction they wish to go this issue should be closed out.

daveythacher · 2023-11-16T18:58:56Z

@kilograham FreeRTOS did not define xPortLockInternalSpinUnlockWithBestEffortWaitOrTimeout. This was defined by the SDK? Which make it optional correct? I mean I already suspect this based on trying to compile with it commented out and disabling configSUPPORT_PICO_SYNC_INTEROP. I just want to make sure.

If this is the case the only point here is to use scheduler's event system. We can patch in just about anything we want here?

Edit:
The way I see it there are two problems:

The mutex is held while the spin lock is released in the middle of the ISR, which allows this to occur.
The spin lock is held while attempting to register the thread state. (Logic does not hand off to different mutex. SDK is commit to try/release notion in my opinion, which makes registering thread state somewhat complex.)

Break either one of these and the dead lock may not happen.

A fundamental concern here is for the mutex design itself. Registering with FreeRTOS is dangerous. You would need to forbid accessing a mutex from ISR in general. You could fix the USB issue with async, however should the spin lock not persist the entire ISR? The ISR cannot release the mutex if it loses the spin lock, which means core 1 can continue to attack core 0. The real reason to move the USB to async would be to allow it to run on both cores. So I guess under this point of view the issue is within the SDK.

Create new mutex functions mutex_try_enter_isr and mutex_exit_isr? Note this comes with priority inversion, which is true regardless for printf. So to some extent printf should be considered logging.

kilograham · 2023-12-24T16:25:11Z

it is lower level than that

on the FreeRTOS port, either lock_internal_spin_unlock_with_wait or lock_internal_spin_unlock_with_notify(i forget which or both off the top of my head) are actually not guaranteed to be "atomic" as per their documentation (because IRQs are enabled on one FreeRTOS path, and a task switch can occur if an IRQ is taken)

Note this is the bug - they should be (and need to be) atomic.

daveythacher · 2024-01-02T17:30:49Z

I argue they are atomic. The problem is they deadlock using two blocking (atomic) operations when split. You need to force serialization which should create the desired atomic. This means you need to have an exclusive section which forces this. You are missing the blocking logic required to create the exclusion which serializes it into atomic.

Overall there is a potential fallacy, parallelizing printf. We could create exclusion from the scheduler or the spin lock within the mutex. The RTOS and NVIC schedulers are not aligned, which is the operation attempted. The ISR is impure in multiple manners. Another solution is to make the grab of any SDK mutex steal the RTOS mutex first.

My concern is for the SDK getting into tradeoffs, which makes things impure. FreeRTOS has no real way of fixing this issue but they can hack it at least two ways. There are at least three solutions on the SDK side.

Personally I would be tempted to make the following point. The APIs outlined by the SDK for the mutex's interaction with RTOS are deprecated and should be removed. This would force RTOS code to use their own version of mutex which are provided potentially in the port code. I am not sure the SDK factory should be used and by extension the SDK is not required for event notification rather the port code is. Again are you commited to these APIs? (configSUPPORT_PICO_SYNC_INTEROP)

We are really arguing over resource usage at this point.

kilograham · 2024-07-12T16:38:19Z

I have figured out the issue; I will submit a PR against FreeRTOS, and a patch for the SDK (there were two bugs)... the good news is that SMP and TinyUSB and configSUPPORT_PICO_SYNC_INTEROP=1 all work together now!

peterharperuk · 2024-08-09T12:07:54Z

Can you re-test this? More work has been done by @kilograham in this area

adri-sass · 2024-08-09T13:15:08Z

Thank you all. Now I'm not able to test it now, but I'll do it asap

daveythacher · 2024-08-09T13:58:21Z

Do you have commits or pull requests related to this?

kilograham · 2024-08-09T19:22:58Z

This is fixed with the latest SDK, and the latest FreeRTOS here https://github.com/raspberrypi/FreeRTOS-Kernel

Temperature6 · 2025-01-08T03:44:47Z

Increase stack size please.

Yes, It works, Thanks

lurch · 2025-01-09T13:01:10Z

This is fixed with the latest SDK, and the latest FreeRTOS here https://github.com/raspberrypi/FreeRTOS-Kernel

For the benefit of anyone else reading this issue: the FreeRTOS ports have now been upstreamed to https://github.com/FreeRTOS/FreeRTOS-Kernel/tree/main/portable/ThirdParty/GCC/RP2040 and https://github.com/FreeRTOS/FreeRTOS-Kernel-Community-Supported-Ports/tree/main/GCC/RP2350_ARM_NTZ and https://github.com/FreeRTOS/FreeRTOS-Kernel-Community-Supported-Ports/tree/main/GCC/RP2350_RISC-V

dmalnati · 2025-01-09T13:11:59Z

Hi, is there documentation I can read describing which version of the repo should be used when building for Pico? The raspberrpi version, the ThirdParty version? I set up my build when 1.5.1 was out and am using the FreeRTOS/FreeRTOS-Kernel repo. I'd like to do it the most well-supported way, this post makes me wonder if I am. Thanks. Doug

…

On Thu, Jan 9, 2025 at 8:01 AM Andrew Scheller ***@***.***> wrote: This is fixed with the latest SDK, and the latest FreeRTOS here https://github.com/raspberrypi/FreeRTOS-Kernel For the benefit of anyone else reading this issue: the FreeRTOS ports have now been upstreamed to https://github.com/FreeRTOS/FreeRTOS-Kernel/tree/main/portable/ThirdParty/GCC/RP2040 and https://github.com/FreeRTOS/FreeRTOS-Kernel-Community-Supported-Ports/tree/main/GCC/RP2350_ARM_NTZ and https://github.com/FreeRTOS/FreeRTOS-Kernel-Community-Supported-Ports/tree/main/GCC/RP2350_RISC-V — Reply to this email directly, view it on GitHub <#1453 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AALBTSZ65QHD5MOANRWV6QL2JZXK3AVCNFSM6AAAAABKZHUCWOVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDKOBQGA4TSMJRGI> . You are receiving this because you are subscribed to this thread.Message ID: ***@***.***>

lurch · 2025-01-09T13:44:58Z

Hi, is there documentation I can read describing which version of the repo should be used when building for Pico? The raspberrpi version, the ThirdParty version?

Apologies if my comment caused any confusion. You should be using the upstream URLs that I mentioned in my last comment. (The https://github.com/raspberrypi/FreeRTOS-Kernel repo was only used during initial development)

You probably want to look at https://github.com/raspberrypi/pico-examples/blob/develop/README.md#freertos
Unfortunately section 2.3.7 of https://datasheets.raspberrypi.com/pico/raspberry-pi-pico-c-sdk.pdf is now out of date, so I've created raspberrypi/pico-feedback#442

dmalnati · 2025-01-09T14:08:33Z

Perfect, thanks!

…

On Thu, Jan 9, 2025 at 8:45 AM Andrew Scheller ***@***.***> wrote: Hi, is there documentation I can read describing which version of the repo should be used when building for Pico? The raspberrpi version, the ThirdParty version? Apologies if my comment caused any confusion. You should be using the upstream URLs that I mentioned in my last comment. (The https://github.com/raspberrypi/FreeRTOS-Kernel repo was only used during initial development) You probably want to look at https://github.com/raspberrypi/pico-examples/blob/develop/README.md#freertos Unfortunately section 2.3.7 of https://datasheets.raspberrypi.com/pico/raspberry-pi-pico-c-sdk.pdf is now out of date, so I've created raspberrypi/pico-feedback#442 <raspberrypi/pico-feedback#442> — Reply to this email directly, view it on GitHub <#1453 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AALBTSZMP4ER4U75ISXGU632JZ4PBAVCNFSM6AAAAABKZHUCWOVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDKOBQGIYTCMJVGI> . You are receiving this because you are subscribed to this thread.Message ID: ***@***.***>

kilograham added pico_stdio FreeRTOS labels Jul 8, 2023

kilograham self-assigned this Jul 8, 2023

kilograham added this to the 1.6.0 milestone Jul 8, 2023

daveythacher mentioned this issue Nov 17, 2023

ISR versions of mutex_try_enter and mutex_exit #1549

Closed

kilograham mentioned this issue Feb 24, 2024

Using FreeRTOS-Kernel-Heap3 library leads to deadlock across cores, race condition on core spinlock #1646

Closed

daveythacher mentioned this issue Jul 12, 2024

Make fields within mutex volatile, just in case it matters. #1580

Closed

kilograham modified the milestones: 1.6.1, 1.6.2 Jul 19, 2024

kilograham modified the milestones: 1.6.2, 2.0.0 Aug 8, 2024

kilograham closed this as completed Aug 9, 2024

lurch mentioned this issue Jan 9, 2025

FreeRTOS ports have been upstreamed raspberrypi/pico-feedback#442

Open

printf deadlock usb using two tasks #1453

printf deadlock usb using two tasks #1453

Comments

adri-sass commented Jul 7, 2023

peterharperuk commented Jul 7, 2023

Uh oh!

adri-sass commented Jul 8, 2023

Uh oh!

kilograham commented Jul 8, 2023

Uh oh!

adri-sass commented Jul 9, 2023

Uh oh!

kilograham commented Jul 9, 2023

Uh oh!

daveythacher commented Aug 12, 2023

Uh oh!

daveythacher commented Aug 12, 2023

Uh oh!

adri-sass commented Sep 13, 2023

Uh oh!

daveythacher commented Nov 11, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

kilograham commented Nov 11, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

daveythacher commented Nov 11, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

daveythacher commented Nov 12, 2023

Uh oh!

daveythacher commented Nov 12, 2023

Uh oh!

daveythacher commented Nov 12, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

daveythacher commented Nov 16, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

kilograham commented Dec 24, 2023

Uh oh!

daveythacher commented Jan 2, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

kilograham commented Jul 12, 2024

Uh oh!

peterharperuk commented Aug 9, 2024

Uh oh!

adri-sass commented Aug 9, 2024

Uh oh!

daveythacher commented Aug 9, 2024

Uh oh!

kilograham commented Aug 9, 2024

Uh oh!

Temperature6 commented Jan 8, 2025

Uh oh!

lurch commented Jan 9, 2025

Uh oh!

dmalnati commented Jan 9, 2025 via email

Uh oh!

lurch commented Jan 9, 2025

Uh oh!

dmalnati commented Jan 9, 2025 via email

Uh oh!

daveythacher commented Nov 11, 2023 •

edited

Loading

kilograham commented Nov 11, 2023 •

edited

Loading

daveythacher commented Nov 11, 2023 •

edited

Loading

daveythacher commented Nov 12, 2023 •

edited

Loading

daveythacher commented Nov 16, 2023 •

edited

Loading

daveythacher commented Jan 2, 2024 •

edited

Loading