|
Description
|
Category
driver
Sub-Category
usb-ehci
Description
When free kernel memory is low, the usb mass storage device driver has
problems recovering from bulk requests failing with USB_NO_RESOURCES.
The error is comming from ehci, which is getting failed ddi_dma_mem_alloc
calls, like this (I found this error message in usba_debug_buf):
ehci0: ehci_create_transfer_wrapper: dma_mem_alloc fail
This error happens during the usb mass storage scsi data transfer phase.
That is, a scsi read or write command has been submitted as a bulk request
to the usb mass storage device, it completes. Next step: a bulk request for
the data phase is submitted to the ehci (or uhci/ohci) host controller driver,
ehci tries to allocate DMA memory for the bulk request, and this fails.
Note that ehci_create_transfer_wrapper is always using kmem_alloc with
KM_NOSLEEP flag, and ddi_dma_* calls with DDI_DMA_DONTWAIT. When free
kernel memory is low, these calls could be failing.
At this point the usb mass storage device turns into a brick, it seems. It
seems to be waiting forever for the data transfer for the pending scsi
read or write command to start, but that never happens. There are attempts
to reset the usb mass storage device, but these run into timeouts as well.
The mass store device resets are also failing with errors.
On the console the user will see something like this:
WARNING: /pci@0,0/pci1011,24@c/pci9710,1906@6,2/storage@4/disk@0,0 (sd3):
SCSI transport failed: reason 'tran_err': retrying command
WARNING: /pci@0,0/pci1011,24@c/pci9710,1906@6,2/storage@4/disk@0,0 (sd3):
SCSI transport failed: reason 'timeout': retrying command
WARNING: /pci@0,0/pci1011,24@c/pci9710,1906@6,2/storage@4/disk@0,0 (sd3):
SCSI transport failed: reason 'timeout': giving up
WARNING: /pci@0,0/pci1011,24@c/pci9710,1906@6,2/storage@4/disk@0,0 (sd3):
SCSI transport failed: reason 'timeout': giving up
...
WARNING: /pci@0,0/pci1011,24@c/pci9710,1906@6,2/storage@4/disk@0,0 (sd3):
SCSI transport failed: reason 'timeout': giving up
panic[cpu0]/thread=ccf0ede0:
ZFS: I/O failure (write on /dev/dsk/c4t0d0p0 off 5859e800: zio d9b44240 [L0
unallocated] vdev=0 offset=5819e800 size=1000L/c00P/c00A fletcher2 lzjb LE
contiguous
birth=66 fill=0
cksum=e5df659b9ece4544:9d661997c3cc1026:9fa3633b5e58de81:3753938f5e3d4327):
error 6
ccf0ec7c zfs:zio_done+2e3 (d9b44240)
ccf0ec9c zfs:zio_next_stage+f1 (d9b44240)
ccf0ecbc zfs:zio_wait_for_children+61 (d9b44240, 13, d9b44)
ccf0ecdc zfs:zio_wait_children_done+18 (d9b44240)
ccf0ecf8 zfs:zio_next_stage+f1 (d9b44240)
ccf0ed2c zfs:zio_vdev_io_assess+148 (d9b44240)
ccf0ed40 zfs:zio_next_stage+f1 (d9b44240)
ccf0ed54 zfs:vdev_disk_io_done+2b (d9b44240, 0, ccf0ed)
ccf0ed64 zfs:vdev_io_done+18 (d9b44240, 158, ccf0)
ccf0ed78 zfs:zio_vdev_io_done+e (d9b44240, 0, 0, 0, )
ccf0edc8 genunix:taskq_thread+194 (c8809180, 0)
ccf0edd8 unix:thread_start+8 ()
syncing file systems...
done
dumping to /dev/dsk/c0d0s1, offset 215154688, content: kernel
::usba_debug_buf contents, 1-2 minutes after the first tran_err / timeout
messages:
(note the "ehci0: ehci_create_transfer_wrapper: dma_mem_alloc fail"
message, resulting in a -2 USB_NO_RESOURCES error from
usb_pipe_bulk_xfer. scsa2usb error recovery fails; a device reset is
failing with 0xc USB_CR_TIMEOUT. It seems scsa2usb doesn't recover
from this error. Root cause for the failed dma memory allocation
appears to be zfs, which consumes all available physical memory)
.
.
.
[ deleted lots of debug output, containing no scsa2usb errors ]
.
.
.
s2u2: scsa2usb_bulk_only_transport: sent cmd = 0x2a Tag = 0x1c7b DataXferLen =
0x1000 rval = 0
s2u2: scsa2usb_handle_data_start: BEGIN cmd = d56342c4, req = d558a51c
s2u2: scsa2usb_bp_to_mblk:
s2u2: scsa2usb_bp_to_mblk: mp=0xc901cdc0 bp=0xcdb5c658 pkt=0xd5634280 off=0x0
sz=4096 add=0xca304000
usbai: usba_hold_ph_data: ph_impl=0xc83dc2f0 state=1 ref=1
usbai: usb_pipe_bulk_xfer: req=0xd558a51c uf=0x100
usbai: usba_check_req: ph_data=0xcff27080 req=0xd558a51c flags=0x100
usbai: usba_check_req: attrs = 0x2 flags=0x101
usbai: usba_pipe_new_state: ph_data=0xcff27080 old=<idle> new=<active> ref=1 re
q=1
ehci0: usba_hcdi_cb: ph_data=0xcff27080 req=0xd558a51c state=2 ref=1 cnt=1 cr=0
usba: usba_add_to_list: head=0xcff270d0 element=0xd558a4c0 count=1
usbai: usba_async_ph_req: ph_data=0xcff27080 func=0xf9defb14, arg=0xcff27080 fl
ag=0x0
ehci0: hcdi_cb_thread: ph_data=0xcff27080 ref=2
usba: usba_rm_first_from_list: head=0xcff270d0 el=0xd558a4c0 cnt=0
ehci0: hcdi_do_cb: wrp=0xd558a4c0 cr=0x0
usbai: usba_req_normal_cb: ph_data=0xcff27080 state=2 wrp=0xd558a4c0 ref=2 req=
1
usbai: usba_pipe_new_state: ph_data=0xcff27080 old=<active> new=<idle> ref=2 re
q=1
usba: usba_rm_first_from_list: head=0xcff27084 el=0x0 cnt=0
usbai: usba_start_next_req done: ph_data=0xcff27080 state=1
usba: usba_rm_first_from_list: head=0xcff270d0 el=0x0 cnt=0
ehci0: hcdi_cb_thread done: ph_data=0xcff27080
usbai: usba_release_ph_data: ph_impl=0xc83dc2f0 state=1 ref=2
usbai: usba_release_ph_data: req_count=0
usbai: usba_pipe_sync_wait: ph_data=0xcff27080 cr=0x0
usbai: usb_pipe_bulk_xfer: rval=0
usbai: usba_release_ph_data: ph_impl=0xc83dc2f0 state=1 ref=1
usbai: usba_release_ph_data: req_count=0
s2u2: scsa2usb_handle_data_start: rval=0 cr=0
s2u2: scsa2usb_handle_data_start: END bulk-out data rval = 0
s2u2: scsa2usb_handle_data_done:
cmd = 0xd56342c4 data = 0xc901cdc0 len = 0x1000
s2u2: len = 0x1000 total = 0x1000
s2u2: scsa2usb_handle_status_start: req = 0xd558a51c
usbai: usba_hold_ph_data: ph_impl=0xc83dc584 state=1 ref=1
usbai: usb_pipe_bulk_xfer: req=0xd558a51c uf=0x100
usbai: usba_check_req: ph_data=0xcff27100 req=0xd558a51c flags=0x100
usbai: usba_check_req: attrs = 0x1 flags=0x101
usbai: usba_pipe_new_state: ph_data=0xcff27100 old=<idle> new=<active> ref=1 re
q=1
ehci0: usba_hcdi_cb: ph_data=0xcff27100 req=0xd558a51c state=2 ref=1 cnt=1 cr=0
usba: usba_add_to_list: head=0xcff27150 element=0xd558a4c0 count=1
usbai: usba_async_ph_req: ph_data=0xcff27100 func=0xf9defb14, arg=0xcff27100 fl
ag=0x0
ehci0: hcdi_cb_thread: ph_data=0xcff27100 ref=2
usba: usba_rm_first_from_list: head=0xcff27150 el=0xd558a4c0 cnt=0
ehci0: hcdi_do_cb: wrp=0xd558a4c0 cr=0x0
usbai: usba_req_normal_cb: ph_data=0xcff27100 state=2 wrp=0xd558a4c0 ref=2 req=
1
usbai: usba_pipe_new_state: ph_data=0xcff27100 old=<active> new=<idle> ref=2 re
q=1
usba: usba_rm_first_from_list: head=0xcff27104 el=0x0 cnt=0
usbai: usba_start_next_req done: ph_data=0xcff27100 state=1
usba: usba_rm_first_from_list: head=0xcff27150 el=0x0 cnt=0
ehci0: hcdi_cb_thread done: ph_data=0xcff27100
usbai: usba_release_ph_data: ph_impl=0xc83dc584 state=1 ref=2
usbai: usba_release_ph_data: req_count=0
usbai: usba_pipe_sync_wait: ph_data=0xcff27100 cr=0x0
usbai: usb_pipe_bulk_xfer: rval=0
usbai: usba_release_ph_data: ph_impl=0xc83dc584 state=1 ref=1
usbai: usba_release_ph_data: req_count=0
s2u2: scsa2usb_handle_status_start: END rval = 0x0
s2u2: CSW: Signature = 0x53425355 Status = 00 Tag = 0x1c7b Residue = 0x0
s2u2: scsa2usb_handle_csw_result: CSW GOOD, resid: 0x0
usbai: usb_free_bulk_req: req=0xd558a51c
usbai: usba_req_wrapper_free: wrp=0xd558a4c0
usba: usba_rm_from_list: head=0xcff27104 element=0xd558a4c0 count=0
usba: usba_rm_from_list: head=0xc83dc908 element=0xd558a4dc count=1
usba: usba_rm_from_list success: head=0xc83dc908 element=0xd558a4dc cnt=0
s2u2: scsa2usb_transport_request: transport rval = 1
s2u2: scsa2usb_pkt_completion:
scsa2usbp = 0xc83db200 reason=0, status=0 state=0x0 stats=0x0 resid=0x0
s2u2: scsa2usb_scsi_destroy_pkt: pkt=0xd5634280
s2u2: scsa2usb_work_thread: exit
s2u2: scsa2usb_pm_idle_component: 0
s2u2: scsa2usb_scsi_init_pkt: mapped in 0xcdb5c658, addr=0xe0b59000
s2u2: scsa2usb_scsi_init_pkt: ap = 0xc85a0a10 pkt: 0xd5634280
bp = 0xcdb5c658 cmdlen = a stlen = 0x20 tlen = 0x0 flags = 0x40001
s2u2: scsa2usb_scsi_start:
bp: 0xcdb5c658 ap: 0xd5634284 pkt: 0xd5634280 flag: 0x0 time: 0x3c
cdb0: 0x28 dev_state: 0x1 pkt_state: 0x0 flags: 0x7 pipe_state: 0x0
s2u2: scsa2usb_prepare_pkt: pkt=0xd5634280 cdb: 0x28 (read10)
usba: usba_add_to_list: head=0xc83db238 element=0xd5634328 count=1
s2u2: scsa2usb_work_thread_id=0x0, count=1, lun=0
usbai: usb_async_req: dip=0xc7b1e768 func=0xf9e22285, arg=0xc83db200 flag=0x100
s2u2: scsa2usb_work_thread start: thread_id=0x1
s2u2: scsa2usb_raise_power:
s2u2: scsa2usb_pm_busy_component: 1
s2u2: scsa2usb_open_usb_pipes: dip = 0xc7b1e768 flag = 0x7
usba: usba_rm_first_from_list: head=0xc83db238 el=0xd5634328 cnt=0
s2u2: scsa2usb_transport_request: cmd=0xd56342c4 bp=0xcdb5c658 addr=0xe0b59000
s2u2: scsa2usb_cmd_transport: pkt: 0xd5634280, cur_pkt = 0x0
s2u2: scsa2usb_check_bulkonly_blacklist_attrs: opcode = read10
s2u2: scsa2usb_handle_scsi_cmd_sub_class: cmd = 0xd56342c4 pkt = 0xd5634280
s2u2: scsa2usb_rw_transport:
s2u2: bcount=0x15800 lba=0xb0814 len=0x20 xfercount=0x10000 total=0x15800
s2u2: lba 0xb0814 len 0x20 xfercount 0x10000 total 0x15800
usbai: usb_alloc_bulk_req: dip=0xc7b1e768 wlen=0x1f flags=0x100
usba: usba_add_to_list: head=0xc83dc908 element=0xd558a4dc count=1
usbai: usba_req_wrapper_alloc: wrp = 0xd558a4c0
usbai: usb_alloc_bulk_req: bulk_req = 0xd558a51c
s2u2: cmd = 0xd56342c4 opcode=read10 cdb: 28 0 0 b 8 14 0 0 20 0 0 0 0 0 0 0
usbai: usba_hold_ph_data: ph_impl=0xc83dc2f0 state=1 ref=1
usbai: usb_pipe_bulk_xfer: req=0xd558a51c uf=0x100
usbai: usba_check_req: ph_data=0xcff27080 req=0xd558a51c flags=0x100
usbai: usba_check_req: attrs = 0x2 flags=0x101
usbai: usba_pipe_new_state: ph_data=0xcff27080 old=<idle> new=<active> ref=1 re
q=1
ehci0: usba_hcdi_cb: ph_data=0xcff27080 req=0xd558a51c state=2 ref=1 cnt=1 cr=0
usba: usba_add_to_list: head=0xcff270d0 element=0xd558a4c0 count=1
usbai: usba_async_ph_req: ph_data=0xcff27080 func=0xf9defb14, arg=0xcff27080 fl
ag=0x0
ehci0: hcdi_cb_thread: ph_data=0xcff27080 ref=2
usba: usba_rm_first_from_list: head=0xcff270d0 el=0xd558a4c0 cnt=0
ehci0: hcdi_do_cb: wrp=0xd558a4c0 cr=0x0
usbai: usba_req_normal_cb: ph_data=0xcff27080 state=2 wrp=0xd558a4c0 ref=2 req=
1
usbai: usba_pipe_new_state: ph_data=0xcff27080 old=<active> new=<idle> ref=2 re
q=1
usba: usba_rm_first_from_list: head=0xcff27084 el=0x0 cnt=0
usbai: usba_start_next_req done: ph_data=0xcff27080 state=1
usba: usba_rm_first_from_list: head=0xcff270d0 el=0x0 cnt=0
ehci0: hcdi_cb_thread done: ph_data=0xcff27080
usbai: usba_release_ph_data: ph_impl=0xc83dc2f0 state=1 ref=2
usbai: usba_release_ph_data: req_count=0
usbai: usba_pipe_sync_wait: ph_data=0xcff27080 cr=0x0
usbai: usb_pipe_bulk_xfer: rval=0
usbai: usba_release_ph_data: ph_impl=0xc83dc2f0 state=1 ref=1
usbai: usba_release_ph_data: req_count=0
s2u2: scsa2usb_bulk_only_transport: sent cmd = 0x28 Tag = 0x1c7c DataXferLen =
0x10000 rval = 0
s2u2: scsa2usb_handle_data_start: BEGIN cmd = d56342c4, req = d558a51c
usbai: usba_hold_ph_data: ph_impl=0xc83dc584 state=1 ref=1
usbai: usb_pipe_bulk_xfer: req=0xd558a51c uf=0x100
usbai: usba_check_req: ph_data=0xcff27100 req=0xd558a51c flags=0x100
usbai: usba_check_req: attrs = 0x1 flags=0x101
usbai: usba_pipe_new_state: ph_data=0xcff27100 old=<idle> new=<active> ref=1 re
q=1
ehci0: ehci_create_transfer_wrapper: dma_mem_alloc fail
ehci0: ehci_allocate_tw_resources: Unable to allocate TW
usbai: usba_pipe_new_state: ph_data=0xcff27100 old=<active> new=<idle> ref=1 re
q=0
usbai: usb_pipe_bulk_xfer: rval=-2
usbai: usba_release_ph_data: ph_impl=0xc83dc584 state=1 ref=1
usbai: usba_release_ph_data: req_count=0
s2u2: scsa2usb_handle_data_start: rval=-2 cr=14
s2u2: scsa2usb_handle_data_start: END bulk-in data rval = -2
s2u2: scsa2usb_handle_data_done:
cmd = 0xd56342c4 data = 0xc872a300 len = 0x0
s2u2: data xfer phase, error = -2, cr = 14
s2u2: scsa2usb_bulk_only_handle_error: req = 0xd558a51c, cr = 0xe
s2u2: scsa2usb_bulk_only_reset_recovery: scsa2usbp = 0xc83db200
usbai: usb_pipe_sync_ctrl_xfer: ph=0xc83dc298
setup = 0x21 0xff 0x0 0x0 0x0 uf = 0x0
usbai: usba_hold_ph_data: ph_impl=0xc83dc298 state=1 ref=1
usbai: usb_alloc_ctrl_req: dip=0xc7b1e768, wlen=0x0, flags=0x100
usba: usba_add_to_list: head=0xc83dc908 element=0xd604424c count=2
usbai: usba_req_wrapper_alloc: wrp = 0xd6044230
usbai: usb_alloc_ctrl_req: ctrl_req = 0xd604428c
usbai: usba_hold_ph_data: ph_impl=0xc83dc298 state=1 ref=2
usbai: usb_pipe_ctrl_xfer: req=0xd604428c, wrp=0xd6044230
setup = 0x21 0xff 0x0 0x0 0x0 uf=0x100
usbai: usba_check_req: ph_data=0xcff27280 req=0xd604428c flags=0x100
usbai: usba_check_req: attrs = 0x12 flags=0x101
usbai: usba_pipe_new_state: ph_data=0xcff27280 old=<idle> new=<active> ref=2 re
q=1
ehci0: usba_hcdi_cb: ph_data=0xcff27280 req=0xd604428c state=2 ref=2 cnt=1 cr=1
2
usba: usba_add_to_list: head=0xcff272d0 element=0xd6044230 count=1
usbai: usba_async_ph_req: ph_data=0xcff27280 func=0xf9defb14, arg=0xcff27280 fl
ag=0x0
ehci0: hcdi_cb_thread: ph_data=0xcff27280 ref=3
usba: usba_rm_first_from_list: head=0xcff272d0 el=0xd6044230 cnt=0
ehci0: hcdi_do_cb: wrp=0xd6044230 cr=0xc
ehci0: exception callback handling: attrs=0x12
usbai: usba_pipe_new_state: ph_data=0xcff27280 old=<active> new=<error> ref=3 r
eq=1
ehci0: hcdi_autoclearing: wrp=0xd6044230
usbai: usba_pipe_clear: ph_data=0xcff27280
ehci0: ehci_wait_for_transfers_completion:No transfers completion confirmation
received
usbai: no flushing on default pipe!
usbai: usba_pipe_new_state: ph_data=0xcff27280 old=<error> new=<idle> ref=3 req
=1
usbai: usba_req_set_cb_flags: wrp=0xd6044230 cb-flags=0x10
usbai: usba_req_exc_cb: scsa2usb2: ph_data=0xcff27280 (ep0) state=1 wrp=0xd6044
230 ref=3 reqcnt=1 cr=12
usbai: usba_req_set_cb_flags: wrp=0xd6044230 cb-flags=0x0
usba: usba_rm_first_from_list: head=0xcff27284 el=0x0 cnt=0
usbai: usba_start_next_req done: ph_data=0xcff27280 state=1
usba: usba_rm_first_from_list: head=0xcff272d0 el=0x0 cnt=0
ehci0: hcdi_cb_thread done: ph_data=0xcff27280
usbai: usba_release_ph_data: ph_impl=0xc83dc298 state=1 ref=3
usbai: usba_release_ph_data: req_count=0
usbai: usba_pipe_sync_wait: ph_data=0xcff27280 cr=0xc
usbai: usb_pipe_ctrl_xfer: rval=0xffffffff
usbai: usba_release_ph_data: ph_impl=0xc83dc298 state=1 ref=2
usbai: usba_release_ph_data: req_count=0
usbai: req=0xd604428c, cr=<Command timed out> cb_flags=<callback processed> dat
a=0x0 rval=<failure>
usbai: usb_free_ctrl_req: req = 0xd604428c
usbai: usba_req_wrapper_free: wrp=0xd6044230
usba: usba_rm_from_list: head=0xcff27284 element=0xd6044230 count=0
usba: usba_rm_from_list: head=0xc83dc908 element=0xd604424c count=2
usba: usba_rm_from_list success: head=0xc83dc908 element=0xd604424c cnt=1
usbai: usba_release_ph_data: ph_impl=0xc83dc298 state=1 ref=1
usbai: usba_release_ph_data: req_count=0
s2u2: bulk-only device-reset rval: -1
usbai: usb_free_bulk_req: req=0xd558a51c
usbai: usba_req_wrapper_free: wrp=0xd558a4c0
usba: usba_rm_from_list: head=0xcff27104 element=0xd558a4c0 count=0
usba: usba_rm_from_list: head=0xc83dc908 element=0xd558a4dc count=1
usba: usba_rm_from_list success: head=0xc83dc908 element=0xd558a4dc cnt=0
s2u2: scsa2usb_transport_request: transport rval = -2
s2u2: scsa2usb_pkt_completion:
scsa2usbp = 0xc83db200 reason=3, status=0 state=0x0 stats=0x10 resid=0x0
s2u2: scsa2usb_work_thread: exit
s2u2: scsa2usb_pm_idle_component: 0
s2u2: scsa2usb_scsi_start:
bp: 0xcdb5c658 ap: 0xd5634284 pkt: 0xd5634280 flag: 0x8000 time: 0x3c
cdb0: 0x28 dev_state: 0x1 pkt_state: 0x0 flags: 0x7 pipe_state: 0x0
s2u2: scsa2usb_prepare_pkt: pkt=0xd5634280 cdb: 0x28 (read10)
usba: usba_add_to_list: head=0xc83db238 element=0xd5634328 count=1
s2u2: scsa2usb_work_thread_id=0x0, count=1, lun=0
usbai: usb_async_req: dip=0xc7b1e768 func=0xf9e22285, arg=0xc83db200 flag=0x100
s2u2: scsa2usb_work_thread start: thread_id=0x1
s2u2: scsa2usb_raise_power:
s2u2: scsa2usb_pm_busy_component: 1
s2u2: scsa2usb_open_usb_pipes: dip = 0xc7b1e768 flag = 0x7
usba: usba_rm_first_from_list: head=0xc83db238 el=0xd5634328 cnt=0
s2u2: scsa2usb_transport_request: cmd=0xd56342c4 bp
|
