Teensyduino 1.56 Beta #1

Status
Not open for further replies.
I have serveral logfiles of several Megabytes of "RAM Dumps"....
Saw the Redmond certifacte, too, tons of javascript, and contents of background programs where I didn't know that they run... "Epic games launcher".. lol..

Have modified the code to print and log to file.

Not sure If I want to post the program...
Can send it to you, Paul, or Tim..

Most of the time it starts silent. Helps to start a Defender Virius-Scan and to start random programs.
After a while (can take minutes!) it starts printing huge amounts of data. Megabytes.

Code:
SubCA0♂♠♥U↔☼♦♦♥☻0☼♠♥U↔‼♦♣0♥0▼♠♥U↔#♦↑0▬¶V\bh=[↑0V♠♥U↔▼♦O0M0KIGEhttp://crl.microsoft.com/pki/crl/products/MicRooCerAut_2010-06-23.crl0Z+♠♣♣♦N0L0J+♠♣♣♂♣♥☻¶|qQyn9><R☼n+?►‼shH4M♣&1Fay8.Ek(↔   →LooCerAut_2010-06-23.crt0
6fj←♦↑↨@26vZ♦▬hbTlP0X|N|sWR!s4ZV♦       ~?↔r⌂Sc=1e▬=B_T↔↔GosNA@_*◄s!(s9_>\`♥►   ⌂QfG↓↕=*h♣wLb{z4♥♫KbzJ7-W|∟=☼Z☻☻:ni!7u↓♣gW^)←9-Es[z▬↓FX^gl5?$5
u♠↑Vx,♣←►♣~,c♠#!xlX↨♠6+↕♥-@↑E\k>♥p↑*
j_Gc
26▼*pZBqKW~!<∟♫E ]b u►w}=EWo3♦wb∟Y~1§z0§v☻001♂0 ♠♥U♦♠‼☻US1‼0◄♠♥U‼
Washington1►0♫♠♥U♦‼Redmond1▲0∟♠♥U♦
        ♥1♂♠    +♠♦7    *H,♠♥U♦♥‼%Microsoft Windows Production PCA 2011☻‼3☻ey▲‼☻0
0∟♠
+♠♦7☻♂1♫0♀♠
        ♦1"♦ →v↕0l*bf∟♂'uJqP0B♠
☼JX>i↨∟BU&u'92|;F*!D(x♫%{<♣!♣/☻R<♂LztJ$♣♣ROKt*]0
=Pz↓
i'♂b>u↕0↕♠
        ►♦H♦D0@☻♠♠♂*H
+♠♦Y
♠       `He♥♦☻♣♦ ▬M;¶bPK[*{K
<NB\☻♠`←↑‼20210724072050.526Z0♦☻01♂0    ♠♥U♦♠‼☻US1‼0◄♠♥U‼
Washington1►0♫♠♥U♦‼Redmond1▲0∟♠♥U♦
‼§Microsoft Corporation1-0+♠♥U♦♂‼$Microsoft Ireland Operations Limited1&0$♠♥U♦♂‼↔Thales TSS ESN:D082-4BFD-EEBA1%0#♠♥U♦♥‼∟Microsoft Time-Stamp Servi♂♣0|1♂0 ♠♥U♦♠‼☻US1‼0◄♠♥U‼
Washington1►0♫♠♥U♦‼Redmond1▲0∟♠♥U♦
220112172827Z01♂0       ♠♥U♦♠‼☻US1‼0◄♠♥U‼ft Time-Stamp PCA 20100▲↨
Washington1►0♫♠♥U♦‼Redmond1▲0∟♠♥U♦
‼§Microsoft Corporation1-0+♠♥U♦♂‼$Microsoft Ireland Operations Limited1&0$♠♥U♦♂‼↔Thales TSS ESN:D082-4BFD-EEBA1%0#♠♥U♦♥‼∟Microsoft Time-Stamp Servi♣♥☼0    *H
☻*u~<&P♀?x]O↑C:F♫{3j03$9♦]po♀y∟ )R!(F^Y[{6aU_§r7x9▼0↓F3QZ0r♥scm♀&Ig^"obO,A1$‼7R
;A♣↕0▼♠♥U↔#♦↑0▬¶c:\1C{|F←3hZmU0V♠♥U↔▼♦O0M0KIGEhttp://crl.microsoft.com/pki/crl/products/MicTimStaPCA_2010-07-01.crl0Z+♠♣♣♦N0L0J+♠♣♣0☻>http://www.microsoft.com/pki/certs/MicTimStaPCA_2010-07-01.crt0♀♠♥U↔‼♦☻00‼♠♥U↔%♦♀0
♂♣♥Rz"}(jH

^><K→Cll%       'i3,|q1xO?♂\{♫Y ^{]q^=Kv,diFuTS▲♦T♫¶♠nR-♫W↑8☻5qh♠5agyLC.a2-CohZ8Pw∟,ve[Y↨:4↔‼[ 3↕▼vV*(▬&g!}DIsY¶~At$0♠q0♦Y♥☻☻☻
♂♣01♂0  ♠♥U♦♠‼☻US1‼0◄♠♥U‼
Washington1►0♫♠♥U♦‼Redmond1▲0∟♠♥U♦
250701214655Z0|1♂0      ♠♥U♦♠‼☻US1‼0◄♠♥U‼ft Root Certificate Authority 20100▲↨
Washington1►0♫♠♥U♦‼Redmond1▲0∟♠♥U♦
♣♥☼0    *Ht Corporation1&0$♠♥U♦♥‼↔Microsoft Time-Stamp PCA 20100"0
While this is harmless, I saw contents of my GithubDesktop software, too - and as it uses my password etc (however, did not see it) I don't want to post too much...


Could not find a way to reliable start "print garbage" so far... I guess that would be better?!?
It always takes some fiddling - like starting other programs etc.
 
I have the vague impression that network traffic helps to start or supports the effect.

After a while it starts repeating the same RAM area over and over.
Hm, I'l restart it..
Code:
[^_Enter password:  %s         *********[80D
grrrr.....
 
Last edited:
Ok, I saw contents of a mail. Enough for me...:)
I'll send the program to Tim & you.

Edit: I pretty sure now, it prints parts of files (which i.e. got read by Defender). Not so risky for passwords.. but files can be risky, too. I.e. Mails.
I saw Teensy ILI 9341 Fonts, too - have not used them for months. So it came from a file which was read by Defender. Defender is a useful too, it seems... ;-)
The bug does not even have to have anything to do with USB, or CDC or usb_ser directly.
It could be somewhere else as well, namely in the file handling of Windows. Or Heap management.


To start the program, it helps to disconnect the teensy - and reconnect - then start the program without waiting too long.
It takes the log- filename as 2nd parameter.


I think you (Tim or Paul) can report that to Microsoft now.

Have fun,
Frank
 
Last edited:
Those links seem to relate Frank - sad they made a new driver and it has that issue unresolved ... even into Windows 11.

Decided to start T_4.1 #4 since it is sitting there - it shares HUB with the one running T_sermon AFAIK. It is hitting 106 to 148 Mbps - so managing to generally keep up avg 140'ish sharing the hub/.
It that delay 1500ns it started first time like this: Slow to start and then GARBAGE then more startup wait - even after triggering a bufDump.
Closed that EXE run and restarted fine - so maybe Windows was just slow to adapt?
Code:
C:\T_Drive\tCode\pjrc_latency_test\FB_SerTest>SerialTestT.exe COM38 SZ32
Port: \\.\COM38
After start, you'll probably see some garbage. Things will normalize after a few seconds.
Waiting...Start.

X_Lines-Delta: 53959. Received: 3300000 Bytes in 179641 us = 146.96 Megabits per second
 bytes: 56
X_Lines-Delta: 99984. Received: 3300000 Bytes in 183311 us = 144.02 Megabits per second
 bytes: 56
X_Lines-Delta: 99936. Received: 3300000 Bytes in 183542 us = 143.84 Megabits per second
 bytes: 56.
Lines-Delta: 100000. Received: 3300000 Bytes in 180621 us = 146.16 Megabits per second
        stats: 100K=1 less=0 repeated 0 rmax=2000000

X_Lines-Delta: 99952. Received: 3300000 Bytes in 192548 us = 137.11 Megabits per second
 bytes: 56
X_Lines-Delta: 99952. Received: 3300000 Bytes in 181678 us = 145.31 Megabits per second
 bytes: 56.
X_Lines-Delta: 99984. Received: 3300000 Bytes in 190939 us = 138.26 Megabits per second
 bytes: 56
X_Lines-Delta: 76682. Received:  bytes: 256
X_Lines-Delta: 22933. Received: 3300000 Bytes in 189380 us = 139.40 Megabits per second
 bytes: 56
X_Lines-Delta: 99952. Received: 3300000 Bytes in 181486 us = 145.47 Megabits per second
 bytes: 56
X_Lines-Delta: 99968. Received: 3300000 Bytes in 240198 us = 109.91 Megabits per second
 bytes: 56
X_Lines-Delta: 51716. Received: 13579abcdefghijklmnopqrs bytes: 256
X_Lines-Delta: 47803. Received: 3300000 Bytes in 180667 us = 146.13 Megabits per second
 bytes: 56
X_Lines-Delta: 99984. Received: 3300000 Bytes in 192033 us = 137.48 Megabits per second
 bytes: 56......
X_Lines-Delta: 99968. Received: 3300000 Bytes in 181930 us = 145.11 Megabits per second
 bytes: 56.............
X_Lines-Delta: 97358. Received: 13579abcde▄¥hWP↕║·♂╔9^Üÿ≤┴╘è╣   ═.[j§σε¥╘▬      ô¶"ΓQ7O|Kº<♀BA╫♂)X↕≤D6,[φ☼╤°w÷ß♥<C2♠:ÿY#╤Æ77ª/σä}≥`¶|═╕w*τ▌╝╓IÄèvH:╘¿╡y∙h∟ê╦@εΦ┌O<7‼ï←δºàHΣΩ£⌡d÷^∞▌◄(Å'╡-♀┌◄@"i▄I╣╓_ò bytes: 256
X_Lines-Delta: 0. Received: ╜gíΦ☻#α#ïÅPδ─zI²!∟√√a7╣☺dî■<^☻╢Gë=☼█∟╞═|p☼▀ƒ'╗ô▄☼ ▄"Γ╝►≥K°ó6∞M4$»ⁿ(=|░∞±é∙í♦┌d┴\S^àσìM▬ⁿ«O%╖?♂]αl╜7∩@x    ░5+f⌡▲ΩI0Vë¼≤╛å3rΣ╜☺g╖≥├Kº▲☻☻å«gdUrR6φmG+σ═ñα╞Σ╢ìYpΦt▄≥╚%╡y*2Σ▀à╖v^ΦjF$úJ▒6▀o⌂ª{→░§
 bytes: 187.X_14        Bufdump of 21033472

X_Lines-Delta: 0. Received: qrstuvwxyz
 bytes: 11.X_56 Bufdump of 34185216

X_Lines-Delta: 0. Received: lmnopqrstuvwxyz
 bytes: 16.X_40 Bufdump of 1765376

X_Lines-Delta: 511. Received: 13579abcdefghijklmfghijklmnopqrstuvwxyz
 bytes: 40
X_Lines-Delta: 63. Received: 13579abcde579abcdefghijklmnopqrstuvwxyz
 bytes: 40
X_Lines-Delta: 575. Received: 13fghijklmnopqrstuvwxyz
 bytes: 24
X_Lines-Delta: 127. Received: 13579abcdenopqrstuvwxyz
 bytes: 24
X_Lines-Delta: 511. Received: 13579abcdefghijklm579abcdefghijklmnopqrstuvwxyz
 bytes: 48
X_Lines-Delta: 63. Received: 1313579abcdefghijklmnopqrstuvwxyz
 bytes: 34
X_Lines-Delta: 191. Received: defghijklmnopqrstuvwxyz
 bytes: 24
X_Lines-Delta: 191. Received: 13579abctuvwxyz
 bytes: 16
X_Lines-Delta: 191. Received: 13579abcdefghijklmnopqrsdefghijklmnopqrstuvwxyz
 bytes: 48
X_Lines-Delta: 35. Received: 13579abc579abcdefghijklmnopqrstuvwxyz
 bytes: 38
X_Lines-Delta: 62690. Received: 3300000 Bytes in 184740 us = 142.90 Megabits per second
 bytes: 56....................
X_Lines-Delta: 41496. Received: 13579abcdef13579abcdefghijklmnopqrstuvwxyz
 bytes: 43
X_Lines-Delta: 57649. Received: 3300000 Bytes in 307325 us = 85.90 Megabits per second
 bytes: 55..........
Lines-Delta: 100000. Received: 3300000 Bytes in 182274 us = 144.84 Megabits per second
..................................................
Lines-Delta: 100000. Received: 3300000 Bytes in 181088 us = 145.79 Megabits per second
....

That First core now cycling 50 to 70% kernel and then App time ( Tsermon ) filling that from 90 to 95% and peaking over.
The other two T_4.1's on front and rear direct USB ports are still showing the sam 140-145 Mbps.

There were some few errors first thing on logging in - unlike the prior night with no delay( 1.5 us ) - they showed:
Code:
stats: 100K=157801 less=7 repeated 0 rmax=2000000

and 

stats: 100K=157801 less=12 repeated 0 rmax=2000000

And while the machine was 'locked' overnight is showed only like 1 each of rmax reading under 2MB of buffer, but since then with machine awake and used off and on it shows about 50 of those in the next 135,000 sets of 100K. That suggests the priorities change on execution when not just monitor 'blank off' and instead 'WinKey + L' locked - requiring password/pin login to open.
 
@Frank B. I'm far from being any expert but reading through the two links in post #253, quoting the last entry:-

so much time has passed, and the bug has not fixed still...

actually for me i have fixed the bug as the feature...

i think the bug is related to buffers overflow in usbser.sys

so if i need to send much data i send it by blocks 4kB

MCU USB-stack is not so fast and between 4kB block the some pauses is appeared to allow usbser.sys flush or switch its buffers

Friday, May 11, 2018 7:13 AM

Curious if sending serial data in 4Kb blocks is worth playing with as a potential workaround?
 
@Frank B. I'm far from being any expert but reading through the two links in post #253, quoting the last entry:-



Curious if sending serial data in 4Kb blocks is worth playing with as a potential workaround?

Hm, I edit these lines:
Code:
#define TX_NUM   4
#define TX_SIZE  2048 /* should be a multiple of CDC_TX_SIZE */
to
Code:
#define TX_NUM   4
#define TX_SIZE  4096 /* should be a multiple of CDC_TX_SIZE */
Still garbage. But I don't know if there has to be done more than that.

Got a nice .lst this time:
Code:
abi\include\machinea:\hardware\tools\arm10\arm-none-eabi\include\sysanalog.c_default_types.h_stdint.himxrt.hpins_arduino.h/48c:e0001000 .word0xe0001000     490:20000d3c .word0x20000d3c00000494 <unused_interrupt_vector>:__disable_irq();     494:b672      cpsidiasm volatile("mrs %0, ipsr\n" : "=r" (ipsr) :: "memory");     496:f3ef 8305 mrsr3, IPSRinfo->ipsr = ipsr;     49a:4c4f      ldrr4, [pc, #316]; (5d8 <unused_interrupt_vector+0x144>)     49c:f8c4 3084 str.wr3, [r4, #132]; 0x84asm volatile("mrs %0, msp\n" : "=r" (stack) :: "memory");     4a0:f3ef 8208 mrsr2, MSPinfo->cfsr = SCB_CFSR;     4a4:f04f 23e0 mov.wr3, #3758153728; 0xe000e000p = (uint32_t *)info;     4a8:4e4c      ldrr6, [pc, #304]; (5dc <unused_interrupt_vector+0x148>)while (p < end) {     4aa:4d4d      ldrr5, [pc, #308]; (5e0 <unused_interrupt_vector+0x14c>)info->cfsr = SCB_CFSR;     4ac:f8d3 0d28 ldr.wr0, [r3, #3368]; 0xd28info->hfsr = SCB_HFSR;     4b0:f8d3 1d2c ldr.wr1, [r3, #3372]; 0xd2c     4b4:e9c4 0122 strdr0, r1, [r4, #136]; 0x88info->mmfar = SCB_MMFAR;     4b8:f8d3 1d34 ldr.wr1, [r3, #3380]; 0xd34info->bfar = SCB_BFAR;     4bc:f8d3 3d38 ldr.wr3, [r3, #3384]; 0xd38     4c0:e9c4 1324 strdr1, r3, [r4, #144]; 0x90info->ret = stack[6];     4c4:6993      ldrr3, [r2, #24]     4c6:f8c4 3098 str.wr3, [r4, #152]; 0x98info->xpsr = stack[7];     4ca:69d3      ldrr3, [r2, #28]     4cc:f8c4 309c str.wr3, [r4, #156]; 0x9cinfo->temp = tempmonGetTemp();     4d0:f000 f8a2 bl618 <tempmonGetTemp>     4d4:ed84 0a28 vstrs0, [r4, #160]; 0xa0info->time = rtc_get();     4d8:f001 f9ba bl1850 <rtc_get>info->len = sizeof(*info) / 4;     4dc:210b      movsr1, #11crc = 0xFFFFFFFF;     4de:f04f 32ff mov.wr2, #4294967295info->time = rtc_get();     4e2:f8c4 00a4 str.wr0, [r4, #164]; 0xa4info->len = sizeof(*info) / 4;     4e6:460b      movr3, r1     4e8:f8c4 1080 str.wr1, [r4, #128]; 0x80for (i=0; i < 32; i++) crc = (crc >> 1) ^ (crc & 1)*0xEDB88320;     4ec:493d      ldrr1, [pc, #244]; (5e4 <unused_interrupt_vector+0x150>)crc ^= *p++;     4ee:1d30      addsr0, r6, #4     4f0:405a      eorsr2, r3     4f2:2420      movsr4, #32for (i=0; i < 32; i++) crc = (crc >> 1) ^ (crc & 1)*0xEDB88320;     4f4:f002 0301 and.wr3, r2, #1     4f8:3c01      subsr4, #1     4fa:fb01 f303 mul.wr3, r1, r3     4fe:ea83 0252 eor.wr2, r3, r2, lsr #1     502:d1f7      bne.n4f4 <unused_interrupt_vector+0x60>while (p < end) {     504:42a8      cmpr0, r5     506:d002      beq.n50e <unused_interrupt_vector+0x7a>crc ^= *p++;     508:6873      ldrr3, [r6, #4]     50a:4606      movr6, r0     50c:e7ef      b.n4ee <unused_interrupt_vector+0x5a>info->crc = crc;     50e:4b32      ldrr3, [pc, #200]; (5d8 <unused_interrupt_vector+0x144>)     510:f8c3 20a8 str.wr2, [r3, #168]; 0xa8static inline void arm_dcache_flush_delete(void *addr, uint32_t size){uint32_t location = (uint32_t)addr & 0xFFFFFFE0;uint32_t end_addr = (uint32_t)addr + size;asm volatile("": : :"memory");asm("dsb");     514:f3bf 8f4f dsbsydo {SCB_CACHE_DCCIMVAC = location;     518:f04f 23e0 mov.wr3, #3758153728; 0xe000e000     51c:492f      ldrr1, [pc, #188]; (5dc <unused_interrupt_vector+0x148>)     51e:4a32      ldrr2, [pc, #200]; (5e8 <unused_interrupt_vector+0x154>)     520:f8c3 1f70 str.wr1, [r3, #3952]; 0xf70     524:f8c3 2f70 str.wr2, [r3, #3952]; 0xf70location += 32;} wh
 
I'm very sure it will work to just use libUSB. However this needs winUSB as driver on the PC - Not USBser. But Teensy wouldn't be a serial device anymore, for Windows.
 
p#259 was a post about install of 1.56b2 - with some notes at the moment. That has had some evolution - but not much in past days ... WIP ...

posted this summary on other Serial thread : Serial-write-xmit-dropping-data
Code:
On the 1.56b1 thread the serial issue testing has ongoing testing results posted.

Indeed Windows (on this machine) can receive at rates over 400 or 500 Mbps as suggested by T_4.1 send rate below.  Just saw this on starting the Windows side 'c' code .EXE:
[CODE]
X_Lines-Delta: 33835. Received: 3800000 Bytes in 60426 us = [B]503.09 Mbps[/B]
Lines-Delta: 100096. Received: 3800000 Bytes in 134677 us = 225.73 Mbps
        stats: 100K=1 less=0 repeated 0 rmax=2000000
..................................................
Lines-Delta: 100096. Received: 3800000 Bytes in 229703 us = 132.34 Mbps
.............^C
Code:
X_Lines-Delta: 37628. Received: 3800000 Bytes in 65136 us = [B]466.72 Mbps[/B]
 bytes: 40.
Lines-Delta: 100096. Received: 3800000 Bytes in 135698 us = 224.03 Mbps

That is two starts of the EXE - the High rates are before the 'c' synchronizes to the data transmission - flowing IN PROGRESS from the T_4.1. The "X_" says the buffer was not parsed for a complete set of 100,096 packets between those strings reporting the "Mbps".

The transmission blocks are each 3.8 MB and then without delay the T_4.1 repeats that and measures the transmit time per block of the 100,096 packets.

Once the 'c' code starts parsing the data it slows and backs the data up in Windows buffers. The 'c' code has a 2MB read buffer and reads are usually all returning 2MB - so it is not keeping up with the incoming data stream even at the 224 Mbps rate.
>> Posted on the Beta 1 thread - the T_4.1 can add significant delay before the 'c' code sees a drop in its ability to keep up with the incoming data. Adding a 50ms delay during send block still comes in over 200 Mbps, making that delay 150ms slowed incoming data to 140 Mbps with transmit time of 180 ms
-> this suggests that Windows is telling the T_4.1 to slow the send by a similar amount once it has filled as much buffered data as it is prepared to.

Adding code to: while ( 2MB read ) { 'read request 2MB', discard, sum the amount read } // Note a single console 'c' print in that loop slows the read rate enough to extend the loop as the buffered data refills!
>> The extent of that Windows buffering is 50MB to over 100MB using that while() to measure!
>> Once data backs up to that magnitude buffers received can be garbled or even system garbage data - but it can work for 24 hours at a steady stream of 220 Mbps with few or no errors, but it is working on buffered data that is maybe 7 seconds old.[/CODE]
 
Updated 'Test2' with 9 digit HEX serialized output : github.com/Defragster/cdcbench

Use serialtest2.c and serialtest2.ino
> The INO prints a '9 char' HEX serialized set of messages - it was hard to not slow it down - so hacked the string and unrolled ???
> that makes the 100,000 loop print out 100,096 times now
> Speed doesn't seem to have dropped - and now fixed length output with 9 HEX counter bytes.
> Format of string is 38 bytes + new_line like : 1EAB80600<<<>>>___[[[]]]---{{{}}}___!
> It can be changed with edit beyond Ser# to : #define FILL_STRING "<<<>>>___[[[]]]---{{{}}}___!\n"

Running some time here in Dual Serial mode:
Code:
count=394640992	Send sec =7874.47
 >> Call by USB==1 or USB1==2 :: 2
Mb/sec 100 up to 110 = 19
Mb/sec 110 up to 120 = 88
Mb/sec 120 up to 130 = 121
Mb/sec 130 up to 140 = 178
Mb/sec 140 up to 150 = 280
Mb/sec 150 up to 160 = 410
Mb/sec 160 up to 170 = 485
Mb/sec 170 up to 180 = 574
Mb/sec 180 up to 190 = 575
Mb/sec 190 up to 200 = 501
Mb/sec 200 up to 210 = 422
Mb/sec 210 up to 220 = 704
Mb/sec 220 up to 230 = 22009
Mb/sec 230 up to 240 = 22805
Mb/sec 240 up to 250 = 7962
Mb/sec 250 up to 260 = 710
Mb/sec 260 up to 270 = 13
Mb/sec 450 up to 460 = 1
Bogus Speed calcs = 5225

If the "serialtest2.exe" is built run it like:
Code:
serialtest2.exe COM7
or (given the default string of 38 + \n)
serialtest2.exe COM7 SZ38
[QUOTE]..................................................
Lines-Delta: 100096. Received: 3803648 Bytes in 132606 us = 229.47 Mbps
        stats: 100K=57401 less=36 repeated 0 rmax=2000000[/QUOTE]
or
serialtest2.exe COM7 SZ38 Q
[QUOTE]        3803648 Bytes in 138478 us = 219.74 Mbps
        3803648 Bytes in 143543 us = 211.99 Mbps[/QUOTE]

or ( shows each line since SZ37 doesn't exclude actual SZ38 )
serialtest2.exe COM7 SZ37 Q
[QUOTE]
        1C4316E47<<<>>>___[[[]]]---{{{}}}___!
        1C4316E48<<<>>>___[[[]]]---{{{}}}___!
        1C4316E49<<<>>>___[[[]]]---{{{}}}___!
        1C4316E4A<<<>>>___[[[]]]---{{{}}}___!
        1C4316E4B<<<>>>___[[[]]]---{{{}}}___![/QUOTE]

OR - instead of running against the serialtest2.exe, run against a SerMon - who knows what you'll get ... this is TyCommander:
Code:
1EB50A916<<<>>>___[[[]]]---{{{}}}___!
1EB50A917<<<>>>___[[[]]]
...
1EAB805FF<<<>>>___[[[]]]---{{{}}}___!
3803648 Bytes in 32816 us = 927.27 Mbps
1EAB80600<<<>>>___[[[]]]---{{{}}}___!
...
1EB33BCFF<<<>>>___[[[]]]---{{{}}}___!
3803648 Bytes in 88483 us = 343.90 Mbps
1EB33BD00<<<>>>___[[[]]]---{{{}}}___!
...

>> There was lots of unprintable stuff that won't copy out.

Teensy Serial seems to be doing well:
Code:
3F80DB1FE<<<>>>___[[[]]]---{{{}}}___!
3F80DB1FF<<<>>>___[[[]]]---{{{}}}___!
3803648 Bytes in 47314 us = 643.13 Mbps
3F80DB200<<<>>>___[[[]]]---{{{}}}___!
3F80DB201<<<>>>___[[[]]]---{{{}}}___!
3F80DB202<<<>>>___[[[]]]---{{{}}}___!
3F80DB203<<<>>>___[[[]]]---{{{}}}___!
3F80DB204<<<>>>___[[[]]]---{{{}}}___!
3F80DB205<<<>>>___[[[]]]---{{{}}}___!
3F80DB206<<<>>>___[[[]]]---{{{}}}___!
3F80DB207<<<>>>___[[[]]]---{{{}}}___!
3F80DB208<<<>>>___[[[]]]---{{{}}}___!
3F80DB209<<<>>>___[[[]]]---{{{}}}___!
3F80DB20A<<<>>>___[[[]]]---{{{}}}___!
3F80DB20B<<<>>>___[[[]]]---{{{}}}___!
3F80DB20C<<<>>>___[[[]]]---{{{}}}___!
3F80DB20D<<<>>>___[[[]]]---{{{}}}___!
3F80DB20E<<<>>>___[[[]]]---{{{}}}___!
3F80DB20F<<<>>>___[[[]]]---{{{}}}___!
3F80DB210<<<>>>___[[[]]]---{{{}}}___!
3F80DB211<<<>>>___[[[]]]---{{{}}}___!
...
40D1EBEFE<<<>>>___[[[]]]---{{{}}}___!
40D1EBEFF<<<>>>___[[[]]]---{{{}}}___!
3803648 Bytes in 131252 us = 231.84 Mbps
40D1EBF00<<<>>>___[[[]]]---{{{}}}___!
40D1EBF01<<<>>>___[[[]]]---{{{}}}___!
40D1EBF02<<<>>>___[[[]]]---{{{}}}___!
>> Got that turning off Autoscroll - it then went badly usable for some time after GARBAGE SPEW - printed some good - then garbage and not usable so closed ... after a long wait ...

After that Dual Serial gives this - which doesn't show all the high numbers above? Noting over 490 recorded:
>> Maybe the INO MATH is bad and those fell into the 'Bogus Speed calcs'
- > Used the original FLOAT
Code:
count=1172691805	Send sec =10843.00
 >> Call by USB==1 or USB1==2 :: 2
Mb/sec 80 up to 90 = 1
Mb/sec 90 up to 100 = 2
Mb/sec 100 up to 110 = 25
Mb/sec 110 up to 120 = 93
Mb/sec 120 up to 130 = 133
Mb/sec 130 up to 140 = 204
Mb/sec 140 up to 150 = 297
Mb/sec 150 up to 160 = 428
Mb/sec 160 up to 170 = 495
Mb/sec 170 up to 180 = 608
Mb/sec 180 up to 190 = 607
Mb/sec 190 up to 200 = 529
Mb/sec 200 up to 210 = 601
Mb/sec 210 up to 220 = 1401
Mb/sec 220 up to 230 = 22173
Mb/sec 230 up to 240 = 22817
Mb/sec 240 up to 250 = 7964
Mb/sec 250 up to 260 = 711
Mb/sec 260 up to 270 = 16
Mb/sec 270 up to 280 = 1
Mb/sec 280 up to 290 = 3
Mb/sec 290 up to 300 = 3
Mb/sec 300 up to 310 = 1
Mb/sec 310 up to 320 = 1
Mb/sec 320 up to 330 = 1
Mb/sec 340 up to 350 = 4
Mb/sec 350 up to 360 = 2
Mb/sec 360 up to 370 = 1
Mb/sec 370 up to 380 = 2
Mb/sec 380 up to 390 = 1
Mb/sec 390 up to 400 = 1
Mb/sec 440 up to 450 = 2
Mb/sec 450 up to 460 = 1
Mb/sec 460 up to 470 = 2
Mb/sec 480 up to 490 = 1
Bogus Speed calcs = 128318
 
Updated 'Test2' with 9 digit HEX serialized output : github.com/Defragster/cdcbench
...

NOTE: Running Dual Serial with LOW OUTPUT (for the Rate table) on request should not have any effect on primary Serial output. TyComm is used to get that on 'Send'.

Updated - the BOGUS number was because the stats collection array wan't large enough to capture the calculated numbers as written:
> the 1340 to 1350 numbers are before the EXE is connected to a free running T_4.1 when nobody is pulling the data.
> That number goes up again when the EXE is close - 'supposing' that is when Teensy is discarding overflow data when the PC stops receiving it?
Code:
count=23069853	Send sec =464.51
 >> Call by USB==1 or USB1==2 :: 2
Mb/sec 90 up to 100 = 5
Mb/sec 100 up to 110 = 9
Mb/sec 110 up to 120 = 15
Mb/sec 120 up to 130 = 7
Mb/sec 130 up to 140 = 16
Mb/sec 140 up to 150 = 12
Mb/sec 150 up to 160 = 28
Mb/sec 160 up to 170 = 39
Mb/sec 170 up to 180 = 42
Mb/sec 180 up to 190 = 31
Mb/sec 190 up to 200 = 64
Mb/sec 200 up to 210 = 917
Mb/sec 210 up to 220 = 1468
Mb/sec 220 up to 230 = 342
Mb/sec 230 up to 240 = 31
Mb/sec 240 up to 250 = 2
[B]Mb/sec 1340 up to 1350 = 659
Bogus Speed calcs = 0[/B]

Starting the EXE "SerialTest2 COM7 SZ38" more quickly after upload doesn't get those - but backlog has started "X_Lines-Delta" and results in WASTE data between good runs of data - before clear buffer prints are registered:
Code:
        X_Lines-Delta: 52600 ::40 bytes Received:    5E76B0<<<>>>___[[[]]]-----{{{}}}___!

        X_Lines-Delta: 15156 ::41 bytes Received: 3803648 Bytes in 144565 us = 210.49 Mbps

        X_Lines-Delta: 37524 ::58 bytes Received:    5F4494<<<>>>___[[[]]]--4A2<<<>>>___[[[]]]---{{{}}}___!

        X_Lines-Delta: 52021 ::169 bytes Received:   WH╪↔éè_╕↓%]▐╤E≥☺öè°¬mm╕+Nïñ╜≈ò5V2?¬*█E≡ú╘3¡⌐P/╬l6╨0«♀∙dç}ûÆ'╠╒@ßfÅ╗8╒Iτ<á╩↑£↨£9)▬¢ v╣I▬Æ╙♦↔▲1£╚·≤pßÜ┴ß╖σ]▓îéG*ê¶è├♫┬°╦≡º):M≡ΩêèH¬↑éAz

        X_Lines-Delta: 0 ::76 bytes Received: **ùL{‼§Ñq♦╫↔°1╝_ßKÄm'<g%⌂IU5;E?[+╬♂↓â╕%‼▐¥û<Öà☼■↨▄é╣╔yÜ|^9♂╓{w5
.X_37
LONG SKIP of 256: .X_15.X_58
        X_Lines-Delta: 52640 ::40 bytes Received:    61AFF1<<<>>>___[[[]]]---{{{}}}_____!

        X_Lines-Delta: 4083 ::41 bytes Received: 3803648 Bytes in 148753 us = 204.56 Mbps
.
[B]Lines-Delta: 100096. Received: 3803648 Bytes in 155539 us = 195.64 Mbps[/B]
        stats: 100K=1 less=0 repeated 0 rmax=2000000

        X_Lines-Delta: 1048 ::20 bytes Received:    634B--{{{}}}___!

        X_Lines-Delta: 52641 ::40 bytes Received:    6418C7<<<><>>>___[[[]]]---{{{}}}___!

        X_Lines-Delta: 46365 ::41 bytes Received: 3803648 Bytes in 150100 us = 202.73 Mbps

        X_Lines-Delta: 6261 ::40 bytes Received:    64E675<<<>>>_>___[[[]]]---{{{}}}___!

        X_Lines-Delta: 93807 ::41 bytes Received: 3803648 Bytes in 149975 us = 202.90 Mbps
..................................................
[B]Lines-Delta: 100096. Received: 3803648 Bytes in 150650 us = 201.99 Mbps[/B]

USING Teensy_SerialMon against the SerialTest2.INO shows a lower average reception rate - and those HIGH numbers {Mb/sec 1340 up to 1350 = 12819} are likely lost data?
Code:
count=151165	Send sec =8.51
 >> Call by USB==1 or USB1==2 :: 2
Mb/sec 20 up to 30 = 1
Mb/sec 40 up to 50 = 3
Mb/sec 50 up to 60 = 1
Mb/sec 60 up to 70 = 1
Mb/sec 70 up to 80 = 1
Mb/sec 1340 up to 1350 = 17
Bogus Speed calcs = 0

count=177344	Send sec =12.71
 >> Call by USB==1 or USB1==2 :: 2
Mb/sec 20 up to 30 = 2
Mb/sec 30 up to 40 = 3
Mb/sec 40 up to 50 = 3
Mb/sec 50 up to 60 = 1
Mb/sec 60 up to 70 = 1
Mb/sec 70 up to 80 = 1
Mb/sec 1340 up to 1350 = 17
Bogus Speed calcs = 0

count=342991	Send sec =18.48
 >> Call by USB==1 or USB1==2 :: 2
Mb/sec 20 up to 30 = 3
Mb/sec 30 up to 40 = 5
Mb/sec 40 up to 50 = 5
Mb/sec 50 up to 60 = 2
Mb/sec 60 up to 70 = 1
Mb/sec 70 up to 80 = 1
Mb/sec 1340 up to 1350 = 37
Bogus Speed calcs = 0

count=601002	Send sec =26.39
 >> Call by USB==1 or USB1==2 :: 2
Mb/sec 20 up to 30 = 3
Mb/sec 30 up to 40 = 10
Mb/sec 40 up to 50 = 6
Mb/sec 50 up to 60 = 2
Mb/sec 60 up to 70 = 1
Mb/sec 70 up to 80 = 1
Mb/sec 100 up to 110 = 1
Mb/sec 170 up to 180 = 4
Mb/sec 180 up to 190 = 9
Mb/sec 190 up to 200 = 1
Mb/sec 200 up to 210 = 1
Mb/sec 740 up to 750 = 1
Mb/sec 1220 up to 1230 = 1
Mb/sec 1340 up to 1350 = 55
Bogus Speed calcs = 0

count=1457648	Send sec =32.62
 >> Call by USB==1 or USB1==2 :: 2
Mb/sec 20 up to 30 = 3
Mb/sec 30 up to 40 = 10
Mb/sec 40 up to 50 = 6
Mb/sec 50 up to 60 = 2
Mb/sec 60 up to 70 = 1
Mb/sec 70 up to 80 = 1
Mb/sec 100 up to 110 = 1
Mb/sec 130 up to 140 = 1
Mb/sec 140 up to 150 = 1
Mb/sec 150 up to 160 = 1
Mb/sec 160 up to 170 = 9
Mb/sec 170 up to 180 = 6
Mb/sec 180 up to 190 = 12
Mb/sec 190 up to 200 = 3
Mb/sec 200 up to 210 = 2
Mb/sec 560 up to 570 = 1
Mb/sec 610 up to 620 = 1
Mb/sec 740 up to 750 = 1
Mb/sec 930 up to 940 = 1
Mb/sec 1080 up to 1090 = 1
Mb/sec 1220 up to 1230 = 1
Mb/sec 1340 up to 1350 = 168
Bogus Speed calcs = 0


count=82710576	Send sec =368.16
 >> Call by USB==1 or USB1==2 :: 2
Mb/sec 20 up to 30 = 3
Mb/sec 30 up to 40 = 10
Mb/sec 40 up to 50 = 6
Mb/sec 50 up to 60 = 2
Mb/sec 60 up to 70 = 1
Mb/sec 70 up to 80 = 1
Mb/sec 80 up to 90 = 1
Mb/sec 100 up to 110 = 1
Mb/sec 120 up to 130 = 1
Mb/sec 130 up to 140 = 1
Mb/sec 140 up to 150 = 2
Mb/sec 150 up to 160 = 11
Mb/sec 160 up to 170 = 133
Mb/sec 170 up to 180 = 76
Mb/sec 180 up to 190 = 33
Mb/sec 190 up to 200 = 23
Mb/sec 200 up to 210 = 14
Mb/sec 210 up to 220 = 1
Mb/sec 470 up to 480 = 1
Mb/sec 480 up to 490 = 3
Mb/sec 490 up to 500 = 1
Mb/sec 520 up to 530 = 2
Mb/sec 540 up to 550 = 2
Mb/sec 550 up to 560 = 1
Mb/sec 560 up to 570 = 5
Mb/sec 570 up to 580 = 1
Mb/sec 580 up to 590 = 2
Mb/sec 590 up to 600 = 1
Mb/sec 600 up to 610 = 1
Mb/sec 610 up to 620 = 2
Mb/sec 630 up to 640 = 2
Mb/sec 640 up to 650 = 4
Mb/sec 650 up to 660 = 1
Mb/sec 660 up to 670 = 1
Mb/sec 680 up to 690 = 3
Mb/sec 690 up to 700 = 1
Mb/sec 700 up to 710 = 1
Mb/sec 710 up to 720 = 2
Mb/sec 720 up to 730 = 2
Mb/sec 730 up to 740 = 3
Mb/sec 740 up to 750 = 1
Mb/sec 750 up to 760 = 1
Mb/sec 760 up to 770 = 1
Mb/sec 770 up to 780 = 1
Mb/sec 780 up to 790 = 3
Mb/sec 790 up to 800 = 1
Mb/sec 820 up to 830 = 2
Mb/sec 840 up to 850 = 1
Mb/sec 850 up to 860 = 1
Mb/sec 860 up to 870 = 2
Mb/sec 880 up to 890 = 2
Mb/sec 890 up to 900 = 1
Mb/sec 900 up to 910 = 1
Mb/sec 910 up to 920 = 1
Mb/sec 930 up to 940 = 2
Mb/sec 940 up to 950 = 2
Mb/sec 950 up to 960 = 1
Mb/sec 980 up to 990 = 1
Mb/sec 990 up to 1000 = 2
Mb/sec 1010 up to 1020 = 1
Mb/sec 1020 up to 1030 = 2
Mb/sec 1080 up to 1090 = 1
Mb/sec 1090 up to 1100 = 1
Mb/sec 1110 up to 1120 = 1
Mb/sec 1130 up to 1140 = 1
Mb/sec 1160 up to 1170 = 2
Mb/sec 1220 up to 1230 = 1
Mb/sec 1270 up to 1280 = 1
Mb/sec 1280 up to 1290 = 1
Mb/sec 1320 up to 1330 = 1
[B][COLOR="#FF0000"]Mb/sec 1340 up to 1350 = 12819[/COLOR][/B]
Bogus Speed calcs = 0
 
After 1700 seconds the T_SerMon is paused ... perhaps to return - running againf a T_4.1 with SerialTest2.ino.
Running against the EXE the mode was about 220 Mbps, running against T_SerMon the mode looks closer to 170 Mbps.
So having MOST groups counting as "Mb/sec 1340 up to 1350 = 69602" suggests it is really getting way more data than it can handle.
Code:
count=440528752	Send sec =1710.85
 >> Call by USB==1 or USB1==2 :: 2
Mb/sec 20 up to 30 = 3
Mb/sec 30 up to 40 = 10
Mb/sec 40 up to 50 = 6
Mb/sec 50 up to 60 = 2
Mb/sec 60 up to 70 = 1
Mb/sec 70 up to 80 = 1
Mb/sec 80 up to 90 = 1
Mb/sec 90 up to 100 = 3
Mb/sec 100 up to 110 = 4
Mb/sec 110 up to 120 = 12
Mb/sec 120 up to 130 = 13
Mb/sec 130 up to 140 = 26
Mb/sec 140 up to 150 = 23
Mb/sec 150 up to 160 = 32
[B]Mb/sec 160 up to 170 = 167[/B]
Mb/sec 170 up to 180 = 91
Mb/sec 180 up to 190 = 46
Mb/sec 190 up to 200 = 38
Mb/sec 200 up to 210 = 66
Mb/sec 210 up to 220 = 29
Mb/sec 220 up to 230 = 9
Mb/sec 230 up to 240 = 8
Mb/sec 240 up to 250 = 10
Mb/sec 250 up to 260 = 5
Mb/sec 260 up to 270 = 10
Mb/sec 270 up to 280 = 6
Mb/sec 280 up to 290 = 4
Mb/sec 290 up to 300 = 2
Mb/sec 300 up to 310 = 4
Mb/sec 310 up to 320 = 5
Mb/sec 320 up to 330 = 3
Mb/sec 330 up to 340 = 4
Mb/sec 340 up to 350 = 2
Mb/sec 350 up to 360 = 2
Mb/sec 360 up to 370 = 5
Mb/sec 370 up to 380 = 3
Mb/sec 380 up to 390 = 2
Mb/sec 390 up to 400 = 3
Mb/sec 400 up to 410 = 3
Mb/sec 410 up to 420 = 2
Mb/sec 420 up to 430 = 2
Mb/sec 430 up to 440 = 2
Mb/sec 440 up to 450 = 1
Mb/sec 450 up to 460 = 2
Mb/sec 460 up to 470 = 1
Mb/sec 470 up to 480 = 3
Mb/sec 480 up to 490 = 4
Mb/sec 490 up to 500 = 2
Mb/sec 500 up to 510 = 2
Mb/sec 510 up to 520 = 2
Mb/sec 520 up to 530 = 3
Mb/sec 530 up to 540 = 4
Mb/sec 540 up to 550 = 3
Mb/sec 550 up to 560 = 2
Mb/sec 560 up to 570 = 5
Mb/sec 570 up to 580 = 1
Mb/sec 580 up to 590 = 3
Mb/sec 590 up to 600 = 2
Mb/sec 600 up to 610 = 4
Mb/sec 610 up to 620 = 3
Mb/sec 620 up to 630 = 1
Mb/sec 630 up to 640 = 2
Mb/sec 640 up to 650 = 8
Mb/sec 650 up to 660 = 1
Mb/sec 660 up to 670 = 1
Mb/sec 670 up to 680 = 2
Mb/sec 680 up to 690 = 4
Mb/sec 690 up to 700 = 1
Mb/sec 700 up to 710 = 2
Mb/sec 710 up to 720 = 2
Mb/sec 720 up to 730 = 2
Mb/sec 730 up to 740 = 3
Mb/sec 740 up to 750 = 2
Mb/sec 750 up to 760 = 2
Mb/sec 760 up to 770 = 1
Mb/sec 770 up to 780 = 2
Mb/sec 780 up to 790 = 4
Mb/sec 790 up to 800 = 2
Mb/sec 820 up to 830 = 2
Mb/sec 840 up to 850 = 1
Mb/sec 850 up to 860 = 2
Mb/sec 860 up to 870 = 2
Mb/sec 870 up to 880 = 1
Mb/sec 880 up to 890 = 2
Mb/sec 890 up to 900 = 1
Mb/sec 900 up to 910 = 1
Mb/sec 910 up to 920 = 3
Mb/sec 920 up to 930 = 1
Mb/sec 930 up to 940 = 2
Mb/sec 940 up to 950 = 2
Mb/sec 950 up to 960 = 2
Mb/sec 960 up to 970 = 2
Mb/sec 980 up to 990 = 3
Mb/sec 990 up to 1000 = 2
Mb/sec 1010 up to 1020 = 1
Mb/sec 1020 up to 1030 = 2
Mb/sec 1040 up to 1050 = 1
Mb/sec 1060 up to 1070 = 2
Mb/sec 1070 up to 1080 = 1
Mb/sec 1080 up to 1090 = 1
Mb/sec 1090 up to 1100 = 2
Mb/sec 1110 up to 1120 = 1
Mb/sec 1130 up to 1140 = 2
Mb/sec 1140 up to 1150 = 1
Mb/sec 1150 up to 1160 = 2
Mb/sec 1160 up to 1170 = 2
Mb/sec 1170 up to 1180 = 1
Mb/sec 1190 up to 1200 = 1
Mb/sec 1220 up to 1230 = 1
Mb/sec 1240 up to 1250 = 1
Mb/sec 1250 up to 1260 = 1
Mb/sec 1270 up to 1280 = 2
Mb/sec 1280 up to 1290 = 1
Mb/sec 1320 up to 1330 = 1
Mb/sec 1340 up to 1350 = 69602
Bogus Speed calcs = 0

T_sermon was lost some 200 seconds and now back after this snapshot:
Code:
count=496157104	Send sec =1912.34
 >> Call by USB==1 or USB1==2 :: 2
...
Mb/sec 120 up to 130 = 13
Mb/sec 130 up to 140 = 27
Mb/sec 140 up to 150 = 23
Mb/sec 150 up to 160 = 33
[B]Mb/sec 160 up to 170 = 167[/B]
Mb/sec 170 up to 180 = 91
Mb/sec 180 up to 190 = 46
Mb/sec 190 up to 200 = 38
Mb/sec 200 up to 210 = 67
Mb/sec 210 up to 220 = 31
Mb/sec 220 up to 230 = 9
...
[B]Mb/sec 1340 up to 1350 = 78489[/B]
Bogus Speed calcs = 0

Similar runtime against the .EXE - that just verifies line length and tracks the end of 100,096 groups to be complete:
-> since starting it processed 12401 groups and shows only 48 lost 'packets' in those groups.
Code:
count=79285575	Send sec =1856.37
 >> Call by USB==1 or USB1==2 :: 2
Mb/sec 90 up to 100 = 1
Mb/sec 100 up to 110 = 18
Mb/sec 110 up to 120 = 32
Mb/sec 120 up to 130 = 35
Mb/sec 130 up to 140 = 45
Mb/sec 140 up to 150 = 51
Mb/sec 150 up to 160 = 73
Mb/sec 160 up to 170 = 124
Mb/sec 170 up to 180 = 176
Mb/sec 180 up to 190 = 173
Mb/sec 190 up to 200 = 186
[B]Mb/sec 200 up to 210 = 3545
Mb/sec 210 up to 220 = 6767[/B]
Mb/sec 220 up to 230 = 1396
Mb/sec 230 up to 240 = 45
[B]Mb/sec 1340 up to 1350 = 6[/B]
Bogus Speed calcs = 0

*Note: still seeing the group break in two on returning to computer with screen gone OFF from time away.
 
Follow up to prior posts. The SerialTest2.exe running a bit longer ... 60076.64 seconds

Printed .ino :: stats: 100K=400001 less=148 repeated 1 rmax=2000000

It seems to run a bit slower when screen is blanked - and the "less=148" could mostly be the unreal high : Mb/sec 1340 up to 1350 = 108. Seems each broken group of 100096 sends counts twice when broken in the middle.
And still seeing a break in the groups when screen gets unblanked on return to keyboard.
Code:
count=2495933048	Send sec =60076.64
 >> Call by USB==1 or USB1==2 :: 2
Mb/sec 50 up to 60 = 1
Mb/sec 60 up to 70 = 1
Mb/sec 70 up to 80 = 12
Mb/sec 80 up to 90 = 77
Mb/sec 90 up to 100 = 486
Mb/sec 100 up to 110 = 688
Mb/sec 110 up to 120 = 784
Mb/sec 120 up to 130 = 1122
Mb/sec 130 up to 140 = 1677
Mb/sec 140 up to 150 = 2535
Mb/sec 150 up to 160 = 3583
Mb/sec 160 up to 170 = 5307
Mb/sec 170 up to 180 = 10344
Mb/sec 180 up to 190 = 51039
Mb/sec 190 up to 200 = 30751
[B]Mb/sec 200 up to 210 = 83963
Mb/sec 210 up to 220 = 170570[/B]
Mb/sec 220 up to 230 = 33210
Mb/sec 230 up to 240 = 2681
Mb/sec 240 up to 250 = 24
Mb/sec 370 up to 380 = 1
[B]Mb/sec 730 up to 740 = 1
Mb/sec 1160 up to 1170 = 1
Mb/sec 1340 up to 1350 = 108[/B]
Bogus Speed calcs = 0

Tried HTerm against T_4.1 running that on a fresh start and it never showed ANY data and USB1 gave these stats as HTerm TERMINATED - so it doesn't work usably here:
Code:
count=2877760	Send sec =36.14
 >> Call by USB==1 or USB1==2 :: 2
Mb/sec 120 up to 130 = 1
Mb/sec 130 up to 140 = 1
Mb/sec 140 up to 150 = 1
Mb/sec 150 up to 160 = 3
Mb/sec 160 up to 170 = 8
Mb/sec 170 up to 180 = 5
Mb/sec 180 up to 190 = 8
Mb/sec 190 up to 200 = 40
Mb/sec 200 up to 210 = 101
Mb/sec 1170 up to 1180 = 1
Mb/sec 1340 up to 1350 = 291

For REF the CMDLINE dos box print is certainly slow, this suggests how slow and lossy it might be - and is visible watching Ser# jumps - worse but similar to p#263 T_sermon with lots of hits in this unreal bin : Mb/sec 1340 up to 1350 = 39848
This USB1 speed recording from the INO with SZ37 on a 38 byte line of output making them ALL print: SerialTest2 COM7 SZ37 Q
Code:
count=252254432	Send sec =975.10
 >> Call by USB==1 or USB1==2 :: 2
Mb/sec 60 up to 70 = 1
Mb/sec 80 up to 90 = 4
Mb/sec 90 up to 100 = 1
Mb/sec 100 up to 110 = 2
Mb/sec 110 up to 120 = 13
Mb/sec 120 up to 130 = 18
Mb/sec 130 up to 140 = 16
Mb/sec 140 up to 150 = 89
Mb/sec 150 up to 160 = 34
Mb/sec 160 up to 170 = 17
Mb/sec 170 up to 180 = 24
Mb/sec 180 up to 190 = 28
Mb/sec 190 up to 200 = 11
Mb/sec 200 up to 210 = 34
Mb/sec 210 up to 220 = 12
Mb/sec 220 up to 230 = 5
Mb/sec 230 up to 240 = 4
Mb/sec 240 up to 250 = 3
Mb/sec 250 up to 260 = 2
Mb/sec 260 up to 270 = 2
Mb/sec 280 up to 290 = 2
Mb/sec 290 up to 300 = 4
Mb/sec 300 up to 310 = 3
Mb/sec 310 up to 320 = 1
Mb/sec 320 up to 330 = 3
Mb/sec 330 up to 340 = 3
Mb/sec 340 up to 350 = 3
Mb/sec 350 up to 360 = 3
Mb/sec 360 up to 370 = 6
Mb/sec 370 up to 380 = 3
Mb/sec 380 up to 390 = 5
Mb/sec 390 up to 400 = 5
Mb/sec 400 up to 410 = 1
Mb/sec 410 up to 420 = 2
Mb/sec 420 up to 430 = 2
Mb/sec 430 up to 440 = 5
Mb/sec 440 up to 450 = 5
Mb/sec 450 up to 460 = 2
Mb/sec 460 up to 470 = 5
Mb/sec 470 up to 480 = 4
Mb/sec 480 up to 490 = 2
Mb/sec 490 up to 500 = 2
Mb/sec 500 up to 510 = 1
Mb/sec 510 up to 520 = 4
Mb/sec 520 up to 530 = 5
Mb/sec 530 up to 540 = 3
Mb/sec 540 up to 550 = 2
Mb/sec 550 up to 560 = 3
Mb/sec 560 up to 570 = 3
Mb/sec 570 up to 580 = 2
Mb/sec 580 up to 590 = 4
Mb/sec 590 up to 600 = 2
Mb/sec 610 up to 620 = 1
Mb/sec 620 up to 630 = 1
Mb/sec 630 up to 640 = 1
Mb/sec 640 up to 650 = 1
Mb/sec 650 up to 660 = 2
Mb/sec 660 up to 670 = 1
Mb/sec 670 up to 680 = 2
Mb/sec 680 up to 690 = 1
Mb/sec 700 up to 710 = 1
Mb/sec 710 up to 720 = 2
Mb/sec 730 up to 740 = 1
Mb/sec 750 up to 760 = 3
Mb/sec 760 up to 770 = 2
Mb/sec 790 up to 800 = 3
Mb/sec 830 up to 840 = 1
Mb/sec 870 up to 880 = 1
Mb/sec 880 up to 890 = 2
Mb/sec 890 up to 900 = 2
Mb/sec 900 up to 910 = 4
Mb/sec 910 up to 920 = 2
Mb/sec 930 up to 940 = 2
Mb/sec 940 up to 950 = 1
Mb/sec 960 up to 970 = 1
Mb/sec 990 up to 1000 = 2
Mb/sec 1000 up to 1010 = 1
Mb/sec 1010 up to 1020 = 1
Mb/sec 1030 up to 1040 = 1
Mb/sec 1040 up to 1050 = 1
Mb/sec 1150 up to 1160 = 1
Mb/sec 1160 up to 1170 = 1
Mb/sec 1180 up to 1190 = 1
Mb/sec 1200 up to 1210 = 1
Mb/sec 1210 up to 1220 = 1
Mb/sec 1230 up to 1240 = 1
Mb/sec 1240 up to 1250 = 1
Mb/sec 1270 up to 1280 = 1
Mb/sec 1310 up to 1320 = 1
Mb/sec 1330 up to 1340 = 1
Mb/sec 1340 up to 1350 = 39848
Bogus Speed calcs = 0

And running the INO with NO device connect to pull data indeed looks like this:
Code:
count=27075968	Send sec =101.24
 >> Call by USB==1 or USB1==2 :: 2
Mb/sec 210 up to 220 = 1
Mb/sec 1340 up to 1350 = 4327
Bogus Speed calcs = 0
 
Last edited:
Yes, both speed tests, mine and Paul's, have the problem that they do not check if the data was sent at all.

print() returns the number of bytes sent. This should be inserted in both tests.

Without that, both can return very wrong numbers (in the case of timeouts)
 
Yes, both speed tests, mine and Paul's, have the problem that they do not check if the data was sent at all.

print() returns the number of bytes sent. This should be inserted in both tests.

Without that, both can return very wrong numbers (in the case of timeouts)

I had not checked that print returned only the number of 'sent' characters.
>>TESTING THAT : print always returns the number SENT, whether printed or not!

... Zzzz's now ...

As far as testing - with some verification using the EXE - size mismatch forcing it to print ALL lines:
I just sent the output of about 60 seconds into a RamDisk file : SerialTest2 COM7 SZ37 Q > r:\st2_sz37.txt

Code:
Got 37M lines in a file of 1.4GB in ~60 seconds ... 24 MB/second
Did "findstr /N Mbps st2_sz37.txt > count.csv" and edited in commas for excel for just the group summary lines.

The first 108 'groups' of 100096 {plus one for end of group summary} sends of 38 characters averages only 99,138 lines per group
[CODE]        Number of lines in a group is 100096
        Bytes in a group is 3803648
The next 266 groups to the end of test ALL had 100097 lines {with summary} accounted for - but not length checked as SZ37!-SZ38 to print ALL no longer verifies 38 bytes/lines, but typical failures were seen to drop the '\n' newline - and they are there to get the right count.
The average Mbps for those lines was 208.
[/CODE]

USB1 stats table shows ( that seems to agree with the data pulled to excel ):
Code:
count=2270008	Send sec =59.29
 >> Call by USB==1 or USB1==2 :: 2
Mb/sec 110 up to 120 = 2
Mb/sec 120 up to 130 = 3
Mb/sec 140 up to 150 = 1
Mb/sec 150 up to 160 = 7
Mb/sec 160 up to 170 = 33
Mb/sec 170 up to 180 = 19
Mb/sec 180 up to 190 = 31
Mb/sec 190 up to 200 = 32
Mb/sec 200 up to 210 = 100
Mb/sec 210 up to 220 = 99
Mb/sec 220 up to 230 = 28
Mb/sec 230 up to 240 = 7
Bogus Speed calcs = 0
 
I had not checked that print returned only the number of 'sent' characters.
>>TESTING THAT : print always returns the number SENT, whether printed or not!

[/CODE]
Hm in this case I read the code wrong, and whether it is compatible with the Arduino documentation is at least questionable.

print() returns the number of bytes written, though reading that number is optional. Data type: size_t.
https://www.arduino.cc/reference/en/language/functions/communication/serial/print/
 
Hm in this case I read the code wrong, and whether it is compatible with the Arduino documentation is at least questionable.


https://www.arduino.cc/reference/en/language/functions/communication/serial/print/

I just happened to have the code open and added += on all the prints per group and redid the posted math quickly and the reported sums always matched the ideal sums.

The quick feed to excel isn't clean but this is how it reads:
Code:
1901082	"	3803648 B {Out"	3803648} in 181209 us 	167.92	 mbps	100043
1969757	"	3803648 B {Out"	3803648} in 239463 us 	127.07	 mbps	68675

3803648 twice is the ideal expected and the 2nd Out is the "+=" sum - and the last number on the line is how many the EXE printed on receipt of 100096 it shows 100043 and 68675.

It is possible they were SENT out USB, and the EXE just didn't get them? But that seems puzzling ... compare below - they took LONGER to SEND when FEWER lines were received - so that says Teensy USB was told by Windows to HOLD UP and threw those bytes away ?????

Versus these later that show all received:
Code:
17436634	"	3803648 B {Out"	3803648} in 147962 us 	205.66	 mbps	100097
17536731	"	3803648 B {Out"	3803648} in 177114 us 	171.81	 mbps	100097
 
Last edited:
In case of a timout it should return zero with the next print, if I read it correctly.
Windows drops packets, or the teensy. Or both.

bool packetdrop = (windows || teensy) || (windows);

which, for windows, can be simplified to

bool packetdrop = true;

So, it doesn't matter on windows machines WHERE it happens.
A theoretical fix must take into account.

I'm 99% sure the only fix is to send slower. That will fix both, windows && teensy.
 
Last edited:
@Paul - when you get back to this ... Minor dual USB2 output updates if used give more feedback : github.com/Defragster/cdcbench
Bottom Line: this 'fast' Windows machine seems capable of handling data steady state at 220-240 Mbps when dumped to RAMDISK or SSD, or parsed minimally by serialtest2.exe. Any attempt at GUI screen display falls behind - quickly it seems

Using USB2 as before for output of low flow debug info. Hoping it doesn't interfere - if anything it might slow the attack on USB1 and give false sense of no issues - but seems that is far off.
> USB_Serial2 and #3 would be good to have upgraded to best known.

Seeing 1400+ Mbps when output is discarded suggests the 9 HEX digit serial# unrolled fixed length printing is not slowing the INO at all

Made another edit to INO to send copy of batch status USB2.print("3803648, B in, 21307, us = ,1428.13, Mbps:BC8FC2000");
That is excel friendly version CSV. And shows the current Ser#/Count of output line.
> Problem is it runs SO much faster when nothing goes out - that it then runs EVER faster compounding the problem overwhelming USB1 { 21ms versus ~150ms }
-> so if a rate limiter could be added it would prevent the overflow, and the compounded overflow when Teensy skips writing.
-> however when there is NO USB EVER , or if lost : it would be nice to not have it add that 'rate limit' slowing the code???

Shows two things:
#1 : that unreal '1428.13, Mbps' means PC is stuffed and the data print transfer is getting skipped. It is showing that in T_sermon and TyComm.
> when that starts coincides with GARBAGE on T_sermon , saw garbage on TyComm too - similar timing?

#2 : from screen shots shows how far out of sync the USB1 displayed Ser#/Count is from the 'current' as comes though on USB2:
Here is one of T_sermon printing info from 'out of left field' - does that mean anything? It was DEAD - never drew again on resize to get more info on screen:
SerT2_Tsermon.png

Here is TyComm where both USB1 and #2 are shown - Ser# out of sync and unreal data rate:
{ ser # on left in USB1 and on right in USB2 and TyComm shows USB2 with 'red dot' }
SerT2_dalTyCommbehind.jpg
Here TyComm serial was turned OFF then ON - that seemed to dump the buffer backlog and go at expected speed ~200 Mbps:
> Odd the USB2 is actually BEHIND in printed Ser# - maybe because the USB1 is being a HOG and USB2 is only printing 6 times per second? Adding .flush() gets them closer - until the USB1 to Windows backlogs after a fresh start.
SerT2_dalTyCommClose.jpg

Tried code edit and upload restart and WIN 11 USB no longer connects to ANY Teensy - not SERIAL or Bootloader ... it disabled my HUB? Unplugged and works on re-plugging ???
> This is the 4th repro - before I restarted the computer - but hub reconnect seems to fix?
-> prior Hub like @KurtE's was failing - but it was 'overcurrent shutdown' - this 'new hub' gave no message. And on port shutdown seems it generally stays off until restart?
> all 4 times it was when T_Loader was doing a code upload to this (and all other?) T_4.1 : using encrypted ehex (required - secure mode is locked)

Running against latest release of TyComm it seems under 30 Mbps, except in bursts toward 200 Mbps between the longer running 1400+ unreal Mbps.

Running against : "SerialTest2 COM7 SZ38 Q" it seems fairly steady around 230-240 Mbps.
> similar for "SerialTest2 COM7 SZ38" - that prints dots in groups of 50 and stats on 200 groups.
> "Q" instead prints only the GROUP output :" 3803648, B in, 132363, us = ,229.89, Mbps: 97BB6800"
--> This shows when the USB HOST code is FAST enough - there is little or NO corruption in USB buffers, unless Windows MultiTasks itself away too long.
> the other way to run is : "SerialTest2 COM7 SZ37 Q" where the SZ does not match the message it then shows ALL lines - where dos box output is SLOW and except in short batches of ~230 Mbps it shows 1454 Mbps showing Teensy discarding data >> Like the T_SerMon does
--> with "SerialTest2 COM7 SZ37 Q > somefile.txt" the full output grows a file FAST and at the rate of ~230 Mbps showing in USB2.

When the USB1 output is not taken by any host code the Teensy is dumping the data at the rate of 1455 Mbps.

Current 'repeat' line length with filler is 38 bytes "1507C5F59<<<>>>___[[[]]]---{{{}}}___!" { needed for 'SZ38' parsing in serialtest2.exe } This is shown on USB2 as:
Code:
C:\T_Drive\tCode\pjrc_latency_test\FB_SerTest\SerialTest2\SerialTest2.ino Oct 22 2021 00:24:41
[B]Test line in Bytes is 38[/B]
Number of lines in a group is 100096
Bytes in a group is 3803648

Filler can be edited in sketch to change the length here: #define FILL_STRING "<<<>>>___[[[]]]---{{{}}}___!\n"
To explain why 100,000 went to 100,096 : The unrolled Ser# prints are in groups of 256
The 'group' status line shows "Bytes in a group is 3803648" and that excludes the bytes printed in that status line.
 
Last edited:
I'm 99% sure the only fix is to send slower. That will fix both, windows && teensy.

Agreed. Sad as throttling the transmit speed will be, I just don't see any other way to make it work well with Windows.

The big question is how slow? We just can't know whether the receiver is a fast data logger or a GUI trying to render text to the screen or a poorly written Python script doing dynamic memory allocation for each byte.
 
Yes, that's the challenge.
Also, perhaps we have to keep in mind slow PCs.

And, a question - there are Tablets etc with Windows. Do they have the same problem? I own no such thing...
The next question: How? :) Do we want full speed for other OSs? Is there a way to detect Windows? (I don't think that.. ) Can we add a #define as switch to enable "slow TX"?
 
Why not have a variable which can be set by the user.

I don't know call it SerialUartSpeed, let's say with a value from 0..255.
At 255 (default) the Serial Usb goes at it's fastest as at the moment.

It is slowed down dependent upon the value of SerialUartSpeed right down to let's say 12mb/s for a value of 0.

Alternatively you could call it SerialUartThrottle, with 0 (default) being the fastest and 255 being the slowest speed.
 
Hm. Not tried - does it help to just make the timer slower? (That would be the perfect place to create a variable speed - IF that works)
Tim? Can you test?

edit:
It would be a opportunity to add different timouts, perhaps.. (see the "todo")
Code:
// TODO: should be 2 different timeouts, high speed (480) vs full speed (12)
#define TRANSMIT_FLUSH_TIMEOUT    75   /* in microseconds */

But again, I have no idea if that is enough. I'd try a pretty high value first, to confirm..
 
Status
Not open for further replies.
Back
Top