Pico Timer Callback - collision with IRQ servicing causes lockup

[mungewell]

Following on from:
https://github.com/orgs/micropython/discussions/11529

I have implement the Timer to modulate the Pico's PIO clock dividers, so that I can a compensate for an imprecise XTAL and get a match to external frequency reference. But every so often the whole code would lock up....

I think I have tracked this down to the IRQ servicing routine is being called during at the same time, and it seems that the timer re-init does NOT operate whilst the IRQs are disabled (as recommended by previous discussion).

Full code is here:
https://github.com/mungewell/pico-timecode/tree/adjust_clock_with_PID

IQR and Timer callback:
https://github.com/mungewell/pico-timecode/blob/adjust_clock_with_PID/pico_timecode.py#L191

With my debug prints in place I get following when crash occurs, and there is no '.' output showing that the Timer Callback is still active.

[[0, 0], [False, False], [False, True]]
+
.

[[0, 0], [False, False], [False, True]]
-
.

[[0, 0], [False, False], [False, True]]
+
. <---- signals Timer callback is complete

[[0, 0], [False, False], [False, True]]
-
0 <--- from IRQ routine happening whilst Timer callback is active

Is there any (practical) way I can pause the IRQ routine, whilst Timer callback/re-init is happening?

[mungewell]

I put in place a whole load of work-arounds, but still get the lock up. :-(

For the IRQ servicing I just decided to exit the routine if it detected that the timer.init() was occurring, which means that it would miss the time stamping of TX/RX packets - not critical. I can see that this 'collision' occurs occasionally, but rarely I still get a lockup.

def irq_handler(m):
    global eng, stop
    global tx_ticks_us, rx_ticks_us
    global core_dis

    if core_dis[1][2]:
        #print("*")
        return

I've also attempted to minimise the 'window of opportunity' around the re-init(), setting up flags and pausing/sleep to prevent 'collision'

    while True:
        if not core_dis[0][2]:
            core_dis[1][2] = True
            break
        '''
        else:
            print("C", machine.mem32[0xd0000000])
        '''

    # and again, in-case IRQ 'missed' [1][2] being set...
    utime.sleep(0.001)
    while core_dis[0][2]:
        #print("C", machine.mem32[0xd0000000])
        utime.sleep(0.001)

    core_dis[1][machine.mem32[0xd0000000]] = machine.disable_irq()

    period -= utime.ticks_diff(ticks, utime.ticks_ms())
    if period < 50:
        period = 50

    timer.init(period=period, mode=Timer.ONE_SHOT, callback=timer_handler)

    machine.enable_irq(core_dis[1][machine.mem32[0xd0000000]])
    core_dis[1][2] = False

If I disable the timer (set duty cycle to X.0 so that it does not start, and therefore no callback gets called) the code will run for hours.

Timing information:
Both TX and RX IRQs happen at 30fps, un-synced these can be anytime but once sync'ed RX will happen ~2/3bit (300us) later than TX.
https://github.com/mungewell/pico-timecode/blob/adjust_clock_with_PID/main.py#L344

Timer is set for a 10s period, but duty factor means that the re-init() can happen any time in the middle of this cycle.

[mungewell]

I also tried disabling the PIO interrupts to prevent the 'collision'

    # disable PIO's IRQ handlers
    for m in eng.sm:
        m.irq(handler=None)

    # re set up IRQ handler
    for m in eng.sm:
        m.irq(handler=irq_handler, hard=True)

But they weren't re-enabled after, maybe this is a thread thing...

[GitHubsSilverBullet]

Probably not the best idea to modify the Timer in its own ISR.
Try to use ›schedule()‹

from machine import Timer
from micropython import schedule
from time import sleep_ms

def timer_cb(t):
    print(f'scheduled callback({t})')

t = Timer()
t.init(mode=Timer.PERIODIC, freq=10, callback=lambda timer_info:schedule(timer_cb, timer_info))
sleep_ms(2000)
t.deinit()

[mungewell]

Yes! Thank you for the suggestion of schedule(), this makes much more sense, and I have coded this into

def timer_sched(timer):
    schedule(timer_re_init, timer)

def timer_re_init(timer):
    global eng

    period = 0
...
    eng.timer.init(period=period, mode=Timer.ONE_SHOT, callback=timer_sched)

However this does NOT prevent the lock-up.

The 'pico_timecode.py' script will run standalone, and I also distilled the code down to a simple script. Well not that simple as I am using PIO blocks to create interrupts (servicing them in the same way), running threaded, and running the Timer.
dumb_test7.py.txt

Enabling/Disabling various bits I notice that:
1). Fault only occurs if there are multiple threads.
2). Fault only occurs when there is Timer active, and it seems to occur in the time frame of the callback happening.

3rd/4th columns are TX/RX timestamp in us.

0 38800 12763524 12769030
0 38900 13111326 13108232
0 39000 13451727 13453831
0 39100 13799533 13799430
[0, 0, False]
.
0 39200 14139926 14145031
0 39300 14487725 14484233
0 39400 14828122 14829833
0 39500 15168525 15175431
0 39600 15516327 15514649
0 39700 15856724 15860232
0 39800 16204527 16199433
0 39900 16544924 16545034
0 40000 16885326 16890631
0 40100 17233124 17229830
0 40200 17573525 17575434
0 40300 17913927 17921048
0 40400 18261727 18266634
0 40500 18609525 18605831
0 40600 18949926 18951431
[ <--- part of print from callback, doesn't always appear

Next step is to re-introduce the 'protections' to see if I can prevent....

I also tried with a 'PERIODIC' timer, so not needing to update it, which also crashed less frequently. Suggesting that this is an issue with the interrupts occurring, rather than with the adjustment of the timer. This could be a different issue.

I want to be using a 'ONE_SHOT' so that I can have different durations for the 'on' and 'off' states. I guess I could run with two timers, but that might double my problems.

Overall I get that I'm pushing the technology quite hard, perhaps triggering unusual glitches.... all help is much appreciated.

I note that there's the 3pin debug header, I'm new to Picos so not sure whether this would be useful and couldn't find a newbie guide on how to use it.

[mungewell]

It seems like schedule() doesn't function (locks up 100%) if the interrupts are disabled when it is called, the best I can do is to check/set the flags to prevent ISR doing stuff...

def irq_handler(m):
    global sm, tx_ticks_us, rx_ticks_us
    global thread_id, core_dis

    if core_dis[1][2]:
        return
    
    core_dis[0][2] = True
    core_dis[0][mem32[0xd0000000]] = disable_irq()
    
    ticks = time.ticks_us()
    if m==sm[0]:
        tx_ticks_us = ticks

    if m==sm[1]:
        rx_ticks_us = ticks

    enable_irq(core_dis[0][mem32[0xd0000000]])
    core_dis[0][2] = False
    
#-------------------------------------------------------

def timer_sched(timer):
    global core_dis
    
    '''
    core_dis[1][2] = True
    '''
    while True:
        if not core_dis[0][2]:
            core_dis[1][2] = True
            break
    while True:
        if not core_dis[0][2]:		# incase ISR set flag at exactly
            break					# the same time...
    
    #core_dis[1][mem32[0xd0000000]] = disable_irq()

    schedule(timer_re_init, timer)

    #enable_irq(core_dis[1][mem32[0xd0000000]])
    core_dis[1][2] = False

dumb_test7.py.txt

Also adding disable_irq() and enable_irq() around the timer.init() doesn't prevent lock-ups, neither does using PERIODIC... so perhaps this is really something different happening in the timer code.

I'll stress again, it does NOT lockup if there is only one thread.

[rkompass]

@mungewell from your code I have the impression, that the interrupt service routines run on both cores. We had seen earlier, that this does lead to unpredictable behaviour. Also you acquire a lock in the ISR. This contradicts the need of the ISR to terminate rapidly.
It seems you want to adjust the frequencies regularly. This is not a very urgent business, I suppose, as all irregularities add up rather continuously by very small steps. So you have to adjust in regular intervals, but not urgently. schedule() is the right way to go, probably. You may keep a function alive (run in regular intervals) by re-scheduling it whenever it is finished, iirc.

[mungewell]

Yes I also think schedule() is part of the solution, but I think this is perhaps a continuation of the issues I was seeing with PIO interrupts... I'm about to answer some stuff above.

The lock(0) is intended NOT to wait for lock, and it would immediately fall through if the lock was ever 'busy'. At the moment it would never be busy...

This timer is very slow, 10s period split into 'on' and 'off' states to modulate the fractional portion of the PIO clock divider.

This means that I can 'precisely match' an external frequency reference using a PID loop, and keep my PIO counters in time with another device. This works quiet well... blue line is delta in us, until the PID was disabled/locked at ~8000s.

[mungewell]

Forgot to say I can confirm that the callback can switch between cores...

[mungewell]

BTW tried your earlier suggestion of locks, the acquire() call seems to lock up when run on 2nd core... very odd.

def timer_sched(timer):
    global core_dis, core_lock

    core = mem32[0xd0000000]
    lock = (core_lock[core]).acquire(0)
    if lock:
        schedule(timer_re_init, timer)
        (core_lock[core]).release()

[GitHubsSilverBullet]

Hi @mungewell ,
I had a look at the sourcecode and it seems as if the timer callback routine already does a ›schedule()‹ That'd explain why it still doesn't work.

Second thought, usually a crystal has a variability of 10…30ppm. Thus using a timer to make adjustment would be a pretty heavy hammer for a delicate wrist-watch repair.

If you need a precision in the sub ppm arena, I'd suggest using a TCXO instead of a regular crystal.

[mungewell]

@GitHubsSilverBullet Using a PID loop, and modulating the PIO dividers does work quite well, the plot above is from:
mungewell/pico-timecode#3 (comment)

In this test I was able to 'calibrate' the stock crystal to an external reference, and when external reference was de-linked the local time took ~15hr to drift by 1 frame (my target would be <1 frame in 8hrs). Yes a TCXO would be better, I have some from Digikey to install.... but I wanted to see what was achievable with stock.

Remember the way that I'm using the timer is to run very-slightly faster for X% of the time, and very-slightly slower for the rest. My previous tests were using NeoTimer in my software loop. Moving to inbuilt Timer() was supposed to be an improvement ;-)

My previous comment about acquire() may be wrong, or influenced by the test script. I put this in the pico_timecode.py script and it appears to run OK. Though I still get crashes....

[mungewell]

I mentioned that the Debug header was a mystery to me... not anymore. Proud to say I've earned that badge!

In case anyone else is following along:
https://wellys.com/posts/rp2040_c_linux/
https://www.youtube.com/watch?v=0i2gLeBal9Y

and some fixes:
#7302
wuxx/pico-lab#1

$ sudo openocd -f interface/cmsis-dap.cfg -f target/rp2040.cfg -c "program blink/blink.elf verify reset exit"
Open On-Chip Debugger 0.11.0-g4f2ae61 (2023-06-08-16:45)
Licensed under GNU GPL v2
For bug reports, read
	http://openocd.org/doc/doxygen/bugs.html
adapter speed: 5000 kHz

Info : auto-selecting first available session transport "swd". To override use 'transport select <transport>'.
Info : Hardware thread awareness created
Info : Hardware thread awareness created
Info : RP2040 Flash Bank Command
Info : Using CMSIS-DAPv2 interface with VID:PID=0x2e8a:0x000c, serial=E66034F71F411424
Info : CMSIS-DAP: SWD  Supported
Info : CMSIS-DAP: FW Version = 2.0.0
Info : CMSIS-DAP: Interface Initialised (SWD)
Info : SWCLK/TCK = 0 SWDIO/TMS = 0 TDI = 0 TDO = 0 nTRST = 0 nRESET = 0
Info : CMSIS-DAP: Interface ready
Info : clock speed 5000 kHz
Info : SWD DPIDR 0x0bc12477
Info : SWD DLPIDR 0x00000001
Info : SWD DPIDR 0x0bc12477
Info : SWD DLPIDR 0x10000001
Info : rp2040.core0: hardware has 4 breakpoints, 2 watchpoints
Info : rp2040.core1: hardware has 4 breakpoints, 2 watchpoints
Info : starting gdb server for rp2040.core0 on 3333
Info : Listening on port 3333 for gdb connections
target halted due to debug-request, current mode: Thread 
xPSR: 0xf1000000 pc: 0x000000ee msp: 0x20041f00
target halted due to debug-request, current mode: Thread 
xPSR: 0xf1000000 pc: 0x000000ee msp: 0x20041f00
** Programming Started **
Info : RP2040 B0 Flash Probe: 2097152 bytes @10000000, in 512 sectors

target halted due to debug-request, current mode: Thread 
xPSR: 0x01000000 pc: 0x00000178 msp: 0x20041f00
target halted due to debug-request, current mode: Thread 
xPSR: 0x01000000 pc: 0x00000178 msp: 0x20041f00
target halted due to debug-request, current mode: Thread 
xPSR: 0x01000000 pc: 0x00000178 msp: 0x20041f00
target halted due to debug-request, current mode: Thread 
xPSR: 0x01000000 pc: 0x00000178 msp: 0x20041f00
target halted due to debug-request, current mode: Thread 
xPSR: 0x01000000 pc: 0x00000178 msp: 0x20041f00
Info : Writing 12288 bytes starting at 0x0
target halted due to debug-request, current mode: Thread 
xPSR: 0x01000000 pc: 0x00000178 msp: 0x20041f00
target halted due to debug-request, current mode: Thread 
xPSR: 0x01000000 pc: 0x00000178 msp: 0x20041f00
target halted due to debug-request, current mode: Thread 
xPSR: 0x01000000 pc: 0x00000178 msp: 0x20041f00
target halted due to debug-request, current mode: Thread 
xPSR: 0x01000000 pc: 0x00000178 msp: 0x20041f00
target halted due to debug-request, current mode: Thread 
xPSR: 0x01000000 pc: 0x00000178 msp: 0x20041f00
target halted due to debug-request, current mode: Thread 
xPSR: 0x01000000 pc: 0x00000178 msp: 0x20041f00
** Programming Finished **
** Verify Started **
target halted due to debug-request, current mode: Thread 
xPSR: 0x01000000 pc: 0x00000178 msp: 0x20041f00
target halted due to debug-request, current mode: Thread 
xPSR: 0x01000000 pc: 0x00000178 msp: 0x20041f00
** Verified OK **
** Resetting Target **
shutdown command invoked

Next challenge building and flashing MicroPython this way, with UART redirect and (possibly) no USB. I found some high precision XTALs but they are 12.8MHz (rather than 12MHz) and I suspect that this might be enough to throw USB out of operation...

https://github.com/orgs/micropython/discussions/10705

[mungewell]

Hmmm, not as difficult as I thought it would be. Was able to build MicroPython after adjusting

$ git diff mpconfigport.h
diff --git a/ports/rp2/mpconfigport.h b/ports/rp2/mpconfigport.h
index 28b06fa3a..f4286a371 100644
--- a/ports/rp2/mpconfigport.h
+++ b/ports/rp2/mpconfigport.h
@@ -37,16 +37,16 @@
 // Board and hardware specific configuration
 #define MICROPY_HW_MCU_NAME                     "RP2040"
 #ifndef MICROPY_HW_ENABLE_UART_REPL
-#define MICROPY_HW_ENABLE_UART_REPL             (0) // useful if there is no USB
+#define MICROPY_HW_ENABLE_UART_REPL             (1) // useful if there is no USB
 #endif
 #ifndef MICROPY_HW_ENABLE_USBDEV
-#define MICROPY_HW_ENABLE_USBDEV                (1)
+#define MICROPY_HW_ENABLE_USBDEV                (0)
 #endif
 
 #if MICROPY_HW_ENABLE_USBDEV
 // Enable USB-CDC serial port
 #ifndef MICROPY_HW_USB_CDC
-#define MICROPY_HW_USB_CDC (1)
+#define MICROPY_HW_USB_CDC (0)
 #endif
 // Enable USB Mass Storage with FatFS filesystem.
 #ifndef MICROPY_HW_USB_MSC

Then I can run the MicroPython using the PicoProbe OpenOCD interface with UART and no USB connection, and debug from GDB.

My pico_timecode.py is saved as main.py and runs automatically. After a while it crashed, well actually it was stuck - I had to Ctrl-C to do a backtrace....

simon@the-void:~/pico/micropython/ports/rp2/build-PICO$ gdb-multiarch  firmware.elf
GNU gdb (Ubuntu 13.1-2ubuntu2) 13.1
Copyright (C) 2023 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<https://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from firmware.elf...
(gdb) target remote localhost:3333
Remote debugging using localhost:3333
warning: multi-threaded target stopped without sending a thread-id, using first non-exited thread
0x20000208 in mutex_enter_blocking ()
(gdb) load
Loading section .boot2, size 0x100 lma 0x10000000
Loading section .text, size 0x32cb0 lma 0x10000100
Loading section .rodata, size 0x13208 lma 0x10032db0
Loading section .binary_info, size 0x68 lma 0x10045fb8
Loading section .data, size 0x61cc lma 0x10046020
Start address 0x100001e8, load size 311788
Transfer rate: 22 KB/sec, 14172 bytes/write.
(gdb) monitor reset init
target halted due to debug-request, current mode: Thread 
xPSR: 0xf1000000 pc: 0x000000ee msp: 0x20041f00
target halted due to debug-request, current mode: Thread 
xPSR: 0xf1000000 pc: 0x000000ee msp: 0x20041f00
(gdb) continue
Continuing.
Polling target rp2040.core1 failed, trying to reexamine
SWD DPIDR 0x0bc12477
SWD DLPIDR 0x10000001
rp2040.core1: hardware has 4 breakpoints, 2 watchpoints

^Ctarget halted due to debug-request, current mode: Handler External Interrupt(16)
xPSR: 0x41000020 pc: 0x1002f0a6 msp: 0x20013cf0

Thread 1 received signal SIGINT, Interrupt.
0x20000208 in mutex_enter_blocking ()
(gdb) bt
#0  0x20000208 in mutex_enter_blocking ()
#1  0x10029ed0 in mp_thread_begin_atomic_section ()
#2  0x10018506 in mp_sched_lock ()
#3  0x100268fa in mp_irq_handler ()
#4  0x1002a2c4 in pio_irq0 ()
#5  0x1002a2ec in pio0_irq0 ()
#6  <signal handler called>
#7  0x10029eea in mp_thread_end_atomic_section ()
#8  0x10029c68 in machine_enable_irq ()
#9  0x10029c68 in machine_enable_irq ()
#10 0x1000fa7e in fun_builtin_1_call ()
#11 0x10017638 in mp_call_function_n_kw ()
#12 0x100176ea in mp_call_method_n_kw ()
#13 0x20002b70 in mp_execute_bytecode ()
#14 0x1000fcf8 in fun_bc_call ()
#15 0x10017638 in mp_call_function_n_kw ()
#16 0x100176ca in mp_call_function_1 ()
#17 0x100184ce in mp_call_function_1_protected ()
#18 0x10018662 in mp_handle_pending ()
#19 0x10029e3c in mp_hal_delay_ms ()
#20 0x1001e29c in time_sleep ()
#21 0x1000fa7e in fun_builtin_1_call ()
#22 0x10017638 in mp_call_function_n_kw ()
#23 0x100176ea in mp_call_method_n_kw ()
#24 0x20002b70 in mp_execute_bytecode ()
#25 0x1000fcf8 in fun_bc_call ()
#26 0x10017638 in mp_call_function_n_kw ()
#27 0x20002ade in mp_execute_bytecode ()
#28 0x1000fcf8 in fun_bc_call ()
#29 0x10017638 in mp_call_function_n_kw ()
#30 0x10017650 in mp_call_function_0 ()
#31 0x10026a54 in parse_compile_execute ()
#32 0x10026d72 in pyexec_file ()
--Type <RET> for more, q to quit, c to continue without paging--
#33 0x10026dde in pyexec_file_if_exists ()
#34 0x10029a22 in main ()

[mungewell]

So I might have the following wrong... but what else can I glean from GDB?

Thread-1 seems to be executing ByteCode, and then swapped out for the interrupt handler.
What is Thread-2 doing at the same time??

(gdb) thread apply all bt


Thread 2 (Thread 2 (Name: rp2040.core1, state: debug-request)):
#0  0x1002f0a6 in multicore_fifo_pop_blocking_inline ()
#1  0x2000060a in multicore_lockout_handler ()
#2  <signal handler called>
#3  0x1002df56 in best_effort_wfe_or_timeout ()
#4  0x1002e1c8 in hardware_alarm_set_target ()
#5  0x2000c39c in ?? ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

Thread 1 (Thread 1 (Name: rp2040.core0, state: debug-request)):
#0  0x20000208 in mutex_enter_blocking ()
#1  0x10029ed0 in mp_thread_begin_atomic_section ()
#2  0x10018506 in mp_sched_lock ()
#3  0x100268fa in mp_irq_handler ()
#4  0x1002a2c4 in pio_irq0 ()
#5  0x1002a2ec in pio0_irq0 () <---------------------- PIO interrupt?
#6  <signal handler called>
#7  0x10029eea in mp_thread_end_atomic_section ()
#8  0x10029c68 in machine_enable_irq ()
#9  0x10029c68 in machine_enable_irq ()
#10 0x1000fa7e in fun_builtin_1_call ()
#11 0x10017638 in mp_call_function_n_kw ()
#12 0x100176ea in mp_call_method_n_kw ()
#13 0x20002b70 in mp_execute_bytecode () <------------------- Bytecode, see below
#14 0x1000fcf8 in fun_bc_call ()
#15 0x10017638 in mp_call_function_n_kw ()
#16 0x100176ca in mp_call_function_1 ()

If I step back to the #13 and dump registers

(gdb) up 13

#13 0x20002b70 in mp_execute_bytecode ()
(gdb) info r

r0             0x1003e728          268691240
r1             0x1                 1
r2             0x0                 0
r3             0x1                 1
r4             0x10044e0d          268717581 <----------- is this location the pointer to my 'frozen' bytecode?
r5             0x20011914          536942868
r6             0x0                 0
r7             0x20011900          536942848
r8             0xffffffff          -1
r9             0xffffffff          -1
r10            0xffffffff          -1
r11            0xffffffff          -1
r12            0x100176cd          268531405
sp             0x20041c20          0x20041c20
lr             0x20002b71          536882033
pc             0x20002b70          0x20002b70 <mp_execute_bytecode+3476>
xPSR           0x21000000          553648128
msp            0x20041c20          0x20041c20
psp            0xfffffffc          0xfffffffc
primask        0x0                 0
basepri        0x0                 0
faultmask      0x0                 0
control        0x0                 0

(gdb) x 0x0000010044e0d

0x10044e0d <fun_data_main_timer_re_init+385>:	0x11811259

// frozen bytecode for file main.py, scope main_timer_re_init
static const byte fun_data_main_timer_re_init[398] = {
    0x99,0x10,0x50, // prelude
    0x3a,0x41, // names: timer_re_init, timer
...
    0x59, // POP_TOP
    0x12,0x02, // LOAD_GLOBAL 'machine'
    0x14,0x37, // LOAD_METHOD 'enable_irq'
    0x12,0x81,0x10, // LOAD_GLOBAL 'core_dis'
    0x81, // LOAD_CONST_SMALL_INT 1
    0x55, // LOAD_SUBSCR
    0xb7, // LOAD_FAST 7
    0x55, // LOAD_SUBSCR
    0x36,0x01, // CALL_METHOD 1
    0x59, // POP_TOP
    0x12,0x81,0x11, // LOAD_GLOBAL 'core_lock'
    0xb7, // LOAD_FAST 7
    0x55, // LOAD_SUBSCR
    0x14,0x38, // LOAD_METHOD 'release'
    0x36,0x00, // CALL_METHOD 0
    0x59, // POP_TOP
    0x51, // LOAD_CONST_NONE
    0x63, // RETURN_VALUE
};

    core = machine.mem32[0xd0000000]
    lock = core_lock[core].acquire()
    if lock:
        core_dis[1][core] = machine.disable_irq()
        eng.timer.init(period=period, mode=Timer.ONE_SHOT, callback=timer_sched)
        machine.enable_irq(core_dis[1][core])
        core_lock[core].release()

[mungewell]

That's a real interesting comment there.... are we stuck endlessly waiting for something to happen, but it can't because we've disabled the interrupts at precisely the wrong time?

// note this method is in RAM because lockout is used when writing to flash
// it only makes inline calls
static void __isr __not_in_flash_func(multicore_lockout_handler)(void) {
    multicore_fifo_clear_irq();
    while (multicore_fifo_rvalid()) {
        if (sio_hw->fifo_rd == LOCKOUT_MAGIC_START) {
            uint32_t save = save_and_disable_interrupts();
            multicore_fifo_push_blocking_inline(LOCKOUT_MAGIC_START);
            while (multicore_fifo_pop_blocking_inline() != LOCKOUT_MAGIC_END) {
                tight_loop_contents(); // not tight but endless potentially
            }
            restore_interrupts(save);
            multicore_fifo_push_blocking_inline(LOCKOUT_MAGIC_END);
        }
    }
}

Note that Thread-1 is atomic at this point....

#1  0x10029ed0 in mp_thread_begin_atomic_section ()

[mungewell]

As you might have a seen, I'm getting 'better' at learning/understanding GDB to see what is going on...

(gdb) monitor reset init
target halted due to debug-request, current mode: Thread 
xPSR: 0xf1000000 pc: 0x000000ee msp: 0x20041f00
target halted due to debug-request, current mode: Thread 
xPSR: 0xf1000000 pc: 0x000000ee msp: 0x20041f00
(gdb) c
Continuing.
Polling target rp2040.core1 failed, trying to reexamine
SWD DPIDR 0x0bc12477
SWD DLPIDR 0x10000001
rp2040.core1: hardware has 4 breakpoints, 2 watchpoints
^Ctarget halted due to debug-request, current mode: Handler External Interrupt(16)
xPSR: 0x41000020 pc: 0x1002f0a6 msp: 0x2000c180

Thread 1 received signal SIGINT, Interrupt.
0x20000208 in mutex_enter_blocking ()
(gdb) thread apply all bt


Thread 2 (Thread 2 (Name: rp2040.core1, state: debug-request)):
#0  0x1002f0a6 in multicore_fifo_pop_blocking_inline ()
#1  0x2000060a in multicore_lockout_handler ()
#2  <signal handler called>
#3  0x1002df56 in best_effort_wfe_or_timeout ()
#4  0x1002e1c8 in hardware_alarm_set_target ()
#5  0x2000c38c in ?? ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)


Thread 1 (Thread 1 (Name: rp2040.core0, state: debug-request)):
#0  0x20000208 in mutex_enter_blocking ()
#1  0x10029ed0 in mp_thread_begin_atomic_section ()
#2  0x10018506 in mp_sched_lock ()
#3  0x100268fa in mp_irq_handler ()
#4  0x1002a2c4 in pio_irq0 ()
#5  0x1002a2ec in pio0_irq0 ()
#6  <signal handler called>
#7  0x10029eea in mp_thread_end_atomic_section ()
#8  0x10029c68 in machine_enable_irq ()
#9  0x10029c68 in machine_enable_irq ()
#10 0x1000fa7e in fun_builtin_1_call ()
#11 0x10017638 in mp_call_function_n_kw ()
#12 0x100176ea in mp_call_method_n_kw ()
#13 0x20002b70 in mp_execute_bytecode ()
#14 0x1000fcf8 in fun_bc_call ()
#15 0x10017638 in mp_call_function_n_kw ()
#16 0x100176ca in mp_call_function_1 ()
#17 0x100184ce in mp_call_function_1_protected ()
#18 0x10018662 in mp_handle_pending ()
#19 0x10029e3c in mp_hal_delay_ms ()
#20 0x1001e29c in time_sleep ()
#21 0x1000fa7e in fun_builtin_1_call ()
--Type <RET> for more, q to quit, c to continue without paging--
#22 0x10017638 in mp_call_function_n_kw ()
#23 0x100176ea in mp_call_method_n_kw ()
#24 0x20002b70 in mp_execute_bytecode ()
#25 0x1000fcf8 in fun_bc_call ()
#26 0x10017638 in mp_call_function_n_kw ()
#27 0x20002ade in mp_execute_bytecode ()
#28 0x1000fcf8 in fun_bc_call ()
#29 0x10017638 in mp_call_function_n_kw ()
#30 0x10017650 in mp_call_function_0 ()
#31 0x10026a54 in parse_compile_execute ()
#32 0x10026d98 in pyexec_frozen_module ()
#33 0x10026dc8 in pyexec_file_if_exists ()
#34 0x10029a22 in main ()
(gdb) 
(gdb) t 1
[Switching to thread 1 (Thread 1)]
#0  0x20000208 in mutex_enter_blocking ()
(gdb) up 13
#13 0x20002b70 in mp_execute_bytecode ()
(gdb) i r r4
r4             0x10044e02          268717570
(gdb) x 0x10044e02
0x10044e02 <fun_data_main_timer_sched+398>:	0x10811259
(gdb) b mutex_enter_blocking
Breakpoint 1 at 0x20000212
(gdb) c
Continuing.
target halted due to debug-request, current mode: Handler External Interrupt(16)
xPSR: 0x41000020 pc: 0x1002f0a6 msp: 0x2000c180

Thread 1 hit Breakpoint 1, 0x20000212 in mutex_enter_blocking ()
(gdb) c
Continuing.
target halted due to debug-request, current mode: Handler External Interrupt(16)
xPSR: 0x41000020 pc: 0x1002f0a6 msp: 0x2000c180

Thread 1 hit Breakpoint 1, 0x20000212 in mutex_enter_blocking ()
(gdb) c
Continuing.
target halted due to debug-request, current mode: Handler External Interrupt(16)
xPSR: 0x41000020 pc: 0x1002f0a6 msp: 0x2000c180

Thread 1 hit Breakpoint 1, 0x20000212 in mutex_enter_blocking ()
(gdb) c
Continuing.
target halted due to debug-request, current mode: Handler External Interrupt(16)
xPSR: 0x41000020 pc: 0x1002f0a6 msp: 0x2000c180

Thread 1 hit Breakpoint 1, 0x20000212 in mutex_enter_blocking ()
(gdb)

What I don't understand ATM is how the call to mutex_enter_blockin is repeated called, when the call the mp_thread_begin_atomic_section is NOT...

Thread-1
ports/rp2/mpthreadport.c

uint32_t mp_thread_begin_atomic_section(void) {
    if (core1_entry) {
        // When both cores are executing, we also need to provide
        // full mutual exclusion.
        mp_thread_mutex_lock(&atomic_mutex, 1); 
        // In case this atomic section is for flash access, then
        // suspend the other core.
        multicore_lockout_start_blocking(); <---- not called?
    }

    return save_and_disable_interrupts();
}

ports/rp2/mpthreadport.h

static inline int mp_thread_mutex_lock(mp_thread_mutex_t *m, int wait) {
    if (wait) {
        mutex_enter_blocking(m); <---- called repeated, why?
        return 1;
    } else {
        return mutex_try_enter(m, NULL);
    }
}

void __time_critical_func(mutex_enter_blocking)(mutex_t *mtx) {
#if PICO_MUTEX_ENABLE_SDK120_COMPATIBILITY
    if (mtx->recursive) {
        recursive_mutex_enter_blocking(mtx);
        return;
    }
#endif
    lock_owner_id_t caller = lock_get_caller_owner_id();
    do {
        uint32_t save = spin_lock_blocking(mtx->core.spin_lock);
        if (!lock_is_owner_id_valid(mtx->owner)) {
            mtx->owner = caller;
            spin_unlock(mtx->core.spin_lock, save);
            break;
        }
        lock_internal_spin_unlock_with_wait(&mtx->core, save);
    } while (true);
}

[mungewell]

I think I found the answer as to why it re-trigger the break point.... GDB is putting the break-point in the MIDDLE of the assembler block.

(gdb) c
Continuing.

Thread 1 hit Breakpoint 4, 0x20000212 in mutex_enter_blocking ()
(gdb) c
Continuing.

Thread 1 hit Breakpoint 4, 0x20000212 in mutex_enter_blocking ()
(gdb) c
Continuing.

Thread 1 hit Breakpoint 4, 0x20000212 in mutex_enter_blocking ()
(gdb) c
Continuing.

Thread 1 hit Breakpoint 4, 0x20000212 in mutex_enter_blocking ()
(gdb) c
Continuing.

Thread 1 hit Breakpoint 4, 0x20000212 in mutex_enter_blocking ()
(gdb) info b
Num     Type           Disp Enb Address    What
4       breakpoint     keep y   0x20000212 <mutex_enter_blocking+22>
	breakpoint already hit 5 times
5       breakpoint     keep y   0x200001fc <mutex_enter_blocking>

So in the disassembled assembler it has a loop to BEFORE that point.

200001fc <mutex_enter_blocking>:
200001fc:       23d0            movs    r3, #208        ; 0xd0
200001fe:       b530            push    {r4, r5, lr}    
20000200:       2400            movs    r4, #0
20000202:       2100            movs    r1, #0
20000204:       061b            lsls    r3, r3, #24
20000206:       571c            ldrsb   r4, [r3, r4]
20000208:       6805            ldr     r5, [r0, #0]
2000020a:       f3ef 8310       mrs     r3, PRIMASK
2000020e:       b672            cpsid   i
20000210:       682a            ldr     r2, [r5, #0]
20000212:       2a00            cmp     r2, #0
20000214:       d0fc            beq.n   20000210 <mutex_enter_blocking+0x14>
20000216:       f3bf 8f5f       dmb     sy
2000021a:       7a05            ldrb    r5, [r0, #8]
2000021c:       6802            ldr     r2, [r0, #0]
2000021e:       2d7f            cmp     r5, #127        ; 0x7f
20000220:       d906            bls.n   20000230 <mutex_enter_blocking+0x34>
20000222:       7204            strb    r4, [r0, #8]
20000224:       f3bf 8f5f       dmb     sy
20000228:       6011            str     r1, [r2, #0]
2000022a:       f383 8810       msr     PRIMASK, r3
2000022e:       bd30            pop     {r4, r5, pc}
20000230:       f3bf 8f5f       dmb     sy
20000234:       6011            str     r1, [r2, #0]
20000236:       f383 8810       msr     PRIMASK, r3
2000023a:       bf20            wfe
2000023c:       e7e4            b.n     20000208 <mutex_enter_blocking+0xc> <-----------------

Note the actual jump into the function is via a "veneer" which DOES hit the start of the function.

10032d88 <__mutex_enter_blocking_veneer>:
10032d88:       b401            push    {r0}
10032d8a:       4802            ldr     r0, [pc, #8]    ; (10032d94 <__mutex_enter_blocking_veneer+0xc>)
10032d8c:       4684            mov     ip, r0
10032d8e:       bc01            pop     {r0}
10032d90:       4760            bx      ip
10032d92:       bf00            nop     
10032d94:       200001fd        .word   0x200001fd

[mungewell]

After 'stalling' on this project for a while I see that there have been fixes done on MicroPython's Mutex... perhaps it's time to get involved again.
https://github.com/micropython/micropython/releases/tag/v1.22.1

[rkompass]

Hello @mungewell,
did you happen to try your old stuff on the new release? Are there any differences?

[mungewell]

To be honest I've forgotten a lot in the past 6 months, and there was a fair amount of 'flailing around' trying random things to see if they worked better - so it'll take a little while to get back into the project.

The glitch/issue that was triggered, was pretty rare - often requiring several hours before it was seen.

commit 4ab527c seems to be running, but the later commit 1f386b5 did not when I gave it a quick try.

[mungewell]

@rkompass

Well I bashed on it pretty hard for the last week.... and ZERO lockups, looks like the microPython team fixed my issue.

[rkompass]

That's good news. Congratulations.