From owner-freebsd-firewire@FreeBSD.ORG Fri Jun 27 03:17:34 2003 Return-Path: Delivered-To: freebsd-firewire@freebsd.org Received: from mx1.FreeBSD.org (mx1.freebsd.org [216.136.204.125]) by hub.freebsd.org (Postfix) with ESMTP id DC5B137B401 for ; Fri, 27 Jun 2003 03:17:34 -0700 (PDT) Received: from internal.mail.uk.tiscali.com (internal.mail.uk.tiscali.com [212.74.96.51]) by mx1.FreeBSD.org (Postfix) with ESMTP id E491B43FAF for ; Fri, 27 Jun 2003 03:17:29 -0700 (PDT) (envelope-from b.candler@pobox.com) Received: from [212.74.113.66] (helo=vaio.linnet.org) by internal.mail.uk.tiscali.com with asmtp (TLSv1:DES-CBC3-SHA:168) (Exim 4.12) id 19VqII-0004Rl-00 for freebsd-firewire@freebsd.org; Fri, 27 Jun 2003 11:17:27 +0100 Received: from brian by vaio.linnet.org with local (Exim 4.20) id 19VqJV-000Fq8-AP for freebsd-firewire@freebsd.org; Fri, 27 Jun 2003 11:18:41 +0100 Date: Fri, 27 Jun 2003 11:18:41 +0100 From: Brian Candler To: freebsd-firewire@freebsd.org Message-ID: <20030627101841.GA60838@uk.tiscali.com> Mime-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline User-Agent: Mutt/1.4.1i Subject: Firewire resets/performance problems X-BeenThere: freebsd-firewire@freebsd.org X-Mailman-Version: 2.1.1 Precedence: list List-Id: Vendors pre-release coordination List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Fri, 27 Jun 2003 10:17:35 -0000 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: 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: 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: 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: 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