Set Input and Output buffer size

[Panu]

VSOS uses HwLocks to achieve mutual exclusion across different libraries and threads. In USBHOST, the BlockRead and BlockWrite entry functions are protected by the mechanism

Code: Select all

	ObtainHwLocksBIP(HLB_NONE, HLIO_NONE, HLP_USB);
		...
	ReleaseHwLocksBIP(HLB_NONE, HLIO_NONE, HLP_USB);

which do mutual exclusion by obtaining a named peripheral lock HLP_USB.

-Panu

[Panu]

Here's an update to the USBHOST driver.

This one is able to run our stress test even when the memory stick is removed and reattached during the process.

I basically just kept adding timeouts to all the locations my updated stop trace shows it to get stuck at, and in the end it just seems to work.

It's sort of ad hoc, but it passes the stress test. Please test.

-Panu

[isonthomas]

Hi Panu,

Thanks for the new driver. I am continuing my testing and shall update the status. This is just to clarify two doubts that I have:

Basically I am facing two issues while working on USB:

1. USB operation seems stuck/takes too long.
2. Application Crash while working on USB.

I think the first case is when I am getting continuous NACKs from the USB stick. Here the 10ms delay added in the driver will enable the SPI operations so that I am able to respond back to the host but whatever USB operation is taking place it needs more than the usual time. What is your opinion on this?

For the application crash, I have mainly observed it in cases similar to that of the stack trace given in my previous post. Here my task playing the audio is trying to re-initialize the USB while another task is trying to read from this. My doubt is that, from the stack trace the re-initialization process did not get completed before the other task tried to read from the file. Could this be like a situation where the usb initialization did not get complete, i.e the USB is not completely ready for the operation but another task is trying to do the read operation.

The init usb function call has 2second delay added in its path. Since the delay enables other task, I will be processing my SPI command to read from the file to get the track name. While this happens my usb-initialization is not complete and all the settings might not be proper for a read operation. Is this a possibility?

Kindly let me know your thoughts on this.

-Ison

[isonthomas]

Hi,

Please find a trace below with ZeroPtrCallTrap. While I was playing song from the USB, the playback suddenly stopped. Here also, the issue occurred during usb device re-initialization.

Hello.<LF>
VSOS 3.35 build Oct 01 2016 18:11:47<LF>
VLSI Solution Oy 2012-2016 - www.vlsi.fi<LF>
<LF>
Starting the kernel..<LF>
Starting Devices... <LF>
Internal Flash<LF>
<LF>
Installed system devices:<LF>
S: SPI Flash c213, handled by FAT.<LF>
Load drivers, config 0...<LF>
Driver: INTTRACE... <LF>
Driver: AUOI2SMA... <LF>
Driver: S:MainApplication.ap3... K: SD card in SD mode<LF>
<LF>
VID_0781 PID_5567 SanDisk Cruzer Blade <LF>
1 drive(s).<LF>
U: USB Flash<LF>
E'RTCREAD not found'<LF>
IMEM: only 3400w free!<LF>
IMEM: only 2238w free!<LF>
Close device U:<LF>
No device.<LF>
E'RTCREAD not found'<LF>
<LF>
VID_0781 PID_5567 SanDisk Cruzer Blade <LF>
1 drive(s).<LF>
U: USB Flash<LF>
<LF>
VID_0781 PID_5567 SanDisk Cruzer Blade <LF>
E'RTCREAD not found'<LF>
<LF>
SOF count: 6749 <LF>
Stop at 21277(0x531d): USBHOST::WaitForUsbInt[8]<LF>
SOF count: 3577 <LF>
Task 0x093c, priority 10, in RUNNING, name "DECOD"<LF>
State: 3 (TS_READY)<LF>
Stack: Start 0x0254, size 0x17c, in use 0x7e, max used 0x15f (0x1d free)<LF>
Stack Trace: current PC 0x5ea3, Tasks::main[195]<LF>
Next: PC 0x1e81 @ stack 0x02db, KERNEL::LoadLibraryFile[10]<LF>
Next: PC 0x312f @ stack 0x02d5, IntTrace::IntReguC[47]<LF>
Next: PC 0x0009 @ stack 0x02c7, KERNEL::ZeroPtrCall$0[9]<LF>
Next: PC 0x518c @ stack 0x02bc, USBHOST::UsbSetupReadOperation[11]<LF>
Next: PC 0x52c5 @ stack 0x02b2, USBHOST::OpenUsbDevice[26]<LF>
Next: PC 0x4dc3 @ stack 0x02ae, USBHOST::DevUMassProbe[10]<LF>
Next: PC 0x4d04 @ stack 0x02a6, USBHOST::DevUMassBlockRead[51]<LF>
Next: PC 0x0c55 @ stack 0x029c, KERNEL::FatImageSectorRead[58]<LF>
Next: PC 0x1278 @ stack 0x0293, KERNEL::VoFatReadFile[84]<LF>
Next: PC 0x5851 @ stack 0x0288, AUDIODEC::DefaultCSRead[90]<LF>
Next: PC 0xd6d4 @ stack 0x027c, IROM::CodMpg[244]<LF>
Next: PC 0x5bca @ stack 0x0270, DECMP3::CodMpgDecode[269]<LF>
Next: PC 0x57f0 @ stack 0x0260, AUDIODEC::MyDecodeAudio[16]<LF>
Next: PC 0x3abd @ stack 0x0259, MainAppl::PlayerTask[15]<LF>
<LF>
Task 0x1c01, priority 10, in readyQueue, name "cyclic"<LF>
State: 3 (TS_READY)<LF>
Stack: Start 0x1c10, size 0x100, in use 0x29, max used 0x3d (0xc3 free)<LF>
Stack Trace: current PC 0x918f, IROM::rtos2[231]<LF>
Next: PC 0x2bcb @ stack 0x1c1e, KERNEL::CyclicMainLoop[97]<LF>
Next: PC 0x90b5 @ stack 0x1c11, IROM::exit<LF>
Registers:<LF>
i0:0x1c1f i1:0x0012 i2:0x1fd9 i3:0x1c08<LF>
i4:0x1c1e i5:0x0000 i6:0x1c2b i7:0xfc08<LF>
a2:0x0000 a1:0x0004 a0:0x8000 b2:0x0000 b1:0x0000 b0:0x0000<LF>
c2:0xffff c1:0xffff c0:0xdf2c d2:0x0000 d1:0x0005 d0:0x0004<LF>
p1:0x0000 p0:0x0000 ls:0xebab le:0xffff lc:0x0000 mr0:0x0210 lr0:0x9184<LF>
<LF>
Task 0x1e15, priority 1, in readyQueue, name "Command_Response"<LF>
State: 3 (TS_READY)<LF>
Stack: Start 0x22dc, size 0x800, in use 0x17, max used 0xff (0x701 free)<LF>
Stack Trace: current PC 0x369c, MainAppl::Command_Response_Task[64]<LF>
Next: PC 0x90b5 @ stack 0x22dd, IROM::exit<LF>
Registers:<LF>
i0:0x0e28 i1:0x0c64 i2:0x0c63 i3:0x0e2a<LF>
i4:0x22de i5:0xffe9 i6:0x22e5 i7:0xfc09<LF>
a2:0x0000 a1:0x0c18 a0:0x00ff b2:0x0000 b1:0x0002 b0:0x0008<LF>
c2:0x0000 c1:0x0704 c0:0xffef d2:0xffff d1:0xffff d0:0x0604<LF>
p1:0x0000 p0:0x003c ls:0xebab le:0xffff lc:0x0000 mr0:0x0288 lr0:0x373a<LF>
<LF>
Task 0x0021, priority 1, in readyQueue, name "MainTask"<LF>
State: 3 (TS_READY)<LF>
Stack: Start 0x0030, size 0x200, in use 0x60, max used 0x183 (0x7d free)<LF>
Stack Trace: current PC 0x38c1, MainAppl::main[185]<LF>
Next: PC 0x03c6 @ stack 0x007c, KERNEL::LoadDrivers[204]<LF>
Next: PC 0x048e @ stack 0x003e, KERNEL::main[142]<LF>
Next: PC 0x0087 @ stack 0x0032, KERNEL::startup[7]<LF>
Registers:<LF>
i0:0x0e28 i1:0x3800 i2:0x1f09 i3:0x001e<LF>
i4:0x007c i5:0x0000 i6:0x0082 i7:0x1e15<LF>
a2:0x0000 a1:0x0702 a0:0x0102 b2:0x0000 b1:0x0000 b0:0x0014<LF>
c2:0x0000 c1:0x0001 c0:0x1f09 d2:0x0000 d1:0x0003 d0:0x0b76<LF>
p1:0x0000 p0:0x000e ls:0x03d2 le:0x03dd lc:0x0000 mr0:0x0281 lr0:0x38b1<LF>
<LF>
Timer queue 0x1c1f for task 0x1c01 ("cyclic")<LF>
Tick count: 0x0000<LF>
<LF>
Interrupts:<LF>
INT 0 INT_DAC , pri 2, vector 0x9385= IROM::AudioBufFree[12]<LF>
INT 4 INT_SPI1 , pri 3, vector 0x38fb= MainAppl::Spi1IntAsm<LF>
INT 13 INT_UART_RX , pri 1, vector 0x809b= IROM::monitorVectors[140]<LF>
INT 15 INT_TIMER1 , pri 2, vector 0x020d= KERNEL::SetNextApp[47]<LF>
INT 16 INT_TIMER2 , pri 2, vector 0x29a7= KERNEL::SystemUiMessageCyclic[23]<LF>
INT 25 INT_REGU , pri 1, vector 0x315d= IntTrace::IntReguAsm<LF>

I will try to get some more stack traces

-Ison

[Panu]

Hi Ison...
Great that you are making progress... sorry I'm in a bit of a bad shape to help you right now... but you are on the right track with what you are doing. Reinitialization of the driver is the key, as well as identifying all locations where the code still gets stuck. Maybe you can look at the hardware protections... the BlockRead and BlockWrite functions are protected by obtaining a hardware lock, so there shouldn't be more than one instance of the USBHOST accessing the bus at one time. main() is not, so bad things happen if someone calls usbhost::main() when a transfer is in progress. But main() is not supposed to be called after the driver is loaded. Maybe there's a structural fallacy in the way the USBHOST initialization is written. Can you try one thing. Rename the main() function of USBHOST to be init() so that it's only called once and see what happens. If you have some RunLibraryFunction or RunLoadedFunction line in your program that calls ENTRY_MAIN, remove those, since the main() function does not exist any more. Or add a dummy main() like this:

DEVICE usbFlash[4];
char usbSystemDevices[4] = {0};

int main(char *parameters){
}

int init(char *parameters) {
u_int16 nDisks;
u_int16 i;

nDisks = DevUMassProbe();

...etc...

If we are lucky, renaming main() to init() fixes problems. If we are unlucky, it disables some recovery mechanism from hardware failure. We'll see. Sorry that I can't test it right now, I'm not at the office.

-Panu

[isonthomas]

Hi Panu,

Thanks for the input and hope that you get well soon.. . I will try out the new changes.

But just one point of clarification. I doubt whether the driver re-intialization as such is happening, in the sense that the main function is getting called again. In DevUMassBlockWrite and DevUMassBlockRead we are re-initializing the device by calling DevUMassProbe if the scsi request return error. Maybe this is where the device is getting re-initialized again and creating the issues? Just a thought, it might be a different case all-together.

Code: Select all

	  
	  st = scsi_request(SCSI_READ_10,epin,epout,data,blocks*512,hw->lun,scp);
	  
	  if (st == E_AGAIN) {
	    // Try same request again 
	    debug_printf1("GOT E_AGAIN\n");
	    continue;
	    
	  } else if (st == S_ERROR) {
	    // Try reconfigure usb_bus	  
	    if (DevUMassProbe() == S_ERROR) {
	      dev->flags = __MASK_PRESENT | __MASK_SEEKABLE | __MASK_READABLE | __MASK_WRITABLE;
	      return S_ERROR;
	    }

I will make the changes in main and init and test it out. Will update the results later

-Ison

[dalibor2000]

Just a quick update...in case it helps.
On some USB drives, we find that the application gets stuck during fopen(), unlink() and fclose() operations. This is when we observe VID and PID printouts coming from the USB host.
Dalibor

[Panu]

Hi, sorry I'm still in a bad shape and of not much help.

I doubt whether the driver re-intialization as such is happening, in the sense that the main function is getting called again. In DevUMassBlockWrite and DevUMassBlockRead we are re-initializing the device by calling DevUMassProbe if the scsi request return error.

Right, my point is that DevUMassBlockRead and DevUMassBlockWrite have ObtainLocks protection, which ensures that only one copy is running. But main() has not, so if it's a re-entrancy issue then I can only see main() as a possible entry point to the driver that is not protected. Another entry point is DevUMassIoctl, but that only calls BlockRead (and StartFileSystem which also just calls BlockRead) so that route should be protected through the BlockRead ObtainLock.

Maybe it's not a re-entrancy issue at all, maybe it is an electrical failure that triggers reinitialization of the driver and the code gets stuck because something bad is happening electrically, and there's more possible deadlock locations in the startup code than in the block read/write code. We need to add timeouts to all stop locations, one by one.

On some USB drives, we find that the application gets stuck during fopen(), unlink() and fclose() operations. This is when we observe VID and PID printouts coming from the USB host.

Ok.. have you installed the tracing libraries (INTTRACE, TRACE etc) so that you can get a Power button Stop trace when the device hangs? Please always get a stop trace when the unit hangs. We need to examine all stop locations and add timeout code to all the functions everywhere where it gets stuck. Like in Ison's last trace there's

Stop at 21277(0x531d): USBHOST::WaitForUsbInt[8]

so we should look at the start of WaitForUsbInt if there's still a deadlock possibility (while loop) there. But it's so strange, my current version's WaitForUsbInt is

Code: Select all

u_int16 WaitForUsbInt(u_int16 mask) {
	u_int16 timeout = 0;	
	u_int16 ret;
	do {
		if (timeout++ > 10000) return 0;
		ret = PERIP(USB_STATUS);
	} while ((ret&mask) == 0);
	PERIP(USB_STATUS) = ret&mask;
	return ret;
}

which has a timeout, so it shouldn't be possible for it to deadlock, so I wonder how your stop trace can show it to be running there? Either your driver version does not have that timeout code or the code is not deadlocked there (it may be looping a larger loop). Can you verify that you are running a driver with this timeout code?

-Panu

PS. There's still the irritating fact that when I use the Developer Board, the driver basically survives anything that I can throw at it, including power outages, cut signal wires, even with four separate concurrent tasks accessing it. So the bug might be something completely different, or in a completely different location, maybe not even related to USB. So let's keep our minds open to all possibilities.

But first find out how on Earth it can be stuck at WaitForUsbInt. Is the timeout code there?

[Panu]

For my own analysis, I wrote new versions of IntTrace and Trace. This IntTrace uses Timer1 to sample 10 execution points and list all of them at the Power button press so it's easier to see where the code is running about, than just the one stop point (you can see if it's really just inside the one function or if it's in a longer loop across different functions). I didn't send it earlier because it uses Timer1 and it clashes with your Timer1 use. I was planning to change it to use Timer0 so it would be easy for you to use, but I can't do that now. So now I send it in case you can change your code or maybe this code to use Timer0 instead......

I also recompiled Trace to give easier to read output, and now it also shows the Kernel interrupt handlers correctly. Please consider using these as best as you can. Hope this helps..

-Panu

[dalibor2000]

Hi,

Ok.. have you installed the tracing libraries (INTTRACE, TRACE etc) so that you can get a Power button Stop trace when the device hangs? Please always get a stop trace when the unit hangs. We need to examine all stop locations and add timeout code to all the functions everywhere where it gets stuck. Like in Ison's last trace there's

We will do this and post the results.

Maybe it's not a re-entrancy issue at all, maybe it is an electrical failure that triggers reinitialization of the driver and the code gets stuck because something bad is happening electrically, and there's more possible deadlock locations in the startup code than in the block read/write code.

We checked this already and could not find any issues. Will put the scope on it again just in case we missed something.

There's still the irritating fact that when I use the Developer Board, the driver basically survives anything that I can throw at it, including power outages, cut signal wires, even with four separate concurrent tasks accessing it. So the bug might be something completely different, or in a completely different location, maybe not even related to USB. So let's keep our minds open to all possibilities.

You should have our unit now...perhaps this will help the debug process once you are feeling better.
Thanks.
Dalibor