HardwareSerial library sometimes sends the same data twice

[johnholman]

Running a Arduino Mega 2560 program that makes heavy use of interrupts and that reports by sending lines of text (about 150 characters) in the main loop via the serial port at 115200 baud, I noiticed that additional spurious characters were sent on average every 2000 lines or so. Looking at the problem in more detail, what was transmitted was a line of exactly 66 characters consisting of the first few characters of the new line followed by last part of the line that had already been sent. The next line missed the first two characters, and then following ones were normal until the next occurrence.

These symptoms seemed consistent with void HardwareSerial::_tx_udr_empty_irq(void) occasionally being invoked at a time when the transmit buffer is in fact empty (i.e. _tx_buffer_head == _tx_buffer_tail), even though this should never happen. So I added some instrumentation:

void HardwareSerial::_tx_udr_empty_irq(void)
{
  // the buffer shouldn't be empty if we get here, but ...
  if (_tx_buffer_head == _tx_buffer_tail) {
    serial_errors++;

where serial_errors is defined in HardwareSerial.h as a private member

volatile uint8_t serial_errors;

and added a method to read and print the error count as part of the main loop.

This confirmed that the problem is indeed associated with the ISR being entered at a time when the buffer is empty, as the error count increments by one each time the problem occurs.

My original code is quite complicated, but I've been able to replicate the problem with a simple testcase in which the loop prints as before while a timer interrupt runs every 0.5ms with an associated ISR running for 0.3ms. The error seems to occur more often at higher baud rates - at 500,000 baud it occurs every few seconds. I can provide the testcase if required.

As a workaround, I've added this section to the start of _tx_udr_empty_irq:

void HardwareSerial::_tx_udr_empty_irq(void)
{
  // the buffer shouldn't be empty if we get here, but ...
  if (_tx_buffer_head == _tx_buffer_tail) {
    serial_errors++;
    // empty buffer so the interrupt should be disabled. Make it so and return.
    cbi(*_ucsrb, UDRIE0);
    return;
  }
...

This fix seems to work for me, but I'm certainly not convinced that it is correct in all circumstances.

I've not been able to figure out why the ISR is ever entered in this situation. Most but not all of the errors disappear if you comment out the part in the busy wait loop in write() that calls the ISR directly when interrupts are disabled globally. (No, I'm not printing to the serial port from an ISR!) Almost all disappear if in addition you comment out the optimisation that writes directly into the output register when the buffer is empty. However I've seen the problem very occasionally (but not with the test case) even when both optimisations are taken out.

[PaulStoffregen]

I can provide the testcase if required.

Yes, please do post a ready-to-run test case!

[johnholman]

OK .. not sure about github conventions and I can't see how to attach files so just pasting here:

Arduino code - serial_test.ino:

unsigned long nlines = 0;
#define MLEN 100
char diagmsg[MLEN+1];

volatile unsigned long cnt = 0;
volatile unsigned long duration = 0;

void setup() {
  Serial.begin(500000);
  delay(100);

 cli();
  TCCR4A = 0;
  TCCR4B = (1 << WGM42) | (1 << CS40) | (1 << CS42); // prescale by 1024 and set CTC mode 
  TCNT4  = 0;
  OCR4A = 8;  // compare with 8 to get interrupt every 0.5 ms
  TIMSK4 = (1 << OCIE4A);  // enable timer overflow interrupt (and no others)
  sei(); 
}

void loop() {
  delay(20);
  nlines++;  
  char c = '0' + nlines % 10;
  int i=0;
  while(i<MLEN) {
    diagmsg[i] = c;
    i++;
  }
  diagmsg[i] = '\0';
  unsigned long start = micros();
  Serial.print(diagmsg);
  Serial.print(" ");
  Serial.print(micros()-start);
  Serial.print(" ");
  Serial.print(cnt);
  Serial.print(" ");
  Serial.print(duration);
  Serial.print(" ");
  Serial.print(Serial.error_count());
  Serial.print(" ");
  Serial.println(nlines);
}

#define NLOOP 200
void test_isr() {
  unsigned long start = micros();
  for (int i=0; i<NLOOP; i++) {
      cnt++;    
  }
  duration = micros() - start;
}

ISR(TIMER4_COMPA_vect) {
  test_isr();
}

Python client, serial_test.py

from __future__ import print_function

import serial
import time

if __name__ == "__main__":

    link = serial.Serial('COM7', 500000)
    print(link)

    try:
        n = 0
        while True:
            n += 1
            start = time.clock()            
            response = link.readline()
            stop = time.clock()
            latency = (stop - start)*1000
            nchars = len(response)
            print("%d %5.2f ms nchars: %d: response: %s"  %(n, latency, nchars, response))
    finally:
        print("closing serial link")
        link.close()

Note that the test case assumes that HardwareSerial.h and .cpp have been amended to add the
instrumentation I mentioned above. Just comment out the line
Serial.print(Serial.error_count());
to see the symptoms but not the diagnostic.

[mattskimi]

Hi, I have the same issue. Sometimes the logic in the hardwareserial::write fails when the tx buffer is empty. I commented out the speedup code when the buffer is empty and made a flush() before reading ack:s from my device, then it started to work. My assumption is that the pointer overruns and the whole buffer is resent. I did not have this problem with version 1.0.x of IDE.
/*******
if (_tx_buffer_head == _tx_buffer_tail && bit_is_set(__ucsra, UDRE0)) {
*_udr = c;
sbi(__ucsra, TXC0);
return 1;
}
******/

[NicoHood]

I also had a serial error. Different than this but it makes sense that this is the same reason.

I know its a lot but you can read this up here:
arduino/Arduino#3207 (comment)

as @mattskimi said its caused by this code. gcc seems (from what ive tested) to maybe optimize the code wrong. Then the data is a) sent twice and sbi(*_ucsrb, UDRIE0); is executed even though its not needed. this causes flush to stuck forever.

The code above seems to not return. For now I dont know why this happens. I have some workaround to fix my issue, but after reading this here it seems that I then still have doubled bytes (havent tested the output, since I send the same data byte).

[NicoHood]

Replacing the udr pointer with the register fixes the issue for me:

It seems that (on the left side) it loads the main class pointer, adds the value for the udr pointer (16) and subtracts it back (17), but the subtraction is wrong. And because of this the offset is -1 for _ucsra.

Files:
https://gist.github.com/NicoHood/288e6ee609954d60ab85

[NicoHood]

Maybe some inline asm can help? I tried but got a compile error:

  if (_tx_buffer_head == _tx_buffer_tail && bit_is_set(*_ucsra, UDRE0)) {
    //*_udr = c;
    asm (
        "st %a[_udr], %[c]\n\t"     // (2) Save byte in buffer
        // Outputs
        : [_udr] "+e" (_udr) // Input and output
        // Inputs
        :  [c] "r" (c)
    );
    sbi(*_ucsra, TXC0);
    return 1;
  }

cores/arduino/HardwareSerial.cpp: In member function 'virtual size_t HardwareSerial::write(uint8_t)':
cores/arduino/HardwareSerial.cpp:229:9: error: read-only member 'HardwareSerial::_udr' used as 'asm' output
        );
         ^
Error compiling.

[matthijskooijman]

So effectively, the sbi(*_ucsra, TXC0) fails because the _ucsra is loaded from the wrong place. When constructing the address of _ucsra, this address is 1 too small. Instead of loading _ucsra, it loads the last byte of _ubrrl and the first byte of _ucsra. On a 328p, _ubrrl is 0x00C4 and _ucsra is 0x00C0. Note that AVR is little endian, so this loads the MSB of _ubrrl (0x00) and the LSB of _ucsra (0xC0) and interprets the result as 0xC000. The two-byte value at that address is loaded, which is then used as the value of _ucsra, so it is dereferenced and the result is written to.

Since 0xC000 is out-of-bounds for a 328p, we need to wonder how AVR handles this. By dumping the entire memory, as well as a bunch of bytes after it using this sketch, you can see that any reads after the end of the memory (0x900 and onward) return the same thing as reads from 0x100 and onward. Since the SRAM is mapped from 0x100 to 0x8ff, it seems that the SRAM region wraps around. This means that 0xC00 really reads from address hex((0xc000 - 0x100) % 0x800 + 0x100) = 0x800, which is some address well on the stack. This does not seem to be any particular value, so the address of _ucsra that is used (and written to) is just random, which doesn't really explain the behaviour we're seeing.

However, trying to print *((uint16_t)0xc000) gives me 0x0000, which is different from what's on 0x800, so perhaps the SRAM only wraps once? If reading 0xc000 would always return 0x0, then sbi(*_ucsra, TXC0) would set a bit in r0, would that explain this behaviour? No time to look more closely at this right now.

Of course, the TXC0 bit is not cleared due to this bug, but I'm not sure how this would cause the described behaviour (since this bit is pretty much only used inside flush()).
'0x800'

[NicoHood]

Have you looked at the other assembly? Maybe this isnt the only place that is wrong. It solves my issue/test case. But maybe there is more wrong with the code. Maybe also in other functions.

One could try the newer 5.1 and see if that fixes the issue. If not, this is a very poor issue to fix. I am afraid that this could occur on other places as well.
arduino/Arduino#660 (comment)

[NicoHood]

5.1 with LTO doesnt fix the problem. It lacks some debug information in the output, but now I know the place to search for:

 2e4:   0c c0           rjmp    .+24        ; 0x2fe <_ZN14HardwareSerial5writeEh+0xac>
 2e6:   d6 01           movw    r26, r12
 2e8:   56 96           adiw    r26, 0x16   ; 22
 2ea:   ed 91           ld  r30, X+
 2ec:   fc 91           ld  r31, X
 2ee:   57 97           sbiw    r26, 0x17   ; 23

The sketch was also tested on a real board!

output:
https://gist.github.com/NicoHood/10a15742a3c76dda3755

tested sketch:
https://gist.github.com/NicoHood/e3d47e5e994a10793688

[NicoHood]

virtual size_t write(uint8_t) __attribute__((optimize("O3")));
Seems to not work. It was worth a try.

O3 output:
https://gist.github.com/NicoHood/1e35660adb92686321d1

Also tested O0 which seems to work \o/ (adds a lot more code)
https://gist.github.com/NicoHood/e664f39e4142a5f834a4

The test were made via uploading and trying. I did not look at the asm this time since it changed too much and I dont want to do that now.

Rearranging the class members did not help with a (single) quick test.

Should we report this upstream? This is a very bad testcase I think. At least one doesnt need an arduino to see the asm is incorrect.

[matthijskooijman]

I guess that reducing the code to a smaller testcase would be the next step, so we can report a bug at gcc. Here's the steps I'd take:

• Take just Print.h, Stream.h, HardewareSerial.h and HardwareSerial.cpp, and make that compile (possibly adding some includes and type definitions if needed).
  • Remove all but the write() method from HardwareSerial.cpp. Perhaps this can be done in the first step already, if that makes it easier to get it compiling.
• No longer let HardwareSerial be a subclass of Stream (I suspect this will stop the bug from occuring, though I'm not sure).
• Remove all unused members from HardwareSerial
• Remove as much code as possible from write()

After every modification, check the generated assembly to see if the bug still exists. If the bug disappears, undo the last change and try to make the change less invasive, or skip to the next change.

I don't have time to dive in right now, perhaps @NicoHood can?

[matthijskooijman]

Also, disabling optimization for a single function using an attribute was smart to try - that might very well be a useful workaround until we can get a fixed compiler. However, reducing the example code should be a first step, since this will also offer insight into what the essential parts are that cause this bug, which might help to figure out a less invasive workaround, and perhaps allows searching the source code for other instances of this bug.

[NicoHood]

If you tell me how to compile those functions outside the IDE I can do this. I have linux with avr-gcc 4.8.1 and also 5.1 available. I just need to know how to manually compile them and get an asm output. Then I can try to debug it.

[matthijskooijman]

Basically just take the avr-gcc command that Arduino uses for HardwareSerial.cpp (from the verbose output) and use that. That should produce a .o file (not linked into .elf yet), but that should already show this bug and can be disassembled using avr-objdump -S just like the .elf. Hope that helps?