Teensy 4.0 Serial.available() stops incrementing

[defragster]

That looks pretty much wonderful/good - using the now current updated github\cores - at least to above sketch - updated below. So the change updates the count on each 512 packet - which moves above sketch along its test for three unique reports. Then when in the while(read) it gets all those and more. That is the .available() only goes up 512 per loop() - but when running the read it gets them all - though before while (Serial.available()) {read()} .available() is still 1536 when 11,200 are read - assuming those were held up behind the three buffers and arrived during read?

Works well on trivial stuff under 512 in groups - and upwards.
Here are smaller working cases - removed the force read on large size.
Also added [diff] numbers to show the math of incoming bytes difference between the three steps it checks for:

T:\tCode\T4\SerAvailTest\SerAvailTest.ino Dec  1 2019 01:13:07

Waiting for three incoming Avail update counts 

Update to incoming Avail counts 145[145] : 0[0] : 0
Update to incoming Avail counts 290[145] : 145[145] : 0
	Got three incoming Avail update counts 435[145] : 290[145] : 145		Bytes read 435
Update to incoming Avail counts 289[289] : 0[0] : 0
Update to incoming Avail counts 578[289] : 289[289] : 0
	Got three incoming Avail update counts 867[289] : 578[289] : 289		Bytes read 867
Update to incoming Avail counts 289[289] : 0[0] : 0
Update to incoming Avail counts 578[289] : 289[289] : 0
	Got three incoming Avail update counts 867[289] : 578[289] : 289		Bytes read 867
Update to incoming Avail counts 433[433] : 0[0] : 0
Update to incoming Avail counts 866[433] : 433[433] : 0
	Got three incoming Avail update counts 1299[433] : 866[433] : 433		Bytes read 1299
Update to incoming Avail counts 512[512] : 0[0] : 0
Update to incoming Avail counts 577[65] : 512[512] : 0
	Got three incoming Avail update counts 1089[512] : 577[65] : 512		Bytes read 1154
Update to incoming Avail counts 512[512] : 0[0] : 0
Update to incoming Avail counts 577[65] : 512[512] : 0
	Got three incoming Avail update counts 1089[512] : 577[65] : 512		Bytes read 1154
Update to incoming Avail counts 512[512] : 0[0] : 0
Update to incoming Avail counts 577[65] : 512[512] : 0
Waiting for three incoming Avail update counts 577 : 577 : 512
	Got three incoming Avail update counts 578[1] : 577[65] : 512		Bytes read 578
Update to incoming Avail counts 4[4] : 0[0] : 0
Update to incoming Avail counts 11[7] : 4[4] : 0
	Got three incoming Avail update counts 21[10] : 11[7] : 4		Bytes read 21

Thought I saw an anomoly on the 11,200 byte file - but doesn't repro now - maybe user error.
Works to read as noted below files of : 2800 Bytes and 5600 and 11,200 byte file ( as sent by TyCommander ).

Update to incoming Avail counts 1[1] : 0[0] : 0
Update to incoming Avail counts 2[1] : 1[1] : 0
	Got three incoming Avail update counts 3[1] : 2[1] : 1		Bytes read 3
Update to incoming Avail counts 512[512] : 0[0] : 0
Update to incoming Avail counts 1024[512] : 512[512] : 0
	Got three incoming Avail update counts 1536[512] : 1024[512] : 512		Bytes read 11200
Update to incoming Avail counts 512[512] : 0[0] : 0
Update to incoming Avail counts 1024[512] : 512[512] : 0
	Got three incoming Avail update counts 1536[512] : 1024[512] : 512		Bytes read 11200
Update to incoming Avail counts 512[512] : 0[0] : 0
Update to incoming Avail counts 1024[512] : 512[512] : 0
	Got three incoming Avail update counts 1536[512] : 1024[512] : 512		Bytes read 11200
Update to incoming Avail counts 512[512] : 0[0] : 0
Update to incoming Avail counts 1024[512] : 512[512] : 0
	Got three incoming Avail update counts 1536[512] : 1024[512] : 512		Bytes read 11200
Update to incoming Avail counts 512[512] : 0[0] : 0
Update to incoming Avail counts 1024[512] : 512[512] : 0
	Got three incoming Avail update counts 1536[512] : 1024[512] : 512		Bytes read 2800
Update to incoming Avail counts 512[512] : 0[0] : 0
Update to incoming Avail counts 1024[512] : 512[512] : 0
	Got three incoming Avail update counts 1536[512] : 1024[512] : 512		Bytes read 5600
Update to incoming Avail counts 512[512] : 0[0] : 0
Update to incoming Avail counts 1024[512] : 512[512] : 0
	Got three incoming Avail update counts 1536[512] : 1024[512] : 512		Bytes read 11200

In case it is useful - or starting point for another test here is the current code that made the above:

void setup() {
	// put your setup code here, to run once:
	Serial.begin(115200);
	while (!Serial && millis() < 4000 );
	Serial.println("\n" __FILE__ " " __DATE__ " " __TIME__);
	Serial.printf( "\nWaiting for three incoming Avail update counts \n\n" );
}

int lastAvail = 0;
int lastAvail2 = 0;
elapsedMillis someWait;
void loop() {
	int myAvail = Serial.available();
	if ( (myAvail != lastAvail && lastAvail != lastAvail2 && 0 != lastAvail2 ) )
	{
		int ii = 0;
		Serial.printf( "\tGot three incoming Avail update counts %u[%u] : %u[%u] : %u", myAvail, myAvail-lastAvail, lastAvail, lastAvail-lastAvail2, lastAvail2 );
		while (Serial.available())
		{
			Serial.read();
			ii++;
		}
		Serial.printf( "\t\tBytes read %u\n", ii);
		lastAvail2 = lastAvail = 0;
	}
	else if ( myAvail != lastAvail )
	{
		someWait = 0;
		Serial.printf( "Update to incoming Avail counts %u[%u] : %u[%u] : %u\n", myAvail, myAvail-lastAvail, lastAvail, lastAvail-lastAvail2, lastAvail2 );
		lastAvail2 = lastAvail;
		lastAvail = myAvail;
	}
	else if ( someWait > 10000 ) {
		if ( myAvail ) {
			someWait = 0;
			Serial.printf( "Waiting for three incoming Avail update counts %u : %u : %u\n", myAvail, lastAvail, lastAvail2 );
		}
	}
}

[PaulStoffregen]

So the change updates the count on each 512 packet - which moves above sketch along its test for three unique reports. Then when in the while(read) it gets all those and more. That is the .available() only goes up 512 per loop() - but when running the read it gets them all - though before while (Serial.available()) {read()} .available() is still 1536 when 11,200 are read - assuming those were held up behind the three buffers and arrived during read?

Yes, I also saw some of this while testing. Even though we're running at 600 MHz, when the host has a large amount of data all buffered as a single transfer (all done by hardware), the 480 Mbit speed is pretty incredible. But adding even a several microseconds of delay in the main loop usually results in having all 3 packet buffers filled.

I've been wondering what we should use a default for RX_NUM. Any thoughts? Currently we're allocating 8192 bytes for transmit buffering, but only 1536 bytes for receive.

[PaulStoffregen]

Also in the new code is optimized Serial.readBytes().

void setup() {
  Serial.setTimeout(0);
}

void loop() {
  char buf[2048];
  unsigned int n = Serial.available();
  if (n > 0) {
    if (n > sizeof(buf)) n = sizeof(buf);
    Serial.printf("n = %u\n", n);
    Serial.readBytes(buf, n);
    Serial.write(buf, n);
    Serial.println();
  }
  //delayMicroseconds(200);
}

[defragster]

I was wondering about readBytes - (and any other class parts?) - especially when the .available() didn't match the while(read) count.

Yes, I also saw some of this while testing. Even though we're running at 600 MHz, when the host has a large amount of data all buffered as a single transfer (all done by hardware), the 480 Mbit speed is pretty incredible. But adding even a several microseconds of delay in the main loop usually results in having all 3 packet buffers filled.

I've been wondering what we should use a default for RX_NUM. Any thoughts? Currently we're allocating 8192 bytes for transmit buffering, but only 1536 bytes for receive.

Seeing 600 makes me wonder about running at least this test at other speeds. Indeed 480 Mbit brings up the 'drink from a firehose' analogy.

> Did post 1.48 changes move Tx and Rx to DMA?
> Does any of this help USBHost throughput?

Not sure about Rx and Tx buffer sizes? Are they compile time alloc? Does it add much overhead to do like KurtE did for UART Serial where user can pass a buffer? Too small would seem to block/limit more - but only with high throughput in that direction.

switched to readBytes and it gets 1536 and leaves - in 3 sets of 512 to same buffer - and nothing new is received in that time - even with debug prints in loop:

		myAvail = Serial.available();
		while (Serial.available())
		{
			kk  = Serial.available();
			if ( kk > 512) kk=512;
			Serial.readBytes( someBuf, kk );
			jj+=kk;
			Serial.printf( "\navail=%u - readBytes=%u [sum=%u]", myAvail, kk, jj );
		}

This is reading the 11,200 byte file - with two 'Enter' to finish the final group {the 'read 0' is the old read() while with nothing to read}:

Update to incoming Avail counts 512[512] : 0[0] : 0
Update to incoming Avail counts 1024[512] : 512[512] : 0
	Got three incoming Avail update counts 1536[512] : 1024[512] : 512
avail=1536 - readBytes=512 [sum=512]
avail=1536 - readBytes=512 [sum=1024]
avail=1536 - readBytes=512 [sum=1536]	readBytes 1536 and read 0 where .avail() was 1536 before read loop()
Update to incoming Avail counts 512[512] : 0[0] : 0
Update to incoming Avail counts 1024[512] : 512[512] : 0
	Got three incoming Avail update counts 1536[512] : 1024[512] : 512
avail=1536 - readBytes=512 [sum=512]
avail=1536 - readBytes=512 [sum=1024]
avail=1536 - readBytes=512 [sum=1536]	readBytes 1536 and read 0 where .avail() was 1536 before read loop()
Update to incoming Avail counts 512[512] : 0[0] : 0
Update to incoming Avail counts 1024[512] : 512[512] : 0
	Got three incoming Avail update counts 1536[512] : 1024[512] : 512
avail=1536 - readBytes=512 [sum=512]
avail=1536 - readBytes=512 [sum=1024]
avail=1536 - readBytes=512 [sum=1536]	readBytes 1536 and read 0 where .avail() was 1536 before read loop()
Update to incoming Avail counts 512[512] : 0[0] : 0
Update to incoming Avail counts 1024[512] : 512[512] : 0
	Got three incoming Avail update counts 1536[512] : 1024[512] : 512
avail=1536 - readBytes=512 [sum=512]
avail=1536 - readBytes=512 [sum=1024]
avail=1536 - readBytes=512 [sum=1536]	readBytes 1536 and read 0 where .avail() was 1536 before read loop()
Update to incoming Avail counts 512[512] : 0[0] : 0
Update to incoming Avail counts 1024[512] : 512[512] : 0
	Got three incoming Avail update counts 1536[512] : 1024[512] : 512
avail=1536 - readBytes=512 [sum=512]
avail=1536 - readBytes=512 [sum=1024]
avail=1536 - readBytes=512 [sum=1536]	readBytes 1536 and read 0 where .avail() was 1536 before read loop()
Update to incoming Avail counts 512[512] : 0[0] : 0
Update to incoming Avail counts 1024[512] : 512[512] : 0
	Got three incoming Avail update counts 1536[512] : 1024[512] : 512
avail=1536 - readBytes=512 [sum=512]
avail=1536 - readBytes=512 [sum=1024]
avail=1536 - readBytes=512 [sum=1536]	readBytes 1536 and read 0 where .avail() was 1536 before read loop()
Update to incoming Avail counts 512[512] : 0[0] : 0
Update to incoming Avail counts 1024[512] : 512[512] : 0
	Got three incoming Avail update counts 1536[512] : 1024[512] : 512
avail=1536 - readBytes=512 [sum=512]
avail=1536 - readBytes=512 [sum=1024]
avail=1536 - readBytes=512 [sum=1536]	readBytes 1536 and read 0 where .avail() was 1536 before read loop()
Update to incoming Avail counts 448[448] : 0[0] : 0
Update to incoming Avail counts 449[1] : 448[448] : 0
	Got three incoming Avail update counts 450[1] : 449[1] : 448
avail=450 - readBytes=450 [sum=450]	readBytes 450 and read 0 where .avail() was 450 before read loop()

[PaulStoffregen]

@noisymime - Please give version 1.49-beta1 a try. Does is fully solve this problem for you?

[noisymime]

@noisymime - Please give version 1.49-beta1 a try. Does is fully solve this problem for you?

Thanks so much Paul. I'm away from my T4 until tomorrow, but I'll give it a crack then and report back

[noisymime]

So with the upfront disclaimer that I might be an idiot, .available() seems to be incrementing now, but it also appears to be returning a value that is twice what it should be. Using the original test sketch I posted, each time I sent a single byte through the serial monitor, the value getting returned by available() appears to go up by 2.

Are the sent/received values somehow being treated as 16-bit rather than 8-bit?

void setup() {
  // initialize serial communication at 9600 bits per second:
  Serial.begin(9600);
}

// the loop routine runs over and over again forever:
void loop() {
  Serial.println(Serial.available());
  if(Serial.available() > 10)
  {
    while(Serial.available())
    {
      Serial.read();
    }
  }
  delay(1000);        // delay in between reads for stability
}

[defragster]

Paul - used Serial.peek() for the first time and it works.

So with the upfront disclaimer that I might be an idiot, .available() seems to be incrementing now, but it also appears to be returning a value that is twice what it should be. Using the original test sketch I posted, each time I sent a single byte through the serial monitor, the value getting returned by available() appears to go up by 2.

Are the sent/received values somehow being treated as 16-bit rather than 8-bit?

No, to get SerMon to send it typically pushes what was typed follwed by "ASCII code 10 = LF ( Line feed )". So a single character send arrives as two characters. TyCommander allows that to be changed: LF, CR, or CRLF, or NONE.

If you print the numeric value of the values the ascii value 10 shows up at the end of each transfer.
Here is abc<enter> then ABC<enter> with code below:

T:\tCode\T4\SimpleSerialAscii\SimpleSerialAscii.in o Dec 4 2019 00:35:34
97==a
98==b
99==c
10==

65==A
66==B
67==C
10==

This is edit of code p#32:

void setup() {
	Serial.begin(115200);
	while (!Serial && millis() < 4000 );
	Serial.println("\n" __FILE__ " " __DATE__ " " __TIME__);
}

void loop() {
	while (Serial.available())
	{
		Serial.print( Serial.peek() );
		Serial.print( "==" );
		Serial.println( (char)Serial.read() );
	}
}

[defragster]

Paul - revisiting : PaulStoffregen/USB-Serial-Print-Speed-Test

When you get back to USB testing - maybe PJRC's IDE SerMon will work better for you than on my Win10 box. In any case this is something you might give a glance to see what you see.

For lack of time to write anything more elaborate - I decided to have that sketch read on serialEvent() and just count the Rx bytes and read in blocks of 512 to a buffer.

In adding the Rx accum count I shortened other strings to compensate - and did an sprintf() once per second ideally to not slow things down for the added overhead of Rx and counter manipulations. So the code won't compare with any old numbers - but with Rx serialEvent() and needing to show that it won't be the same.

It makes things in SerMon really UGLY quickly and not sure it is ever SENDING any chars as the Rx count doesn't go up on Send.

TyCommander does much better but shows some minor issues - had to add delays to make it a bit more stable even so - and over time it also gets dead after some much longer time

Notes:
> When serialEvent gets chars it also updates the string printed each loop - so that should show ASAP on arrive - except for buffering … it is a bit delayed as SerMon parses incoming data
> Just added PIN13 ON in serialEvent and off each second in loop
> SerMon issues may be bigger than T4 USB issues, showing 600-700+K lps, but does not SEND data at this time - no LED light after buffers fill!
> TyCommander decent and over 700K lps with this altered code
> Both on occasion show flashes of 'Garbage' chars, or Registry keys or something from the system?
> Tweaking the two delay's up drops the lps count and improves stability
> Large files can be send from TyCommander - before it gets flakey and non-Responding

This is from TyCommander - showing I sent 100 chars

count=67942104 Rx#=100, lps=793936
count=67942105 Rx#=100, lps=793936
count=67942106 Rx#=100, lps=793936
count=67942107 Rx#=100, lps=793936

Most of the added code is obvious and Bold or Red - runs normally until it receives Rx input then that number changes on incoming until wait when it is cleared.

uint32_t count, prior_count;
uint32_t prior_msec;
uint32_t count_per_second;
uint32_t jj = 0, kk = 0;

void setup() {
  Serial.begin(1000000); // edit for highest baud your board can use
  while (!Serial) ;
  count = 10000000; // starting with 8 digits gives consistent chars/line
  prior_count = count;
  count_per_second = 0;
  prior_msec = millis();
  pinMode( 13, OUTPUT );
  Serial.print("Send Serial Data to start ...");
  while ( 0 == jj ) delay(1);
}

char lBuf[100] = " ... Waiting first count ...\n";
void loop() {
  Serial.print("count=");
  Serial.print(count);
  /*Serial.print(",Rx#=");
  Serial.print(jj);
  //Serial.print(", lines/sec=");
  Serial.print(", lps=");
  Serial.println(count_per_second);
  */
  Serial.print(lBuf);
  count = count + 1;
  uint32_t msec = millis();
  if (msec - prior_msec > 1000) {
    digitalWriteFast( 13, 0);
    // when 1 second as elapsed, update the lines/sec count
    prior_msec = prior_msec + 1000;
    count_per_second = count - prior_count;
    prior_count = count;
    sprintf( lBuf, " Rx#=%lu, lps=%lu\n",  jj, count_per_second );
    kk++;
    if ( !(kk % 10) ) jj = 0; // Clear Rx Count each 10 seconds
    delay(5); // LONG DELAY for PC to catch up each second
  }
#if defined(__IMXRT1062__)
  delayNanoseconds(400); // SHORT DELAY each loop() to minimize PC hammering
#endif
}

char sBuf[512];
void serialEvent() {
  int ii = Serial.available();
  digitalWriteFast( 13, 1);
  if (ii > 512 ) ii = 512;
  Serial.readBytes( sBuf, ii );
  jj += ii;
  kk = 1; // New Chars - update string and delay Rx count zero
  sprintf( lBuf, " Rx#=%lu, lps=%lu\n",  jj, count_per_second );
}

CODE EDITED - requires INITIAL SEND to start the code running - IDE SerMon does this and a couple sends then add a couple chars - then it stops getting cycles to send?

Second EDIT:: Test on Teensy 3.6 - #if added on delaynano(). T-3.6 at 256 MHz is indeed returning similar lps as seen before:

count=13337723 Rx#=0, lps=27399
count=13337724 Rx#=0, lps=27399
count=13337725 Rx#=0, lps=27399
count=13337726 Rx#=0, lps=27399

Third and final edit pending feedback - bumping the delay segment to 6 and 600 as shown:

    delay(6); // LONG DELAY for PC to catch up each second
  }
#if defined(__IMXRT1062__)
  delayNanoseconds(600); // SHORT DELAY each loop() to minimize PC hammering
#endif

> IDE PJRC SerMon more stable close to 500K lps - but still losing the SEND trigger LED or Rx receive on T4 after buffers fill
> Those numbers make TyCommander much more stable at 650K lps and T4 hits LED in a second - but still perhaps 10-15 seconds delay in Rx=1 showing on text output.
> Though while typing TyComm did this and went 'not responding':

Upping delay to (7) and (700) to see if TyComm stays longer there - now hitting 400K lps with those delays - and delay to increment of Rx on 'Send' is only about a second - so that may be near steady state?
<>> After 15+ minutes TyComm still running at 7/700 with 600K lps now - with Send LED under 1 sec - but about 6 seconds to propagate through to TyComm display.

And those delays let t_sermon live about 30 seconds then this explodes on the screen with lps under 300K:

[defragster]

Modified the output to show a run time time measure in minutes:

51393413 1.8m Rx#=4, lps=500286
51393414 1.8m Rx#=4, lps=500286
51393415 1.8m Rx#=4, lps=500286

Moved the two delay times to #define at the top - printed for ref in setup():

#define LONG_DELAY_SEC 7000 // in delayMicroseconds
#define SHORT_DELAY_LOOP 700 // on T4 in delayNanoseconds
---
Delay times are LONG_DELAY_SEC=7000 and SHORT_DELAY_LOOP=700
Send Serial Data to start ...

> T_3.6 still shows 27K lps with altered output size.order.

> tSerMon - the same : Send fails LED trigger after a few seconds running - but T4 shows the lps counts are similar varies <200K to >600K like TyComm
-> showing a good long run this time - now over 33min! <edit:running at 50.1m>:

1102861826 29.7m Rx#=0, lps=632096
1102861827 29.7m Rx#=0, lps=632096

> TyComm - the same: occasional garbage, Send triggers LED and then Rx count Quickly at first then slows to 6 or 30 seconds to see reflected in screen data after some minutes, dies after some time - just quit at 8 mins.
-> TyComm can do multiple SerMon - the T4 lps can show like 200K until T_3.6 running same code on same HUB it will then double the reported lps to 400K ? Then turn off T_3.6 and then T4 shows 500K lps??

Minor code change/clean from p#34:

#define LONG_DELAY_SEC 7000 // in delayMicroseconds
#define SHORT_DELAY_LOOP 700 // on T4 in delayNanoseconds
uint32_t count, prior_count;
uint32_t prior_msec;
uint32_t count_per_second;
uint32_t jj = 0, kk = 0;

void setup() {
  Serial.begin(1000000); // edit for highest baud your board can use
  while (!Serial) ;
  count = 10000000; // starting with 8 digits gives consistent chars/line
  prior_count = count;
  count_per_second = 0;
  prior_msec = millis();
  pinMode( 13, OUTPUT );
  Serial.printf("\nDelay times are LONG_DELAY_SEC=%u and SHORT_DELAY_LOOP=%u", LONG_DELAY_SEC, SHORT_DELAY_LOOP );
  Serial.print("\nSend Serial Data to start ...");
  while ( 0 == jj ) delay(1);
}

char lBuf[100] = " ... Waiting first count ...\n";
//char tBuf[32] = "cnt=";
void loop() {
//  Serial.print(tBuf);
  Serial.print(count);
  Serial.print(lBuf);
  count = count + 1;
  uint32_t msec = millis();
  if (msec - prior_msec > 1000) {
    digitalWriteFast( 13, 0);
    // when 1 second as elapsed, update the lines/sec count
    prior_msec = prior_msec + 1000;
    count_per_second = count - prior_count;
    prior_count = count;
    sprintf( lBuf, " %5.1fm Rx#=%lu, lps=%lu\n",  millis() / 60000.0,  jj, count_per_second );
    kk++;
    if ( !(kk % 10) ) jj = 0; // Clear Rx Count each 10 seconds
    delayMicroseconds(LONG_DELAY_SEC); // LONG DELAY for PC to catch up each second
  }
#if defined(__IMXRT1062__)
  delayNanoseconds(SHORT_DELAY_LOOP); // SHORT DELAY each loop() to minimize PC hammering
#endif
}

char sBuf[512];
void serialEvent() {
  int ii = Serial.available();
  digitalWriteFast( 13, 1);
  if (ii > 512 ) ii = 512;
  Serial.readBytes( sBuf, ii );
  jj += ii;
  kk = 1; // New Chars - update string and delay Rx count zero
  sprintf( lBuf, " %5.1fm Rx#=%lu, lps=%lu\n",  millis() / 60000.0,  jj, count_per_second );
}

[PaulStoffregen]

When you get back to USB testing

I'm going to get back to USB stuff late tonight or early tomorrow, now that the MacOS Catalina stuff is at a good beta testing stage.

[defragster]

I'm going to get back to USB stuff late tonight or early tomorrow, now that the MacOS Catalina stuff is at a good beta testing stage.

Cool. Seeing signs of good throughput as noted above - but requires the indicated delay()'s in some fashion to have my Win10 PC keep running.

Right now with the last posted 7000/700 I have two T4's on the same HUB running for 140 [tSerMon] and 88 [TyComm] minutes - here is a screen shot grabbed earlier in case they quit - but they did not:

> You can see TyComm eating more CPU, but both about the same on allocated memory. TyComm 10% higher 'lps'

> With that sketch as noted tSerMon is unable to Send - even a NL on clicking. That isn't a T4 USB issue though. TyComm shows the Rx byte from Send in 18-20 seconds just now - and LED trigger in serialEvent within 1 sec after 74m running.

> As noted both Serial Monitors tend to flash a buffer of nonsense at times - though more so early on as if they are dumping data from prior use of the memory as a new buffer is put to use?

> Just sent a 4872 byte file with TyComm to its T4 and it showed up in Rx# after 20'ish seconds - not verified just read and ignored, but that works from the T4 point of view

<edit>:
Well TyComm died - USB LOST it was not hung - even restarting fails to reconnect. But it running and could connect because SEND is firing the LED ? It did program and restart just fine.
>> 3404672864 96.5m Rx#=0, lps=552158

And tSerMon running fine at 243 minutes showing 586K lps.

[defragster]

Paul - minor update ... Interedted to hear if you try this sketch and see similar or different behavior.

I finally stopped the tSerMon - running fine - [ except no send after the first few seconds ] - at 348 minutes. TyComm dies at 19 minutes then 119 minutes - it seemed to hang and one point then it was running again - so it may be time to reboot PC - web pages were slow to load so I turned off both T4's.

The appearance of garbage oddly appears on both SerMon's in use - seems early in the run - not sure what part has to be freshly started - it is a dump of random chars and PC data - IDE code or notes on Visual studio by name - or perhaps registry type keys - and DIR paths with my user name on. So the data is not coming from T4 data - unless the garbage data is making both Win Apps act badly.

I've not seen any other sketches or tests posted - maybe you have something good in mind - but this shows some anomalies - even with the slowdown delays - and reducing them may make them more ominous - and certainly kill the PC faster. If you can suggest any changes to make this more usable let me know. Maybe a button to toggle the delay values in the code or to pause/restart output.

If you add any useful Debug to Serial UART let me know and I can hook one up. I didn't so that is why I put the minutes in the output line, and the LED on the Rx code for some feedback.

I thought about modifying the latency or lps PC EXE test code - but they didn't seem to run any faster than SerMon - and would be more complex to replicate some of what SerMon does already and could get Win specific …

Swapping these lines puts 10 on a row with tabs between - except when serialEvent forms the string on Rx:

  count = count + 1;
  if ( !(count%10)) Serial.println();
  uint32_t msec = millis();
  if (msec - prior_msec > 1000) {
    digitalWriteFast( 13, 0);
    // when 1 second as elapsed, update the lines/sec count
    prior_msec = prior_msec + 1000;
    count_per_second = count - prior_count;
    prior_count = count;
    sprintf( lBuf, " %5.1fm Rx#=%lu, lps=%lu\t",  millis() / 60000.0,  jj, count_per_second );

That makes the scroll slower and the buffer last longer and the lps seems the same. Make the print anomalies easier to see and last longer.

[defragster]

@Paul - modified prior PC app to read 512 bytes in groups of 1,000 times - and sends each buffer back to the T4, but only prints the last buffer of the 1,000. One sign of trouble with that garbage buffer - though not parsing and better testing the data on either end.

>>> time is short - days end here ...

> Here is the trouble sign - where it mirrors what I saw in both t_sermon and TyComm - the PC code uses the same buffer over and over - so something is causing the PC to send bad data - and these were caught on sparse printing 1/1K or 1/10K:

Zip of the full output file :: foo1_garb.zip

BUF of 512 : __>> 40 ... Waiting first count ...
10269741 ... Waiting first count ...
10269742 ... Waiting first count ...
10269743 ... Waiting first count ...
10269744 ... Waiting first count ...
10269745 ... Waiting first count ...
10269746 ... Waiting first count ...
10269747 ... Waiting first count ...
10269748 ... Waiting first count ...
10269749 ... Waiting first count ...
10269750 ... Waiting first count ...
10269751 ... Waiting first count ...
10269752 ... Waiting first count ...
10269753 ... Waiting first count ...
 <<__
 ------	 elapsed time 0.067 secs for 512000 Bytes 	outer loop left 982
BUF of 512 : __>> ÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿ <<__
 ------	 elapsed time 0.061 secs for 469146 Bytes 	outer loop left 981
BUF of 512 : __>>        "id" : "",
         "path" : ""
      },
      {
         "date" : "",
         "hash" : "03FBBFC587F2D6D06B6F085F2E745EC8",
         "id" : "",
         "path" : ""
      },
      {
         "date" : "",
         "hash" : "7A907BC8A3183142266FCFF1A65A1DCB",
         "id" : "",
         "path" : ""
      },
      {
         "date" : "",
         "hash" : "AB822181ED39642F3BD3124B3735EFEB",
         "id" : "",
         "path" : ""
      },
      {
         "date" : "",
         "hash" : "11DE7AC5B18CC <<__
 ------	 elapsed time 0.058 secs for 455260 Bytes 	outer loop left 980
BUF of 512 : __>> s= 7687509, lps=311586
10323897   0.1m RxBps= 7687509, lps=311586
10323898   0.1m RxBps= 7687509, lps=311586
10323899   0.1m RxBps= 7687509, lps=311586
10323900   0.1m RxBps= 7687509, lps=311586
10323901   0.1m RxBps= 7687509, lps=311586
10323902   0.1m RxBps= 7687509, lps=311586
10323903   0.1m RxBps= 7687509, lps=311586
10323904   0.1m RxBps= 7687509, lps=311586
10323905   0.1m RxBps= 7687509, lps=311586
10323906   0.1m RxBps= 7687509, lps=311586
10323907   0.1m RxBps= 7687509, lps=311586
10323908   0.1m  <<__
 ------	 elapsed time 0.072 secs for 481619 Bytes 	outer loop left 979

And again on another run only showing buffer 1 in 10,000 reads:

10143360 ... Waiting first count ...
10143361 ... Waiti <<__
 ------	 elapsed time 0.669 secs for 5117745 Bytes 	outer loop left 999
BUF of 512 : __>> ˆ8Œ8�8”8˜8œ8*8¤8¨8¬8°8´8¸8¼8À8Ä8È8Ì8Ð8Ô8Ø8Ü8à8ä8è8ì8ð8ô8ø8ü8 <<__
 ------	 elapsed time 0.685 secs for 5102635 Bytes 	outer loop left 998
BUF of 512 : __>>  7899264, lps=233362
10397019   0.1m RxBps= 7899264, lps=233362

Notes: on the good/expected output:
> this looks like 45 chars per line - so shifting lines in 512 buffer
> the RxBps is number of Bytes read per sec in serialEvent - oddly it only accounts for 10 to 24 bytes of the 44 coming back - just did more read in serialEvent
> Turning off the T4 leaves the code running some time with PC feeding backed up USB data
> TaskMan shows running ~6% CPU IIRC for the PC EXE
> the elapsed time is for the group of 1,000 or 10,000 and shows the bytes read in that time
> Modified the ser_test.ino to do newline on each print as shown
> Removed the two delays so the ser_test.ino is running full speed.
> The PC code on reading the buffer writes those bytes back to the T4. The Rx# is the bytes received in the last second, reset when lps is calc'd
> I didn't test without doing the PC USB send to T4.

Here are two of the BEST lps counts early (after 60 iterations of 10K) for groups of 10,000 USB 512 byte reads and it is only getting 7.38 Rx bytes per line:

BUF of 512 : __>> 6m RxBps= 9035776, lps=1224273
39387169   0.6m RxBps= 9035776, lps=1224273
39387170   0.6m RxBps= 9035776, lps=1224273
39387171   0.6m RxBps= 9035776, lps=1224273
39387172   0.6m RxBps= 9035776, lps=1224273
39387173   0.6m RxBps= 9035776, lps=1224273
39387174   0.6m RxBps= 9035776, lps=1224273
39387175   0.6m RxBps= 9035776, lps=1224273
39387176   0.6m RxBps= 9035776, lps=1224273
39387177   0.6m RxBps= 9035776, lps=1224273
39387178   0.6m RxBps= 9035776, lps=1224273
39387179   0.6m RxBps= 9035776, lps=12242 <<__
 ------	 elapsed time 0.555 secs for 5120000 Bytes 	outer loop left 940
BUF of 512 : __>>   0.6m RxBps= 9035776, lps=1224273
39503760   0.6m RxBps= 9035776, lps=1224273
39503761   0.6m RxBps= 9035776, lps=1224273
39503762   0.6m RxBps= 9035776, lps=1224273
39503763   0.6m RxBps= 9035776, lps=1224273
39503764   0.6m RxBps= 9035776, lps=1224273
39503765   0.6m RxBps= 9035776, lps=1224273
39503766   0.6m RxBps= 9035776, lps=1224273
39503767   0.6m RxBps= 9035776, lps=1224273
39503768   0.6m RxBps= 9035776, lps=1224273
39503769   0.6m RxBps= 9035776, lps=1224273
39503770   0.6m RxBps= 9035776, lps=1 <<__
 ------	 elapsed time 0.552 secs for 5120000 Bytes 	outer loop left 939

At 45 bytes/line that would be 55 MB/sec sent and at 0.555 sec per 5.12 MB received that is 9,225,225 bytes per second?

Anyhow - that is what I can say so far - when you see this and see anything of interest let me know. Too late to post code or do more.

[PaulStoffregen]

If you can suggest any changes to make this more usable let me know.

While working on the teensy_serialmon.exe that's in 1.49-beta1, I did quite a bit of testing running it from a CMD window. It expects a single input on the command line, which is the port name shown in the lower right corner of the Arduino IDE.

Here's a screenshot showing how to run it.



I also used a slightly modified copy of the lines per second benchmark, which immediately stops if pin 17 is low.

uint32_t count, prior_count;
uint32_t prior_msec;
uint32_t count_per_second;

void setup() {
  pinMode(17, INPUT_PULLUP);
  Serial.begin(1000000); // edit for highest baud your board can use
  while (!Serial) ;
  count = 10000000; // starting with 8 digits gives consistent chars/line
  prior_count = count;
  count_per_second = 0;
  prior_msec = millis();
}

void loop() {
  while (digitalRead(17) == LOW) ; // stop if pin 17 low
  Serial.print("count=");
  Serial.print(count);
  Serial.print(", lines/sec=");
  Serial.println(count_per_second);
  count = count + 1;
  uint32_t msec = millis();
  if (msec - prior_msec > 1000) {
    // when 1 second as elapsed, update the lines/sec count
    prior_msec = prior_msec + 1000;
    count_per_second = count - prior_count;
    prior_count = count;
  }
}

[PaulStoffregen]

Windows CMD is slow, much slower than the Arduino Serial Monitor.

Usually when I run this, it will show an impossibly high lines/sec speed, like 600000 to 750000. But just by watching which digit of the count number is incrementing about once per seconds, it's easy to visually see the real speed is about 100000 lines/sec.

Strange things happen occasionally. Usually the count number will "catch up" by taking a huge jump all at once. Sometimes the screen will go blank for a moment. Maybe it's the same "garbage" you're seeing? Sometimes it will stall. When it does, typing any character causes it to run a bit farther, then finally lock up.

After much investigation, I'm convinced Windows has bugs in its anonymous pipes which are used for the "stdout" stream between teensy_serialmon.exe and cmd.exe (or Java powering the Arduino IDE).

Windows seems to allow a pretty incredible amount of buffering of data "inside" the anonymous pipe. You can see this with a pushbutton or switch connected between pin 17 and GND. When the ground pin 17, you'll see data continue printing for quite some time. Inside teensy_serialmon.exe is a fixed-size 1 megabyte buffer, which is only able to hold about 30000 lines, well under 50 ms of buffering at these speeds. If you watch with Windows Task Manager, you'll see the total memory used by teensy_serialmon.exe is only 2 megabytes and remains constant. Sometimes when you ground pin 17, it will keep printing for several seconds. Just 3 seconds at this speed mean ~60 megabytes is getting buffered *somewhere*. You can also see cmd.exe allocates very little memory. A huge buffer is being used somewhere, but it's not in the process space of either program.

My best guess is Windows doesn't really expect those hidden buffers to get so large, and when they do "bad things" happen. I did track down the problem to fwrite(data, 1, n, stdout) returning an integer claiming it transmitted data, but nothing actually comes out of the other end of the pipe at cmd.exe or Arduino. Using fflush() has no effect. I tried WIN32 WriteFile with the handle from GetStdHandle(STD_OUTPUT_HANDLE), but it does exactly the same thing. The value returned by the 4th param claims the data was written to the pipe, but clearly something is going wrong after the WIN32 function call.

The Windows documentation says writing to the pipe is supposed to block if the other side isn't reading fast enough. But clearly that is not what's actually happening in this case.

Unfortunately, Windows provides almost no functionality with anonymous pipes. You can't even use WIN32 overlapped / async I/O. I haven't found any way to control or limit or even affect the buffering between teensy_serialmon.exe and cmd.exe.

I've considered trying named pipes, which do provide much more functionality. But as nearly as I can tell, named pipes aren't supported at all by Java on Windows.

So basically, I'm completely stuck. If Windows will just keep buffering more and more data and won't block when it can't successfully buffer more data between the 2 ends of the pipe, I just don't know what I can do to work around it.

[PaulStoffregen]

The urgent question right now is whether the USB code on the Teensy side is working properly. With the recent tests on issue #401, and many tests I did before this week's MacOS Catalina work, and with every indication these buffering issues are a problem happening inside Windows, I'm leaning towards moving forward with porting this USB serial code to USB MIDI and the other missing USB types.

Longer-term, I do want to make the serial monitor on Windows able to sustain 700000 or more lines/sec speed. But that's a separate and lower priority project. Right now, the big question is whether the USB serial code is working well enough to start that work on the non-serial USB types?

[KurtE]

From what I have seen, I think the USB Serial is working well, and it makes sense to start including some of the non-serial USB types.

[mjs513]

I will second that sentiment @KurtE.

[defragster]

Odd things noted above - using sketch with no delays posted below.

Not sure if any of this is T4 related - but all make at this this Win_10 PC an unreliable test bed::

> I see garbage spew on GUI[Teensy_sermon] and TyCommander and the PC Echo ser_test.exe
- same with teensy_serialmon.exe usb:0/140000/0/4/7

> when lps test running GUI[t_sermon] unable to Send characters

> Running [teensy_serialmon.exe usb:0/140000/0/4/7] for a couple minutes, I turned off T4 a minute or so ago and data still spewing forth at 787615 lps
- I wasn't expecting that so didn't have a timer running but I called my wife at 9:10 am and it is still catching spew showing 3.2m runtime and counting
--> finally stopped at 9:20 am showing run stopped at 3.4m

> Turned T4 back on with teensy_serialmon.exe usb:0/140000/0/4/7 still active and this flashed by - and many pages more before stopping:

10838553   0.0m RxBps=       0, lps=451934
10838554   0.0m RxBps=       0, lps=451934
10838555   0.0m RxBps=       0, lps=451934
10838556   0.0m RxBps=       0, lps=451934
10838557   0.0m RxBps=       0, lps=451934
10838558   0.0m RxBps=       0, lps=451934
10838559   0.0m RxBps=       0, lps=451934
10838560   0.0m RxBps=       0, lps=451934
10838561   0.0m RxBps=       0, lps=451934
10838562   0.0m RxBps=       0, lps=451934
10838563   0.0m RxBps=       0, lps=451934
10838564   0.0m RxBps=       0, lps=451934
10838565   0.0m RxBps=       0, lps=451934
 08385" "   / >
                 < P C I I n f o   d e v i c e I D = " 9 C B A "   v e n d o r I D = " 8 0 8 6 "   s u b D e v i c e I D = " "   s u b V e n d o r I D = " "   / >
                 < P C I I n f o   d e v i c e I D = " 9 C B D "   v e n d o r I D = " 8 0 8 6 "   s u b D e v i c e I D = " "   s u b V e n d o r I D = " "   / >
                 < P C I I n f o   d e v i c e I D = " 9 D 3 A "   v e n d o r I D = " 8 0 8 6 "   s u b D e v i c e I D = " "   s u b V e n d o r I D = " "   / >
                 < P C I I n f o   d e v i c e I D = " 9 D 3 A "   v e n d o r I D = " 8 0 8 6 "   s u b D e v i c e I D = " 0 7 5 B "   s u b V e n d o r I D = " 1 0 2 8 "   / >
                 < P C I I n f o   d e v i c e I D = " 9 D 3 A "   v e n d o r I D = " 8 0 8 6 "   s u b D e v i c e I D = " 0 8 2 A "   s u b V e n d o r I D = " 1 0 2 8 "   / >
                 < P C I I n f o   d e v i c e I D = " 9 D 3 D "   v e n d o r I D = " 8 0 8 6 "   s u b D e v i c e I D = " "   s u b V e n d o r I D = " "   / >
                 < P C I I n f o   d e v i c e I D = " 9 D 3 D "   v e n d o r I D = " 8 0 8 6 "   s u b D e v i c e I D = " 0 7 5 B "   s u b V e n d o r I D = " 1 0 2 8 "   / >
                 < P C I I n f o   d e v i c e I D = " 9 D 3 D "   v e n d o r I D = " 8 0 8 6 "   s u b D e v i c e I D = " 0 8 2 A "   s u b V e n d o r I D = " 1 0 2 8 "   / >
                 < P C I I n f o   d e v i c e I D = " 9 D E 0 "   v e n d o r I D = " 8 0 8 6 "   s u b D e v i c e I D = " "   s u b V e n d o r I D = " "   / >
                 < P C I I n f o   d e v i c e I D = " 9 D E 3 "   v e n d o r I D = " 8 0 8 6 "   s u b D e v i c e I D = " "   s u b V e n d o r I D = " "   / >
                 < P C I I n f o   d e v i c e I D = " 9 D F 0 "   v e n d o r I D = " 8 0 8 6 "   s u b D e v i c e I D = " "   s u b V e n d o r I D = " "   / >
                 < P C I I n f o   d e v i c e I D = " A 0 F 0 "   v e n d o r I D = " 8 0 8 6 "   s u b D e v i c e I D = " "   s u b V e n d o r I D = " "   / >
                 < P C I I n f o   d e v i c e I D = " A 1 3 A "   v e n d o r I D = " 8 0 8 6 "   s u b D e v i c e I D = " "   s u b V e n d o r I D = " "   / >
                 < P C I I n f o   d e v i c e I D = " A 1 3 D "   v e n d o r I D = " 8 0 8 6 "   s u b D e v i c e I D = " "   s u b V e n d o r I D = " "   / >
                 < P C I I n f o   d e v i c e I D = " A 1 B A "   v e n d o r I D = " 8 0 8 6 "   s u b D e v i c e I D = " "   s u b V e n d o r I D = " "   / >
                 < P C I I n f o   d e v i c e I D = " A 1 B D "   v e n d o r I D = " 8 0 8 6 "   s u b D e v i c e I D = " "   s u b V e n d o r I D = " "   / >
                 < P C I I n f o   d e v i c e I D = " A 2 3 A "   v e n d o r I D = " 8 0 8 6 "   s u b D e v i c e I D = " "   s u b V e n d o r I D = " "   / >
                 < P C I I n f o   d e v i c e I D = " A 2 3 D "   v e n d o r I D = " 8 0 8 6 "   s u b D e v i c e I D = " "   s u b V e n d o r I D = " "   / >
                 < P C I I n f o   d e v i c e I D = " A 2 B A "   v e n d o r I D = " 8 0 8 6 "   s u b D e v i c e I D = " "   s u b V e n d o r I D = " "   / >
                 < P C I I n f o   d e v i c e I D = " A 2 B D "   v e n d o r I D = " 8 0 8 6 "   s u b D e v i c e I D = " "   s u b V e n d o r I D = " "   / >
                 < P C I I n f o   d e v i c e I D = " A 2 E 0 "   v e n d o r I D = " 8 0 8 6 "   s u b D e v i c e I D = " "   s u b V e n d o r I D = " "   / >
                 < P C I I n f o   d e v i c e I D = " A 2 E 3 "   v e n d o r I D = " 8 0 8 6 "   s u b D e v i c e I D = " "   s u b V e n d o r I D = " "   / >
                 < P C I I n f o   d e v i c e I D = " A 3 6 0 "   v e n d o r I D = " 8 0 8 6 "   s u b D e v i c e I D = " "   s u b V e n d o r I D = " "   / >
                 < P C I I n f o   d e v i c e I D = " A 3 6 3 "   v e n d o r I D = " 8 0 8 6 "   s u b D e v i c e I D = " "   s u b V e n d o r I D = " "   / >
                 < P C I I n f o           5▄F°**        É≡∞}Ç**                       g ê Ç  Lj├ó▒¿**
       Φ]▀ó▒¿**            Ç****■**  ▄╔ßó▒¿**         áßó▒¿**  └ó▒¿** P* ∞ü
                                                                           ***  **■**  Ç`,ä┼**               ╕≥∞}Ç**       ìe╠F°**U╜.ú▒¿**g╕u╞
  
   ***?α      Aâ**Å  ì   É∞}Ç**¿èG°**¿èG°**¿èG°**▌.╠F°** ≥∞}Ç**e?╠F°**               **■**
S╠F°**¿èG°**╕≥∞}Ç**                *?Ç╨⌡**Ç=ä┼** ≥∞}Ç**0h╨áAâ**  ⌡            
⌡
   X
        φ}Ç** É∞}Ç**0h╨áAâ**0h╨áAâ**                Ç=ä┼**        ¿èG°**
                 ä┼** ░             @■∞}Ç**                Ç`,ä┼**
           Ç**    ä┼**  └F°**Ç =ä┼** G°**  └F°** `½ `σ ¿èG°** ⌡∞}Ç**        ê╖(î¿***⌡    ¿*∞}Ç**└*∞}Ç**¿èG°** ñG°**   @ â**  ***                                  °⌠∞}Ç**       ìe╠F°**x┬.ú▒¿**á╦F°**  ***  **■**  Ç`,ä┼**               H⌡∞}Ç**       ìe╠F°**Ö·1ú▒¿** + + S 
    α          Å  ì   É∞}Ç**¿èG°**¿èG°**¿èG°**▌.╠F°**É⌠∞}Ç**
                      **■**
S╠F°**¿èG°**H⌡∞}Ç**                                
       5cP      
Y            
   X
        φ}Ç** É∞}Ç**                                                ¿èG°**
                      ░             @■∞}Ç**                Ç`,î¿**        ¿*∞}Ç**└*∞}Ç**¿èG°**                                                                                                                                Ç`,ä┼** `·î¿**Éó?ä┼**┌å├F°**  Ç   + + S +   
       α▀-î¿**#       P       
       L       `║┴î¿**        Gapl    `╡▀    H┤▀    Ç╡▀    8≤▀    xⁿö             0` î¿**K├ó▒¿**                ********Ç£     *******─#t▄°      **0F?î¿**~
H   Ç      Ça,ä┼** πΘΣâ┼**ÇqöX █**╚       @éòX █**Ç`,ä┼**ÇqöX █**∩å▄F°***┐¢╜∩$  
       ~
H          Ça,ä┼** πΘΣâ┼**ÇqöX █**─       @éòX █**Ç`,ä┼**ÇqöX █**∩å▄F°***┐¢╜∩$  
            █**                                fé▄F°**                                                                                                                                                                        Ñ▐├F°**                P ░                     Γ╟├F°**0⌡]î¿**#       P       
       L       É▓┴î¿**        Gapl     
  î¿**╫^─F°**@  î¿***       É·∞}Ç**        0` î¿**K├ó▒¿**                
      T∞╡F°*ε      
       Ç`,ä┼**
î¿**                        f«─F°**       
       ÇækX █**òδ╡F°**                     á√∞}Ç** ·∞}Ç**       ****
      ÷***                                                                                                                                                                                                     qöX █**g*÷o**Ç`╕ ä┼**    î¿** ⁿ∞}Ç**▀┴ó▒¿**   
           *                       ║q├ó▒¿**                
       ≡a╕ ä┼**
                       ÇqöX █**≡a╕ ä┼**Ç`╕ ä┼**Ç`╕ ä┼**╙î─F°**ÇqöX █**"  Ç°**
       HΦ╡F°**≡┌⌐ä┼**É┌⌐ä┼**Yⁿ∞}Ç**HΦ╡F°**
       1;┬ó▒¿**αô▀ä┼**Çûÿ     Éτ 
            αô▀ä┼**Çûÿ             └      2       d                     └      °ⁿö     Éτ 
             ≡┌⌐ä┼**        ─e┬ó▒¿**`kö     ┐H┬ó▒¿**        Éτ 
                    ─                                       ÿd┬ó▒¿**      ì üH°**  █≤B**°ⁿö     `kö     t:5ú▒¿**▄ÿ    p■∞}Ç**Hnù|Ç**Hnù|Ç**ÇqöX █**                        
       úà─F°**@nù|Ç**
       @nù|Ç**¿■∞}Ç**        ░■∞}Ç       ╕■∞}Ç**        └■∞}Ç**╨mù|Ç**                       ╨mù|Ç**        @*∞}Ç**ryJ°**╨mù|Ç**@*∞}Ç**░▀            F      
     ╨mù|Ç**         ,│ä┼**                                ,│ä┼**                X-│ä┼** ,│ä┼**        ¢1J°** ,│ä┼**░,│ä┼**                                 ,│ä┼**                        ≡Zù|Ç**«M▄F°**╨*∞}Ç**[ù|Ç**ÇPo⌠â┼**
       ¬LU╚  lM▄F°**3       00Jÿ***   Ç**░$╠I°**á   Ç**
   Ç**   °**    ä┼**               ╕Φ∞}Ç**PΦ∞}Ç**└Φ∞}Ç**HM╛ä┼**σP╟I°**░$╠I°**á    ÿ**Ö2╒I°**PΦ∞}Ç**                *   ä┼**░$╠I°**á              
▀┐≥â┼**
   Ç**                                     ÿ**HM╛ä┼**HM╛ä┼**       ╡╫I°**    ä┼**áΘéä┼**                                                                     ÿ**┴┐≥â┼**ΦM╛ä┼**        XN╛ä┼***í╟I°**                P▀┐≥â┼**Åj├F°**á∩∞}Ç**
       á∩∞}Ç**               ÿ∩∞}Ç**     σ∞}Ç**#}─F°**XN╛ä┼**        áΘéä┼**|£╟I°** ∞∞}Ç**ê∞∞}Ç**Çæ\X █**        Çæ\X █**                *í╟I°**        ≈∙╞F°**P▀┐≥â┼**Åj├F°** æ\X █**Ç`,ä┼**                        `OH_╒c**        ░▀┐≥â┼**P∞∞}Ç**¿εéä┼**           ä┼**   
  ****                  
      0u√
ÿ**                │τ∞}Ç**áp√
ÿ**áp√                     Y&╟F°**α╣j
ÿ**áp√
ÿ** *              ╨τ∞}Ç**        
   ä┼**êµ∞}Ç**    Ç**         «╫I°** Φ∞}Ç** Θéä┼***           
  
        Φ∞}Ç**░δ∞}Ç**êµ∞}Ç**╕δ∞}Ç**ñδ∞}Ç**        ╨τ∞}Ç**áp√
ÿ**≡µ∞}Ç**                            ****                        ╒eÇò**     ╕δ∞}Ç**
      áp√
ÿ**                0Φ∞}Ç******    W╟F°**                αä┼** Ü╫I°**
                  ⁿO**áêTG°**    Ç**
       ╕δ∞}Ç**░δ∞}Ç**ñδ∞}Ç**                 Φ∞}Ç**╨τ∞}Ç**│τ∞}Ç**                 
 
        
°**                                                                "  └                                                        Ç******    ,Θ∞}Ç**ÿ**
       ñδ∞}Ç**
              D╟F°** α≈ä┼** ─MH°**0α≈ä┼**
       
          Ç**
δ∞}Ç**áêTG°**
Θéä┼**╕δ∞}ÿ**        pÇvä┼**pÇvä┼**Çæ\X █**                                úà─F°**hÇvä┼**        hÇvä┼**úà─F°** Çvä┼**        hÇvä┼**úà─F°**        ╕╠4ú▒¿** εéä┼**                              ╢┤╧F°**       `≥∞}Ç**        P≥∞}Ç** ñG°**  ⌡     ñG°**╨r"     
       
        çu ö**       Ç      :¢┴F°**        
   °**        Çæ\X █**                 
   
                 0┤G°**                                Çz
  â**aS ö** çu ö**        ╨r"     @       
       lm┴F°**╨r"            
                                                   ò**0≈∞}Ç**    @   
    â**Ç=ä┼**  ÿ**         ñG°**aS ö**g╕u╞
                          Çz
  â**                                g╕u╞
    ⌡    ╨r"                     ⌡╦F°**                                                                                                                               -'   
     UeÇò**
                               ⌡╦F°**                                                                                                                                        g╕u╞

        ≤∞}Ç**                        ⌡╦F°**                                                                                                                                
       g╕A

       (≤∞}Ç**                                                                        ╦╢F°**                                ≡c╝┬≡
                  Ç                               ≡c╝┬≡
                  Ç                               ≡c╝┬≡
                  Ç                               ≡c╝┬≡
                  Ç                               ≡c╝┬≡
                  Ç       É@*┴≡
  É@*┴≡
          ≡c╝┬≡
                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                  G+┴≡
                                 ≡c╝┬≡
                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                          pΩèä┼**                                        
M╛ä┼**`εéä┼**ÿ**        Ç`,ä┼**Ωèä┼**zj├F°**                        0u├F°**Ωèä┼**                pΩèä┼**                        {╔G°**                0 ßä┼**0 ßä┼** ßä┼**S╒I°** ßä┼**                                pΩèä┼**             ÿ**        Ç`,ä┼**Ωèä┼**zj├F°**                        0u├F°**Ωèä┼**                pΩèä┼**                        {╔G°**                0Çÿ ä┼**0Çÿ ä┼**Çÿ ä┼**S╒I°**Çÿ ä┼**            Ç******    ▀┐≥â┼**ûàHP0τKÿc■├P╬ì╒-eÇÿ**o÷╔F°**                      HM╛ä┼**        
                                       
╪     ÷╔F°**             ÿ**        Ç`,ä┼**Ωèä┼**zj├F°**                        0u├F°**Ωèä┼**                pΩèä┼**                     ÿ**o÷╔F°**                  »**HM╛ä┼**        Éh2»**    »**                        
╪     ÷╔F°**             ÿ**        Ç`,ä┼**Ωèä┼**zj├F°**                        0u├F°**Ωèä┼**                pΩèä┼**                     ÿ**╕Φ∞}Ç**                                                                                                                                                                                                                                                                                P4+┴≡
  ROM ContentGroup WHERE _WorkId>0 AND _WorkId<>0;

Current Ser_test.ino in use:

uint32_t count, prior_count;
uint32_t prior_msec;
uint32_t count_per_second;
uint32_t rx_per_second;
uint32_t jj = 0, kk = 0;

void setup() {
  Serial.begin(1000000); // edit for highest baud your board can use
  while (!Serial) ;
  count = 10000000; // starting with 8 digits gives consistent chars/line
  prior_count = count;
  count_per_second = 0;
  rx_per_second = 0;
  prior_msec = millis();
  pinMode( 13, OUTPUT );
  Serial.print("\nSend Serial Data to start ...");
  while ( 0 == jj ) delay(1);
}

char lBuf[100] = " ... Waiting first count ...\n";
//char tBuf[32] = "cnt=";
void loop() {
//  Serial.print(tBuf);
  Serial.print(count);
  Serial.print(lBuf);
  count = count + 1;
  uint32_t msec = millis();
  if (msec - prior_msec > 1000) {
    digitalWriteFast( 13, 0);
    // when 1 second as elapsed, update the lines/sec count
    prior_msec = prior_msec + 1000;
    count_per_second = count - prior_count;
    prior_count = count;
    rx_per_second = jj;
    sprintf( lBuf, " %5.1fm RxBps=%8lu, lps=%lu\n",  millis() / 60000.0,  rx_per_second, count_per_second );
    kk++;
    jj = 0; // Clear Rx Count each X? seconds
  }
}

char sBuf[512];
void serialEvent() {
  int ii;
  digitalWriteFast( 13, 1);
  while ( (ii = Serial.available() ) ) {
    if (ii > 512 ) ii = 512;
    Serial.readBytes( sBuf, ii );
    jj += ii;
  }
}

[defragster]

Doing this :: T:\arduino_1.8.10\hardware\tools>teensy_serialmon. exe usb:0/140000/0/1 > seeme.txt

The created file this way doesn't seem to show the printed corrupt messages in a couple of tries. Also hitting ENTER does flash LED as it runs, when not redirected to a file the CMDline t_sermon would also not get characters out.

It does seem the T4 is working, would be interested to hear if running above sketch shows similar for others.

Only suggestion: Is there an easy way to have the T4 USB Engine limit output rate and block above 600K lps where that might be 25 MB/sec?

--- final test
I plugged in T4 for 1 minute to :: T:\arduino_1.8.10\hardware\tools>teensy_serialmon. exe usb:0/140000/0/1 > seeme.txt
Unplugged T4 and Screen noted : Disconnect COM3
18 seconds later SublimeText saw the file close/changed
The file is reported as :: 1.97 GB (2,118,688,448 bytes) and shows 48,233,645 lines of 43 chars + '\n' { quick scroll shows the file to be PERFECT }
>> for 60 seconds that would be : 35311474 bytes per second

AND:: this nearly matches "lps=820760" for the 44 char lines at 36113440 chars per second, but 60 seconds output took 78 seconds to write. That is an overage factor of 1.3 suggesting it might keep up with 630K lps.

[defragster]

Windows CMD is slow, much slower than the Arduino Serial Monitor.

Usually when I run this, it will show an impossibly high lines/sec speed, like 600000 to 750000. But just by watching which digit of the count number is incrementing about once per seconds, it's easy to visually see the real speed is about 100000 lines/sec.

Strange things happen occasionally. Usually the count number will "catch up" by taking a huge jump all at once. Sometimes the screen will go blank for a moment. Maybe it's the same "garbage" you're seeing? Sometimes it will stall. When it does, typing any character causes it to run a bit farther, then finally lock up.

After much investigation, I'm convinced Windows has bugs in its anonymous pipes which are used for the "stdout" stream between teensy_serialmon.exe and cmd.exe (or Java powering the Arduino IDE).

Windows seems to allow a pretty incredible amount of buffering of data "inside" the anonymous pipe. You can see this with a pushbutton or switch connected between pin 17 and GND. When the ground pin 17, you'll see data continue printing for quite some time. Inside teensy_serialmon.exe is a fixed-size 1 megabyte buffer, which is only able to hold about 30000 lines, well under 50 ms of buffering at these speeds. If you watch with Windows Task Manager, you'll see the total memory used by teensy_serialmon.exe is only 2 megabytes and remains constant. Sometimes when you ground pin 17, it will keep printing for several seconds. Just 3 seconds at this speed mean ~60 megabytes is getting buffered *somewhere*. You can also see cmd.exe allocates very little memory. A huge buffer is being used somewhere, but it's not in the process space of either program.

My best guess is Windows doesn't really expect those hidden buffers to get so large, and when they do "bad things" happen. I did track down the problem to fwrite(data, 1, n, stdout) returning an integer claiming it transmitted data, but nothing actually comes out of the other end of the pipe at cmd.exe or Arduino. Using fflush() has no effect. I tried WIN32 WriteFile with the handle from GetStdHandle(STD_OUTPUT_HANDLE), but it does exactly the same thing. The value returned by the 4th param claims the data was written to the pipe, but clearly something is going wrong after the WIN32 function call.

The Windows documentation says writing to the pipe is supposed to block if the other side isn't reading fast enough. But clearly that is not what's actually happening in this case.

Unfortunately, Windows provides almost no functionality with anonymous pipes. You can't even use WIN32 overlapped / async I/O. I haven't found any way to control or limit or even affect the buffering between teensy_serialmon.exe and cmd.exe.

I've considered trying named pipes, which do provide much more functionality. But as nearly as I can tell, named pipes aren't supported at all by Java on Windows.

So basically, I'm completely stuck. If Windows will just keep buffering more and more data and won't block when it can't successfully buffer more data between the 2 ends of the pipe, I just don't know what I can do to work around it.

Indeed Win CMD output is slow - that is why I was doing the 1,000 batches before printing even one buffer. Though doing 10K batches did not run any faster - likely the minimal code overhead to clean and check receive buffer.

Looking at the seeme.txt file in the last post where that last line was #48233645 here are first and last 3 lines of the file

Delay times are LONG_DELAY_SEC=70 and SHORT_DELAY_LOOP=7
Send Serial Data to start ...10000000 ... Waiting first count ...
10000001   0.1m RxBps=       2, lps=1
 // ...
58234489   1.0m RxBps=       0, lps=817343
58234490   1.0m RxBps=       0, lps=817343
58234491   1.0m RxBp

where it starts at count = 10000000 that shows a discrepancy of 846 lines captured in the file at 800K lps.

[PaulStoffregen]

Sure does look like a bug in Windows, maybe even a buffer overflow, judging by the sudden appearance of stuff about PCI bus devices in what looks like 16 bit wchar format that Windows uses internally. That data sure didn't come from firmware on Teensy! (where we use utf8 or just plain ascii) I wonder if any security research folks will find this thread and turn it into something more "interesting"?

Regarding limiting the output rate, Teensy is already doing this the way USB is supposed to work. Serial.write() on the Teensy side waits if all the USB buffers are full. They only become empty after the USB hardware indicates they've been transferred to the PC. The PC is only supposed to do the transfers when it can accept more data into its buffers.

I'm saving a link to this thread as a lower priority bug. For now, I'm concentrating on the USB code on Teensy. Later I'll revisit this. But that's probably going to be a "large" project if we have to switch from anonymous pipes (the way Windows implements stdout, stdin, stderr) to named pipes, localhost networking, or some sort of Windows specific interprocess communication.

[defragster]

Sure does look like a bug in Windows, maybe even a buffer overflow, judging by the sudden appearance of stuff about PCI bus devices in what looks like 16 bit wchar format that Windows uses internally. That data sure didn't come from firmware on Teensy! (where we use utf8 or just plain ascii) I wonder if any security research folks will find this thread and turn it into something more "interesting"?

Regarding limiting the output rate, Teensy is already doing this the way USB is supposed to work. Serial.write() on the Teensy side waits if all the USB buffers are full. They only become empty after the USB hardware indicates they've been transferred to the PC. The PC is only supposed to do the transfers when it can accept more data into its buffers.

I'm saving a link to this thread as a lower priority bug. For now, I'm concentrating on the USB code on Teensy. Later I'll revisit this. But that's probably going to be a "large" project if we have to switch from anonymous pipes (the way Windows implements stdout, stdin, stderr) to named pipes, localhost networking, or some sort of Windows specific interprocess communication.

Indeed, sounds like a Win issue - the few cmdline t_sermon dumps were garbage free output to file - it was good to see that finally.

Security:: for sure some of the dumps of garbage could have been who knows what for data in what was visible - and those unprintable data blocks could be the real treasure.

Given that the

only GUI_t_sermon issue is the failure to send when the incoming is keeping Screen Text and buffer juggling busy. Also CMDline fails to send when output is to display instead of a file, going to file it works.

Last Number thing:: given the 'count = count + 1;' per loop that means the T4 that can normally run 7-20 million loop()'s per second is indeed being limited 'by PC full buffers' to about 800K loop() per second with that Serial.print()'ing.

One last note {to the topic of this thread}: my PC app {and that sketch} was really made to also test T4 Rx - using serialEvent() - and That seems to be working at least in transferring bytes to be counted if not viewed - without breaking anything - or even slowing it down. But the SerMon garbage appears even when nothing is sent to the T4, so given the issue with transfer speed on Windows - have to assume the USB Rx is working properly. I should rewrite it so the T4 just echo's back what the PC sends instead of the way it is.