Serial.print() from ISR will hang

This is a continuation of some of the comments I put into the RTC keyboards thread:

And maybe also implied in a few other threads.

Some of the examples shown have a timer and in the callback code they do something like:
Serial.print("Interrupt") and only the first character "I" shows up and the program hangs.

I believe in the case of the R4 Wifi with NO_USB defined the Serial.print uses the UART1 object
I believe the Serial.print(...) calls one of the two methods:

size_t UART::write(uint8_t c) {
/* -------------------------------------------------------------------------- */  
  if(init_ok) {
    tx_done = false;
    R_SCI_UART_Write(&uart_ctrl, &c, 1);
    while (!tx_done) {}
    return 1;
  }
  else {
    return 0;
  }
}

size_t  UART::write(uint8_t* c, size_t len) {
  if(init_ok) {
    tx_done = false;
    R_SCI_UART_Write(&uart_ctrl, c, len);
    while (!tx_done) {}
    return len;
  }
  else {
    return 0;
  }
}

And in either case they will try wait for the entire transfer to complete before returning. That is tx_done will only be set to true in the ISR callback:

void UART::WrapperCallback(uart_callback_args_t *p_args) {
/* -------------------------------------------------------------------------- */  

  uint32_t channel = p_args->channel;
  
  UART *uart_ptr = UART::g_uarts[channel];

  if(uart_ptr == nullptr) {
    return;
  }
  ...
      case UART_EVENT_TX_COMPLETE:
      case UART_EVENT_TX_DATA_EMPTY:
      {
        //uint8_t to_enqueue = uart_ptr->txBuffer.available() < uart_ptr->uart_ctrl.fifo_depth ? uart_ptr->txBuffer.available() : uart_ptr->uart_ctrl.fifo_depth;
        //while (to_enqueue) {
        uart_ptr->tx_done = true;
        break;
      }
      case UART_EVENT_RX_CHAR:

Maybe slightly lying here, it will clear it with two case, not sure if that is an issue..

And if I am reading the IRQ code correctly (IRQManager.cpp)

#define ETHERNET_PRIORITY          12
#define SDCARD_ACCESS_PRIORITY     10
#define SDCARD_DMA_REQ_PRIORITY    10
#define SDCARD_CARD_PRIORITY       12
#define EXTERNAL_PIN_PRIORITY      12
#define UART_SCI_PRIORITY          12
#define USB_PRIORITY               12
#define AGT_PRIORITY               14
#define RTC_PRIORITY               12
#define I2C_MASTER_PRIORITY        12
#define I2C_SLAVE_PRIORITY         12
#define SPI_MASTER_PRIORITY        6
#define DMA_PRIORITY               12
#define TIMER_PRIORITY             8
#define ADC_PRIORITY               12
#define CAN_PRIORITY               12
#define CANFD_PRIORITY             12
#define FIRST_INT_SLOT_FREE         0

And this is following the Arm M3/M4 standard for NVIC, I am assuming that lower priority numbers are higher priority...
And guessing Timer is runnning at Priority 8 and UART at 12 so it will not be called while in the Timer interrupt.

Not sure what best approach here would be, but some possibilities that can maybe be tried:
a) add TX queue and calls to know how much can add before it will have to wait.

b) Try changing the priority for UART.

c) Detect if priority of current code is higher (lower value) than the ISR and either temporarily boast the priority of the IRQ handler, or put code in place that detects the same stuff that the ISR is detecting and process it in the wait code.
...
z) Punt.

If it were me, I would probably do a combination of several of these, like I did with some other boards, but...

Thoughts? Am I missing something? Should this be raised as an issue in github?

Kurt

1 Like

That is exactly what to expect, and why you should NEVER do serial I/O, or any other activity that depends on interrupts, within an ISR.

Interrupts are turned off within the ISR, so just set a global flag, and let the main program deal with the action.

Very unwisely, the people who wrote the Arduino core for the Uno R3 and the like, put in a silly hack to allow Serial.prints() within an interrupt, giving a legion of beginners the idea that this is OK. It is NOT OK.

3 Likes

Thanks for the feedback.

I somewhat agree with you should be careful on what you do within an ISR. But that is true of most all systems. And I often do as you mentioned of setting a flag and processing it later. (And hopefully remember to mark the appropriate variables as volatile)

And in this case, I believe most of the issue is because this is a new code base where parts of it were probably cobbled up to get some of the basics working and some parts like this were probably not fully fleshed out.

For example calling: Serial.write('X');
In most systems, it would simply put the X into the next free space in the TX queue. Only when the queue is full would it wait for space to be free in the output queue to be able to store that X.
And if you want to make sure that you don't have to wait, the Print class has a method:
availableForWrite() which should return to you how much space is free in the output queue.

But in the current code base the call to write, queues the data up to the Uart register and then waits for the interrupt that it completed. Which does not make a lot of sense. That is if you are always going to wait for each output to complete, why enable and field the interrupt for it. Why not just check the status register...

But again I am assuming that this current code is just a stop gap, until someone updates it.

That was true for the old AVR boards, but this board is an ARM Cortex M4 board, uses NVIC (Nested Vectored Interrupt Controller). Note: the NVIC registers and the like are fully described in the processor specification. Section 13.2 says:

This chapter does not describe Arm® NVIC internal registers. For information on these registers, see the ARM® Cortex®-
M4 Processor Technical Reference Manual (ARM DDI 0439D).

For this I typically look at the book by Joseph Yiu, The definitive guide to ARM Cortex-M3 AND Cortex-M4 processors.

And unless you explicitly disable interrupts, an interrupt handler can be interrupted by a higher priority Interrupt (lower number). I am not sure yet how many priority levels this board supports, guessing maybe 16.

I don't take the current code bases like AVR or Teensy or the like as having "silly hacks" to deal with issues like priority inversion. The AVR code does it one way, by detecting that interrupts are disabled and then looking at the registers. And others detect that the ISR has a lower priority, than the current code running and temporarily bumps up the priority or handles it in a similar way to how the AVR boards do.

Again, I agree with your sentiment that, you should try to avoid things in an interrupt that rely on interrupts or can consume a lot of time!

Thanks again

1 Like

Sounds good if the Arduino core software actually takes advantage of it, but it evidently does not. After all, you are here because your code does not work.

If you try printing within an ISR on an ESP32, the system sometimes, if not always, crashes.

Have fun!

1 Like

Actually it does, the problem is that in this instance the priorities are such that timer has a higher priority and as such the UART ISR is not called.

However if I take the slightly modified RTC_Alarm example sketch and change the LED Pin numbers to something that compiles and add a print in the ISR like:

/*
 * This example demonstrates how to use the alarm functionality of the RTC
 * (Real Time Clock) on the Portenta C33.
 *
 * It switches the built-in LED between blue and red each time the alarm
 * is triggered, which is once every minute in this example.
 *
 */

#include "RTC.h"
#define LEDB LED_BUILTIN
#define LEDR 2

void alarmCallback()
{
  static bool ledState = false;
  if (!ledState) {
    digitalWrite(LEDB, HIGH);
    digitalWrite(LEDR, LOW);
  }
  else {
    digitalWrite(LEDR, HIGH);
    digitalWrite(LEDB, LOW);
  }
  ledState = !ledState;
  Serial.println("Alarm");
}

void setup() {
  Serial.begin(115200);
  Serial.println("Start");
  pinMode(LEDR, OUTPUT);
  pinMode(LEDB, OUTPUT);
  digitalWrite(LEDR, HIGH);
  digitalWrite(LEDB, LOW);

  // Initialize the RTC
  RTC.begin();

  // RTC.setTime() must be called for RTC.setAlarmCallback to work, but it doesn't matter
  // what date and time it's set to in this example
  RTCTime initialTime(7, Month::JUNE, 2023, 13, 03, 00, DayOfWeek::WEDNESDAY, SaveLight::SAVING_TIME_ACTIVE);
  RTC.setTime(initialTime);

  // Trigger the alarm every time the seconds are zero
  RTCTime alarmTime;
  alarmTime.setSecond(0);

  // Make sure to only match on the seconds in this example - not on any other parts of the date/time
  AlarmMatch matchTime;
  matchTime.addMatchSecond();
  
  RTC.setAlarmCallback(alarmCallback, alarmTime, matchTime);
}

void loop() {
}

It will fail like we are talking about:

Start
A

But now if I go into the file: cores\IRQManager.cpp
and change the define of the UART prioirty and change it from 12 to 6
#define UART_SCI_PRIORITY 6 //12

Then we see:

Start
Alarm
Alarm
Alarm
Alarm
Alarm
...

Which is at least a quick and dirty temporary patch...

I'm with @jremington on this

ISRs are supposed to be fired and have a very limited time frame to be executed, so is anything else these call from within.

While working on the LED Matrix library's API and trying to address my needs, I quickly realised that what I wanted to obtain was just wrong.
I wanted to allow invoking a sketch callback on completion of animation, passing in the method at loading time.
That would have given the wrong message to the user that they could run an arbitrary piece of code without minding the time taken by their function.
I opted for setting a flag and the user can check for it in the loop, so that I don't continue on this string of bad practices

(I had to quote you, @jremington :joy: )

I am also partially in agreement. You need to be careful on things you do within an interrupt, and it is up to Arduino to decide what it is that you/they wish to do on their platform.

But as this typically works on a lot of the different processors, would suggest fixing some of these obvious faults/hangs. As I mentioned here and on issue, a quick and dirty fix is to somply change the priority of the Serial ISR to be higher (lower value) than most of the others...

And when you don't have a debugger to use, most users end up debugging their code with things like Serial.print() and digitalWrite...

I am also surprised on how easy it is to crash these boards. For example pinMode(50, OUTPUT); will likely crash, ditto for digitalWrite(-1, HIGH); As these calls do not do any bounds checking. I am used to the Teensy boards where we have tried to catch most of these things.

Funny you should mention that. I was about to raise an issue on this code.

    void next() {
        uint32_t frame[3];
        frame[0] = reverse(*(_frames+(_currentFrame*4)+0));
        frame[1] = reverse(*(_frames+(_currentFrame*4)+1));
        frame[2] = reverse(*(_frames+(_currentFrame*4)+2));
        _interval = *(_frames+(_currentFrame*4)+3);
        _currentFrame = (_currentFrame + 1) % _framesCount;
        if(_currentFrame == 0){
            if(!_loop){
                _interval = 0;
            }
            if(_callBack != nullptr){
                _callBack();
                _sequenceDone = true;
            }
        }

I was wondering if you really wanted to only set _sequenceDone to true, if the user had set a callback? I was assuming that you probably want to move it out of the if.

Also was going to suggest that maybe you might want the ability to set the timer speed. For example the sketch that outputs a banner of text outputs I believe 20 frames per second. Note he does it without interrupts, not sure how fast your could could reasonably run.

This is sort of a interesting trade off, that is if you have a callback, than you give a reasonable way for the caller to setup the next frame, such that you have a continuous 1000/96 frames per second, where you can get a seamless and consistent number of frames per second...

One thought would be if the sketch could setup something like a two frame sequence and update the frame that is not currently being rendered to the leds... But probably not enough information exported, like what is the current frame to do it this way.

Always interesting sets of trade offs.

But anyway having some fun :smiley:

seems that there's still some WIP code in there

because invoking _callBack() had a time limit I was trying to run it and use the flag in another part of the execution to trigger something else but of course it did not work :frowning:

Quick FYI - I just posted a sketch in the thread:
LED Matrix matrix.on(pin) = blink? - UNO R4 / UNO R4 WiFi - Arduino Forum

Which was sort of fun with the callback.

Quick update: I opened up a new issue:

Serial[x].print/write - Could use some major performance enhancement. · Issue #44 · arduino/ArduinoCore-renesas (github.com)

Lots more details in the issue.

Found first bug: in Serial.h and Serial.cpp.
size_t write(uint8_t* c, size_t len);
should be:
size_t write(const uint8_t* c, size_t len);

As it does not match the virtual method in Print.h and as such:
Serial1.print("ABCD");
Will not call it but insteall will call the one byte print 4 times.

WIll investigate the next issue tomorrow.