On Tue, Oct 09, 2012 at 02:31:05PM +0200, Christian Gmeiner wrote:
2012/10/9 Kevin O'Connor kevin@koconnor.net:
On Mon, Oct 08, 2012 at 02:14:03PM +0200, Christian Gmeiner wrote:
HI all
I am running into some usb problems with coreboot & seabios:
Can you set the debug level to 8 and post the whole log? Also, for timeout issues, having timestamps (via tools/readserial.py tool) sometimes helps.
Attached
Hrmm, I guess you've disabled threads in your config?
From your log, I see:
[14:23:00.5] ehci_send_bulk qh=0x000ef680 dir=0 data=0x00006d55 size=31^M [14:23:00.5] ehci_send_bulk qh=0x000ef700 dir=128 data=0x00006e3c size=36^M [14:23:00.5] ehci_send_bulk qh=0x000ef700 dir=128 data=0x00006d8f size=13^M [14:23:05.5] WARNING - Timeout at ehci_wait_td:542!^M [14:23:05.5] ehci pipe=0x000ef700 cur=00000000 tok=00000000 next=6b80 td=0x00006b80 +status=d0d80^M [14:23:05.5] USB transmission failed^M [14:23:05.5] Unable to configure USB MSC drive.^M
This looks like the transfer is stalling in the cdb_get_inquiry() call as part of scsi_init_drive(). The drive is identified okay and at least some transfers look okay, so it doesn't appear to be a controller issue.
I've been told some USB sticks are very picky about init order, but I'm surprised to see that this is occuring for you on a variety of USB sticks.
It's possible to verify that a stall has occurred - print out tds[i].token for all tds in ehci_send_bulk() on the error path.
Does this device still have problems if you soft-reset after a failed boot?
-Kevin
2012/10/11 Kevin O'Connor kevin@koconnor.net:
On Tue, Oct 09, 2012 at 02:31:05PM +0200, Christian Gmeiner wrote:
2012/10/9 Kevin O'Connor kevin@koconnor.net:
On Mon, Oct 08, 2012 at 02:14:03PM +0200, Christian Gmeiner wrote:
HI all
I am running into some usb problems with coreboot & seabios:
Can you set the debug level to 8 and post the whole log? Also, for timeout issues, having timestamps (via tools/readserial.py tool) sometimes helps.
Attached
Hrmm, I guess you've disabled threads in your config?
yep...
From your log, I see:
[14:23:00.5] ehci_send_bulk qh=0x000ef680 dir=0 data=0x00006d55 size=31^M [14:23:00.5] ehci_send_bulk qh=0x000ef700 dir=128 data=0x00006e3c size=36^M [14:23:00.5] ehci_send_bulk qh=0x000ef700 dir=128 data=0x00006d8f size=13^M [14:23:05.5] WARNING - Timeout at ehci_wait_td:542!^M [14:23:05.5] ehci pipe=0x000ef700 cur=00000000 tok=00000000 next=6b80 td=0x00006b80 +status=d0d80^M [14:23:05.5] USB transmission failed^M [14:23:05.5] Unable to configure USB MSC drive.^M
This looks like the transfer is stalling in the cdb_get_inquiry() call as part of scsi_init_drive(). The drive is identified okay and at least some transfers look okay, so it doesn't appear to be a controller issue.
I've been told some USB sticks are very picky about init order, but I'm surprised to see that this is occuring for you on a variety of USB sticks.
It's possible to verify that a stall has occurred - print out tds[i].token for all tds in ehci_send_bulk() on the error path.
Does this device still have problems if you soft-reset after a failed boot?
Here are the results with some more debug:
Cold Reboot ------------
|0f7a5000| pmm_malloc zone=0x0f7afe87 handle=ffffffff size=192 align=40 ret=0x0f7a7bc0 (detail=0x0f7a7d70) |0f7a5000| ehci_control: td at phys(f7a7bc0): status: 80 : token 80e80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_control: td at phys(f7a7c00): status: 0 : token d00 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_control: td at phys(f7a7c40): status: 0 : token 0 |0f7a5000| - cerr: 0, total_len: 0 |0f7a5000| pmm_free 0x0f7a7bc0 (detail=0x0f7a7d70) |0f7a5000| ehci_alloc_async_pipe 0x0f7a9090 2 |0f7a5000| pmm_malloc zone=0x0f7afe7f handle=ffffffff size=92 align=80 ret=0x000ef700 (detail=0x0f7a7d70) |0f7a5000| ehci_alloc_async_pipe 0x0f7a9090 2 |0f7a5000| pmm_malloc zone=0x0f7afe7f handle=ffffffff size=92 align=80 ret=0x000ef680 (detail=0x0f7a7d10) |0f7a5000| ehci_control 0x0f7a7cd0 (dir=128 cmd=8 data=1) |0f7a5000| pmm_malloc zone=0x0f7afe87 handle=ffffffff size=192 align=40 ret=0x0f7a7bc0 (detail=0x0f7a7ce0) |0f7a5000| ehci_control: td at phys(f7a7bc0): status: 80 : token 80e80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_control: td at phys(f7a7c00): status: 0 : token d00 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_control: td at phys(f7a7c40): status: 0 : token 1c00 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| pmm_free 0x0f7a7bc0 (detail=0x0f7a7ce0) |0f7a5000| pmm_malloc zone=0x0f7afe83 handle=ffffffff size=48 align=10 ret=0x000fdae0 (detail=0x0f7a7ce0) |0f7a5000| usb_cmd_data id=0x000fdae0 write=0 count=1 bs=36 buf=0x0f7a5f3c |0f7a5000| cbw to device |0f7a5000| ehci_send_bulk qh=0x000ef680 dir=0 data=0x0f7a5e65 size=31 |0f7a5000| before setup: td at phys(f7a5c80): status: 0 : token 0 |0f7a5000| - cerr: 0, total_len: 0 |0f7a5000| ehci_send_bulk: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| Data-In from the device to the host - 36 bytes |0f7a5000| ehci_send_bulk qh=0x000ef700 dir=128 data=0x0f7a5f3c size=36 |0f7a5000| before setup: td at phys(f7a5c80): status: 0 : token 0 |0f7a5000| - cerr: 0, total_len: 0 |0f7a5000| ehci_send_bulk: td at phys(f7a5c80): status: 80 : token d80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token d80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token d80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token d80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token d80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token d80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token d80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token d80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token d80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token d80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token d80 |0f7a5000| - cerr: 3, total_len: 0
Warm Reboot -----------
0f7a5000| pmm_free 0x0f7a7bc0 (detail=0x0f7a7d70) |0f7a5000| ehci_alloc_async_pipe 0x0f7a9090 2 |0f7a5000| pmm_malloc zone=0x0f7afe7f handle=ffffffff size=92 align=80 ret=0x000ef700 (detail=0x0f7a7d70) |0f7a5000| ehci_alloc_async_pipe 0x0f7a9090 2 |0f7a5000| pmm_malloc zone=0x0f7afe7f handle=ffffffff size=92 align=80 ret=0x000ef680 (detail=0x0f7a7d10) |0f7a5000| ehci_control 0x0f7a7cd0 (dir=128 cmd=8 data=1) |0f7a5000| pmm_malloc zone=0x0f7afe87 handle=ffffffff size=192 align=40 ret=0x0f7a7bc0 (detail=0x0f7a7ce0) |0f7a5000| ehci_control: td at phys(f7a7bc0): status: 80 : token 80e80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_control: td at phys(f7a7c00): status: 0 : token d00 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_control: td at phys(f7a7c40): status: 0 : token 1c00 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| pmm_free 0x0f7a7bc0 (detail=0x0f7a7ce0) |0f7a5000| pmm_malloc zone=0x0f7afe83 handle=ffffffff size=48 align=10 ret=0x000fdae0 (detail=0x0f7a7ce0) |0f7a5000| usb_cmd_data id=0x000fdae0 write=0 count=1 bs=36 buf=0x0f7a5f3c |0f7a5000| cbw to device |0f7a5000| ehci_send_bulk qh=0x000ef680 dir=0 data=0x0f7a5e65 size=31 |0f7a5000| before setup: td at phys(f7a5c80): status: 0 : token 0 |0f7a5000| - cerr: 0, total_len: 0 |0f7a5000| ehci_send_bulk: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0 |0f7a5000| ehci_wait_td: td at phys(f7a5c80): status: 80 : token c80 |0f7a5000| - cerr: 3, total_len: 0
This is the used patch:
diff --git a/src/usb-ehci.c b/src/usb-ehci.c index 2676615..92a9c60 100644 --- a/src/usb-ehci.c +++ b/src/usb-ehci.c @@ -178,6 +178,14 @@ check_ehci_ports(struct usb_ehci_s *cntl) * Setup ****************************************************************/
+static void dump_td(struct ehci_qtd *td, const char *func) +{ + u32 addr = (u32)td; + dprintf(1, "%s: td at phys(%x): status: %x : token %x\n", func, addr, td->token & QTD_STS_MASK, td->token); + dprintf(1, "- cerr: %x, total_len: %x\n", (td->token & QTD_CERR_MASK) >> QTD_CERR_SHIFT, + (td->token & QTD_LENGTH_MASK) >> QTD_LENGTH_SHIFT); +} + // Wait for next USB async frame to start - for ensuring safe memory release. static void ehci_waittick(struct usb_ehci_s *cntl) @@ -535,6 +543,9 @@ ehci_wait_td(struct ehci_pipe *pipe, struct ehci_qtd *td, int timeout) status = td->token; if (!(status & QTD_STS_ACTIVE)) break; + + dump_td(td, __func__); + if (check_tsc(end)) { u32 cur = GET_LOWFLAT(pipe->qh.current); u32 tok = GET_LOWFLAT(pipe->qh.token); @@ -633,6 +644,7 @@ ehci_control(struct usb_pipe *p, int dir, const void *cmd, int cmdsize int i, ret=0; for (i=0; i<3; i++) { struct ehci_qtd *td = &tds[i]; + dump_td(td, __func__); ret = ehci_wait_td(pipe, td, 500); if (ret) break; @@ -665,18 +677,25 @@ ehci_send_bulk(struct usb_pipe *p, int dir, void *data, int datasize) struct ehci_qtd *td = &tds[tdpos++ % STACKQTDS]; int ret = ehci_wait_td(pipe, td, 5000); if (ret) + { + dump_td(td, "ehci_send_bulk ERROR2"); return -1; + }
struct ehci_qtd *nexttd_fl = MAKE_FLATPTR(GET_SEG(SS) , &tds[tdpos % STACKQTDS]);
+ dump_td(td, "before setup"); + int transfer = fillTDbuffer(td, maxpacket, data, datasize); td->qtd_next = (transfer==datasize ? EHCI_PTR_TERM : (u32)nexttd_fl); td->alt_next = EHCI_PTR_TERM; barrier(); - td->token = (ehci_explen(transfer) | QTD_STS_ACTIVE + td->token = (/*ehci_explen(transfer) | */QTD_STS_ACTIVE | (dir ? QTD_PID_IN : QTD_PID_OUT) | ehci_maxerr(3));
+ dump_td(td, __func__); + data += transfer; datasize -= transfer; } @@ -685,7 +704,10 @@ ehci_send_bulk(struct usb_pipe *p, int dir, void *data, int datasize) struct ehci_qtd *td = &tds[tdpos++ % STACKQTDS]; int ret = ehci_wait_td(pipe, td, 5000); if (ret) + { + dump_td(td, "ehci_send_bulk ERROR2"); return -1; + } }
return 0;
greets --- Christian Gmeiner, MSc
-
Christian Gmeiner -
Kevin O'Connor