Firewire resets/performance problems

[Brian Candler]

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