Re: Firewire

[Torrey Hoffman <thoffman@arnor.net>]

This email is a little long because of all the log output... I hope all
the people on the cc line don't mind.

So, I applied Ben's last patch, added an extra debug line to print
jiffies, expire, and packet->sendtime in abort_timedouts, and enabled
the "excessive debugging output" config option. 

This was based on 2.6.0-test1-ac3.   When I booted, with nothing plugged
into the firewire card, this is the tail of the dmesg log:

SCSI subsystem initialized
ohci1394: $Rev: 986 $ Ben Collins <bcollins@debian.org>
PCI: Found IRQ 10 for device 0000:02:0b.0
PCI: Sharing IRQ 10 with 0000:02:01.0
ohci1394_0: Remapped memory spaces reg 0xec893000
ohci1394_0: Soft reset finished
ohci1394_0: Iso contexts reg: 000000a8 implemented: 000000ff
ohci1394_0: 8 iso receive contexts available
ohci1394_0: Iso contexts reg: 00000098 implemented: 000000ff
ohci1394_0: 8 iso transmit contexts available
ohci1394_0: GUID: 00406300:00001c47
ohci1394_0: Receive DMA ctx=0 initialized
ohci1394_0: Receive DMA ctx=0 initialized
ohci1394_0: Transmit DMA ctx=0 initialized
ohci1394_0: Transmit DMA ctx=1 initialized
ohci1394_0: OHCI-1394 1.0 (PCI): IRQ=[10]  MMIO=[e8201000-e82017ff]  Max Packet=[2048]
ohci1394_0: request csr_rom address: e6770000
ohci1394_0: IntEvent: 00030010
ohci1394_0: irq_handler: Bus reset requested
ohci1394_0: Cancel request received
ieee1394: TLABEL: splicing pending packets for abort_requests
ohci1394_0: Got RQPkt interrupt status=0x00008409
ohci1394_0: SelfID interrupt received (phyid 0, root)
ohci1394_0: SelfID packet 0x807f8956 received
ieee1394: Including SelfID 0x56897f80
ohci1394_0: SelfID for this node is 0x807f8956
ohci1394_0: SelfID complete
ohci1394_0: PhyReqFilter=ffffffffffffffff
ieee1394: selfid_complete called with successful SelfID stage ... irm_id: 0xFFC0 node_id: 0xFFC0
ieee1394: NodeMgr: Processing host reset for knodemgrd_0
ohci1394_0: Single packet rcv'd
ohci1394_0: Got phy packet ctx=0 ... discarded
ieee1394: Initiating ConfigROM request for node 00:1023
ieee1394: send packet local: ffc00140 ffc0ffff f0000400
ieee1394: TLABEL: appending packet to pending list
ieee1394: TLABEL: packet removed in abort_timedouts:
ieee1394: TLABEL: jiffies=4294693285d, expire=98d, packet->sendtime=4294693186d:
ieee1394: received packet: ffc00140 ffc0ffff f0000400
ieee1394: send packet local: ffc00160 ffc00000 00000000 7ee60404
ieee1394: TLABEL: no_waiter, returning
ieee1394: received packet: ffc00160 ffc00000 00000000 7ee60404
ieee1394: TLABEL: Checking for tlabel 0
ieee1394: unsolicited response packet received - no tlabel match
ieee1394: contents: ffc00160 ffc00000 00000000 7ee60404
ieee1394: send packet local: ffc00540 ffc0ffff f0000400
ieee1394: TLABEL: appending packet to pending list
ieee1394: TLABEL: packet removed in abort_timedouts:
ieee1394: TLABEL: jiffies=4294693717d, expire=98d, packet->sendtime=4294693618d:
ieee1394: received packet: ffc00540 ffc0ffff f0000400
ieee1394: send packet local: ffc00560 ffc00000 00000000 7ee60404
ieee1394: TLABEL: no_waiter, returning
ieee1394: received packet: ffc00560 ffc00000 00000000 7ee60404
ieee1394: TLABEL: Checking for tlabel 1
ieee1394: unsolicited response packet received - no tlabel match
ieee1394: contents: ffc00560 ffc00000 00000000 7ee60404
Linux Tulip driver version 1.1.13 (May 11, 2002)
PCI: Found IRQ 9 for device 0000:02:09.0
PCI: Sharing IRQ 9 with 0000:00:1f.2
tulip0:  MII transceiver #1 config 3000 status 7829 advertising 01e1.
eth0: Lite-On 82c168 PNIC rev 32 at 0xec897800, 00:A0:CC:D2:4A:8A, IRQ 9.
ieee1394: send packet local: ffc00940 ffc0ffff f0000400
ieee1394: TLABEL: appending packet to pending list
ieee1394: TLABEL: packet removed in abort_timedouts:
ieee1394: TLABEL: jiffies=4294694149d, expire=98d, packet->sendtime=4294694050d:
ieee1394: received packet: ffc00940 ffc0ffff f0000400
ieee1394: send packet local: ffc00960 ffc00000 00000000 7ee60404
ieee1394: TLABEL: no_waiter, returning
ieee1394: received packet: ffc00960 ffc00000 00000000 7ee60404
ieee1394: TLABEL: Checking for tlabel 2
ieee1394: unsolicited response packet received - no tlabel match
ieee1394: contents: ffc00960 ffc00000 00000000 7ee60404
ieee1394: ConfigROM quadlet transaction error for node 00:1023
ieee1394: send packet 100: ffff0100 ffc0ffff f0000234 1f0000c0
ohci1394_0: Inserting packet for node 63:1023, tlabel=0, tcode=0x0, speed=0
ohci1394_0: Starting transmit DMA ctx=0
ohci1394_0: IntEvent: 00000001
ohci1394_0: Got reqTxComplete interrupt status=0x00008011
ohci1394_0: Packet sent to node 63 tcode=0x0 tLabel=0x00 ack=0x11 spd=0 data=0x1F0000C0 ctx=0
ieee1394: TLABEL: not pending or no response expected, returning
process `syslogd' is using obsolete setsockopt SO_BSDCOMPAT
eth0: Setting full-duplex based on MII#1 link partner capability of 41e1.
Installing knfsd (copyright (C) 1996 okir@monad.swb.de).
(END)

When I plugged in a firewire device (which happened to be an IDE CDRW in
an external bridge case) I got an endless spew of messages dumped to the
log, until I unplugged the firewire cable:

Jul 25 10:32:26 torrey kernel: ohci1394_0: IntEvent: 00020010
Jul 25 10:32:26 torrey kernel: ohci1394_0: irq_handler: Bus reset requested
Jul 25 10:32:26 torrey kernel: ohci1394_0: Cancel request received
Jul 25 10:32:26 torrey kernel: ieee1394: TLABEL: splicing pending packets for abort_requests
Jul 25 10:32:26 torrey kernel: ohci1394_0: Got RQPkt interrupt status=0x00008409
Jul 25 10:32:26 torrey kernel: ohci1394_0: Single packet rcv'd
Jul 25 10:32:26 torrey kernel: ohci1394_0: Got phy packet ctx=0 ... discarded
Jul 25 10:32:26 torrey kernel: ohci1394_0: IntEvent: 00010000
Jul 25 10:32:26 torrey kernel: ohci1394_0: SelfID interrupt received (phyid 1, root)
Jul 25 10:32:26 torrey kernel: ohci1394_0: SelfID packet 0x807f8762 received
Jul 25 10:32:26 torrey kernel: ieee1394: Including SelfID 0x62877f80
Jul 25 10:32:26 torrey kernel: ohci1394_0: SelfID packet 0x817f89d4 received
Jul 25 10:32:26 torrey kernel: ieee1394: Including SelfID 0xd4897f81
Jul 25 10:32:26 torrey kernel: ohci1394_0: SelfID for this node is 0x817f89d4
Jul 25 10:32:26 torrey kernel: ohci1394_0: SelfID complete
Jul 25 10:32:26 torrey kernel: ohci1394_0: PhyReqFilter=ffffffffffffffff
Jul 25 10:32:26 torrey kernel: ieee1394: selfid_complete called with successful SelfID stage ... irm_id: 0xFFC1 node_id: 0xFFC1
Jul 25 10:32:26 torrey kernel: ohci1394_0: Cycle master enabled
Jul 25 10:32:26 torrey kernel: ieee1394: NodeMgr: Processing host reset for knodemgrd_0
Jul 25 10:32:26 torrey kernel: ieee1394: Initiating ConfigROM request for node 00:1023
Jul 25 10:32:26 torrey kernel: ieee1394: send packet 400: ffc00d40 ffc1ffff f0000400
Jul 25 10:32:26 torrey kernel: ohci1394_0: Inserting packet for node 00:1023, tlabel=3, tcode=0x4, speed=2
Jul 25 10:32:26 torrey kernel: ohci1394_0: Starting transmit DMA ctx=0
Jul 25 10:32:26 torrey kernel: ohci1394_0: IntEvent: 00000001
Jul 25 10:32:26 torrey kernel: ohci1394_0: Got reqTxComplete interrupt status=0x00008012
Jul 25 10:32:26 torrey kernel: ohci1394_0: Packet sent to node 0 tcode=0x4 tLabel=0x03 ack=0x12 spd=0 data=0x00000000 ctx=0
Jul 25 10:32:26 torrey kernel: ieee1394: TLABEL: appending packet to pending list
Jul 25 10:32:26 torrey kernel: ohci1394_0: IntEvent: 00000020
Jul 25 10:32:26 torrey kernel: ohci1394_0: Got RSPkt interrupt status=0x00008451
Jul 25 10:32:26 torrey kernel: ohci1394_0: Single packet rcv'd
Jul 25 10:32:26 torrey kernel: ohci1394_0: Packet received from node 0 ack=0x11 spd=2 tcode=0x6 length=20 ctx=0 tlabel=21
Jul 25 10:32:26 torrey kernel: ieee1394: received packet: ffc10d60 ffc00000 00000000 45863a04
Jul 25 10:32:26 torrey kernel: ieee1394: TLABEL: Checking for tlabel 3
Jul 25 10:32:26 torrey kernel: ieee1394: TLABEL: tlabel 3 in list
Jul 25 10:32:27 torrey kernel: ieee1394: TLABEL: Found tlabel
Jul 25 10:32:27 torrey kernel: abel=0x27 ack=0x12 spd=0 data=0x00000000 ctx=0
Jul 25 10:32:27 torrey kernel: ieee1394: TLABEL: appending packet to pending list
Jul 25 10:32:27 torrey kernel: ohci1394_0: IntEvent: 00000020
Jul 25 10:32:27 torrey kernel: ohci1394_0: Got RSPkt interrupt status=0x00008451
Jul 25 10:32:27 torrey kernel: ohci1394_0: Single packet rcv'd
Jul 25 10:32:27 torrey kernel: ohci1394_0: Packet received from node 0 ack=0x11 spd=2 tcode=0x6 length=20 ctx=0 tlabel=21
Jul 25 10:32:27 torrey kernel: ieee1394: received packet: ffc19d60 ffc00000 00000000 00c00054
Jul 25 10:32:27 torrey kernel: ieee1394: TLABEL: Checking for tlabel 39
Jul 25 10:32:27 torrey kernel: ieee1394: TLABEL: tlabel 39 in list
Jul 25 10:32:27 torrey kernel: ieee1394: TLABEL: Found tlabel
Jul 25 10:32:27 torrey kernel: ieee1394: send packet 400: ffc0a140 ffc1ffff f0000444
Jul 25 10:32:28 torrey kernel: ohci1394_0: Inserting packet for node 00:1023, tlabel=40, tcode=0x4, speed=2
Jul 25 10:32:28 torrey kernel: ohci1394_0: Waking transmit DMA ctx=0
Jul 25 10:32:28 torrey kernel: ohci1394_0: IntEvent: 00000001
Jul 25 10:32:28 torrey kernel: ohci1394_0: Got reqTxComplete interrupt status=0x00008012
Jul 25 10:32:28 torrey kernel: ohci1394_0: Packet sent to node 0 tcode=0x4 tLabel=0x28 ack=0x12 spd=0 data=0x00000000 ctx=0
Jul 25 10:32:28 torrey kernel: ieee1394: TLABEL: appending packet to pending list
Jul 25 10:32:28 torrey kernel: ohci1394_0: IntEvent: 00000020
Jul 25 10:32:28 torrey kernel: ohci1394_0: Got RSPkt interrupt status=0x00008451
Jul 25 10:32:28 torrey kernel: ohci1394_0: Single packet rcv'd
Jul 25 10:32:28 torrey kernel: ohci1394_0: Packet received from node 0 ack=0x11 spd=2 tcode=0x6 length=20 ctx=0 tlabel=21
Jul 25 10:32:28 torrey kernel: ieee1394: received packet: ffc1a160 ffc00000 00000000 083c003a
Jul 25 10:32:28 torrey kernel: ieee1394: TLABEL: Checking for tlabel 40
Jul 25 10:32:28 torrey kernel: ieee1394: TLABEL: tlabel 40 in list
Jul 25 10:32:28 torrey kernel: ieee1394: TLABEL: Found tlabel
Jul 25 10:32:28 torrey kernel: ieee1394: send packet 400: ffc0a540 ffc1ffff f0000448
Jul 25 10:32:28 torrey kernel: ohci1394_0: Inserting packet for node 00:1023, tlabel=41, tcode=0x4, speed=2
Jul 25 10:32:28 torrey kernel: ohci1394_0: Waking transmit DMA ctx=0
Jul 25 10:32:28 torrey kernel: ohci1394_0: IntEvent: 00000001
Jul 25 10:32:28 torrey kernel: ohci1394_0: Got reqTxComplete interrupt status=0x00008012
Jul 25 10:32:29 torrey kernel: ohci1394_0: Packet sent to node 0 tcode=0x4 tLabel=0x29 ack=0x12 spd=0 data=0x00000000 ctx=0
Jul 25 10:32:29 torrey kernel: ieee1394: TLABEL: appending packet to pending list
Jul 25 10:32:29 torrey kernel: ohci1394_0: IntEvent: 00000020
Jul 25 10:32:29 torrey kernel: ohci1394_0: Got RSPkt interrupt status=0x00008451
Jul 25 10:32:29 torrey kernel: ohci1394_0: Single packet rcv'd
Jul 25 10:32:29 torrey kernel: ohci1394_0: Packet received from node 0 ack=0x11 spd=2 tcode=0x6 length=20 ctx=0 tlabel=21
Jul 25 10:32:29 torrey kernel: ieee1394: received packet: ffc1a560 ffc00000 00000000 9e600038
Jul 25 10:32:29 torrey kernel: ieee1394: TLABEL: Checking for tlabel 41
Jul 25 10:32:29 torrey kernel: ieee1394: TLABEL: tlabel 41 in list
Jul 25 10:32:29 torrey kernel: ieee1394: TLABEL: Found tlabel
Jul 25 10:32:29 torrey kernel: ieee1394: send packet 400: ffc0a940 ffc1ffff f000044c
Jul 25 10:32:29 torrey kernel: ohci1394_0: Inserting packet for node 00:1023, tlabel=42, tcode=0x4, speed=2
Jul 25 10:32:29 torrey kernel: ohci1394_0: Waking transmit DMA ctx=0
Jul 25 10:32:29 torrey kernel: ohci1394_0: IntEvent: 00000001
Jul 25 10:32:29 torrey kernel: ohci1394_0: Got reqTxComplete interrupt status=0x00008012
Jul 25 10:32:29 torrey kernel: ohci1394_0: Packet sent to node 0 tcode=0x4 tLabel=0x2A ack=0x12 spd=0 data=0x00000000 ctx=0
Jul 25 10:32:29 torrey kernel: ieee1394: TLABEL: appending packet to pending list

...  

This went on for about 30 seconds until I gave up and unplugged it.
Finally, some hardware information:

The machine is an ordinary "HP Vectra", single CPU, Pentium III 733, 
RDRAM, 640 MB of RAM.

[root@torrey root]# lspci
00:00.0 Host bridge: Intel Corp. 82820 820 (Camino) Chipset Host Bridge (MCH) (rev 03)
00:01.0 PCI bridge: Intel Corp. 82820 820 (Camino) Chipset AGP Bridge (rev 03)
00:1e.0 PCI bridge: Intel Corp. 82801AA PCI Bridge (rev 02)
00:1f.0 ISA bridge: Intel Corp. 82801AA ISA Bridge (LPC) (rev 02)
00:1f.1 IDE interface: Intel Corp. 82801AA IDE (rev 02)
00:1f.2 USB Controller: Intel Corp. 82801AA USB (rev 02)
01:00.0 VGA compatible controller: ATI Technologies Inc Radeon RV200 QW [Radeon 7500]
02:01.0 Multimedia audio controller: Cirrus Logic CS 4614/22/24 [CrystalClear SoundFusion Audio Accelerator] (rev 01)
02:09.0 Ethernet controller: Lite-On Communications Inc LNE100TX (rev 20)
02:0b.0 FireWire (IEEE 1394): VIA Technologies, Inc. IEEE 1394 Host Controller (rev 46)


On Fri, 2003-07-25 at 09:18, Ben Collins wrote: 
> On Fri, Jul 25, 2003 at 09:07:06AM -0700, Chris Ruvolo wrote:
> > On Fri, Jul 25, 2003 at 11:40:09AM -0400, Ben Collins wrote:
> > > Ok, so revert everything and try this patch.
> > 
> > FYI, I got this compile warning (but I don't think its relevant).  Full
> > output from module load follows.
> 
> Ok, in ieee1394_core.c, when it does the "packet removed in
> abort_timedouts" could you make it print the value of jiffies, expire
> and packet->sendtime?
> 
> Thanks.
-- 
Torrey Hoffman
torrey.hoffman@myrio.com (work) / thoffman@arnor.net (home)