`sleep_ms(900)` stuck forever when compiled with Debug Build Type (FreeRTOS)

[bittailor]

I have the issue that a sleep_ms(900) never returns when code is compiled with Debug Build Type and uses BLE. I could reduce my code to a bt-pico-freeze-issue sample, with which I can reproduce the problem.

When I run the sample with Release Build Type, all works perfect, BLE is advertising and the LED is blinking.

When I run the sample with Debug Build Type, most of the time, the first sleep_ms(900) in the loop is stuck forever no LED blinking and also USB serial output stops, but BLE advertisement work. I can see them with a BLE scanner like nRF Connect.

Very interesting is that when I then connect via BLE the sleep_ms(900) returns (even after being stuck for 5 minutes) and then the loop and with this the LED blinking works perfect. The same also happens when I disconnect and reconnect the USB serial port. So for me, it looks like some kind of external event fixes the stuck sleep_ms().

Serial output (USB) of Debug Build Type stuck at the sleep_ms(900) :

[00:00:00.875] STARTUP ...
[00:00:00.877] Versions: PICO_SDK = 2.1.1, BTSTACK = 1.6.2
Version: 7.95.61 (abcd531 CY) CRC: 4528a809 Date: Wed 2023-01-11 10:29:38 PST Ucode Ver: 1043.2169 FWID 01-7afb0879
cyw43 loaded ok, mac 2c:cf:67:b8:8d:69
BT FW download, version = CYW4343A2_001.003.016.0031.0000_Generic_SDIO_37MHz_wlbga_BU_dl_signed
[00:00:01.742] ... STARTUP done
[00:00:01.746] Loop 0 
[00:00:01.751] sleep 100 ...
[00:00:01.806] BTstack up and running on 2C:CF:67:B8:8D:6A.
[00:00:01.811] advertisement of length 22 enabled.
[00:00:01.942]  ... sleep 100 done
[00:00:01.950] sleep 900 ...

Serial output (USB) of Debug when I do a BLE connection after ~8 minutes :

[00:00:01.950] sleep 900 ...
[00:08:14.027]  ... sleep 900 done
[00:08:14.030] Loop 1 
[00:08:14.033] sleep 100 ...
[00:08:14.136]  ... sleep 100 done
[00:08:14.141] sleep 900 ...
[00:08:15.043]  ... sleep 900 done
[00:08:15.047] Loop 2 
[00:08:15.050] sleep 100 ...
[00:08:15.153]  ... sleep 100 done
[00:08:15.157] sleep 900 ...
[00:08:16.060]  ... sleep 900 done
[00:08:16.063] Loop 3 
[00:08:16.066] sleep 100 ...
[00:08:16.169]  ... sleep 100 done
[00:08:16.174] sleep 900 ...
[00:08:17.076]  ... sleep 900 done
...

serial output (USB) of Release Build Type:

[00:00:00.895] STARTUP ...
[00:00:00.897] Versions: PICO_SDK = 2.1.1, BTSTACK = 1.6.2
[00:00:01.731] ... STARTUP done
[00:00:01.734] Loop 0 
[00:00:01.738] sleep 100 ...
[00:00:01.791] BTstack up and running on 2C:CF:67:B8:8D:6A.
[00:00:01.797] advertisement of length 22 enabled.
[00:00:01.852]  ... sleep 100 done
[00:00:01.858] sleep 900 ...
[00:00:02.760]  ... sleep 900 done
[00:00:02.764] Loop 1 
[00:00:02.767] sleep 100 ...
[00:00:02.870]  ... sleep 100 done
[00:00:02.874] sleep 900 ...
[00:00:03.777]  ... sleep 900 done
[00:00:03.780] Loop 2 
[00:00:03.783] sleep 100 ...
[00:00:03.886]  ... sleep 100 done
[00:00:03.890] sleep 900 ...
[00:00:04.793]  ... sleep 900 done
[00:00:04.796] Loop 3 
[00:00:04.800] sleep 100 ...
[00:00:04.902]  ... sleep 100 done
[00:00:04.907] sleep 900 ...
[00:00:05.809]  ... sleep 900 done
...

When I debug it and break while the sleep_ms() is stuck, it's always at the timer_time_reached method (before the IRQ).

When looking at the variable values, the method would actually return true so the sleep_until loop would end, but somehow it never gets over that line as if all CPU is used by IRQ handlers?

[peterharperuk]

You don't mention what version of the SDK you are using? Can you try the LATEST master branch 2.1.1 that we released last week as it includes some timer fixes.

[bittailor]

I use SDK 2.1.1 installed via VsCode it is bddd20f which is 1 commit behind current master, but to what I see that just changed a comment.

[peterharperuk]

Ok, sorry, I see you had the version in the log.
What device are you using Pico W (rp2040) or Pico 2 W (rp2350)?

[bittailor]

I used a Pico 2 W (rp2350).

I now also run it with a Pico W (rp2040) and it does not happen, also with Debug Build Type, on the Pico W all works perfect, BLE is advertising and the LED is blinking.

[peterharperuk]

I can't immediately reproduce your issue. I'm testing Pico 2 W on Windows and choosing "Pico Debug (Cortex Debug)". Is that what you're using? The is flashing and I see console output.

It sounds like there are too many interrupts going off constantly. I would guess cyw43. I've no idea why it would only affect debug. You could try defining PICO_BTSTACK_CYW43_MAX_HCI_PROCESS_LOOP_COUNT=10 to limit the work done in hci_transport_cyw43_process in case that's constantly busy.

[bittailor]

Defining PICO_BTSTACK_CYW43_MAX_HCI_PROCESS_LOOP_COUNT=10 did not help.

I'm working on macOS, but hope that should not make a difference. It's not about launching with a debugger but building the Debug Version like

or settingCMAKE_BUILD_TYPE=Debug. It's also happening when flashing via USB with picotool.

So for me the following reproduces it:

git clone https://github.com/bittailor/bt-pico-freeze-issue
cd bt-pico-freeze-issue
cmake -DPython3_EXECUTABLE=${HOME}/.pico-sdk/python/3.12.1/python.exe -DCMAKE_BUILD_TYPE=Debug -G Ninja -B ./build .
${HOME}/.pico-sdk/ninja/v1.12.1/ninja -C build
${HOME}/.pico-sdk/picotool/2.1.1/picotool/picotool load ./build/bt-pico-freeze-issue.elf -fx 
sleep 2
screen /dev/tty.usbmodem21401 115200

As then, the output of screen is

[00:00:01.625] STARTUP ...
[00:00:01.627] Versions: PICO_SDK = 2.1.1, BTSTACK = 1.6.2
Version: 7.95.61 (abcd531 CY) CRC: 4528a809 Date: Wed 2023-01-11 10:29:38 PST Ucode Ver: 1043.2169 FWID 01-7afb0879
cyw43 loaded ok, mac 2c:cf:67:b8:8d:69
BT FW download, version = CYW4343A2_001.003.016.0031.0000_Generic_SDIO_37MHz_wlbga_BU_dl_signed
[00:00:02.491] ... STARTUP done
[00:00:02.495] Loop 0 
[00:00:02.501] sleep 100 ...
[00:00:02.555] BTstack up and running on 2C:CF:67:B8:8D:6A.
[00:00:02.561] advertisement of length 22 enabled.
[00:00:02.692]  ... sleep 100 done
[00:00:02.700] sleep 900 ...

and stuck at the last line of sleep 900

[digiexchris]

I'm getting this also, with the current head of main on an RP2040. It seems that get_absolute_time() always returns 0, so the sleep functions never advance. gcc arm-none-eabi 13.2.rel1 supplied by Ubuntu 24.04 (on an x86_64 host). Not certain about debug vs release configurations, I do have PICO_DEOPTIMIZED_DEBUG set. Minimum reproducible code:

stdio_init_all();

auto time = get_absolute_time();
auto incrementingTime = time;

for(int i = 0; i < 12500000; i++) //about 10 seconds elapses
{
	incrementingTime = get_absolute_time();
}

auto time2 = get_absolute_time();

printf("Time: %llu\n", time);
printf("incrementingTime: %llu\n", incrementingTime);
printf("Time2: %llu\n", time2);

sleep_ms(10);

printf("Time After Sleep: %llu\n", time_us_64()); //never gets hit

output:

Time: 0                                                        
incrementingTime: 0                                            
Time2: 0   

Giving the loop a few hundred million iterations doesn't change the output at all.

[digiexchris]

clarifying information: this only seems to happen with a debugger attached, if you just let it run without launching with a debugger, it does give the expected output:

Time: 494
incrementingTime: 17800515
Time2: 17800517
Time After Sleep: 17815898

[digiexchris]

I may have figured it out, thanks to raspberrypi/debugprobe#45

the vscode extension's launch configuration has this

"overrideLaunchCommands": [
                "monitor reset init",
                "load \"${command:cmake.launchTargetPath}\"",
            ],

adding in another monitor reset seems to have kicked off the timers again.

"overrideLaunchCommands": [
                "monitor reset init",
                "load \"${command:cmake.launchTargetPath}\"",
                "monitor reset"
            ],

and sleep_ms() works again while a debugger is attached.

It wasn't specific to 2.1.1 either, this happened on 2.0.0 (tested just now). The underlying issue for the OP may be that one core was stuck in a halted state after the firmware was loaded (possibly from a previous debugging session?). For me, it was one core was stuck in a stopped state due to the openocd load command, and never restarted the timers again.

[lurch]

@digiexchris I suspect that your issue may be different to the OP's issue, as I think your issue means that every sleep_ms would lock up, whereas the OP's output logging indicates that their initial sleep_ms(100) works, and it's only the later sleep_ms(900) that locks up?

[digiexchris]

yes you may be right, but I wonder if it is related to when the default timer gets started, and on which core the sleep is called on. but yeah it doesn't look like the OP's reproduction code does the sleeps on the second core. I wonder if the behaviour is any different if a full power cycle is done after flashing? That is what pointed me to the realization that my issue was actually related to the cores halting for the load function.

Also in my case it does seem like it's only the default timer that's affected, since the FreeRTOS tick timer that gets started when the scheduler starts works totally fine.

[lurch]

Also in my case it does seem like it's only the default timer that's affected, since the FreeRTOS tick timer that gets started when the scheduler starts works totally fine.

@digiexchris I's a bit OffTopic from the original issue here, but see #1152 for more info.

[digiexchris]

Interestingly, I added an additional sleep_ms into my duplication code above, and despite not having a debugger connected, I am having the same symptoms as the OP! The second sleep stalls!

Callstack:
vPortLockInternalSpinUnlockWithWait@0x1004505c (/home/chris/repos/PicoMillPowerFeed/src/FreeRTOS-Kernel/portable/ThirdParty/GCC/RP2040/port.c:1047)
sleep_until@0x10035ee0 (/toolchain/pico-sdk/src/common/pico_time/time.c:410)
sleep_us@0x10035f3e (/toolchain/pico-sdk/src/common/pico_time/time.c:424)
sleep_ms@0x10035f70 (/toolchain/pico-sdk/src/common/pico_time/time.c:440)
main@0x10001c12 (/home/chris/repos/PicoMillPowerFeed/src/main.cxx:146)

I do have freertos included, but the scheduler is not active at the time when these sleep_ms are called. I wonder if there's an issue with the freertos port.

[kilograham]

I do have freertos included, but the scheduler is not active at the time when these sleep_ms are called

What version of FreeRTOS (upstream, or rpi repo)?
is this on RP2040?
what does "not active" mean - you haven't started it yet?

[digiexchris]

I do have freertos included, but the scheduler is not active at the time when these sleep_ms are called

What version of FreeRTOS (upstream, or rpi repo)? is this on RP2040? what does "not active" mean - you haven't started it yet?

Correct, I have not started the scheduler yet when calling the pico sdk sleep functions in the above repro code. I am using the head of upstream, since the rp2040 and smp code has been merged in there. Or so I read, maybe I'm wrong, but SMP and all other expected features appear to be working once I start the scheduler, but I do not use any normal sleep_ms type functions in the freertos tasks and use vTaskDelay() in those. The sleep_ms() calls are just during setup, like giving a short delay after GPIO setup to allow an SSD1306 to settle before starting everything that's going to use it.

I've since moved to a deterministic order of starting of freertos tasks instead of using sleep_ms, but it's probably worth addressing since there was no indication anything was broken other than the default timer never firing.