Data dropouts in serial transfer over USB

[rwalters]

Like many others, I'd like to pull data as quickly as possible from my Teensy 3.2 and want to figure out the best strategy for Serial communication.

I know I can get better effective throughput by changing my code -- by sending binary data, being careful not to send redundant info, etc -- but here I am sending plain text to keep things simple. It is possible that my python listener code is causing problems and needs to be in a separate thread or should read data bytewise using PySerial's in_waiting rather than readline().

I am using windows and the Teensy USB serial driver.

Basically I don't understand:

1. the difference between send_now() and flush()
2. why I get a "corrupted" data stream using just println()
3. why I can't manage more than about ~300kbps (or ~1Mb/sec if I try to manage the corruption)

I've attached my sketch and a python script for reading and parsing the data.

The results look like this for me:

 

[rwalters]

Here is an example of the "corruption" I mentioned:

S
594
94571
594.000000
027


S
595
94727
595.000000
027


S
596
94886
596.000000
027


S
597
95055
597S
731
231989
731.000000
028


S
732
232171
732.000000
028


S
733
232340
733.000000
028

This snippet shows 3 good messages and then a garbled message with a ~120 msec jump in the timestamp.

I see this a lot when using println() alone.

 

[rwalters]

When the jump occurs, note that the loop iteration counter is incremented from 597 to 732 -- so my loop is still running and I'm still presumably making calls to println() -- this data seems to just be "lost" somewhere...

 

[PaulStoffregen]

Good question. I can't comment on the Python side, but I can about what's going on with Teensy.

First, do *not* call flush() or send_now() if your goal is maximum bandwidth. Those cause the USB code to send a partial packet. If you've written a bunch of data and you're done, so you're not going to write any more for a while, those cause the last partial packet to send as soon as possible. Normally the USB stack holds the data so your next write can fill the rest of the packet... which maximizes bandwidth.

1 MByte/sec is usually about as fast as USB 12 Mbit/sec goes. Some people have seen 1.1 MByte/sec, but it really depends on whether you have other USB devices active and how your operating system and host controller chip on your PC's motherboard allocates the bandwidth.

The missing data is mysterious. Perhaps the PC is falling far behind and Teensy is mistakenly timing out?

 

[rwalters]

Thanks for the tips Paul. I'm getting about 6Mb/sec when I write larger chunks of ~80bytes. The data rate is definitely faster when I let the USB stack manage everything but I get a lot more dropouts.

I have now confirmed that I still get occasional drop-outs when I include the send_now() calls too...

(Now I'm sending real data: 'S', i, k, deltatime, 6 floats of MPU9250 data, three filter indices, and finally a zero padded message length...)

S
776747
417
78565534
0.054688
0.005371
-0.985840
0.000000
-1.373291
4.638672
0
7
0
088


81738
0.823975
0
7
0
089


S
776749
419
78567590
0.049316
-0.000977
-0.989258
5.340576
5.218506
0.061035

 

[rwalters]

The python code is about as simple as I can make it:

with (serial):
while (true):
file.write(serial.readline())

I suppose it is possible that PySerial can't keep up, but I'm not sure how to test this. Any ideas?

 

[retospect]

rwalters:
Are you using OSX by any chance?
I have a test setup (other thread) that drops data on El Capitan only. I get about 14% drops/mangled data on El Captian only, Linux, Windows and Yosemite is unaffected.

Here is an example of the "corruption" I mentioned:
...

 

[rwalters]

I'm using Windows -- it would be great if you could test the code I shared on a mac just to see if this is a windows-specific problem.

 

[rwalters]

@retospect -- I downloaded and ran your code from the other thread without any issues...

Getting Port
Found Teensy at COM7.
Opening port
Starting to read
Last error:
No Error

OK: 10000, Error: 0, Error rate 0.0%

View attachment retospectTest.zip

 

[rwalters]

Some statistics on the dropouts using send_now() -- In ~262k transfers I got 180 corruptions.

The errors seem random...

 

[rwalters]

I am returning to my minimal code example because I seem to have some other timing weirdness in my MPU9250 data collection loop.

Just to re-establish the problems I am seeing:

When sending data without calling the "send_now()" function I get significant data dropouts. I lose almost half of my 20byte writes while sending 20k iterations over a ~5.13sec time period:



I seem to get no (?) dropouts calling "send_now()" inside my loop, but now it takes me ~20sec to send the 20k writes:



The loop time seems to increase after the first ~10 iterations (corresponding to about 200 bytes of data being sent over serial USB)...


Here is the code for the teensy:

#pragma GCC optimize ("-O2")

// library imports
#include <Arduino.h>
#include <cstdio>

void setup()
{
    Serial.begin(9600); // USB is always 12 Mbit/sec
    delay(10000); //wait for user to start up serial listener...
}

char datastring[100];
void fillbuffer(uint32_t iterationCount, uint32_t timeStart, uint32_t timeNow, uint32_t timeDelta)
{
    sprintf(datastring,"S\n%lu\n%lu\n%lu\n", iterationCount, timeNow - timeStart, timeDelta); 
    sprintf(&datastring[strlen(datastring)], "%03d\n\n", 4+strlen(datastring));
}

void loop() 
{
    // test serial output
    uint32_t timePrev = 0;
    uint32_t timeStart = micros();
    
    uint32_t samples = 20000;
    
    timePrev = timeStart;
    
    for (uint32_t iterationCount = 0; iterationCount<samples; iterationCount++){ 
        uint32_t timeNow = micros();
        fillbuffer(iterationCount, timeStart, timeNow, timeNow-timePrev);
        timePrev = timeNow;
        Serial.print(datastring);
        Serial.send_now();
        //Serial.flush();
    }
}

and in python:

#!/usr/bin/env python
import serial  # requires pyserial
import sys, os
def collectRawData(port, samples):
    collected_data = False
    serial_timeouts = 0
    f = open(os.path.join(os.path.dirname(os.path.realpath(__file__)), 'raw.txt'), 'w')
    f.seek(0)
    with serial.Serial(port, timeout=0.01) as ser:
        i = 0
        while i<samples:
            i += 1
            newline = ser.readline()
            if not newline:
                serial_timeouts+=1
            else:
                collected_data = True
                serial_timeouts = 0
            if collected_data and serial_timeouts>100:
                break
            f.write(newline)
            if (i%1000) == 0:
                print i
               
    f.close()

def parseRawData():
    message_length = 4 # S, i, t, dt
    
    with open(os.path.join(os.path.dirname(os.path.realpath(__file__)), 'parsed.csv'), 'w') as out:
        with open(os.path.join(os.path.dirname(os.path.realpath(__file__)), 'raw.txt'), 'r') as f:
            state = 0
            buffer = ""
            line_number = 0
            data_iteration = 0
            for line in f:
                if line[0] is "S":
                    state = 1
                elif state > 0 and state < message_length:
                    buffer = buffer + line.strip() + ", " 
                    state += 1
                elif state == message_length:
                    buffer = buffer + line.strip() + "\n"     
                    state += 1
                elif state == message_length + 1:    
                    if line.strip():
                        print "****** (not handled) unexpected text: '", line.strip(), "' @ line ", line_number
                    else:
                        data_iteration = int(buffer.split(',')[0])
                    out.write(buffer)
                    buffer = ""
                    state = 0 # reset for next S
                else:
                    print "syncing to 'S' @ line", line_number
                    if state == 0:
                        print "writing error line to file"
                        buffer = str(data_iteration + 1) + ', ' + ( '-9999, '*(message_length-1) ) + '\n'
                        out.write(buffer)
                        buffer = ""
                        state = -1 #don't write multiple error lines
                line_number +=1
                
                
if __name__ == '__main__':
    collectRawData('COM7', 500000)
    parseRawData()

I'm just using excel to make plots.

 

[rwalters]

A little bit of cleanup on code. Also verified that my -O2 pragma was not relevant.

View attachment teensyserialtest.zip

 

[stevech]

I haven't read all this thread, but what are you using for flow control between receiver and sender?

 

[rwalters]

On the Tx side, I'm just calling "Serial.print()" with a port that I have set up using "Serial.begin(9600)" -- so whatever the defaults are I guess. (Also -- baud rate doesn't matter AFAIK)

On the Rx side, I'm using PySerial to set up a port using "serial.Serial(port, timeout=0.01)" and reading data using "serial.readline()"

What would you suggest for flow control?

 

[defragster]

I took your code and modified it as it was hard to see the streaming broken numbers in TYQT monitor. I ended up with the code below that looks fine. Unless you comment out one of the number prints - then the time elapsedMicros value from temp or runningms jumps oddly - which may just be the Teensy stopping to wait for the PC to keep up.

<edit: even with the time JUMPS I don't see data loss or corruption in the counts. USB is Flow Control - thus the time jumps?>

#pragma GCC optimize ("-O2")

// library imports
#include <Arduino.h>
//#include <cstdio>

void setup()
{
  Serial.begin(9600); // USB is always 12 Mbit/sec
  delay(10000); //wait for user to start up serial listener...
}

elapsedMicros runningms;
void loop()
{
  uint32_t temp;
  for (uint32_t iterationCount = 0; iterationCount < 20000; iterationCount++) {
    Serial.print("abcdefghijklmnopqrstuvwxyz0123456789");
    Serial.print("__");
    temp = runningms;
//    Serial.print(temp);
//    Serial.print(runningms);
    Serial.print("__");
    Serial.print(iterationCount);
    Serial.print("\n");
    Serial.send_now();
    runningms = 0;
    //Serial.flush();
  }
}

 

[rwalters]

It looks like you removed the calls to "micros()" and put in an elapsedMicros variable -- curious if you think this might be part of the problem?

Also, did you try running this without calling send_now() inside the loop?

 

[rwalters]

I modified your code a little bit so that I could use the same python serial reader:

#include <Arduino.h>

void setup()
{
  Serial.begin(9600); // USB is always 12 Mbit/sec
  delay(10000); //wait for user to start up serial listener...
}

elapsedMicros runningms;
void loop()
{
  runningms = 0;
  for (uint32_t iterationCount = 0; iterationCount < 20000; iterationCount++) {
    Serial.print("S\n");
    Serial.print(iterationCount);
    Serial.print("\n");
    Serial.print(runningms);
    Serial.print("\n\n\n");
    //Serial.send_now();
    runningms = 0;
  }

  while(1){}
}

I also had to change the "message_length" in my parser:

#!/usr/bin/env python


import serial  # requires pyserial
import sys, os

def collectRawData(port, samples):
    collected_data = False
    serial_timeouts = 0
    f = open(os.path.join(os.path.dirname(os.path.realpath(__file__)), 'raw.txt'), 'w')
    f.seek(0)
    with serial.Serial(port, timeout=0.01) as ser:
        i = 0
        while i<samples:
            i += 1
            
            newline = ser.readline()
            if not newline:
                serial_timeouts+=1
            else:
                collected_data = True
                serial_timeouts = 0
            
            if collected_data and serial_timeouts>100:
                break
            
            f.write(newline)
            
            if (i%1000) == 0:
                print i
               
    f.close()


def parseRawData():
    
    message_length = 2 # S, t, i
    
    with open(os.path.join(os.path.dirname(os.path.realpath(__file__)), 'parsed.csv'), 'w') as out:
        with open(os.path.join(os.path.dirname(os.path.realpath(__file__)), 'raw.txt'), 'r') as f:
            state = 0
            buffer = ""
            line_number = 0
            data_iteration = 0

            for line in f:
                
                if line[0] is "S":
                    state = 1
                elif state > 0 and state < message_length:
                    buffer = buffer + line.strip() + ", " 
                    state += 1
                elif state == message_length:
                    buffer = buffer + line.strip() + "\n"     
                    state += 1
                elif state == message_length + 1:    
                    if line.strip():
                        print "****** unexpected text: '", line.strip(), "' @ line ", line_number
                        # don't put bad data line in our outfile
                    else:
                        data_iteration = int(buffer.split(',')[0])
                        out.write(buffer)
                        buffer = ""
                    state = 0 # reset for next S

                else:
                    print "syncing to 'S' @ line", line_number
                    if state == 0:
                        print "writing error line to file"
                        buffer = str(data_iteration + 1) + ', ' + ( '-0.9, '*(message_length-1) ) + '\n'
                        out.write(buffer)
                        buffer = ""
                        state = -1 #don't write multiple error lines
                        
                line_number +=1
                
                
if __name__ == '__main__':

    collectRawData('COM7', 500000)
    parseRawData()

Here is the progression of timestamps when we call Serial.send_now() inside the for loop:



and when we do not:



I think the results are essentially the same -- we lose data without send_now()...

 

[rwalters]

Here is what the dropouts look like:

S
1624
7


S
1625
7
13


S
5724
7


S
5725
7

 

[defragster]

It looks like you removed the calls to "micros()" and put in an elapsedMicros variable -- curious if you think this might be part of the problem?

Also, did you try running this without calling send_now() inside the loop?

I'm hitting this from the 10,000 foot view. I am using TYQT for my Win10 serial Monitor - just to make the view easier I wanted linear formatted data - printing the growing millis() got in the way.

When I used the elapsedMicros() and just the alpha print it fit on one line - and the only anomalies look like this:

abcdefghijklmnopqrstuvwxyz0123456789__118__5851
abcdefghijklmnopqrstuvwxyz0123456789__108__5852
abcdefghijklmnopqrstuvwxyz0123456789__120__5853
abcdefghijklmnopqrstuvwxyz0123456789__118__5854
abcdefghijklmnopqrstuvwxyz0123456789__43068__5855
abcdefghijklmnopqrstuvwxyz0123456789__40__5856
abcdefghijklmnopqrstuvwxyz0123456789__121__5857
abcdefghijklmnopqrstuvwxyz0123456789__96__5858
abcdefghijklmnopqrstuvwxyz0123456789__118__5859
abcdefghijklmnopqrstuvwxyz0123456789__107__5860

After running in a range on the cycle time it jumps up 43 millis() - all the indexes I glanced at are linear. I put in temp thinking that the runningms was changing during access? Turns out that I suspect that is just a buffer empty wait from the PC USB.

Try this on TYQT (is it awesome).

But I think the root of the problem is unthrottled writes of course and the USB just halts transfers, but it doesn't seem lossy. I suspect the python processing code may add to the issues for you. When I watch in TYQT it keeps up on my slow old Win10 i5. TYQT months back could not achieve this data rate - but Koromix addressed that and the throughput is now impressive.

This is 9DOF data right ? Will you be doing 1000 updates/sec? Not sure how fast this is running as I have to run myself.

If this tight FOR loop were turned into a re-entrant 'while' using loop() as it is meant to and you constrained the writes to average out that __43068__ backlog over all previous transactions - perhaps use elapsedMicros to prevent re-entry & print faster than ~600us the process should smooth out. The code could figure this out and monitor it to tell you what works using more elapsedMicros timers - they are cool and no math is needed, just reset to 0.

I just re-ran with : delayMicroseconds(600);

NOTE: with this wait I see no difference with or without the Serial.send_now();. Using the Serial.send_now(); as Paul said will actually slow the system down with less efficient transfers, so you would find less data loss on the python end if it cannot keep up. You have my code and the one line I added - and TYQT is in the news with a new update today, if you experiment along these lines you can soon fine tune it to maximal transfers from the Teensy to the PC - try both at 600 and dropp down and see which backs up first - then you just have deal with how fast the python USB code can get data without loss.

Then 20,000 iterations completes with no time wait backlog - and I assume no lost or altered data as the rows are even length. That would represent sample data rate of 1,666 per second [for my ~50 char string]?

abcdefghijklmnopqrstuvwxyz0123456789__614__9995
abcdefghijklmnopqrstuvwxyz0123456789__611__9996
abcdefghijklmnopqrstuvwxyz0123456789__613__9997
abcdefghijklmnopqrstuvwxyz0123456789__611__9998
abcdefghijklmnopqrstuvwxyz0123456789__613__9999
abcdefghijklmnopqrstuvwxyz0123456789__613__10000
abcdefghijklmnopqrstuvwxyz0123456789__611__10001
abcdefghijklmnopqrstuvwxyz0123456789__612__10002
abcdefghijklmnopqrstuvwxyz0123456789__612__10003
abcdefghijklmnopqrstuvwxyz0123456789__611__10004
abcdefghijklmnopqrstuvwxyz0123456789__612__10005

 

[rwalters]

I appreciate your help.. I'm not familiar with TYQT -- (this one right? https://github.com/Koromix/ty) -- It may very well turn out to be PySerial that is the problem here.

(To address your question on the MPU9250 -- I'm looking at some vibration processes and wanting to capture data quickly to make nice noise power spectra plots. The chip supports 1kHz output.)

Does the delayMicroseconds() call block anything that the Serial library might be doing in the background? Otherwise I'm not sure we should necessarily conclude from your last test that PySerial is causing the problem...

 

[rwalters]

Slowing down the rate that data is fed to Serial.print does seem to replace send_now(). Here I am gradually slowing down the loop and looking for the place where I stop seeing the dropouts (maybe around 200usec of delay?):

#include <Arduino.h>
void setup()
{
  Serial.begin(9600); // USB is always 12 Mbit/sec
  delay(10000); //wait for user to start up serial listener...
}
elapsedMicros runningms;
void loop()
{
  runningms = 0;
  for (uint32_t iterationCount = 0; iterationCount < 40000; iterationCount++) {
    delayMicroseconds(iterationCount * 600/40000.0);
    Serial.print("S\n");
    Serial.print(iterationCount);
    Serial.print("\n");
    Serial.print(runningms);
    Serial.print("\n\n\n");
    
    //Serial.send_now();
    runningms = 0;
  }
  while(1){}
}

I am still confused on what causes the dropouts... As I understand it, Serial.write is managing a buffer (of some reasonable size?) under the hood. Is there a way to check if this buffer is full before I write more data in?

It seems like the later calls to Serial.write() are throwing away data unless I explicitly call send_now() (does this block until the pc collects all the buffered data?)

Is send_now() essential for reliable information transfer if I don't want to carefully tune for a particular transfer rate?

Also, it seems strange to me that PySerial wouldn't be able to keep up.

View attachment teensyserialtest_fragster.zip

 

[rwalters]

The delayMicroseconds() required to reduce dropouts seems dependent on data writing rate. Also sometimes the loop takes significantly longer to run:

#include <Arduino.h>
void setup()
{
  Serial.begin(9600); // USB is always 12 Mbit/sec
  delay(10000); //wait for user to start up serial listener...
}
elapsedMicros runningms;
void loop()
{
  runningms = 0;
  for (uint32_t iterationCount = 0; iterationCount < 40000; iterationCount++) {
    delayMicroseconds(iterationCount * 600/40000.0);
    Serial.print("START\n");
    Serial.print(iterationCount);
    Serial.print("\n");
    Serial.print(runningms);
    Serial.print("\n");
    //extra data payload...
    Serial.print("1"); // 1 bytes
    //Serial.print("1234567890"); //10 bytes
    //Serial.print("12345678901234567890"); //20 bytes
    Serial.print("\n");
    Serial.print("\n\n"); //use two protective lines to help with parsing
    runningms = 0;
  }
  while(1){}
}

with 10 extra bytes:


with 20 extra bytes:


with 1 extra byte:

 

[defragster]

I have a REALLY COOL update to the sketch - it works well with Serial.send_now(); - but without it seems to get into a DEATH wait on USB? The sketch starts with a low throttle WAIT and increases it every time it fails to complete a cycle in that time - due to USB blocking.

As noted it runs perfectly up to the needed wait until I take out the send_now() - then it repeatedly DIES/HANGS/QUITS with no sign of life - I didn't add qBlink() as I should have. It was working - but would regularly do this where I get to equilibrium.

I should post the INO but I don't have time for that - here is the code as I have it:

#include <Arduino.h>
void setup()
{
  Serial.begin(9600); // USB is always 12 Mbit/sec
  while ( !Serial && millis() < 10000); //wait for user to start up serial listener...
}
elapsedMicros runningms;
uint32_t runningtemp;
uint32_t iterationCount = 0;
#define THROTTLEINIT  200
uint32_t throttle = THROTTLEINIT;
boolean useSendNow = false;
uint32_t GoodThrottle[2] = {0, 0};
void loop()
{
  if ( runningms > throttle ) {
    runningtemp = runningms;
    runningms = 0;
    if ( runningtemp > ( throttle + 10 )) {
      if ( iterationCount < 5000 )
        throttle += 30;
      else if ( iterationCount < 12000 )
        throttle += 10;
      else
        throttle += 3;
      Serial.print("\n\n\n________adjustING_123___");
      showStuff();
      iterationCount = 0;
      delay(50);
      runningms = 0;
      return;
    }
    //    delayMicroseconds(iterationCount * 600/40000.0);
    if (useSendNow)
      Serial.print("TEST_SendNow__");
    else
      Serial.print("TEST_!SendNow_");

    iterationCount++;
    showStuff();
    if (iterationCount >= 40000) {
      Serial.print("\n\n 40,000 with ___\n");
      showStuff();
      GoodThrottle[ useSendNow ] = throttle;
      Serial.print("\n__throttle [ NO SEND NOW ] =");
      Serial.print(GoodThrottle[0]);
      Serial.print("\n__throttle [ with SEND NOW ] =");
      Serial.print(GoodThrottle[1]);
      useSendNow = !useSendNow;
      throttle = THROTTLEINIT;
      iterationCount = 0;
      delay(10000);
    }
    if (useSendNow)
      Serial.send_now();
  }
}

void showStuff() {
  Serial.print("__iterations=");
  Serial.print(iterationCount);
  Serial.print("__throttle=");
  Serial.print(throttle);
  Serial.print("__runningms=");
  Serial.print(runningtemp);
  Serial.print("______\n");
}


/*

 40,000 with ___
__iterations=40000__throttle=770__runningms=773______

__throttle [ NO SEND NOW ] =0
__throttle [ with SEND NOW ] =770
 */

 

[rwalters]

I think the "very long loops" may also be related to serial comm issues.

Sending +1 byte of data as we ramp up to 1200usec delay per loop:


Sending +20 bytes of data per loop:


Note that the dropouts are worse whenever the data rate goes up.

View attachment teensyserialtest_fragster_2.zip

If I use "send_now" instead of delayMicroseconds, I get slower performance but no dropouts or weirdly long loops...

 

[rwalters]

I'm looking over your code and I am not sure I'm following ... are you measuring the time it takes to use send_now()? Why not just print the elapsed micros()?

This does suggest the idea of using some sort of feedback-system to dynamically figure out how quickly to send data, but I don't know how we would get an error signal to control on without being able to see if the write buffer is full or else by moving to some kind of bidirectional ACK scheme...

I went back and read Paul's benchmark work: http://www.pjrc.com/teensy/benchmark_usb_serial_receive.html

Is it reasonable to assume we would be able to get similar write performance as read performance?