PIO Interrupts causing Pico to lock up - apparently two are 'colliding' in time

[mungewell]

I have a project which is concerned with aligning two devices in time, they communicate 'LTC' and one will sync with the other. In the interrupt routine I am using utime.ticks_us() to measure the difference between 'TX' and 'RX'.

All of the processing of the LTC signal(s) is done in a collection of PIO blocks, it is these which issue irq(rel(0)) at the appropriate times. If the IRQ handler for the 'sync_and_read()' StateMachine is not enabled, the problem does not occur.

There are two threads; one for co-ordinating the PIO blocks (filling/emptying FIFOs), and another for printing information to screen.

Once synchronized, the 'slave' device will crash after a short period of time (say within 5mins). I think this is the device with the (slightly) slower clock/xtal, though not sure on that...

The interrupt routine is:

def irq_handler(m):
    global sm, tx_ticks_us, rx_ticks_us, stop
    global tc

    disable = machine.disable_irq()

    ticks = utime.ticks_us()
    if m==sm[1]:
        tx_ticks_us = ticks
        machine.enable_irq(disable)
        return

    if m==sm[5]:
        rx_ticks_us = ticks
        machine.enable_irq(disable)
        return

I recently added the 'enable/disable' functions after reading the following, but that did not fix the issue. [Edit: ie the bug existed before they were added]
https://docs.micropython.org/en/latest/reference/isr_rules.html

A single device can measure it's own output (literally a loop back, ie cable between pins 13 and 18), however this does NOT trigger the issue. I think this is because the in/out clocks are EXACTLY the same rate, but with two devices they are slightly different (especially considering any start up variance, or fraction clock action).

The project as a whole is complex, but the 'core' file can be run on it's own... with just a text output to Thonny.
https://github.com/mungewell/pico-timecode/blob/main/pico_timecode.py

Instructions to recreate issue:
1). Device A is sender, run code as above.
2). Device B will receive and sync. Change line 676 to tc.mode = 64. This will cause it to 'jam' and then will report the received RX timecode, and will stop printing when it crashes.
2). Connect cable (and ground) from Device-A pin 13 to Device-B in pin 18

If anyone has any suggestion on how to fix, I would happily implement them. :-)

[peterhinch]

Communicating between threads running on two cores has many pitfalls, and you haven't explained how this is being done. I suggest you look at this doc. Don't be put off by the fact that the doc assumes that uasyncio is running on core 0. The notes about communicating between cores are general.

[mungewell]

@peterhinch

Thanks for comment. I'm not sure that 'async' is the answer, but worth reading up on...

The threads communicate with 'timecode()' class variables, and these are protected with acquire()/release() locking. These are used to communicate the current frame number being TX'ed and the RX'ed one. For the test mentioned the 'tx_ticks_us' and 'rx_ticks_us' are not even used.... even removing the setting of them at all in the IRQ callback does not improve bug.

Generally the timing of coms is not critical, thead0 is just managing the display - for the 'core' file this is deliberately slowed with a sleep(0.1) and is outputting every 3rd or 4th frame.

Thread1 is a bit more sensitive, but prefills the PIO TX FIFO with data for 3 frames ahead of time. I track for an underflow and this have never been a problem. As mentioned above the really critical stuff happens in the PIO blocks.

[rkompass]

Can you change the code so that you use different interrupts for 'master' and 'slave' device?

As an alternative: Interrupts are not very fast and also introduce 'jitter' latency:
If there are enough instructions left you could try to measure the 'TX' and 'RX' time difference by another PIO state machine counting cycles.
Also a measuring timer is possible with PWM: Every PWM channel in the Pico has two slices: Two adjacent pins called pin A and pin B. Pin B can be set as input gate for the counting of the PWM channel counter. So instead of eliciting interrupts with the PIO you might set such a gate pin by one PIO state machine and reset it by another. Then one interrupt only would be employed to read the PWM counter out and reset it. Note that the PIO state machine with the higher number will determine the setting if both happen to address the pin in the same clock cycle. You might check for that by ensuring that the reset is done by a lower PIO state machine and check in the evaluating interrupt whether the PWM is still free running (i.e. its gating pin is still high).

Still the interrupt issue seems worth to be investigated. I have the feeling that it might be disabled twice simultaneously (with counter) and enabled back to the wrong state of enable-disable-counter perhaps? Something like that might happen if both ISRs overlap.

[mungewell]

@rkompass

Thank you for suggestions. I have tried using a different callback/handler function for RX interrupt, but this did not solve the problem. I also simplifed the IRQ handler to do nothing, but it would still crash.

The function for 'tx_ticks_us' and 'rx_ticks_us' is to display an error bar on the screen (so user can see if/when the two devices are drifting apart), and they are not critical for operation. A little jitter would be acceptable.

PIO engine 2 is totally full, I had to struggle to get code to fit. PIO engine 1 has 3 spare instructions... :-)

I already output a pulses on pin(s). For TX I drive the 1PPS flash to the LED, normally this happens every second (vs every frame) but the flash duration is under FIFO control so I could output a very short pulse every frame and a long one to mark the 0th frame. Every RX frame is also marked on a different pin, I use this to synchronize the TX with the RX stream.

I could/should read-up on PWM, they could maybe be used. I would need (want) to have a +/- value, ie A before B, or B before A. Maybe this can be processed out of single measurement.

For clarity, I only added the 'enable/disable' functions after the bug was discovered and would be happy to remove them. I have a feeling that the bug is actually further up in the code (maybe microPython itself).

[rkompass]

@mungewell please have a look at discussion/10638.
My hypothesis, more elaborated, is that the irq_handler(m) is running on both cores in parallel.
You may test this by evaluating mem32[0xd0000000], the CPU core id register. Store it's value an a preallocated array, while in the irq_handler(m) ...
If this hypothesis is true then we have a case for which no precaution was taken against yet. It could be that parallel/overlapping
machine.disable_irq() 's and machine.enable_irq(disable) 's are the culprit. You might try to prevent such a race condition by
another use of acquire()/release() locking within the ISR although I have no idea if this is allowable :-) - interesting new territory, it seems.

[mungewell]

@rkompass

Thank you for a very interesting insight, I'll follow up on this as a possible/probably cause.

I wrote a test script over my lunch break and no matter what I did with a single core could not trigger a fail. When I introduced another thread it started failing.
dumb_test4.py.txt

[mungewell]

I cleaned up my stand-alone test script (bare Pico, no wires needed), and even with the 'armoured' IRQ handler it still crashes the Pico. :-(

dumb_test4.py.txt

def irq_handler(m):
    global sm, tx_ticks_us, rx_ticks_us
    global thread_id, core_dis
    
    core_dis[mem32[0xd0000000]] = disable_irq()
    
    if thread_id != _thread.get_ident():
        enable_irq(core_dis[mem32[0xd0000000]])
        return
    
    ticks = time.ticks_us()
    if m==sm[0]:
        tx_ticks_us = ticks
        enable_irq(core_dis[mem32[0xd0000000]])
        return

    if m==sm[1]:
        rx_ticks_us = ticks
        enable_irq(core_dis[mem32[0xd0000000]])
        return

    enable_irq(core_dis[mem32[0xd0000000]])

I will also note that with checking the Thread_ID, the progression of counting is slower (compared to the single thread version) - suggesting that PIO interrupts are flip-flopping between the two threads.

It does not crash if:

1. I use a single thread.
2. I turn off the interrupts (then it does not count either)
3. I only have one statemachine active

[rkompass]

I 'simplified' your code a bit:

from time import ticks_us, sleep_ms
from array import array
from machine import mem32, enable_irq, disable_irq
import _thread
import rp2
import micropython
micropython.alloc_emergency_exception_buf(100)

@rp2.asm_pio()
def every_36():
    nop()         [25]
    irq(rel(0))   [9]

@rp2.asm_pio()
def every_37():
    nop()         [26]
    irq(rel(0))   [ 9]

#---------------- Handler for IRQs  -------------------------------

LEN_ARR = 1000
id_sm0 = 0
idm_arr = array('B', (9 for _ in range(LEN_ARR)))
coreid_arr = array('B', (9 for _ in range(LEN_ARR)))
ticks_arr = array('I', (9 for _ in range(LEN_ARR)))
idx = 0

stop = False

def irq_handler(m):
    global LEN_ARR, id_sm0, idm_arr, coreid_arr, ticks_arr, idx
    
#    disable = machine.disable_irq()  # does not improve the situation
    if idx < LEN_ARR:
        if id(m) == id_sm0:
            idm_arr[idx] = 0
        else:
            idm_arr[idx] = 4
        coreid_arr[idx] = mem32[0xd0000000]
        ticks_arr[idx] = ticks_us()
        idx += 1
#    machine.enable_irq(disable)

def go():
    global stop, id_sm0

    print("Started, Thread id:", _thread.get_ident())

    sm0 = rp2.StateMachine(0, every_37, freq=2000); sm0.irq(handler=irq_handler, hard=True)
    id_sm0 = id(sm0)
#    sm4 = rp2.StateMachine(4, every_37, freq=2000); sm4.irq(handler=irq_handler, hard=True)
    sm0.active(1); sleep_ms(100)#; sm4.active(1)
    
    while(not stop and idx < LEN_ARR):
        pass
    sm0.active(0)#; sm4.active(0)
    print("Stopped")

#-------------------------------------------------------

print("Main, Thread id:", _thread.get_ident())

stop = False
_thread.start_new_thread(go, ())  # Start up thread
# go()
sleep_ms(2000)
stop = True       # Stop state machines
sleep_ms(100)

for i in range(1, 250):
    # if ticks_arr[i]-ticks_arr[i-1] < 500:
    print(i, idm_arr[i], coreid_arr[i], ticks_arr[i]-ticks_arr[i-1])

to find:
With one or two PIO blocks instantiated on core 1 their interrupts always are served on core 1 - at least as long as there is no crash.
PIO generated interrupts don't have to happen simultaneously to elicit a crash.
The output shows a crash at about the 100-th interrupt. Interrupts from second PIO blocks do not exist.

102 0 1 18501
103 0 1 18500
104 0 1 18499
105 0 1 18499
106 0 1 18496
107 0 1 18503
108 9 9 -1045070294
109 9 9 0
110 9 9 0

Perhaps some internal (timer) interrupts happen simultaneously.
Here just a single state machine was active (SM4 was commented out) and still it crashed.
With SM0 and SM4 present the crash happens at about the 210-th interrupt, indicating that it is at about the same time of running program.

Btw. The C/C++ SDK says that its functions, apart from printf and some others, are not thread-safe.
So one might ask whether it is safe at all to have interrupts on core 1 - if this also holds for the functionality when processing the interrupts.

[mungewell]

I marked your comment about 'mem32[0xd0000000]' as the answer.... after a very late night it now seems to be working for me.

Don't truly know what made it work but I changed to hard=True when setting up the IRQ, and also noticed that they way I connected/restarted my Pico made a difference. I think that it I let it run the (already) iffy code, then some 'badness' persisted when I was then running script from Thonny.

Thank you everyone for your help and suggestions.

[mungewell]

For clarity when using a single device, I wrote the In/Out clocks are EXACTLY the same... whilst this is true (as best as I can get it with clock granularity) for the LTC streams, the TX and RX interrupts are separated by 1 bit clock (416us) due to processing delay in decoding the Differential Manchester Coding. This is likely why the 'one device' test does NOT fail.

So I am theorizing that the slightly different clock/XTAL speed between two devices is causing them to drift enough that the problem DOES occur. Indeed if I swap device A and B over, the code ran for 5hours (overnight) before the bug triggered. I had previously noted that it took ~5hrs for the devices to drift apart by 1 frame, meaning that interrupts would again overlap.

I mentioned in a reply, removing setting of variable in the interrupt did not solve the bug. I have a feeling that the bug may be in code 'above' mine... maybe in microPython. I am new to the Pico, and have not (yet) used the 3pin debug header. Started Googling on this, but can anyone point me at a good guide on "how to find out where your code is crashing"...?

For reference I am using "rp2-pico-20230426-v1.20.0.uf2" microPython.

[mungewell]

Further confirmed that this is to do with interrupts happening in same time frame.

I did a Device A -> Device B connection, but unplugged shortly after B had jammed. Then after 1hr I reconnected, and it then failed the 5hrs later.

Previously:
A->B: failed at 00:05:00:xx
B->A: failed at 05:19:35:xx

New test with replugging:
A->B: failed at 05:34:36.xx

from this I take it the clock/xtal speed are different on devices, such that they drift apart by 1 frame in 5hrs 27m(-ish). I could also see my 'error bar' reducing as the clocks became re-aligned.