Test of Serial Transfer, fails for large transfers

Status
Not open for further replies.

DrM

Well-known member
The following demonstrates a problem I am having with the Serial interface on the Teensy. Large transfers fail as shown below.


Code snippet from Teensy 3.2
Code:
      case 'v':
      case 'V':

	if (*nextcharpointer == 'x') {

	  char *pc = (char *)databuffer;

	  Serial.println( (char *)"starting" );
	  
	  for (n = 0; n < 4096; n++ ) {
	    pc[n] = 'a' + n%26;
	  }
	  
	  for (n = 0; n < 100; n++ ) {
	    Serial.write( (uint8_t *) databuffer, 4096 );
	  }
	  break;
	}
	
        if ( parseint( p0, &p1, &debug ) ) {
          debug = strtoul( p0, &p1, 0 );
          serialprintf( (char *)"%s  - debug = %d\n", versionstr, debug );
        }
        else {
          serialprintf( (char *)"%s\n", versionstr );
        }
        break;


Python
Code:
#!/usr/bin/python

import serial


ser = serial.Serial( '/dev/ttyACM0', 19600, timeout = 2 )


ser.write( 'v'.encode() )

rawbuf = ser.readline( )
print( rawbuf.decode() )

ser.write( 'x'.encode() )
rawbuf = ser.readline( )
print( rawbuf.decode() )

n = 0
while True:
    rawbuf = ser.read(  4096)
    print( 'read', n, len(rawbuf) )
    n += 1
    if n > 10:
       break


And the result, is the two short lines of text are transferred, then the first 4096, then 302 bytes of the next buffer, and then nothing.

Code:
$ ./HostFlowTest.py
TDAQ Firmware 2.4
DONE

read 0 4096
read 1 302
read 2 0
read 3 0
read 4 0
read 5 0
read 6 0
read 7 0
read 8 0
read 9 0
read 10 0
 
Without testing I assume the following:

This:
Code:
 for (n = 0; n < 100; n++ ) {
    Serial.write( (uint8_t *) databuffer, 4096 );
 }

does not take into account that the PC might not fetch all sent bytes immediately. In this case Teensyduino tries for 120ms (see https://github.com/PaulStoffregen/c...54e4c11f869e685b7d4/teensy4/usb_serial.c#L277) and then aborts. Your code ignores that and tries to send another frame so you will loose the not sent bytes from the other frame.

Serial.write() returns the actually written bytes back, so you need to take that into account. For a quick check you can simply increase TX_TIMEOUT_MSEC (see link above) to some very large value (say 10s) and see what happens then. A quick experiment (Win10) with TyCommander showed that it usually transfers a 10k buffer in about 700µs (Teensy 4.x). But, from time to time it takes about 250ms. In those cases Serial.write does not transmit the full frame. This is not a problem per se but of course needs to be taken care of.

EDIT: Might also be important to understand that the send buffer is 8kB (T4.x) large. The return value of Serial.write is the number of bytes written to this buffer of course. If your PC is not reading quick enough this buffer is full with two frames.

If necessary I can post my test program later today.
 
Last edited:
You could also send a "ack" from Python when it received a packet. On the Teensy, wait with sending more data until it receives the ack.
 
Idea:

Since you're using linux - can't you just use stty and write the serial output to a file? then in python you would just read the file.
 
Try this in a terminal:
(stty raw; cat > received.log) < /dev/ttyACM0

With a added "&" at the end of the line you can run it in the background.

I started my virtual box ubuntu and tried it. I creates a nice file.. i guess you can run the above from Python or a shell script. Then, just read the file?
For your "realtime".. yes i guess can read it while it gets written.

I'm in no way a linux expert and had too google ... :)

Or, write a short minimal program in C that does the same.
 
Last edited:
Using TyCommander as SerMon code below sends perfectly displayed data from a T_3.2:
Code:
T:\tCode\Serial\SerSpeed\SerSpeed.ino Aug  2 2021 01:32:23
starting with Serial.availableForWrite() 64
0	abcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyz
1	abcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyz
2	abcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyz
...
9997	abcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyz
9998	abcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyz
9999	abcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyz

1358890 bytes printed in 1557001 microseconds
DONE with Serial.availableForWrite() 59

Given a 'snippet' not working code - and wanting to see the results:
Code:
void setup() {
  Serial.begin(115200);
  while (!Serial && millis() < 4000 );
  Serial.println("\n" __FILE__ " " __DATE__ " " __TIME__);
}

char databuffer[4096];
void loop() {
  if ( Serial.available() ) {
    while ( Serial.available() ) Serial.read();
    char *pc = databuffer;
    Serial.printf( "starting with Serial.availableForWrite() %u\n", Serial.availableForWrite() );
    int n;
    for (n = 0; n < 130; n++ ) {
      pc[n] = 'a' + n % 26;
    }
    pc[n++] = '\n';
    pc[n++] = 0;

    uint32_t cnt = 0;
    uint32_t prTime = micros();
    for (n = 0; n < 10000; n++ ) {
      cnt += Serial.print( n );
      cnt += Serial.print( "\t" );
      cnt += Serial.print( databuffer );
      [B]if ( 0 && Serial.availableForWrite() < 132 ) {[/B]
        cnt += Serial.print( "\tFLUSH ...\n" );
        [B]Serial.flush();[/B]
      }
    }
    prTime = micros() - prTime;
    Serial.printf( "\n%lu bytes printed in %lu microseconds\n", cnt, prTime);
    delay(4);
    Serial.printf( "DONE with Serial.availableForWrite() %u", Serial.availableForWrite() );
  }
}

Moved code to a T_4.1 and caught this glitch without the FLUSH:
Code:
6512	abcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyz
6513	abcdefghijklmnopqrstuvwxyzavwxyzabcdefghijklmnopqrstuvwxyz
6521	abcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyz

Removed the ( 0 && ... ) and it takes a longer - but data shows no obvious skips:
Code:
1468395 bytes printed in 520108 microseconds
DONE with Serial.availableForWrite() 6144


@Paul - on T_4.1 the utility of these functions seems suspect - TyCommander on code above doesn't always complete printing?
> And it is no better on IDE:Teensy_ports

Code:
      if ( [B][U]Serial.availableForWrite()[/U][/B] < 132 ) {
        [B][U]Serial.flush()[/U][/B];
> with this version of 'if' replaced above for T_4.1
 
@Tim, tried that.. i don't see a glitch using the serial monitor.

Odd - I didn't see it 'halt before 9999' the first couple times I ran it ... maybe the port is getting tired :)
> scanning 9999 lines is not fast/fun :(

Both TyComm and IDE:teensy_ports? : and as noted that is with FLUSH - skipped line glitch was with no flush().

This is a new i7-10700 and should be fast enough - interesting if you can't see failure ... Zzzzz's ...
 
@DrM As mentioned in #2 you have a bug in your teensy code. It is important to understand that USB has a perfectly working flow control built in. AFAIK, if the serial buffers in the PC overflow, the host stops polling for more data. Teensy knows of this and tries for 120ms to send the data. After this it gives up and the print/write functions return without sending or with sending only a part of the requested bytes. All those functions inform you about this 'problem' by returning the actual number of sent bytes. If this is not the number you requested it to send you will need to resend the missing parts otherwise they are lost.

Since it is not unusual that a PC pauses for more than 120ms you need to either increase the waiting time or (better) take the paused transmission into account:

Here a version of your sketch which works for me (used tripple serial to have the control and debug channel separated from the data channel)

Code:
#include "Arduino.h"

Stream& dbg = SerialUSB2;
Stream& ctrl = SerialUSB1;

constexpr size_t frameSize = 4096;
uint8_t frame[frameSize];
elapsedMillis stopwatch;

void setup()
{
    pinMode(LED_BUILTIN, OUTPUT);

    // fill buffer
    for (unsigned n = 0; n < frameSize; n++)
    {
        frame[n] = 'a' + n % 26;
    }  
}

void loop()
{
    if (ctrl.available() > 0)  // check for start command
    {
        switch (ctrl.read())
        {
            case 'v':
                dbg.println("start");

                for (unsigned n = 0; n < 100; n++)                             // write 100 frames
                {
                    size_t written = 0;
                    while (written != frameSize)                               // need to account for blocked usb transmission (pc busy, buffer too small etc)
                    {                        
                         written += Serial.write(frame + written, frameSize - written);
                    }
                    dbg.printf("#:%d w: %d\n", n, written);
                }

            default:
                break;
        };
    }

    if (stopwatch > 100)
    {
        digitalToggleFast(LED_BUILTIN);
        stopwatch -= 100;
    }
}

And here the corresponding python

Code:
import serial

ser = serial.Serial( 'COM50')
ctrl = serial.Serial( 'COM48')

ctrl.write('v'.encode() )

n = 0
while True:
    rawbuf = ser.read(  4096)
    print( 'read', n, len(rawbuf) )
    n += 1
    if n > 10:
       break

Which prints:
Code:
read 0 4096
read 1 4096
read 2 4096
read 3 4096
read 4 4096
read 5 4096
read 6 4096
read 7 4096
read 8 4096
read 9 4096
read 10 4096

Regarding the experiments with various terminals: They are probably using a much larger serial buffer which will greatly reduce the problem. I understood that DrM has no possibiltiy to increase the default buffer from within python... Anyway, fixing the bug is the better solution anyway.
 
Last edited:
Regarding the experiments with various terminals: They are probably using a much larger serial buffer which will greatly reduce the problem. I understood that DrM has no possibiltiy to increase the default buffer from within python... Anyway, fixing the bug is the better solution anyway.

Maybe they have larger buffers, maybe they are just faster. Since he refused to do any control (or, at least did not respond so far) (as he needs" realtime" whatever this means) the only way is to make the receiver better / faster.
 
Last edited:
In this case you need to fix the bug in the sender, i.e. you must not ignore the fact that the Teensy didn't send the complete buffer...
 
Yes, it does not send it because the other end does not read fast enough, or there are other devices (with a ´hub) that block ... anyhow, just let's see if your solution is acceptable for him! -
And if he can reach 150kb/s with usb 12 Mbit/s (Teensy 3.2) (which is a problem only if the teensy has to wait too long)
Would be good, if yes.
If not: -> No python.
 
@luni @frankb @degragster (and of course, @Paul)

The point of the snippet was to show that it hangs. After that, you cannot send the remaining part of the buffer.

So why does Luni's example not hang? There are three differences.

a) It is running on Windows, not Linux

b) He uses three ports, not one

c) He uses each port in one direction only


That means it is a bug, Maybe it is on the host side, maybe it is in pyserial, but we cannot say from these two examples. How does Paul do it?


P/S @Luni, that is a nice design, I like the use of three ports, and perhaps I should have done that from the beginning. But, I was going for simplicity for users, and I sometimes have three of these connected at one time.

I do know about retrieving the number of bytes and sending the remainder until finished. I omitted it because, as noted above, it is not relevant to the fact that it hangs.
 
@luni @frankb @degragster (and of course, @Paul)


I just tried Luni's code on Linux, it works great.


So, using multiple ports works on both platforms. Using one port fails on both platforms.


Is hanging while using one port, not a bug?
 
- you don't need the debug channel - you can try a single channel version.

Have you ever tried Luni's version if it "hangs" (see below) with one port?

Where should it hang? Python is just too slow and misses the most data, in your version. That's not hanging. :)
 
@FrankB

What you are saying is not making sense to me. Take a look, he has three channels; recv from ctrl, send through serial, and send through dbg. And in fact, Python keeps up very very well in that arrangement.

I think you meant to write if you remove ctrl and dbg channel, and use serial for send and receive?

If you do that, then quite obviously, his implementation is the same as mine (apart from the re-send, which has zero to do with the problem). And I'll go out on a limb here and predict that whenever you use one port bidirectionally, it will not be reliable.
 
@WMXZ line 95,


Code:
written += Serial.write(frame + written, frameSize - written);



Come'on guys, lets focus. The failure scenario is clearly single port, bi-directional, commands down, data up.
 
apart from the re-send, which has zero to do with the problem...

...which actually is the root cause for your problem. As wrote a couple of times now you can not expect that Serial.write(buf, bufsize) will always send out the complete buffer to the bus. USB will stop requesting bytes if its internal buffer is full and Teensy will abort the operation 120ms later. If you don't resend the missing bytes you will end up with less bytes sent to the bus.

Quick check. Increase the framesize to 100'000 and remove the the spinning:
Code:
for (unsigned n = 0; n < 100; n++)                             // write 100 frames
{
     size_t written = 0;
    [B][COLOR="#FF0000"] // while (written != frameSize)                               // need to account for blocked usb transmission (pc busy, buffer too small etc)
      // {[/COLOR][/B]
             written += Serial.write(frame + written, frameSize - written);
     [COLOR="#FF0000"][B] // }[/B][/COLOR]
      dbg.printf("#:%d w: %d\n", n, written);
                }

and don't read in your python script:

Code:
import serial

ser = serial.Serial( 'COM50',timeout=1)
ctrl = serial.Serial( 'COM48')

ctrl.write('v'.encode() )

[B][COLOR="#FF0000"]exit[/COLOR][/B]

n = 0
while True:
    rawbuf = ser.read(  100)
    print( 'read', n, len(rawbuf) )
    n += 1
    if n > 99:     
       ser.read(4096)
       break

I get the following output on the debug channel:

Code:
start
#:0 w: 30720
#:1 w: 0
#:2 w: 0
#:3 w: 0
#:4 w: 0
#:5 w: 0
#:6 w: 0
#:7 w: 0
#:8 w: 0
#:9 w: 0
#:10 w: 0
#:11 w: 0
#:12 w: 0
#:13 w: 0
#:14 w: 0
#:15 w: 0
#:16 w: 0
#:17 w: 0
#:18 w: 0
#:19 w: 0
#:20 w: 0
#:21 w: 0
#:22 w: 0
#:23 w: 0
#:24 w: 0
#:25 w: 0
#:26 w: 0

Showing that 30720 bytes from the first 100000 bytes where sent to the bus which obviously filled the buffers (Teensy + PC). After that the USB stopped receiving and Teensy stopped trying. From then on each and every send trial failed.

If you want to reliably send data to USB you need to take care of this.
 
In your version wasn't the "written +=" , and this is what makes the difference. Not the debug channel, not the control channel...
 
@DrM,
I saw my error and removed my post, but is Serial not equal to SerialUSB1 according to Serial.h?
 
@Luni No Luni, it hangs. As shown in the original post. You cannot resend if it has hung. You are focusing on an unrelated issue, and one that I am well practiced in from the time micro-computers were invented. I left it out because it is the hang that I am focusing on.


@FrankB no that absolutely does not make the difference. It takes a few extra ops, not significant.
 
Would you mind adding the spinning to your original code and see if it still hangs?
 
@Luni Listen Luni, your multi-port code is wondeful, and it seems to work robustly. And in fact, I added a resend counter. It has not ever gone back to pick up an unsent piece. And that is what is expected given Paul's discussion about how it works, and your description of the 120 ms time out, which is a fantastically long time for something like this..
 
Status
Not open for further replies.
Back
Top