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

[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