Date: Fri, 27 Jun 2003 11:18:41 +0100 From: Brian Candler <B.Candler@pobox.com> To: freebsd-firewire@freebsd.org Subject: Firewire resets/performance problems Message-ID: <20030627101841.GA60838@uk.tiscali.com>
next in thread | raw e-mail | index | archive | help
I have FreeBSD-4.8 running with a Lucent DV1000LE card. I have it talking to my brand new Apple iPod (new-style, 15GB), which seems to be detected fine; relevant log messages are attached below. However I have a couple of problems which I think are related: (1) Data transfer is extremely slow. Using 'dd' to read from /dev/da0, I get perhaps 10MB per minute; using 'dd' to write is maybe 3MB per minute max. (2) About every 2 seconds I get the following kernel message logged: sbp:0:0:0 No additional information to report Setting debug.firewire_debug=1 doesn't show anything extra. Setting debug.sbp_debug does give some additional information which doesn't mean much to me, apart from the fact that it seems to be doing a lot of bus resets and attaches, and "dead:1" doesn't look healthy either :-( Jun 27 11:03:01 playdog /kernel: sbp0:0:0 sbp_cam_scan_target Jun 27 11:03:01 playdog /kernel: sbp0:0:0 ORB status src:0 resp:0 dead:1 len:2 stat:0 orb:000010c10 Jun 27 11:03:01 playdog /kernel: sbp0:0:0 No additional information to report Jun 27 11:03:01 playdog /kernel: sbp0:0:0 XPT_SCSI_IO: cmd: 1a 00 0a 00 14 00 00 00 00 00, flags: 0x40, 6b cmd/20b data/32b sense Jun 27 11:03:01 playdog /kernel: sbp0:0:0 SCSI status 2 sfmt 0 valid 0 key 5 code 0 qlfr 0 len 2 Jun 27 11:03:01 playdog /kernel: sbp0:0:0 sbp_agent_reset Jun 27 11:03:01 playdog /kernel: sbp0:0:0 sbp_do_attach Jun 27 11:03:03 playdog /kernel: sbp0:0:0 sbp_cam_scan_target Jun 27 11:03:03 playdog /kernel: sbp0:0:0 ORB status src:0 resp:0 dead:1 len:2 stat:0 orb:000010fac Jun 27 11:03:03 playdog /kernel: sbp0:0:0 No additional information to report Jun 27 11:03:03 playdog /kernel: sbp0:0:0 XPT_SCSI_IO: cmd: 12 01 80 00 ff 00 00 00 00 00, flags: 0x40, 6b cmd/255b data/18b sense Jun 27 11:03:03 playdog /kernel: sbp0:0:0 SCSI status 2 sfmt 0 valid 0 key 5 code 26 qlfr 1 len 2 Jun 27 11:03:03 playdog /kernel: sbp0:0:0 sbp_agent_reset Jun 27 11:03:03 playdog /kernel: sbp0:0:0 sbp_cam_scan_lun Jun 27 11:03:03 playdog /kernel: sbp0:0:0 sbp_do_attach Jun 27 11:03:05 playdog /kernel: sbp0:0:0 sbp_cam_scan_target Jun 27 11:03:05 playdog /kernel: sbp0:0:0 ORB status src:0 resp:0 dead:1 len:2 stat:0 orb:000011a80 Jun 27 11:03:05 playdog /kernel: sbp0:0:0 No additional information to report Jun 27 11:03:05 playdog /kernel: sbp0:0:0 XPT_SCSI_IO: cmd: 1a 00 0a 00 14 00 00 00 00 00, flags: 0x40, 6b cmd/20b data/32b sense Jun 27 11:03:05 playdog /kernel: sbp0:0:0 SCSI status 2 sfmt 0 valid 0 key 5 code 0 qlfr 0 len 2 Jun 27 11:03:05 playdog /kernel: sbp0:0:0 sbp_agent_reset Jun 27 11:03:05 playdog /kernel: sbp0:0:0 sbp_do_attach Jun 27 11:03:07 playdog /kernel: sbp0:0:0 sbp_cam_scan_target Jun 27 11:03:07 playdog /kernel: sbp0:0:0 ORB status src:0 resp:0 dead:1 len:2 stat:0 orb:000011e1c Jun 27 11:03:07 playdog /kernel: sbp0:0:0 No additional information to report Jun 27 11:03:07 playdog /kernel: sbp0:0:0 XPT_SCSI_IO: cmd: 12 01 80 00 ff 00 00 00 00 00, flags: 0x40, 6b cmd/255b data/18b sense Jun 27 11:03:07 playdog /kernel: sbp0:0:0 SCSI status 2 sfmt 0 valid 0 key 5 code 26 qlfr 1 len 2 Jun 27 11:03:07 playdog /kernel: sbp0:0:0 sbp_agent_reset Jun 27 11:03:07 playdog /kernel: sbp0:0:0 sbp_cam_scan_lun Jun 27 11:03:07 playdog /kernel: sbp0:0:0 sbp_do_attach Jun 27 11:03:09 playdog /kernel: sbp0:0:0 sbp_cam_scan_target Jun 27 11:03:09 playdog /kernel: sbp0:0:0 ORB status src:0 resp:0 dead:1 len:2 stat:0 orb:000010270 Jun 27 11:03:09 playdog /kernel: sbp0:0:0 No additional information to report Jun 27 11:03:09 playdog /kernel: sbp0:0:0 XPT_SCSI_IO: cmd: 1a 00 0a 00 14 00 00 00 00 00, flags: 0x40, 6b cmd/20b data/32b sense Jun 27 11:03:09 playdog /kernel: sbp0:0:0 SCSI status 2 sfmt 0 valid 0 key 5 code 0 qlfr 0 len 2 Jun 27 11:03:09 playdog /kernel: sbp0:0:0 sbp_agent_reset Jun 27 11:03:09 playdog /kernel: sbp0:0:0 sbp_do_attach Jun 27 11:03:11 playdog /kernel: sbp0:0:0 sbp_cam_scan_target Jun 27 11:03:11 playdog /kernel: sbp0:0:0 ORB status src:0 resp:0 dead:1 len:2 stat:0 orb:00001060c Jun 27 11:03:11 playdog /kernel: sbp0:0:0 No additional information to report Jun 27 11:03:11 playdog /kernel: sbp0:0:0 XPT_SCSI_IO: cmd: 12 01 80 00 ff 00 00 00 00 00, flags: 0x40, 6b cmd/255b data/18b sense Jun 27 11:03:11 playdog /kernel: sbp0:0:0 SCSI status 2 sfmt 0 valid 0 key 5 code 26 qlfr 1 len 2 Jun 27 11:03:11 playdog /kernel: sbp0:0:0 sbp_agent_reset Jun 27 11:03:11 playdog /kernel: sbp0:0:0 sbp_cam_scan_lun Jun 27 11:03:11 playdog /kernel: sbp0:0:0 sbp_do_attach Jun 27 11:03:13 playdog /kernel: sbp0:0:0 No additional information to report Any clues? Would setting any of the hw.firewire / kern.cam sysctl variables help? Cheers, Brian. Jun 27 08:52:55 playdog /kernel: fwohci0: <Lucent FW322/323> mem 0xe4000000-0xe4000fff irq 9 at device 8.0 on pci0 Jun 27 08:52:55 playdog /kernel: fwohci0: PCI bus latency is 32. Jun 27 08:52:55 playdog /kernel: fwohci0: OHCI version 1.0 (ROM=1) Jun 27 08:52:55 playdog /kernel: fwohci0: No. of Isochronous channel is 8. Jun 27 08:52:55 playdog /kernel: fwohci0: EUI64 00:60:1d:00:00:00:c8:f5 Jun 27 08:52:55 playdog /kernel: fwohci0: Phy 1394a available S400, 3 ports. Jun 27 08:52:55 playdog /kernel: fwohci0: Link S400, max_rec 2048 bytes. Jun 27 08:52:55 playdog /kernel: firewire0: <IEEE1394(FireWire) bus> on fwohci0 Jun 27 08:52:55 playdog /kernel: fwohci0: Initiate bus reset Jun 27 08:52:55 playdog /kernel: fwohci0: BUS reset Jun 27 08:52:55 playdog /kernel: fwohci0: node_id = 0xc800ffc0, CYCLEMASTER mode Jun 27 08:52:55 playdog /kernel: firewire0: 1 nodes, maxhop <= 0, cable IRM = 0 (me) Jun 27 08:52:55 playdog /kernel: sbp0: <SBP2/SCSI over firewire> on firewire0 Jun 27 09:00:33 playdog /kernel: fwohci0: BUS reset Jun 27 09:00:33 playdog /kernel: fwohci0: node_id = 0x8800ffc0, non CYCLEMASTER mode Jun 27 09:00:33 playdog /kernel: firewire0: 2 nodes, maxhop <= 1, cable IRM = 0 (me) Jun 27 09:00:34 playdog /kernel: firewire0: New S400 device ID:000a2700020f9552 Jun 27 09:00:34 playdog /kernel: firewire0: Device SBP-II Jun 27 09:00:38 playdog /kernel: sbp0:0:0 No additional information to report Jun 27 09:00:40 playdog /kernel: sbp0:0:0 No additional information to report Jun 27 09:00:42 playdog /kernel: da0 at sbp0 bus 0 target 0 lun 0 Jun 27 09:00:42 playdog /kernel: da0: <Apple Co iPod 2700> Removable Simplified Direct Access SCSI-2 device Jun 27 09:00:42 playdog /kernel: da0: 50.000MB/s transfers, Tagged Queueing Enabled Jun 27 09:00:42 playdog /kernel: da0: 14305MB (29297520 512 byte sectors: 255H 63S/T 1823C) Jun 27 09:00:42 playdog /kernel: sbp0:0:0 No additional information to report
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20030627101841.GA60838>