Serial bugs, non-intuitive programming default, during timer interrupts #1147

Tenacious-Techhunter · 2012-11-30T23:47:58Z

/* The following code does not behave as expected due to:
Default test case: No default ISR, or some other ISR related failure
Interrupt & Serial test case: Some timer interrupt & serial interrupt conflict
Some of these may simply be non-intuitive results
from the default programming conditions, but others are clearly bugs.
Test cases are marked with "***" preceeding and following,
and can be enabled by disabling the preceeding "/*". Please correct all issues. */

/* This was tested on a Sparkfun 3.3v Arduino Pro Mini with the Arduino 1.0.2 IDE. */

#define T1CRA 0b00000011    // COM1A = 0, COM1B = 0, WGM[1:0] = 3;
#define T1CRB 0b00011101    // FOC1A = 0, FOC1B = 0, WGM[3:2] = 3, CS1 = 5;

void setup()
 {
  // Disable the Interrupts.
  noInterrupts();

  Serial.begin(9600);

  // Configure the Timer. WGM = 7, which tops out at OCR1A.
  TCCR1A = T1CRA;
  TCCR1B = T1CRB;
  OCR1A = 250;
  TCNT1 = 0;

// valid */ valid

/*
  // This byte disables timer interrupts.
  TIMSK1 = 0b00000000;        // *** Disable this interrupt enable bit to work around the bug. ***
                              // *** Re-enable before performing the tests that follow.        ***

  // This byte enables timer interrupts.
// */ TIMSK1 = 0b00000010;    // *** Disable this interrupt enable bit to work around the bug. ***
                              // *** Re-enable before performing the tests that follow.        *** */

  // Initialize pins
  pinMode(13, OUTPUT);

  // Reenable the Interrupts.
  interrupts();
  }

/*                           // *** Disable again before performing the tests that follow. ***
ISR(TIMER1_COMPA_vect) {}    // *** Re-enabling an empty vector also works around the bug. *** */

/*                           // *** Disable again before performing the tests that follow. ***
ISR(TIMER1_COMPA_vect)       // *** Valid non-serial code also works around the bug. ***
 {
  digitalWrite(13, !digitalRead(13));
  }
//*/

/*                           // *** Keep enabled for the following test.                            ***
ISR(TIMER1_COMPA_vect)       // *** Serial code in an interrupt seems to cause occasional problems. ***
 {
  Serial.println("Blaaarg???");
  // Serial.flush();              // *** Adding flush seems to grind my Arduino to a halt. ***
  }
//*/


void loop()
 {
  Serial.println("Blarg!");
  Serial.flush();
  }

matthijskooijman · 2013-04-16T13:53:02Z

I'm not sure what all the problems are you're trying to describe, but the "Adding flush seems to grind my Arduino to a halt" is caused by a deadlock inside HardwareSerial, see #672.

Tenacious-Techhunter · 2013-04-16T18:18:26Z

Yes, but there are other problems as well. The serial output is often cut off mid-report. Even if the serial output cannot all be sent at once, everything should at least be sent in the right order.

Since serial is the primary means of debugging in Arduino, and Interrupts are a critical component to certain kinds of embedded development, correcting serial performance inside an interrupt should be made a priority.

Ryan Pettigrew
Chair of the Boston Area IEEE Robotics & Automation Society

On Apr 16, 2013, at 9:53 AM, Matthijs Kooijman [email protected] wrote:

I'm not sure what all the problems are you're trying to describe, but the "Adding flush seems to grind my Arduino to a halt" is caused by a deadlock inside HardwareSerial, see #672.

—
Reply to this email directly or view it on GitHub.

matthijskooijman · 2013-04-16T18:23:48Z

Hi Ryan,

Yes, but there are other problems as well. The serial output is often
cut off mid-report.
Hmm, not sure why that would be.

I suggested some changes in the other ticket I referred to. I'll see
about implementing those somewhere in the coming weeks and perhaps you
can have a try to see if there are still problems remaining after that.

Gr.

Matthijs

Tenacious-Techhunter · 2013-04-16T18:34:49Z

Run the tests in the sequence in the document on GitHub. It should show you the various problems I'm talking about. Hopefully, most will not be too hard to fix.

Ryan Pettigrew
Chair of the Boston Area IEEE Robotics & Automation Society

On Apr 16, 2013, at 2:24 PM, Matthijs Kooijman [email protected] wrote:

Hi Ryan,

Yes, but there are other problems as well. The serial output is often
cut off mid-report.
Hmm, not sure why that would be.

I suggested some changes in the other ticket I referred to. I'll see
about implementing those somewhere in the coming weeks and perhaps you
can have a try to see if there are still problems remaining after that.

Gr.

Matthijs
—
Reply to this email directly or view it on GitHub.

matthijskooijman · 2013-04-16T20:48:11Z

I've tried running your sketch, but I'm not sure what to look for. At first, nothing seemed to happen. I tried changing the register settings (which seemed wrong, they were set to a PWM mode, probably because I'm running on an Arduino UNO with a different microcontroller). I changed them to:

#define T1CRA 0b00000000 // COM1A = 0, COM1B = 0, WGM[1:0] = 0;
#define T1CRB 0b00001101 // ICNC1 = 0, ICES1 = 0, WGM[3:2] = 1, CS1 = 5;

This made the timer interrupt at least do something, I got a blinking led with the toggle pin 13 example, but it only lasts for half a second. Is this one of the problems you saw?

Other than this, I'm really not sure what problems you were trying to illustrate with your example. It would help if you could describe a bit more clearly what happens and what you would have expected to happen, for each of the tests in your program.

matthijskooijman · 2013-04-16T21:11:30Z

Ah, found the problem. There were /* */ around both the TIMSK1 settings in your sketch, which I hadn't noticed, so I was never enabling the interrupt. With that out of the way, I still don't see all those problems your are seeing (at least I think so).

I tried:

The empty ISR, which obviously doesn't do anything special (just prints Blarg!)
The pin 13 ISR, which blinks my led very fast
The serial ISR without flush, which prints a lot of Blarg! and the occasional Blaaarg???
The serial ISR with flush, which prints some Blarg! and some Blaarg?? for a fraction of a second and then locks up (which was expected and I'll see about fixing this, though I had expected the lockup to occur on the first flush, not on the fourth one, but I'll experiment with this a bit more).

So, are there any other bugs/problems apart from the flush issue? Your code talks about workarounds for "the bug". Which is that?

When interrupts are disabled, writing to HardwareSerial could cause a lockup. When the tx buffer is full, a busy-wait loop is used to wait for the interrupt handler to free up a byte in the buffer. However, when interrupts are disabled, this will of course never happen and the Arduino will lock up. This often caused lockups when doing (big) debug printing from an interrupt handler. Additionally, calling flush() with interrupts disabled while transmission was in progress would also cause a lockup. When interrupts are disabled, the code now actively checks the UDRE (UART Data Register Empty) and calls the interrupt handler to free up room if the bit is set. This can lead to delays in interrupt handlers when the serial buffer is full, but a delay is of course always preferred to a lockup. Closes: arduino#672 References: arduino#1147

This prevents a potential race condition where for example write() would detect that there is room in the tx buffer, an interrupt would trigger where the interrupt handler writes to Serial filling up that room, and write() would then reset the head pointer, effectively throwing away the bytes written by the interrupt handler. References: arduino#1147

Tenacious-Techhunter · 2013-05-03T21:22:52Z

Sorry for the delay; I had to prioritize my Robotics conference.

Both the Pro Mini and the UNO use the Atmega 328, so they should be identical, as far as the test is concerned.

The default test fails because there is no default ISR vector when an interrupt is enabled but no ISR vector specified. This would easily happen when someone is commenting out code to try and debug a problem. The assertion of my colleagues and myself is that ISR vectors should be loaded with a default, and that default should be to return without doing anything. Compiler/IDE warnings should probably also be thrown. The second, third, fourth, and fifth tests merely confirm this is the case by disabling & reenabling the interrupt enable, and enabling an empty ISR and a valid ISR, showing that the problems are confined to the interrupt with no default vector and nothing more.

The last two are the serial problems. Serial code in an interrupt behaves badly. Serial Writes do not reserve space; when an interrupt comes along, the first write is unfinished, and the write from the interrupt cuts it off to perform its own write, and the previous write continues after the interrupt finishes. The real problem here is not the interrupt behaving like an interrupt should, by interrupting, but by serial not reserving the first write's "place in line". When the flush happens (or, in this case, should happen, but doesn't), the previous write from outside of the ISR should finish where it left off before the ISR write begins. I see you have fixed some issues relating to the atomicity of serial writes; has this problem now been fixed?

I have not found any information on how better to submit test cases like these to Arduino; is there one somewhere?

matthijskooijman · 2013-05-03T21:37:02Z

Great, your explanation helps to understand your concerns. As for how to report these bugs, your example combined with the explanation looks good to me. For clarity, it might be useful to separate both issues at some point, but let's see where this leads.

As for the absence of a default timer ISR, I'm not really sure what the policy is here. I guess a default empty ISR declared as "weak" should be possible, but perhaps one of the official developers can comment.

As for the Serial issues: my fixes make sure that bytes that are printed are actually printed, even when printing from both an ISR and regular code, without lockups. However, there is no concept of "reserving space", so if an interrupt occurs halfway through a print, the ISR's print will be in the middle of the original print.

This is something that is pretty impossible to fix, because:

The serial driver doesn't know about complete prints or lines, it just sees character by character.
If a print would reserve space at a higher level, so subsequent prints from an ISR would end up after a print in progress and the space reserved is more than the available buffer space, then the ISR would not have room to buffer its own messages (but it can't just wait for room to appear, since the reserved space is not filled until it returns from the ISR).

If you care about not getting mixed messages, you should disable interrupts whenever you write a message to the Serial console (which, for messages longer than the serial buffer, can mean that interrupts are disabled for quite some time...).

I'm entirely sure if I understand your issue correctly, or if you refer to some other (now fixed) race condition, though.

Tenacious-Techhunter · 2013-05-03T23:33:32Z

Yes, I was thinking of weak declared ISRs too, but I'm not sure how that might fit against other concerns.

You seem to be addressing my concerns with the serial, yes.

I've thought for a while that maybe a "prebuffer" with something like a linked list of the heads and tails of things to be sent out by serial might be a potential approach to solve the serial sequencing issue. Serial writes would add a head and tail to the prebuffer. The serial interrupt (and flush in an interrupt) will start at the first head and add data to the serial buffer, updating the head appropriately until the transmission completes, and moving on to the next entry head. New writes always get added to the end of the prebuffer list, leaving the sequence intact.

I've wondered if the relevant memories are fast enough compared to the serial itself that you could maybe buffer the transmission in-place without a separate buffer in memory, but I've not considered the performance issues or tradeoffs.

When interrupts are disabled, writing to HardwareSerial could cause a lockup. When the tx buffer is full, a busy-wait loop is used to wait for the interrupt handler to free up a byte in the buffer. However, when interrupts are disabled, this will of course never happen and the Arduino will lock up. This often caused lockups when doing (big) debug printing from an interrupt handler. Additionally, calling flush() with interrupts disabled while transmission was in progress would also cause a lockup. When interrupts are disabled, the code now actively checks the UDRE (UART Data Register Empty) and calls the interrupt handler to free up room if the bit is set. This can lead to delays in interrupt handlers when the serial buffer is full, but a delay is of course always preferred to a lockup. Closes: arduino#672 References: arduino#1147

This prevents a potential race condition where for example write() would detect that there is room in the tx buffer, an interrupt would trigger where the interrupt handler writes to Serial filling up that room, and write() would then reset the head pointer, effectively throwing away the bytes written by the interrupt handler. References: arduino#1147

When interrupts are disabled, writing to HardwareSerial could cause a lockup. When the tx buffer is full, a busy-wait loop is used to wait for the interrupt handler to free up a byte in the buffer. However, when interrupts are disabled, this will of course never happen and the Arduino will lock up. This often caused lockups when doing (big) debug printing from an interrupt handler. Additionally, calling flush() with interrupts disabled while transmission was in progress would also cause a lockup. When interrupts are disabled, the code now actively checks the UDRE (UART Data Register Empty) and calls the interrupt handler to free up room if the bit is set. This can lead to delays in interrupt handlers when the serial buffer is full, but a delay is of course always preferred to a lockup. Closes: arduino#672 References: arduino#1147

matthijskooijman · 2015-06-18T14:10:45Z

Since the serial issues here are either fixed, or tricky to solve, I'm closing this issue. If you feel strongly about the empty ISRs, I would advice collecting some opinions on the mailing list and perhaps opening a pullrequest.

matthijskooijman mentioned this issue Apr 16, 2013

Way to check if Serial.write() will block or way to have it fail instead of block. [imported] #672

Closed

ffissore added the New label Feb 27, 2014

matthijskooijman removed the New label Sep 11, 2014

matthijskooijman closed this as completed Jun 18, 2015

ffissore added this to the Release 1.6.6 milestone Jun 19, 2015

ffissore assigned matthijskooijman Jul 9, 2015

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Serial bugs, non-intuitive programming default, during timer interrupts #1147

Serial bugs, non-intuitive programming default, during timer interrupts #1147

Tenacious-Techhunter commented Nov 30, 2012

matthijskooijman commented Apr 16, 2013

Tenacious-Techhunter commented Apr 16, 2013

matthijskooijman commented Apr 16, 2013

Tenacious-Techhunter commented Apr 16, 2013

matthijskooijman commented Apr 16, 2013

matthijskooijman commented Apr 16, 2013

Tenacious-Techhunter commented May 3, 2013

matthijskooijman commented May 3, 2013

Tenacious-Techhunter commented May 3, 2013

matthijskooijman commented Jun 18, 2015

Serial bugs, non-intuitive programming default, during timer interrupts #1147

Serial bugs, non-intuitive programming default, during timer interrupts #1147

Comments

Tenacious-Techhunter commented Nov 30, 2012

matthijskooijman commented Apr 16, 2013

Tenacious-Techhunter commented Apr 16, 2013

matthijskooijman commented Apr 16, 2013

Tenacious-Techhunter commented Apr 16, 2013

matthijskooijman commented Apr 16, 2013

matthijskooijman commented Apr 16, 2013

Tenacious-Techhunter commented May 3, 2013

matthijskooijman commented May 3, 2013

Tenacious-Techhunter commented May 3, 2013

matthijskooijman commented Jun 18, 2015