Transmission stall..

[HondaRulez]

Hi,

Weird transmission stall.

Env.:
RP2040 @166mhz can2040 on PIO1. @ 500Kbps.
Freertos, can2040 pinned to core1, max priority, app runs from flash but the whole can2040 loaded into the RAM by linker script. (also the ISR functions of cos)

Continous Tx only, (other devices not sending anything but accepting) short frame, 8 byte data every 10 msec.
(transmission period no matter, same result if sending 1 packet/sec or if sheduling for continous transmission...)

USB and TCP IP stack runing on core 0 (pinned).
Agressive trafic on the USB somtimes cause missing interrupt on the USB controller (this is a well known BUG in the HW/Tiny USB stack.)

Before this happening I got error callback 1-3 times form the can2040, then the USB stalls and somtimes the CAN stops transmissing too.
(out FIFO is remains full).
When this event happened the whole chip blocking for a short period.~500msec (so the CAN timing is broken at all for sure.)

the transmission never restores until sending a message from another device, then the can2040 restores, and continue working.

Any 'poke' method to start the transmission again without stop/start the can stack ?

This is a reproducable error, so I able to do some testing if needed...

[HondaRulez]

I check the sources (not so deeply), the problem the PIO losts the SI_TXPENDING flag.
Maybe a temporary solution if the
__DMB();
pio_signal_set_txpending(cd)
would called from both can2040_check_transmit() and can2040_transmit() all the time if the tx fifo not empty.
This way the user app will reactivate transmission if tx is stalled.
The final solution is need to discover why this flag losts while the tx fifo not empty.

[KevinOConnor]

That sounds like it will be a challenging issue to track down. For what it is worth, at a high-level it sounds more like a freertos integration issue than a can2040 issue.

It is possible, of course, that there is a subtle defect in can2040. I have not seen any similar reports. It sounds like you are saying that SI_TXPENDING is cleared while there is still data on the transmit queue. However, the only place that flag is cleared is in tx_schedule_transmit() and it only clears it after confirming the queue is empty. There are places where we temporarily mask the SI_TXPENDING flag, but in all those cases SI_MAYTX should be set and the PIO should always eventually emit either that irq or SI_RX_DATA. So, it's not immediately clear to me how the code could get into a situation where it has work to do and is not getting any irqs at all.

One thing that may help is if you could build some kind of minimal test case demonstrating the issue. Something built on just the pico-sdk or otherwise stripped down code (that is, not using something complicated like FreeRTOS).

Finally, make sure you are running the latest can2040 code. There were some known errors in this area in the past (though all known errors were fixed years ago).

Maybe that helps a little,
-Kevin

[HondaRulez]

I just done more debugging..., as you said it's not due the SI_TXPENDING.

I don't think it's related to anything freertos or other libraryes.
the can2040 runs on separated core and no any freertos stuff used there., also the receiving totally discarded.

### some new observation:

The transmission restores after 10+ minutes without touching/poking/receiving anything. (repeatable !!)

Here is some logs with remarks:

after the initial start..

CAN: rx: 0, tx: 2392, tx_atp: 2392, perr: 0, ts: 00000000, ps: 00000008, rs: 00000000, nosc: 00000000

_

ts = tx_status, p =: parse_status and so on.. from the can statistic...
nosc = is my variable from this code part:

tx_schedule_transmit(struct can2040 *cd)
{
if (cd->tx_state == TS_QUEUED && !pio_tx_did_fail(cd)) {
// Already queued or actively transmitting
dbg_can2040_freason |= (0x80000000 | cd->tx_state);
return 0;
}
_

Where the transmissoin start failing..

WARN: starting new transfer on already active ep 82
when tyhis happening both core stalls for a short period( I can't catch the problem yet..)
WARN: starting new transfer on already active ep 82
CAN: error: 00000004
Ingress: i/o overflow/error occured
CAN: error: 00000004
Ingress: i/o overflow/error occured
CAN: error: 00000004
Ingress: i/o overflow/error occured
CAN: error: 00000004
Ingress: i/o overflow/error occured
CAN: error: 00000005 er r + txdone ??? (maybe in sepatreted callback but very close to each other if the log can sees together..)
Ingress: i/o overflow/error occured
CAN: error: 00000004
Ingress: i/o overflow/error occured
CAN: Can't send...
CAN: Can't send...

at this point no acivity on the BUS, fifo is full.

CAN: rx: 0, tx: 30959, tx_atp: 30965, perr: 6, ts: 00000001, ps: 00000009, rs: 00000000, nosc: 80000001
CAN: Can't send...

notice on the nosc variable !!!! so the tx_schedule_transmit() exited without scheduling new packet !
also the tx_stat = 1 and parse_stat = 9, on fail I got same values all the time.

around 8 minute later :

lot of CAN: Can't send...

CAN: rx: 0, tx: 30959, tx_atp: 30965, perr: 6, ts: 00000001, ps: 00000000, rs: 00000000, nosc: 80000001

the parser_status = 0 ? what happened??

even few munte later..

lot of CAN: Can't send...

CAN: rx: 0, tx: 31796, tx_atp: 31802, perr: 6, ts: 00000000, ps: 00000008, rs: 00000000, nosc: 80000001

the transmission is runing fine again.

This is fully repeatable sequence !

Any free running counter or (n * pio loop) or anything else waht can cause restoration ?

[KevinOConnor]

If the receive PIO is idle for 1<<33 ticks then it will leave its idle state and start emitting SI_RX_DATA irqs. The cpu code then handles this in the data_state_line_passive() function and puts the PIO back into idle state.

So, the above is another symptom that processing restarts on an SI_RX_DATA irq.

If you think there is an issue in pio_tx_did_fail(), you could try this change:

--- a/src/can2040.c
+++ b/src/can2040.c
@@ -333,7 +333,7 @@ pio_tx_did_fail(struct can2040 *cd)
     if (pio_hw->sm[SM_TX].addr == can2040_offset_tx_conflict)
         return !(pio_hw->intr & SI_RX_DATA);
     // Check for unexpected drain of transmit queue without parser noticing
-    return (!(pio_hw->flevel & PIO_FLEVEL_TX3_BITS)
+    return ((pio_hw->flevel & PIO_FLEVEL_TX3_BITS) <= 1
             && (pio_hw->intr & (SI_MAYTX | SI_RX_DATA)) == SI_MAYTX);
 }
 

If you'd like me to look at the logs, I'd need the following information:

• The git commit of the can2040.c code you are using.
• If there are any modifications to the can2040.c code, I'd need to know those modifications.
• I'd need to know the c code that is emitting the log messages.
• The key information I'd be interested in is the tx_state, parse_state, report_state of the can2040 code along with the pio_hw->inte0, pio_hw->ints0, pio_hw->intr, pio_hw->sm[SM_TX].addr, pio_hw->flevel from the pio hardware. So, it would be good to emit that information periodically (or during the outage). As above, I'd need to see the c code of the emitting code so I know what the log messages mean.
• I'd need the complete log from the event, not just snippets from it.
• It'd help to have some kind of timestamp in the log.

You may also want to confirm that FreeRTOS isn't somehow running your PIO irq handler from both cores.

Cheers,
-Kevin

[KevinOConnor]

On a closer look, this change does look like it is needed to can2040:

--- a/src/can2040.c
+++ b/src/can2040.c
@@ -333,7 +333,7 @@ pio_tx_did_fail(struct can2040 *cd)
     if (pio_hw->sm[SM_TX].addr == can2040_offset_tx_conflict)
         return !(pio_hw->intr & SI_RX_DATA);
     // Check for unexpected drain of transmit queue without parser noticing
-    return (!(pio_hw->flevel & PIO_FLEVEL_TX3_BITS)
+    return ((pio_hw->flevel & PIO_FLEVEL_TX3_BITS) <= 1
             && (pio_hw->intr & (SI_MAYTX | SI_RX_DATA)) == SI_MAYTX);
 }
 

As there seems to be a race where the PIO could raise SI_MAYTX while still transmitting trailing passive bits. In that case, both SI_MAYTX and SI_TXPENDING could be masked in report_line_maytx().

It's unclear if that is the root cause of your issue though.

Cheers,
-Kevin

[KevinOConnor]

Actually, the patch probably needs to be something like:

--- a/src/can2040.c
+++ b/src/can2040.c
@@ -333,8 +333,8 @@ pio_tx_did_fail(struct can2040 *cd)
     if (pio_hw->sm[SM_TX].addr == can2040_offset_tx_conflict)
         return !(pio_hw->intr & SI_RX_DATA);
     // Check for unexpected drain of transmit queue without parser noticing
-    return (!(pio_hw->flevel & PIO_FLEVEL_TX3_BITS)
-            && (pio_hw->intr & (SI_MAYTX | SI_RX_DATA)) == SI_MAYTX);
+    uint32_t tl = (pio_hw->flevel & PIO_FLEVEL_TX3_BITS) >> PIO_FLEVEL_TX3_LSB;
+    return (tl <= 1 && (pio_hw->intr & (SI_MAYTX | SI_RX_DATA)) == SI_MAYTX);
 }
 
 // Enable host irqs for state machine signals

I don't have a test setup immediately available to test this directly.

-Kevin

[HondaRulez]

I use the latest version, can2040 not modified except that the variable added for debug also this small patch applied.
(not helped anything)

here is the func of the CAN side log:
extern uint32_t dbg_can2040_freason;

void can_print_stat(void)
{
struct can2040 cd = &((can_con_t) pio_slots[PIO_CAN_A])->cbus;
struct can2040_stats stat;

can2040_get_statistics(cd, &stat);

LOGI("rx: %d, tx: %d, tx_atp: %d, perr: %d, ts: %08X, ps: %08X, rs: %08X, nosc: %08X",
stat.rx_total, stat.tx_total, stat.tx_attempt, stat.parse_error,
cd->tx_state, cd->parse_state, cd->report_state, dbg_can2040_freason
);
LOGI("e0: %08X, s0: %08X, ir: %08X, addr: %08X, flev: %08X",
pio1_hw->inte0, pio1_hw->ints0, pio1_hw->intr, pio1_hw->sm[3].addr, pio1_hw->flevel
);
}

called from teh debug console when I press 'd' also from the sender loop..

  if(can2040_transmit(&cc->cbus, &cmsg) < 0) {
     if(! ++txerr) {
        LOGE("Can't send...");
        can_print_stat();
     }
  } else
     txerr=0;

The project is very complex BTW, so I not really can separate just a part..
butI I can do more logs as needed because the problem easily reproducable.

I attached a log file what is started from a cold boot until the can fail..

log.txt

.
.
.

after about 8min this was the latest message, and teh CAN runs again...

ps: [20578.16h.44m.47s.125] CAN: Can't send...
[20578.16h.44m.47s.125] CAN: rx: 0, tx: 22854, tx_atp: 22856, perr: 2, ts: 00000001, ps: 00000009, rs: 00000000, nosc: 80000001
[20578.16h.44m.47s.125] CAN: e0: 00000002, s0: 00000000, ir: 000003D0, addr: 0000001C, flev: 02000000

[KevinOConnor]

Okay. I'm not really sure what is the cause of your issue.

After taking another look, I think the upstream pio_tx_did_fail() should actually be okay. So, again, I'm not sure what could be the cause of your issue.

From your description, it sounds like irqs are not making there way to the can2040 code, even though can2040 has work to do. As before, I'd focus on tx_state, parse_state, report_state of the can2040 code along with the pio_hw->inte0, pio_hw->ints0, pio_hw->intr, pio_hw->sm[SM_TX].addr, pio_hw->flevel from the pio hardware. I'd look for situations where the PIO should be indicating flags but isn't (pio_hw->intr) or cases where the PIO is indicating flags but the cpu code has them masked (pio_hw->ints0). If you can find some code trace that shows how the code got into an invalid state then I'll take a look at it.

Maybe that helps a little,
-Kevin

[HondaRulez]

Ok, I found the root of 'MY' problem.

it was a interrupt priority problem !

Very important the RP2040 only uses the most 2 upper bits for priority (rp235x and riscV uses upper 4 bit)

so setting 0-63 are all the same -> 0, which is the HIGHEST priority.

By the default config (as the in the exemple with value 1) the can2040 runs at the highest priority.
In my case I set this to 0xFF because I expected that is the highest available priority and same time I set the serial port priority to 0.
so this cause a priority inversion what getting more and more worse as the sytem load increased.

settings the priorities right all the problems gone (USB also works fine since that).

However the problem is still there if the intrerupt not serviced in time. The transmission will stall for a while.

When I finish this project I wil;l made a test app what will block the interrupt services randomly, so we can trace what happening really.

Thanks for the help Kevin.