Teensyduino 1.62 Beta #4 - Release Candidate

I need feedback with Windows. If you're using Windows, please give this quick test a try.

Open Windows Device Manager and put it's window side-by-side with Arduino IDE and Teensy Loader. Expand the "Ports (COM & LPT)" section. We're looking for how many times Device Manager redraws during upload of programs using Serial+MTP, and the approximate timing relative to changes seen in Teensy Loader and the Arduino IDE windows. If you're able to see the updates long enough, please look for which show the COM port for Teensy.

On my Windows 11 laptop, I see 1 redraw as the upload starts, and 2 more shortly after "Reboot OK" in Teensy Loader. Then I see a 4th update about 4 seconds later. The first update has no COM port. The other 3 updates all show the COM port on my Windows 11 laptop.

The big mystery is what's happening between the 3rd redraw that 4th redraw which comes about 4 seconds later. During that time, attempts to open the COM port return Windows error code 433. WIN32 FormatMessage() says 433 means "A device which does not exist was specified." But the COM port is visible in Device Manager (and teensy_monitor see it too) during those 4 seconds. So far I've not been able to find any solution other than simply waiting.

Main question is whether you see similar timing in Device Manager relative to what's happening in Teensy Loader and Arduino IDE, and if you get that 4th redraw seconds later, even an approximate measurement of the time before you see the 4th update would really help.

If you have really quick fingers, can you use any terminal program to open the COM port during this time?
 
On the plus side, diving into this device detection stuff on Windows revealed a long-standing issue where teensy_monitor wasn't properly responding to the close command Arduino CLI sends. Fixing this problem removes noticeable lag from clicking Upload in Arduino IDE to when the upload actually begins, if serial monitor was open (as it usually is for the way most people use Arduino IDE). If you measure the time from when the memory usage info appears to when the upload actually begins, with beta4 and all prior versions in IDE 2.x.x, it's significantly faster if serial monitor is not in use. Next beta will fix this lag, so speed from memory usage to upload begin should be similar regardless of whether serial monitor is in use.

On the mystery Windows delay with Serial+MTP, maybe it's related to "auto play" settings when a new disk appears? I don't actually use Windows as my main OS, so I'm not very familiar with its various features and settings. If there are ways to configure auto play, maybe they might have some effect on that ~4 second lag where the COM port can't be opened?
 
PaulStoffregen said:
On my Windows 11 laptop, I see 1 redraw as the upload starts, and 2 more shortly after "Reboot OK" in Teensy Loader. Then I see a 4th update about 4 seconds later. The first update has no COM port. The other 3 updates all show the COM port on my Windows 11 laptop.

The big mystery is what's happening between the 3rd redraw that 4th redraw which comes about 4 seconds later. During that time, attempts to open the COM port return Windows error code 433. WIN32 FormatMessage() says 433 means "A device which does not exist was specified." But the COM port is visible in Device Manager (and teensy_monitor see it too) during those 4 seconds. So far I've not been able to find any solution other than simply waiting.
Click to expand...
I only see 2 redraws; one is a short time after the upload finishes, the second is approx. 5 seconds later. Any attempts to open the COM port before the second update fail.

I had a look in \windows\inf\setupapi.dev.log from when the driver for this Teensy config was installed, there's separate entries for the USB interfaces (serial / MTP) and the timestamps on these lines for the MTP driver stand out to me:
dvi: Install Device: Starting device 'USB\VID_16C0&PID_04D5&MI_02\6&224D1205&0&0002'. 12:48:29.753
dvi: Install Device: Starting device completed. 12:48:34.863
Click to expand...
These timestamps match up with MTP events 1001 ("device will enter suspend state if idle for 30 secs") and 1003 ("device is resuming operation from idle state") visible in the Event Viewer under Applications and Services Logs -> Microsoft -> Windows -> WPD-MTPClassDriver. I have no idea if a user-level application can catch these events but it may be worth looking into...

I would not be surprised if there's a 5 second startup delay hardcoded into the MTP driver, and since it's a child of the composite device driver (usbccgp.sys) it's locking the entire device and blocking access to the serial device until it's done.
 
I'm talking about the OS (windows) MTP driver... it appears to have a 5 second delay in its startup, which probably blocks access to any interface on the device.

Edit: I know what's going on... the windows MTP driver is trying to talk to the device during its startup routine, but the device is waiting for the PC to establish a serial connection before it starts running MTP.loop() so the requests aren't serviced. Teensy Loader can't open the serial port because the MTP driver is blocking access to the entire device so there's a deadlock until it gives up.

This slightly modified sketch allows the IDE to reconnect the serial port after uploading:
Code: 
#include <SD.h>

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

  puts("Starting MTP...");
  MTP.begin();
  MTP.addFilesystem(SD, "SD CARD");

  Serial.begin(0);
  while(!Serial) MTP.loop();

  puts("Loop is starting");
  digitalWriteFast(LED_BUILTIN, HIGH);
}

void loop() {
  MTP.loop();
}
 
Last edited:
Ah, that make sense. Well, as much a driver for one interface on a USB device blocking other unrelated interfaces can make sense.

I have an ugly hack inside teensy_monitor which just keeps trying for several seconds. It "solves" the problem of Arduino Serial Monitor not connecting, but during those seconds we're not responsive to commands from Arduino CLI. I was going to try a better way, but knowing we can do something on the Teensy side probably makes this hack good enough for now (releasing 1.62).

So far I haven't found a way to get Windows to send a message when COM port becomes possible to open. We do get WM_DEVICECHANGE and WM_TIMER. There is one mystery message that arrives with ID number 799, though the timing doesn't seem to match up well. I found info online that 799 might be WM_DWMNCRENDERINGCHANGED, but it makes no sense to me. But somehow Windows Device Manager redraws around that time, so there much be some way. Or maybe Device Manager is also polling something rather than responding to a message?

We already have some limited code on the Teensy side that responds to urgent MTP communication from interrupts rather than MTP.loop(). Long term solution will probably look like moving more into that interrupt-based code. No way that can happen for 1.62 release, and probably not 1.63 which will focus on merging and updating stuff, but I'm putting MTP startup improvement onto my todo list for 1.64 or later.

Right now, I'm going to run a few more tests and then package up beta5. My hope is more people using Windows can test various serail monitor usage in Arduino IDE 2.3.10. I personally do not use Windows much, so I'm not familiar with a lot of its quirks, and my Windows 11 laptop has basically no other software installed.
 
PaulStoffregen said:
Right now, I'm going to run a few more tests and then package up beta5. My hope is more people using Windows can test various serail monitor usage in Arduino IDE 2.3.10. I personally do not use Windows much, so I'm not familiar with a lot of its quirks, and my Windows 11 laptop has basically no other software installed.
Click to expand...
Sorry took me so long try this issue out. I ran the code in post #30 with the serial monitor closed.

Uploaded the sketch a couple of times with Monitor closed. Device manager refreshed twice in each upload and the SD Card directory popped open in each case didn't see any hangs. Is there something I am missing?

I am running windows 10 home and IDE 2.3.10, testing on the mini-dev board. Also I selected Serial+MTP for the serial port. Not sure that matters

If I use MTP Disk: Directory window still opens on upload with monitor closed and no comport is shown in the device manager.
 
PaulStoffregen said:
Use the code from msg #23 to reproduce the problem. The code in msg #30 is a workaround for the problem.
Click to expand...
Yep seeing the same issue with device manager refreshing a few times.

But just for the record I never really use `while(!Serial)` by itself, when I use it I usually do `while(!Serial && millis() < 5000);` which does work.
 
mjs513 said:
Yep seeing the same issue with device manager refreshing a few times.

But just for the record I never really use `while(!Serial)` by itself, when I use it I usually do `while(!Serial && millis() < 5000);` which does work.
Click to expand...
That would still have the same problem with the serial monitor. The windows MTP driver also silently fails to initialize when the device doesn't respond with 5 seconds (there's further events in Event Viewer confirming this).
 
Just to repeat, beta5 has new code in teensy_monitor.exe which keeps trying to open the port for about 8 seconds. So even if you do wait indefinitely in a while (!Serial) loop on Teensy, when Windows MTP driver gives lets the COM port become accessible after ~5 sec of not getting the info it wanted, teensy_monitor.exe is supposed to be able to connect and the while (!Serial) loop will see Arduino Serial Monitor is connected.

At least that's what's supposed to happen. I tested it many times on my Windows 11 laptop. But that's just one Windows machine, and one without much other software and without special drivers and other stuff so many Windows systems accumulate over time. I'm really hoping more people will well-used Windows systems can give it a try to confirm whether code like msg #23 really does work now? (prints a new message to Serial Monitor and LED turns on to confirm setup() completed)
 
I got some series issues with 0.60.4, that are very easy to tell but difficult to explain (have not tried 1.62 yet)

While developing a large program (adding functionalities) I got frequently situations where
the red BOOT LED flashes 8 times and the program is in some stop and go mode.

Most of the time I could get the program working by undoing the modification (using #if #else #endif), but not always.
Returning to 1.61 , I cannot see this issue.

program does data acquisition (custom TDM), uses CMSIS to do some processing and SdFat to write to disk.

Not sure what the 8 blinks of the red LED means in this case (docu: "Software which mis-configures pins can also cause this error").
So I dynamically modify, say SAI pins that are uses for data acquisition?
 
There were some startup issues fixed from 0.60.5 onwards which sound very much like this. They manifested as red LED blinks after flashing new code (8 could be the number…), but apparently minor changes could make them disappear … until they came back!

I experienced this a lot with Audio and TeensyDebug libraries, so it may well be associated with use of the SAI hardware.

I’d suggest you try to avoid anything earlier than 0.60.5. 1.62 seems to be pretty good, and faster to build, too.
 
@h4yn0nnym0u5e . Just tried 1.62 (no change in code), but gave me the same 8blink stop and go behaviour. returned to 1.61 (and is working again)
BTW 1.62 shows much more padding
Code: 
1.61
Memory Usage on Teensy 4.1:
  FLASH: code:100720, data:160952, headers:8660   free for files:7856132
   RAM1: variables:282912, code:95736, padding:2568   free for local variables:143072
   RAM2: variables:28800  free for malloc/new:495488
 EXTRAM: variables:10485760

1.62
Memory Usage on Teensy 4.1:
  FLASH: code:103648, data:160952, headers:8804   free for files:7853060
   RAM1: variables:282912, code:98600, padding:32472   free for local variables:110304
   RAM2: variables:28800  free for malloc/new:495488
 EXTRAM: variables:10485760

Obviously, I cannot exclude hard/sw issues on my side, that are surfacing with new compiler.
 
Last edited:
Padding exists to round the code size up to a multiple of 32768. The code size increased by more than the old padding size (2568), requiring an extra 32768 bytes total to be used.
 
Yes - if you could shave >=296 bytes off the code or variables then you’d have low padding and more stack space. Then again, 110,304 should be easily enough for any sane application!

If I recall correctly it was quite hard to nail down the point at which the Teensy crashed during boot. It probably involved putting in some hardware register bashing to do the equivalent of digitalWrite(), and using a scope to see where it stopped. It’s well-nigh impossible to do the canonical “small sketch to reproduce the problem”, because as you’ve seen, almost any change can make the problem disappear.

If you can share your program, e.g. as a GitHub repo, then maybe someone could investigate further.
 
OK, switched back to the released version of cores, and this is what I get:
Code: 
Memory Usage on Teensy 4.1:
  FLASH: code:103648, data:160952, headers:8804   free for files:7853060
   RAM1: variables:282912, code:98600, padding:32472   free for local variables:110304
   RAM2: variables:356480  free for malloc/new:167808
Same as you, except for a huge chunk of RAM2 in use! Can't see where, I'll investigate. It runs just fine for me...
 
This is the version where I used RAM2 instead of EXTMEM for the Data Queue. I wanted to see if writing/reading to EXTMEM was the issue. But I had the same 8-led blinks.
So, you are saying that you have with 1.62 no 8-red-blinks?
 
OK, so it's putting queue_buffer in RAM2, not EXTRAM (aka EXTMEM). Looking at the source, this seems correct, so not entirely sure if I have your current (troublesome) code. Forcing it into EXTRAM still works, yes.
 
OK, I found an unused T4.1 and repeated the tests (without added hardware) and indeed both versions (based on 1.61 and 1.62) are working.
However it shows also a problem, in the middle of the scrolling monitor where you see mostly the number 3 (indicating zero data, or better -1 or FFFFFFFF), from time to time the number 15 will show up indicating a high value in the buffer. Something, I could nor see on RP2350 with the same program. So there is indeed a problem with my SAI driver. This issue is also on 1.61. So somewhere between SAI ISR and writing to file the is an issue. The main difference between T4.1 and RP2350 is the access to the ADC, that in RP2350 is made with PIO (and the compiler)

Edit:
I found some suspicious pattern, that indicate a corruption of the acquired data before compression (resulting in the number 14/15), but cannot relate that yet to the 8-red-led-blink pattern.

Edit 2:
setting all data to -1 after dma before pushing to queue, removes the issue, all data shown on screen are the same.
So issue seems to be between SAI and

Edit 3: (for the records)
I found an issue in the process(buffer) routine that is called from the SAI ISR, I war processing inplace an DMA buffer, that yielded to the SAI interferences (8-red-led-blinks) and the error in the data. Copying the DMA buffer to a process buffer solves the issue. So, the observation that the program worked without hardware (thanks @h4yn0nnym0u5e ) gave me the direction to look for.
 
Last edited:
You must log in or register to reply here.
Back
Top