From owner-freebsd-hackers@FreeBSD.ORG Tue Sep 7 23:50:43 2004 Return-Path: Delivered-To: freebsd-hackers@freebsd.org Received: from mx1.FreeBSD.org (mx1.freebsd.org [216.136.204.125]) by hub.freebsd.org (Postfix) with ESMTP id EE6F116A4DD for ; Tue, 7 Sep 2004 23:50:42 +0000 (GMT) Received: from mta202-rme.xtra.co.nz (mta202-rme.xtra.co.nz [210.86.15.145]) by mx1.FreeBSD.org (Postfix) with ESMTP id 4442B43D2F for ; Tue, 7 Sep 2004 23:50:26 +0000 (GMT) (envelope-from james.collier@xtra.co.nz) Received: from mta1-rme.xtra.co.nz ([210.86.15.157]) by mta202-rme.xtra.co.nz with ESMTP <20040907235024.FFWC15448.mta202-rme.xtra.co.nz@mta1-rme.xtra.co.nz> for ; Wed, 8 Sep 2004 11:50:24 +1200 Received: from kanga.cyberdyne.co.mars ([210.86.98.90]) by mta1-rme.xtra.co.nz with SMTP <20040907235023.BWGY21194.mta1-rme.xtra.co.nz@kanga.cyberdyne.co.mars> for ; Wed, 8 Sep 2004 11:50:23 +1200 Received: (qmail 70938 invoked from network); 7 Sep 2004 23:50:23 -0000 Received: from tigger.cyberdyne.co.mars (HELO xtra.co.nz) (10.146.171.54) by 0 with SMTP; 7 Sep 2004 23:50:23 -0000 Message-ID: <413E493E.6070809@xtra.co.nz> Date: Wed, 08 Sep 2004 11:50:22 +1200 From: James Collier Organization: Cyberdyne Systems Ltd. User-Agent: Mozilla/5.0 (X11; U; FreeBSD i386; en-US; rv:1.6) Gecko/20040622 X-Accept-Language: en-us, en MIME-Version: 1.0 To: freebsd-hackers@freebsd.org Content-Type: text/plain; charset=us-ascii; format=flowed Content-Transfer-Encoding: 7bit X-Mailman-Approved-At: Wed, 08 Sep 2004 11:47:28 +0000 Subject: Problem with DVD writer and ehci on 4.10-STABLE X-BeenThere: freebsd-hackers@freebsd.org X-Mailman-Version: 2.1.1 Precedence: list List-Id: Technical Discussions relating to FreeBSD List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Tue, 07 Sep 2004 23:50:43 -0000 I'm trying to get a USB2 DVD writer working with growisofs under 4.10-STABLE (updated yesterday 6-Sep-04), but am having problems - the burn (on a DVD+R) always fails with an I/O Error anywhere between 10M and 1.5Gbytes. I can read from the unit, and short burns seem OK. There seems to be some correlation with system load, but my testing of this was inconclusive - long burns fail even when the system is quiescent. I've now got to the point where I'm well out of my depth, and I was wondering whether anyone can tell me whether I'm wasting my time on this. I'm aware of some problems with ehci, but not sure if this is a symptom ... The units in question are: NEC uPD 720100 USB 2.0 Host controller Genesys GL811 USB2/ATA Bridge NEC 1300A Rev 1.08 DVD writer I had to modify my umass.c to work with the GL811 bridge (note that the vendor/product ID matches USB_PRODUCT_GENESYS_GL641USB2IDE_2): -------------------------------------------------------------- *** .orig/umass.c Mon Sep 6 19:03:50 2004 --- ./umass.c Mon Sep 6 21:25:32 2004 *************** *** 703,706 **** --- 703,707 ---- UGETW(dd->idProduct) == USB_PRODUCT_GENESYS_GL641USB2IDE_2 || UGETW(dd->idProduct) == USB_PRODUCT_GENESYS_GL641USB)) { + sc->proto = UMASS_PROTO_SCSI | UMASS_PROTO_BBB; sc->quirks |= FORCE_SHORT_INQUIRY | NO_START_STOP | IGNORE_RESIDUE; } -------------------------------------------------------------- [IMHO it would be nice if this stuff could be configurable in the pattern of /etc/pccard.conf but ...] I enabled CAM and USB debugging, and caught the point of failure (two traces with varying levels of debugging attached). Having stared dumbly at the trace, code and the EHCI spec for long enough, it appears that the unit is returning a transaction error (XACTERR - possibly a timeout) implying that the transaction should be retried (EHCI spec 4.12.1.2), but it seems that this is not happening. If this problem is considered interesting enough I can supply more background detail (config file and/or boot log - but the boot log is a hideous length with full debugging enabled.) Any advice - no matter how pointed - will be appeciated. Thanks & regards James Collier. -------------------------------------------------------------- Trace #1 - hw.usb.ehci.debug=1 -------------------------------------------------------------- Sep 7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): WRITE(10). CDB: 2a 0 0 0 c7 90 0 0 10 0 Sep 7 13:54:10 tigger /kernel: ehci_alloc_sqtd_chain: start len=32768 Sep 7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_done Sep 7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): camisr Sep 7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): entering cdgetccb Sep 7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_schedule Sep 7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_setup_ccb Sep 7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_action Sep 7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): WRITE(10). CDB: 2a 0 0 0 c7 a0 0 0 10 0 Sep 7 13:54:10 tigger /kernel: ehci_alloc_sqtd_chain: start len=32768 Sep 7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_done Sep 7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): camisr Sep 7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): entering cdgetccb Sep 7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_schedule Sep 7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_setup_ccb Sep 7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_action Sep 7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): WRITE(10). CDB: 2a 0 0 0 c7 b0 0 0 10 0 Sep 7 13:54:10 tigger /kernel: ehci_alloc_sqtd_chain: start len=32768 Sep 7 13:54:10 tigger /kernel: ehci_idone: error, addr=2, endpt=0x02, status 0x8 Sep 7 13:54:10 tigger /kernel: ehci_device_clear_toggle: epipe=0xc15fec00 status=0x8d00 Sep 7 13:54:10 tigger /kernel: usbd_dump_pipe: pipe=0xc15fec00 Sep 7 13:54:10 tigger /kernel: usbd_dump_iface: iface=0xc15f8e60 Sep 7 13:54:10 tigger /kernel: device=0xc15fee00 idesc=0xc15f8e89 index=0 altindex=0 priv=0 Sep 7 13:54:10 tigger /kernel: usbd_dump_device: dev=0xc15fee00 Sep 7 13:54:10 tigger /kernel: bus=0xc15ee400 default_pipe=0xc15fed80 Sep 7 13:54:10 tigger /kernel: address=2 config=1 depth=1 speed=3 self_powered=1 power=4 langid=1033 Sep 7 13:54:10 tigger /kernel: usbd_dump_endpoint: endp=0xc15d87f0 Sep 7 13:54:10 tigger /kernel: edesc=0xc15f8e92 refcnt=1 Sep 7 13:54:10 tigger /kernel: bEndpointAddress=0x81 Sep 7 13:54:10 tigger /kernel: (usbd_dump_pipe:) Sep 7 13:54:10 tigger /kernel: refcnt=1 running=0 aborting=0 Sep 7 13:54:10 tigger /kernel: intrxfer=0, repeat=0, interval=-1 Sep 7 13:54:10 tigger /kernel: ehci_device_clear_toggle: epipe=0xc15fec80 status=0x9c08 Sep 7 13:54:10 tigger /kernel: usbd_dump_pipe: pipe=0xc15fec80 Sep 7 13:54:10 tigger /kernel: usbd_dump_iface: iface=0xc15f8e60 Sep 7 13:54:10 tigger /kernel: device=0xc15fee00 idesc=0xc15f8e89 index=0 altindex=0 priv=0 Sep 7 13:54:10 tigger /kernel: usbd_dump_device: dev=0xc15fee00 Sep 7 13:54:10 tigger /kernel: bus=0xc15ee400 default_pipe=0xc15fed80 Sep 7 13:54:10 tigger /kernel: address=2 config=1 depth=1 speed=3 self_powered=1 power=4 langid=1033 Sep 7 13:54:10 tigger /kernel: usbd_dump_endpoint: endp=0xc15d87f8 Sep 7 13:54:10 tigger /kernel: edesc=0xc15f8e99 refcnt=1 Sep 7 13:54:10 tigger /kernel: bEndpointAddress=0x02 Sep 7 13:54:10 tigger /kernel: (usbd_dump_pipe:) Sep 7 13:54:10 tigger /kernel: refcnt=1 running=0 aborting=0 Sep 7 13:54:10 tigger /kernel: intrxfer=0, repeat=0, interval=-1 Sep 7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_done Sep 7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): camisr Sep 7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): entering cdgetccb Sep 7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_schedule Sep 7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_setup_ccb Sep 7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_action Sep 7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): SYNCHRONIZE CACHE. CDB: 35 2 0 0 0 0 0 0 0 0 Sep 7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_done Sep 7 13:54:10 tigger /kernel: (pass0:umass-sim0:0:1:0): camisr Sep 7 13:54:11 tigger /kernel: (pass0:umass-sim0:0:1:0): entering cdgetccb Sep 7 13:54:11 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_schedule Sep 7 13:54:11 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_setup_ccb Sep 7 13:54:11 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_action Sep 7 13:54:11 tigger /kernel: (pass0:umass-sim0:0:1:0): TEST UNIT READY. CDB: 0 0 0 0 0 0 Sep 7 13:54:12 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_done Sep 7 13:54:12 tigger /kernel: (pass0:umass-sim0:0:1:0): camisr Sep 7 13:54:12 tigger /kernel: (pass0:umass-sim0:0:1:0): entering cdgetccb Sep 7 13:54:12 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_schedule Sep 7 13:54:12 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_setup_ccb Sep 7 13:54:12 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_action Sep 7 13:54:12 tigger /kernel: (pass0:umass-sim0:0:1:0): SYNCHRONIZE CACHE. CDB: 35 0 0 0 0 0 0 0 0 0 -------------------------------------------------------------- Trace #2: Drilling down on a subsequent run (hw.usb.ehci.debug=3), we see: -------------------------------------------------------------- Sep 7 17:29:44 tigger /kernel: (pass0:umass-sim0:0:1:0): WRITE(10). CDB: 2a 0 0 0 da 50 0 0 10 0 Sep 7 17:29:44 tigger /kernel: ehci_device_bulk_transfer: xfer=0xc15f7100 len=31 flags=0 Sep 7 17:29:44 tigger /kernel: ehci_alloc_sqtd_chain: start len=31 Sep 7 17:29:44 tigger /kernel: ehci_check_intr: ex=0xc15f7100 Sep 7 17:29:44 tigger /kernel: ehci_idone: ex=0xc15f7100 Sep 7 17:29:44 tigger /kernel: ehci_idone: xfer=0xc15f7100, pipe=0xc15fec80 ready Sep 7 17:29:44 tigger /kernel: ehci_idone: len=31, actlen=31, status=0x0 Sep 7 17:29:44 tigger /kernel: ehci_device_bulk_transfer: xfer=0xc1602f00 len=32768 flags=0 Sep 7 17:29:44 tigger /kernel: ehci_alloc_sqtd_chain: start len=32768 Sep 7 17:29:44 tigger /kernel: ehci_alloc_sqtd_chain: multiple QTDs, curlen=4096 Sep 7 17:29:44 tigger last message repeated 6 times Sep 7 17:29:44 tigger /kernel: ehci_idone: ex=0xc15f7100 done Sep 7 17:29:44 tigger /kernel: ehci_check_intr: ex=0xc1602f00 Sep 7 17:29:44 tigger /kernel: ehci_idone: ex=0xc1602f00 Sep 7 17:29:44 tigger /kernel: ehci_idone: xfer=0xc1602f00, pipe=0xc15fec80 ready Sep 7 17:29:44 tigger /kernel: ehci_idone: len=32768, actlen=32768, status=0x8 Sep 7 17:29:44 tigger /kernel: ehci_idone: error, addr=2, endpt=0x02, status 0x8 Sep 7 17:29:44 tigger /kernel: QH(0xc15fdea0) at 0x0f871ea0: Sep 7 17:29:44 tigger /kernel: link=0x0f871f02 Sep 7 17:29:44 tigger /kernel: endp=0x82002202 Sep 7 17:29:44 tigger /kernel: addr=0x02 inact=0 endpt=2 eps=2 dtc=0 hrecl=0 Sep 7 17:29:44 tigger /kernel: mpl=0x200 ctl=0 nrl=8 Sep 7 17:29:44 tigger /kernel: endphub=0x40000000 Sep 7 17:29:44 tigger /kernel: smask=0x00 cmask=0x00 huba=0x00 port=0 mult=1 Sep 7 17:29:44 tigger /kernel: curqtd=0x0f834e40<> Sep 7 17:29:44 tigger /kernel: Overlay qTD: Sep 7 17:29:44 tigger /kernel: next=0x00000001 altnext=0x00000011 Sep 7 17:29:44 tigger /kernel: status=0x80009c08: toggle=1 bytes=0x0 ioc=1 c_page=0x1 Sep 7 17:29:44 tigger /kernel: cerr=3 pid=0 stat=0x8 Sep 7 17:29:44 tigger /kernel: buffer[0]=0x00023000 Sep 7 17:29:44 tigger /kernel: buffer[1]=0x00000000 Sep 7 17:29:44 tigger /kernel: buffer[2]=0x00000000 Sep 7 17:29:44 tigger /kernel: buffer[3]=0x00000000 Sep 7 17:29:44 tigger /kernel: buffer[4]=0x00000000 Sep 7 17:29:44 tigger /kernel: QTD(0xc1600f00) at 0x0f834f00: Sep 7 17:29:44 tigger /kernel: next=0x0f834c00<> altnext=0x0f834c00<> Sep 7 17:29:44 tigger /kernel: status=0x80001c00: toggle=1 bytes=0x0 ioc=0 c_page=0x1 Sep 7 17:29:44 tigger /kernel: cerr=3 pid=0 stat=0x0 Sep 7 17:29:44 tigger /kernel: buffer[0]=0x0001c000 Sep 7 17:29:44 tigger /kernel: buffer[1]=0x00000000 Sep 7 17:29:44 tigger /kernel: buffer[2]=0x00000000 Sep 7 17:29:44 tigger /kernel: buffer[3]=0x00000000 Sep 7 17:29:44 tigger /kernel: buffer[4]=0x00000000 ...... Sep 7 17:29:44 tigger /kernel: QTD(0xc1600c00) at 0x0f834c00: ...... Sep 7 17:29:44 tigger /kernel: status=0x80001c00: toggle=1 bytes=0x0 ioc=0 c_page=0x1 ...... Sep 7 17:29:44 tigger /kernel: QTD(0xc1600c60) at 0x0f834c60: ...... Sep 7 17:29:44 tigger /kernel: status=0x80001c00: toggle=1 bytes=0x0 ioc=0 c_page=0x1 ...... Sep 7 17:29:44 tigger /kernel: QTD(0xc1600cc0) at 0x0f834cc0: ...... Sep 7 17:29:44 tigger /kernel: status=0x80001c00: toggle=1 bytes=0x0 ioc=0 c_page=0x1 ...... Sep 7 17:29:44 tigger /kernel: QTD(0xc1600d20) at 0x0f834d20: ...... Sep 7 17:29:44 tigger /kernel: status=0x80001c00: toggle=1 bytes=0x0 ioc=0 c_page=0x1 ...... Sep 7 17:29:44 tigger /kernel: QTD(0xc1600d80) at 0x0f834d80: ...... Sep 7 17:29:44 tigger /kernel: status=0x80001c00: toggle=1 bytes=0x0 ioc=0 c_page=0x1 ...... Sep 7 17:29:44 tigger /kernel: QTD(0xc1600de0) at 0x0f834de0: ...... Sep 7 17:29:44 tigger /kernel: status=0x80001c00: toggle=1 bytes=0x0 ioc=0 c_page=0x1 ...... Sep 7 17:29:44 tigger /kernel: QTD(0xc1600e40) at 0x0f834e40: ...... Sep 7 17:29:44 tigger /kernel: status=0x80009c08: toggle=1 bytes=0x0 ioc=1 c_page=0x1 Sep 7 17:29:44 tigger /kernel: QTD(0xc1600e40) at 0x0f834e40: Sep 7 17:29:44 tigger /kernel: next=0x00000001 altnext=0x00000001 Sep 7 17:29:44 tigger /kernel: status=0x80009c08: toggle=1 bytes=0x0 ioc=1 c_page=0x1 Sep 7 17:29:44 tigger /kernel: cerr=3 pid=0 stat=0x8 Sep 7 17:29:44 tigger /kernel: buffer[0]=0x00023000 Sep 7 17:29:44 tigger /kernel: buffer[1]=0x00000000 Sep 7 17:29:44 tigger /kernel: buffer[2]=0x00000000 Sep 7 17:29:44 tigger /kernel: buffer[3]=0x00000000 Sep 7 17:29:44 tigger /kernel: buffer[4]=0x00000000 Sep 7 17:29:44 tigger /kernel: ehci_idone: ex=0xc1602f00 done Sep 7 17:29:44 tigger /kernel: ehci_check_intr: ex=0xc1602a00 Sep 7 17:29:44 tigger /kernel: ehci_idone: ex=0xc1602a00 Sep 7 17:29:44 tigger /kernel: ehci_idone: xfer=0xc1602a00, pipe=0xc15fed80 ready Sep 7 17:29:44 tigger /kernel: ehci_idone: len=0, actlen=0, status=0x0 Sep 7 17:29:44 tigger /kernel: ehci_device_clear_toggle: epipe=0xc15fec00 status=0x8d00 Sep 7 17:29:44 tigger /kernel: usbd_dump_pipe: pipe=0xc15fec00 Sep 7 17:29:44 tigger /kernel: usbd_dump_iface: iface=0xc15f8e60 Sep 7 17:29:44 tigger /kernel: device=0xc15fee00 idesc=0xc15f8e89 index=0 altindex=0 priv=0 Sep 7 17:29:44 tigger /kernel: usbd_dump_device: dev=0xc15fee00 Sep 7 17:29:45 tigger /kernel: bus=0xc15ee400 default_pipe=0xc15fed80 Sep 7 17:29:45 tigger /kernel: address=2 config=1 depth=1 speed=3 self_powered=1 power=4 langid=1033 Sep 7 17:29:45 tigger /kernel: usbd_dump_endpoint: endp=0xc15d87f0 Sep 7 17:29:45 tigger /kernel: edesc=0xc15f8e92 refcnt=1 Sep 7 17:29:45 tigger /kernel: bEndpointAddress=0x81 Sep 7 17:29:45 tigger /kernel: (usbd_dump_pipe:) Sep 7 17:29:45 tigger /kernel: refcnt=1 running=0 aborting=0 Sep 7 17:29:45 tigger /kernel: intrxfer=0, repeat=0, interval=-1 Sep 7 17:29:45 tigger /kernel: ehci_idone: ex=0xc1602a00 done Sep 7 17:29:45 tigger /kernel: ehci_check_intr: ex=0xc1602900 Sep 7 17:29:45 tigger /kernel: ehci_idone: ex=0xc1602900 Sep 7 17:29:45 tigger /kernel: ehci_idone: xfer=0xc1602900, pipe=0xc15fed80 ready Sep 7 17:29:45 tigger /kernel: ehci_idone: len=0, actlen=0, status=0x0 Sep 7 17:29:45 tigger /kernel: ehci_device_clear_toggle: epipe=0xc15fec80 status=0x80009c08 Sep 7 17:29:45 tigger /kernel: usbd_dump_pipe: pipe=0xc15fec80 Sep 7 17:29:45 tigger /kernel: usbd_dump_iface: iface=0xc15f8e60 Sep 7 17:29:45 tigger /kernel: device=0xc15fee00 idesc=0xc15f8e89 index=0 altindex=0 priv=0 Sep 7 17:29:45 tigger /kernel: usbd_dump_device: dev=0xc15fee00 Sep 7 17:29:45 tigger /kernel: bus=0xc15ee400 default_pipe=0xc15fed80 Sep 7 17:29:45 tigger /kernel: address=2 config=1 depth=1 speed=3 self_powered=1 power=4 langid=1033 Sep 7 17:29:45 tigger /kernel: usbd_dump_endpoint: endp=0xc15d87f8 Sep 7 17:29:45 tigger /kernel: edesc=0xc15f8e99 refcnt=1 Sep 7 17:29:45 tigger /kernel: bEndpointAddress=0x02 Sep 7 17:29:45 tigger /kernel: (usbd_dump_pipe:) Sep 7 17:29:45 tigger /kernel: refcnt=1 running=0 aborting=0 Sep 7 17:29:45 tigger /kernel: intrxfer=0, repeat=0, interval=-1 Sep 7 17:29:45 tigger /kernel: ehci_idone: ex=0xc1602900 done Sep 7 17:29:45 tigger /kernel: ehci_check_intr: ex=0xc1602800 Sep 7 17:29:45 tigger /kernel: ehci_idone: ex=0xc1602800 Sep 7 17:29:45 tigger /kernel: ehci_idone: xfer=0xc1602800, pipe=0xc15fed80 ready Sep 7 17:29:45 tigger /kernel: ehci_idone: len=0, actlen=0, status=0x0 Sep 7 17:29:45 tigger /kernel: (pass0:umass-sim0:0:1:0): xpt_done Sep 7 17:29:45 tigger /kernel: ehci_idone: ex=0xc1602800 done Sep 7 17:29:45 tigger /kernel: (pass0:umass-sim0:0:1:0): camisr ----------------------------------------------------------------------------------- [End of traces]