USB Serial data loss - Teensy3.2 receive buffer full prevents sending data

[delineate]

Hi,

I want to use Teensy 3.2 both to receive streaming LED data over USB and send sensor data to the host.

However, I'm running into an issue where if the host sends data too quickly, communication from the Teensy stops.

Here is a minimum working example:

void setup() {
  pinMode(13, OUTPUT);
  digitalWrite(13, HIGH);

  Serial.println("Hello world");
}

void loop() {
  digitalWrite(13, LOW);

  while (Serial.available()) {
    char c = Serial.read();
    if (c == '\n') {
      Serial.println("Received");

      delay(400);

      if (Serial.availableForWrite() == 0) {
          digitalWrite(13, HIGH);
          delay(20);
      }
      Serial.println("Finished");

      break;
    }
  }
}

And sender script:

import serial
import time

ser = serial.Serial(port="/dev/tty.usbmodem66941801", baudrate=115200,
    timeout=10.0, write_timeout=10.0)

while True:
    a = time.time()
    n = ser.write(bytes("x"*1500 + "\n", "utf-8"))
    print(f"Wrote. {n} bytes in {(time.time() - a)*1000:.3f}ms")

    inp = ser.read_all()
    if inp:
        print(f"Read: {inp}")
    time.sleep(0.02)

I get the following:

Wrote. 1501 bytes in 0.098ms
Wrote. 1501 bytes in 0.192ms
Read: b'Received\r\n'
Wrote. 1501 bytes in 0.153ms
Wrote. 1501 bytes in 1010.470ms
Read: b'Received\r\n'
Wrote. 1501 bytes in 0.180ms
Read: b'Received\r\n'
Wrote. 1501 bytes in 1027.110ms
Read: b'Received\r\n'
Wrote. 1501 bytes in 0.192ms
Read: b'Received\r\n'
Wrote. 1501 bytes in 1027.653ms
Read: b'Received\r\n'
Wrote. 1501 bytes in 0.163ms

As you can see, it prints Received and not Finished. And the LED is blinking, which means that availableForWrite() is returning 0. If I change the final sleep in the python to 0.4sec, then it works correctly as the buffer can be emptied in time.

When I look at the Teensy platform code my guess is that usb_malloc() is failing when the receive buffer is full. But I have no idea how to overcome this. I have also tried separating the return data stream to SerialUSB1, but it doesn't fix the issue - both devices share the same usb_malloc().

 

[joepasquariello]

I can't test this for you, but wouldn't it be a good idea to at least count the number of bytes received on the Teensy side? I'm not sure how this can work at all with no call to Serial.begin(). What is the purpose of the delay(400)?

 

[delineate]

The delay is to make it so that the Teensy processing takes a lot longer, i.e. the Python host program is sending lines of data a lot faster than the Teensy is able to process them.

Serial.begin() is optional on Teensy, but the same happens if it is added. Here is the modified sketch with comments

void setup() {
  pinMode(13, OUTPUT);
  digitalWrite(13, HIGH);

  Serial.begin(115200);
  Serial.println("Hello world");
}

uint32_t count = 0;
void loop() {
  digitalWrite(13, LOW);

  while (Serial.available()) {
    char c = Serial.read();
    count++;
    if (c == '\n') {
      Serial.print("Received: ");
      Serial.println(count);
      count = 0;

      // Simulate slow processing
      // During this time, the serial receive buffer is filling up.
      delay(400);

      // Now the serial receive buffer is full.
      // It should not be affecting the write buffer, but it does.
      // The LED blinks, indicating that availableForWrite() is 0.
      if (Serial.availableForWrite() == 0) {
          digitalWrite(13, HIGH);
          delay(20);
      }

      // This line never gets sent!
      Serial.println("Finished");

      break;
    }
  }
}

You can see in the output below that each line is received correctly. Also, the input to the Teensy gets correctly rate limited by flow control, as the Python program blocks as it waits for the Teensy to get through the backlog.

However, the word "Finished" is missing from every response! And the LED is blinking, indicating that data could not be written.

Wrote. 1501 bytes in 0.177ms
Wrote. 1501 bytes in 0.215ms
Read: b'Received: 1501\r\n'
Wrote. 1501 bytes in 0.155ms
Wrote. 1501 bytes in 980.790ms    <--- RATE LIMITED BY SERIAL FLOW CONTROL
Read: b'Received: 1501\r\n'
Wrote. 1501 bytes in 0.204ms
Read: b'Received: 1501\r\n'
Wrote. 1501 bytes in 1005.910ms
Read: b'Received: 1501\r\n'
Wrote. 1501 bytes in 0.288ms
Read: b'Received: 1501\r\n'
Wrote. 1501 bytes in 1003.357ms
Read: b'Received: 1501\r\n'
Wrote. 1501 bytes in 0.173ms
Read: b'Received: 1501\r\n'
Wrote. 1501 bytes in 1002.997ms
Read: b'Received: 1501\r\n'
Wrote. 1501 bytes in 0.170ms
Read: b'Received: 1501\r\n'
Wrote. 1501 bytes in 1002.919ms
Read: b'Received: 1501\r\n'
Wrote. 1501 bytes in 0.347ms
Read: b'Received: 1501\r\n'

This seems like a bug in the Teensy USB serial implementation, and unfortunately pretty serious for my application.

 

[defragster]

Not sure where usb_malloc() is seen? PJRC USB does AFAIK static allocation of buffers in RAM2/DMAMEM

And if the right spots just seen in CORES the Rx and Tx buffers are allocated individually.

There is very little indicated output from the Teensy and no reason for the write buffer to be full?

400 ms is a really long wait and maybe in a bad spot.

If the output shown is from the Python code? It takes under 0.2 ms to send 1501 bytes? So ignoring reads for 400 ms is extreme.

Suggest altering the test until "Finished" is found. The problem is not likely in the Teensy support code, but the PC (?) Python Rx or in how the sketch is written with delays.

Once '\n' then "Finished" should print then not after a long delay - unless that is the key for the Python code to send the next set of bytes?

Too little info for a clear understanding of the process and interaction beyond more questions than clear answers.

 

[delineate]

The delay is exaggerated for clarity. Yes, the output shown is for the Python code running on the PC (Mac laptop). As I mentioned, modifying the sleep to 0.4 (400ms) on the Python side causes the Finished to appear, and the LED (indicating write buffer full) stays off. You can also decrease the delay on the Teensy side, the important thing is that the host is sending faster than the Teensy can read.

Yes, there is very little output from the Teensy and no reason for the write buffer to be full. But that is exactly what I am seeing, as indicated by the LED coming on. That's probable evidence of a bug to me.

If you read in the code for availableForWrite (I think it was in usb_serial.h), it is calling usb_malloc if an outgoing packet isn't created yet. I suspect it is failing because all of the memory is allocated to the incoming packets that haven't been processed yet.

It's quite troublesome and unexpected that the exhaustion of any usb buffer affects both send and receive across all of the virtual serial ports simultaneously.

Hoping @Paul can chime in here

 

[defragster]

Indeed, that might be something @PaulStoffregen can see to answer. USB Rx and Tx buffers are pre-allocated and unique? The values from 'Available' are odd - but that has been seen here before and not a problem with function.

Not sure about mac - but generally python has shown to be a problem in some cases.

Not seeign python code - does it just send repeatedly? Have a delay? wait for Finished?