USBHost_t36 USB Mass Storage Driver Experiments

[jmarsh]

notice the sector count?

Looks like it's being printed as a signed 32-bit int when it should be unsigned. -387938129 = 0xE8E088AF = 3,907,029,167 sectors. Multiply by 512 bytes per sector = 2000398933504 bytes which matches the reported capacity.

[wwatson]

Ok did some testing with MTP (writing/reading files and transferring files) and all worked fine with that change.

Drives tested so far:
1. Crucial MX500 500GB 3D NAND SATA 2.5 Inch Internal SSD, up to 560MB/s - CT500MX500SSD1
2. INDMEM mSATA SSD 256GB Internal Mini SATA III SSD Micro-SATA TLC 3D NAND Flash 256 GB
3. HP SSD S 600 120GB


4. Silicon Power 2TB Rugged Portable External Hard Drive Armor A30:
This was a strange one:

       connected: 1
     initialized: 1
   USB Vendor ID: 174c
  USB Product ID: 55aa
      HUB Number: 0
        HUB Port: 0
  Device Address: 1
Removable Device: NO
        VendorID: PHD 3.0 
       ProductID: Silicon-Power   
      RevisionID: 0   
         Version: 6
    Sector Count: -387938129
     Sector size: 512
   Disk Capacity: 2000398933504 Bytes

notice the sector count?

PS did find adding a delay(500) allowed the drive to come on line

  while (!myDrive) {
    myusb.Task();
  }
delay(500);

Thanks for testing I'll test more of my devices and issue an appropriate PR.

[mjs513]

Thanks for testing I'll test more of my devices and issue an appropriate PR.

Thanks for digging and finding the issue!!!!! I had the easy part. Oh of course I tested the three sansdisk drives I had as I previously mentioned.

[KurtE]

Quick update:

The problem child (SDCZ73-032G-G46) that "works now"
https://www.amazon.com/dp/B01FTQP7ZM?psc=1

I was able to transfer a 6.44mb file to it, but it took probably over a minute to complete.

As compared to an SSD I recently purchased to test...
https://www.amazon.com/gp/product/B095P3ZT2B
which is installed onto:
https://www.amazon.com/gp/product/B07VP2WH73

Which maybe took something like 7 seconds for MTP to transfer to the SSD.

I also tried it with another 8gb stick enfain (USB 2) Probably: https://www.amazon.com/Enfain-Delive.../dp/B00HQWLHIE
same file took maybe 15 seconds.

EDIT: I also tried with Kingston SSD https://www.amazon.com/gp/product/B01N6JQS8C
connected using: https://www.amazon.com/gp/product/B00HJZJI84
And again in the 7 to 8 second range of time to copy the file

[mjs513]

Quick update:

The problem child (SDCZ73-032G-G46) that "works now"
https://www.amazon.com/dp/B01FTQP7ZM?psc=1

I was able to transfer a 6.44mb file to it, but it took probably over a minute to complete.

As compared to an SSD I recently purchased to test...
https://www.amazon.com/gp/product/B095P3ZT2B
which is installed onto:
https://www.amazon.com/gp/product/B07VP2WH73

Which maybe took something like 7 seconds for MTP to transfer to the SSD.

I also tried it with another 8gb stick enfain (USB 2) Probably: https://www.amazon.com/Enfain-Delive.../dp/B00HQWLHIE
same file took maybe 15 seconds.

Seeing the same issue with copying large files to those drives from the PC. Just copied a 12gb directory to the drive and took like 10 minutes

[jesusangel]

Thank you all for your effort, I'm a bit lost, what is the change to finally make? Tomorrow I'll have access to the teensy 4.1 to try all the drives that didn't work for me until now.

[mjs513]

Thank you all for your effort, I'm a bit lost, what is the change to finally make? Tomorrow I'll have access to the teensy 4.1 to try all the drives that didn't work for me until now.

Look at post #689 basically in mscInit comment out the msReset() line.

[wwatson]

@KurtE @mjs512 - Decided to just comment out "msReset()" call. Updated my version of USBHost_t36 with @PaulStoffregen version and did a PR for it and extending the timeouts defined in "msc.h".

Glad to see a lot of the problem USB drives are working now Sorry it took so long to discover the problem...

[KurtE]

I am still sort of curious on the speed of these drives:
So put an elapsedMillis into the sendObject code, and at the end (debug >= 1)

  printf("SendObject complete size:%u dt:%u\n", size, (uint32_t)emSendObject);

First run: Kingston SSD 240gb
SendObject complete size:6754230 dt:5839

Newer 250GB SSD
SendObject complete size:6754230 dt:5096

Old 8 GB Stick:
SendObject complete size:6754230 dt:8429

New 32 GB USB 3 stick:
SendObject complete size:6754230 dt:75461

So like 9 times slower than old stick and like 15 times slower than the SSDs

None of these was running using a HB, the SSDs are running and they have the USB3 connector (blue)

[jmarsh]

Is it just me or are there major race conditions in ehci.cpp? Lots of list manipulation happening without interrupts disabled and isr() being triggered can easily modify those same lists...

As a basic example, look at USBDriverTimer::Start(). Imagine there's already one active timer, so our timer will be added after it. Instruction flow reaches line 512 and the timer interrupt triggers for the already active timer; when the interrupt handler returns, our timer gets added after the now retired timer and will never be triggered.

[jesusangel]

Hi, thank you again, both Sandisk drives working now, CSW error is gone, but Kingston Datatraveler G2 keeps initializing infinitely as shown here. Maybe the unit is too old and is faulty but works on Windows, what I've noticed is when I plug into PC the led light flashes, aswell when writing/reading, but not when I plug into teensy even being detected and reported in log.

[mjs513]

@KurtE @mjs512 - Decided to just comment out "msReset()" call. Updated my version of USBHost_t36 with @PaulStoffregen version and did a PR for it and extending the timeouts defined in "msc.h".

Glad to see a lot of the problem USB drives are working now Sorry it took so long to discover the problem...

@wwatson - sounds good and again glad you tracked it down and it was a easy fix.

[KurtE]

Is it just me or are there major race conditions in ehci.cpp? Lots of list manipulation happening without interrupts disabled and isr() being triggered can easily modify those same lists...

As a basic example, look at USBDriverTimer::Start(). Imagine there's already one active timer, so our timer will be added after it. Instruction flow reaches line 512 and the timer interrupt triggers for the already active timer; when the interrupt handler returns, our timer gets added after the now retired timer and will never be triggered.

I understand what you are saying, but at least in many of these cases it may depend on who and how these methods are called. For example if you look in Serial.cpp,
where the txTimer is used.

Whenever we start or stop the timer, there hopefully is code in it like:

	NVIC_DISABLE_IRQ(IRQ_USBHS);
	txtimer.stop();  		// Stop longer timer.
	txtimer.start(100);		// Start a mimimal timeout
//	timer_event(nullptr);   // Try calling direct - fails to work 
	NVIC_ENABLE_IRQ(IRQ_USBHS);

So it disables the USB interrupt while it is mucking with the stuff.

I believe Paul originally set it up, this way and I then when I was working on Serial, I continued to do it how the earlier code was.

We could use sledgehammer and turn off all interrupts.

But we may not always know the context of how it is going to be called. That is, OK easy to disable all interrupts or specific interrupt, but now always sure it is OK to enable them afterwords. That is the change to the timer may only a part of changing a logical state.

Hope that makes sense

[jmarsh]

I understand what you are saying, but at least in many of these cases it may depend on who and how these methods are called. For example if you look in Serial.cpp,
where the txTimer is used.

Whenever we start or stop the timer, there hopefully is code in it like:

	NVIC_DISABLE_IRQ(IRQ_USBHS);
	txtimer.stop();  		// Stop longer timer.
	txtimer.start(100);		// Start a mimimal timeout
//	timer_event(nullptr);   // Try calling direct - fails to work 
	NVIC_ENABLE_IRQ(IRQ_USBHS);

So it disables the USB interrupt while it is mucking with the stuff.

I believe Paul originally set it up, this way and I then when I was working on Serial, I continued to do it how the earlier code was.

The mass storage code definitely isn't doing anything like that, data transfers are being queued with interrupts enabled which means there is the potential for list corruption (due to the interrupt service routine modifying the lists while they're being updated). I don't think it should be the responsibility of the individual USB device drivers to handle that; the lists are private to the host controller so the proper place would be in ehci.cpp.

We could use sledgehammer and turn off all interrupts.

But we may not always know the context of how it is going to be called. That is, OK easy to disable all interrupts or specific interrupt, but now always sure it is OK to enable them afterwords. That is the change to the timer may only a part of changing a logical state.

Hope that makes sense

Saving+clearing then restoring bit 7 of SREG (which is an AVR register but emulated in code for Teensy) is one way of disabling global interrupts without unconditionally turning them on at the end. Or else it's easy to make a reference counting class to disable/restore the state of the USBHS interrupt in the NVIC registers.

[KurtE]

Sorry, I am just trying to be pragmatic here and go with the flow.

As I mentioned, I have tried to keep things within the ways that Paul has used in some of these areas. And with the case you mentioned, tried to show where that should be currently handled. In other setups I would probably use things like semaphores and the like, but ...

Now if someone comes up with a better solution, that for example makes it easier and does not impact other things like the latency for higher priority interrupts, like maybe those who service the Audio board and Paul agrees, with it, I will happily adapt to the new...

In the meantime, if you know of specific places in the code which are currently at risk, please point those out, and hopefully we can plug the holes.

Thanks again!

P.S. - Before you mention it. Yes there should be better documentation for things like this. I just don't know where to put it. Readme file is one obvious place, however I don't believe Teensyduino installs the readme files for the different libraries it installs.
(It appears there are Readme files now...)

EDIT: One area I earlier suspected for unprotected structures was calls like:
queue_Data_Transfer(datapipeOut, CBW, sizeof(msCommandBlockWrapper_t), this); // Command stage.

Which we may need to look into:
Two cases:

a) The calls are made from within the ISR... in which case we are safe as the ISR will not be called again until we return. I think this is most of them.

b) Not within ISR... These we should for sure look at.

[BriComp]

however I don't believe Teensyduino installs the readme files for the different libraries it installs.

...loads of ReadMe.txt and other text/help files in my Teensy Libraries stored in C:\Program Files (x86)\Arduino\hardware\teensy\avr\libraries.

[KurtE]

...loads of ReadMe.txt and other text/help files in my Teensy Libraries stored in C:\Program Files (x86)\Arduino\hardware\teensy\avr\libraries.

You are right... For awhile, I did not see ones from some libraries I have worked on... like FlexIO... But it is there now
Thanks

[KurtE]

I am still sort of curious on the speed of these drives:
So put an elapsedMillis into the sendObject code, and at the end (debug >= 1)

  printf("SendObject complete size:%u dt:%u\n", size, (uint32_t)emSendObject);

First run: Kingston SSD 240gb
SendObject complete size:6754230 dt:5839

Newer 250GB SSD
SendObject complete size:6754230 dt:5096

Old 8 GB Stick:
SendObject complete size:6754230 dt:8429

New 32 GB USB 3 stick:
SendObject complete size:6754230 dt:75461

So like 9 times slower than old stick and like 15 times slower than the SSDs

None of these was running using a HB, the SSDs are running and they have the USB3 connector (blue)

@wwatson @mjs513 @defragster and all

I hacked up the USB_MTP-logger.ino sketch and added a write file test. Pretty primitive:

void test_write_file(int ch) {
  test_file_write_size = CommandLineReadNextNumber(ch, test_file_write_size);
  test_file_size = CommandLineReadNextNumber(ch, test_file_size);
  if (ch >= ' ') {
    Serial.setTimeout(0);
    int cb = Serial.readBytesUntil( '\n', test_file_name, sizeof(test_file_name));
  }
  File testFile; // Specifes that dataFile is of File type

  mscDisk->remove(test_file_name);  // try to remove files before as to force it to reallocate the file...
  
  testFile = mscDisk->open(test_file_name, FILE_WRITE_BEGIN);
  if (!testFile) {
    Serial.printf("Failed to open %s\n", test_file_name);
    return;
  }
  Serial.printf("Start write file: %s length:%u Write Size:%u\n", test_file_name, test_file_size, test_file_write_size);  

  uint32_t cb_write = test_file_write_size;
  uint32_t cb_left = test_file_size;
  uint8_t fill_char = '0';
  test_file_buffer[cb_write - 2] = '\n'; // make in to text...

  elapsedMillis em;
  while (cb_left) {
    if (cb_left < cb_write) cb_write = cb_left;
    memset(test_file_buffer, cb_write - 1, fill_char);
    testFile.write(test_file_buffer, cb_write);
    fill_char = (fill_char == '9')? '0' : fill_char + 1;
    cb_left -= cb_write;
  }  
  testFile.close();
  Serial.printf("Time to write: %u\n", (uint32_t)em);
  
}

Changes pushed up mtp_teensy:

Now running MMOD... With the slow drive:

Menu Options:
	1 - List USB Drives (Step 1)
	2 - Select USB Drive for Logging (Step 2)
	l - List files on disk
	e - Erase files on disk
	s - Start Logging data (Restarting logger will append records to existing log)
	x - Stop Logging data
	d - Dump Log
	w [write size] [size] [file name]
	r - reset MTP
	h - Menu

Start write file: write_test_file.txt length:1048576 Write Size:512
Time to write: 10959
Start write file: write_test_file.txt length:1048576 Write Size:64
Time to write: 10935
Start write file: write_test_file.txt length:1048576 Write Size:4096
Time to write: 258

Now with the 8GB stick I mentioned:

Dump Index List
Drive # 2 Selected
Start write file: write_test_file.txt length:1048576 Write Size:512
Time to write: 1270
Start write file: write_test_file.txt length:1048576 Write Size:64
Time to write: 912
Start write file: write_test_file.txt length:1048576 Write Size:4096
Time to write: 263

One the newer SSD:

Start write file: write_test_file.txt length:1048576 Write Size:512
Time to write: 802
Start write file: write_test_file.txt length:1048576 Write Size:64
Time to write: 788
Start write file: write_test_file.txt length:1048576 Write Size:4096
Time to write: 212

So those newer 32GB drives really want to write whole clusters! A lot more than the others appear to require.