Does anyone have firewire running on Linux 2.6.0-test1-mm2 ?
This is what dmesg reports after boot. If I plug in an iPod and use
sbp2, I can mount the iPod as a disk and look at its files but using
gtkpod freezes up the machine.
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc00160 ffc00000 00000000 dee10404
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc00560 ffc00000 00000000 dee10404
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc00960 ffc00000 00000000 dee10404
ieee1394: ConfigROM quadlet transaction error for node 00:1023
On Thu, Jul 24, 2003 at 09:34:34AM -0400, gaxt wrote:
> Does anyone have firewire running on Linux 2.6.0-test1-mm2 ?
It is not working for me under 2.6.0-test1 (vanilla). Same hardware works
great under 2.4.20.
> This is what dmesg reports after boot. If I plug in an iPod and use
> sbp2, I can mount the iPod as a disk and look at its files but using
> gtkpod freezes up the machine.
When I power-on my DV camera, messages like yours pour out, and the kernel
takes up 40% of my CPU time until I turn the camera off.
-Chris
--- module load messages ---
ohci1394: $Rev: 578 $ Ben Collins <[email protected]>
PCI: Found IRQ 10 for device 00:0b.0
ohci1394_0: OHCI-1394 1.0 (PCI): IRQ=[10] MMIO=[db001000-db0017ff] Max Packet=[2048]
raw1394: /dev/raw1394 device initialized
ieee1394: Host added: Node[00:1023] GUID[0011060000006a85] [Linux OHCI-1394]
--- end ---
--- power-on DV camera messages ---
ieee1394: Node added: ID:BUS[0-00:1023] GUID[0010950010090143]
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc10160 ffc10000 00000000 60f30404
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc10560 ffc10000 00000000 60f30404
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc10960 ffc10000 00000000 60f30404
ieee1394: ConfigROM quadlet transaction error for node 01:1023
ieee1394: The root node is not cycle master capable; selecting a new root node and resetting...
--- repeats ---
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc03160 ffc00000 00000000 60f30404
ieee1394: ConfigROM quadlet transaction error for node 00:1023
ieee1394: Node removed: ID:BUS[0-00:1023] GUID[0010950010090143]
--- end ---
--- lspci for firewire card ---
00:0b.0 FireWire (IEEE 1394): VIA Technologies, Inc. IEEE 1394 Host Controller (rev 46) (prog-if 10 [OHCI])
Subsystem: VIA Technologies, Inc. IEEE 1394 Host Controller
Flags: bus master, medium devsel, latency 32, IRQ 10
Memory at db001000 (32-bit, non-prefetchable) [size=2K]
I/O ports at e800 [size=128]
Capabilities: [50] Power Management version 2
--- end ---
> --- module load messages ---
> ohci1394: $Rev: 578 $ Ben Collins <[email protected]>
> PCI: Found IRQ 10 for device 00:0b.0
> ohci1394_0: OHCI-1394 1.0 (PCI): IRQ=[10] MMIO=[db001000-db0017ff] Max Packet=[2048]
> raw1394: /dev/raw1394 device initialized
> ieee1394: Host added: Node[00:1023] GUID[0011060000006a85] [Linux OHCI-1394]
> --- end ---
I know damn well that 2.6.0-test1 is not running r578 of the ohci1394
driver. In fact, that's 10 months old.
Try sending some of this info to [email protected]. I'm
running current code with 2.4.22-pre's and 2.6.0-test. SBP2 and eth1394
or working well. Haven't tried DV inawhile, but I know the stack is
working.
--
Debian - http://www.debian.org/
Linux 1394 - http://www.linux1394.org/
Subversion - http://subversion.tigris.org/
On Thu, Jul 24, 2003 at 06:36:15PM -0400, Ben Collins wrote:
> I know damn well that 2.6.0-test1 is not running r578 of the ohci1394
> driver. In fact, that's 10 months old.
Er.. whoops. Sorry, that was from my 2.4 boot. Here's the right one. This
is at module load time. The rest of the data is correct.
-Chris
ohci1394: $Rev: 986 $ Ben Collins <[email protected]>
PCI: Found IRQ 10 for device 0000:00:0b.0
ohci1394_0: OHCI-1394 1.0 (PCI): IRQ=[10] MMIO=[db001000-db0017ff] Max Packet=[2048]
raw1394: /dev/raw1394 device initialized
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc00160 ffc00000 00000000 60f30404
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc00560 ffc00000 00000000 60f30404
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc00960 ffc00000 00000000 60f30404
ieee1394: ConfigROM quadlet transaction error for node 00:1023
On Thu, Jul 24, 2003 at 04:09:29PM -0700, Chris Ruvolo wrote:
> On Thu, Jul 24, 2003 at 06:36:15PM -0400, Ben Collins wrote:
> > I know damn well that 2.6.0-test1 is not running r578 of the ohci1394
> > driver. In fact, that's 10 months old.
>
> Er.. whoops. Sorry, that was from my 2.4 boot. Here's the right one. This
> is at module load time. The rest of the data is correct.
>
> -Chris
>
>
> ohci1394: $Rev: 986 $ Ben Collins <[email protected]>
> PCI: Found IRQ 10 for device 0000:00:0b.0
> ohci1394_0: OHCI-1394 1.0 (PCI): IRQ=[10] MMIO=[db001000-db0017ff] Max Packet=[2048]
> raw1394: /dev/raw1394 device initialized
> ieee1394: unsolicited response packet received - np
> ieee1394: contents: ffc00160 ffc00000 00000000 60f30404
> ieee1394: unsolicited response packet received - np
> ieee1394: contents: ffc00560 ffc00000 00000000 60f30404
> ieee1394: unsolicited response packet received - np
> ieee1394: contents: ffc00960 ffc00000 00000000 60f30404
> ieee1394: ConfigROM quadlet transaction error for node 00:1023
That's more like it, thanks.
I've seen this before, but I can never reproduce it. Not with i386, nor
with sparc64, and not running 2.4 or 2.6. I know what is happening
though. The response packet is getting processed before the status
packet (IOW, the ack for your request is getting back after the actual
response to your request).
Not sure how that is possible, but I suspect it's just a bit of logic
that needs to be applied, or queue the replies waiting for the ack.
--
Debian - http://www.debian.org/
Linux 1394 - http://www.linux1394.org/
Subversion - http://subversion.tigris.org/
On Thu, Jul 24, 2003 at 07:14:21PM -0400, Ben Collins wrote:
> I've seen this before, but I can never reproduce it. Not with i386, nor
> with sparc64, and not running 2.4 or 2.6. I know what is happening
> though. The response packet is getting processed before the status
> packet (IOW, the ack for your request is getting back after the actual
> response to your request).
>
> Not sure how that is possible, but I suspect it's just a bit of logic
> that needs to be applied, or queue the replies waiting for the ack.
That is very odd, considering it works under 2.4. Is it possible the
pending_packets list isn't being updated? Would the verbose debug option
help?
Thanks for looking into this.
-Chris
On Thu, Jul 24, 2003 at 04:48:37PM -0700, Chris Ruvolo wrote:
> On Thu, Jul 24, 2003 at 07:14:21PM -0400, Ben Collins wrote:
> > I've seen this before, but I can never reproduce it. Not with i386, nor
> > with sparc64, and not running 2.4 or 2.6. I know what is happening
> > though. The response packet is getting processed before the status
> > packet (IOW, the ack for your request is getting back after the actual
> > response to your request).
> >
> > Not sure how that is possible, but I suspect it's just a bit of logic
> > that needs to be applied, or queue the replies waiting for the ack.
>
> That is very odd, considering it works under 2.4. Is it possible the
> pending_packets list isn't being updated? Would the verbose debug option
> help?
If it wasn't being updated, I would see the problem too, and I'm not.
--
Debian - http://www.debian.org/
Linux 1394 - http://www.linux1394.org/
Subversion - http://subversion.tigris.org/
On Thu, Jul 24, 2003 at 07:45:03PM -0400, Ben Collins wrote:
> If it wasn't being updated, I would see the problem too, and I'm not.
On another note, I just got this output when doing a 'rmmod' ohci1394:
bad: scheduling while atomic!
Call Trace:
[<c01159c7>] schedule+0x3b7/0x3c0
[<c0115d28>] wait_for_completion+0x78/0xd0
[<c0115a20>] default_wake_function+0x0/0x30
[<c0115a20>] default_wake_function+0x0/0x30
[<c01226c0>] kill_proc_info+0x40/0x60
[<c89ddff5>] nodemgr_remove_host+0x55/0xa0 [ieee1394]
[<c89d9b66>] highlevel_remove_host+0x76/0x90 [ieee1394]
[<c89c56ee>] ohci1394_pci_remove+0x3e/0x160 [ohci1394]
[<c01a44eb>] pci_device_remove+0x3b/0x40
[<c01c4efe>] device_release_driver+0x5e/0x60
[<c01c4f2b>] driver_detach+0x2b/0x40
[<c01c518b>] bus_remove_driver+0x3b/0x70
[<c01c55b4>] driver_unregister+0x14/0x28
[<c01a47a7>] pci_unregister_driver+0x17/0x30
[<c89c5ad2>] ohci1394_cleanup+0x12/0x16 [ohci1394]
[<c012cdc5>] sys_delete_module+0x125/0x190
[<c013fcb3>] sys_munmap+0x43/0x70
[<c010940b>] syscall_call+0x7/0xb
> That is very odd, considering it works under 2.4. Is it possible the
> pending_packets list isn't being updated? Would the verbose debug option
> help?
Here is the debug output from loading ohci1394:
-Chris
ohci1394: $Rev: 986 $ Ben Collins <[email protected]>
PCI: Found IRQ 10 for device 0000:00:0b.0
ohci1394_0: Remapped memory spaces reg 0xc897a000
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: 00110600:00006a85
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=[db001000-db0017ff] Max Packet=[2048]
ohci1394_0: request csr_rom address: c0961000
ohci1394_0: IntEvent: 00030010
ohci1394_0: irq_handler: Bus reset requested
ohci1394_0: Cancel request received
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: received packet: ffc00140 ffc0ffff f0000400
ieee1394: send packet local: ffc00160 ffc00000 00000000 60f30404
ieee1394: received packet: ffc00160 ffc00000 00000000 60f30404
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc00160 ffc00000 00000000 60f30404
ieee1394: send packet local: ffc00540 ffc0ffff f0000400
ieee1394: received packet: ffc00540 ffc0ffff f0000400
ieee1394: send packet local: ffc00560 ffc00000 00000000 60f30404
ieee1394: received packet: ffc00560 ffc00000 00000000 60f30404
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc00560 ffc00000 00000000 60f30404
ieee1394: send packet local: ffc00940 ffc0ffff f0000400
ieee1394: received packet: ffc00940 ffc0ffff f0000400
ieee1394: send packet local: ffc00960 ffc00000 00000000 60f30404
ieee1394: received packet: ffc00960 ffc00000 00000000 60f30404
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc00960 ffc00000 00000000 60f30404
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
On Thu, 2003-07-24 at 16:09, Chris Ruvolo wrote:
...
> ieee1394: unsolicited response packet received - np
> ieee1394: contents: ffc00960 ffc00000 00000000 60f30404
> ieee1394: ConfigROM quadlet transaction error for node 00:1023
I have had problems like this with the SBP2 driver since ~2.5.75 when I
attach (or sometimes when I attempt to mount) my 250 GB external drive.
This never used to happen with 2.5.73 or earlier though.
Sometimes the driver seems to go into an loop of "unsolicted packet
received" messages and attempted resets. Here's what the log looks like
when that happens: (this was on 2.5.75)
Jul 24 16:04:37 torrey kernel: ieee1394: The root node is not cycle master capable; selecting a new root node and resetting...
Jul 24 16:04:37 torrey kernel: ieee1394: Node changed: 0-01:1023 -> 0-00:1023
Jul 24 16:04:37 torrey kernel: ieee1394: sbp2: Reconnected to SBP-2 device
Jul 24 16:04:37 torrey kernel: ieee1394: sbp2: Node[00:1023]: Max speed [S400] - Max payload [2048]
Jul 24 16:04:37 torrey kernel: ieee1394: unsolicited response packet received - np
Jul 24 16:04:37 torrey kernel: ieee1394: contents: ffc10160 ffc10000 00000000 7ee60404
Jul 24 16:04:38 torrey kernel: ieee1394: unsolicited response packet received - np
Jul 24 16:04:38 torrey kernel: ieee1394: contents: ffc10560 ffc10000 00000000 7ee60404
Jul 24 16:04:38 torrey kernel: ieee1394: unsolicited response packet received - np
Jul 24 16:04:38 torrey kernel: ieee1394: contents: ffc10960 ffc10000 00000000 7ee60404
Jul 24 16:04:39 torrey kernel: ieee1394: ConfigROM quadlet transaction error for node 01:1023
Jul 24 16:04:39 torrey kernel: ieee1394: The root node is not cycle master capable; selecting a new root node and resetting...
(this sequence repeats until I turn off or unplug the drive.)
I have not tried every kernel release along the way, so I don't know
exactly when the problem started. It is also interesting that I have
not observed this problem when I use a 120 GB drive in the same firewire
enclosure.
Here's another snippet from the dmesg of my most recent boot, into
2.6.0-test1-ac3. Luckily it didn't go into the infinite error loop this
time, but it did get one of those unsolicited packet errors:
SCSI subsystem initialized
ohci1394: $Rev: 986 $ Ben Collins <[email protected]>
PCI: Found IRQ 10 for device 0000:02:0b.0
PCI: Sharing IRQ 10 with 0000:02:01.0
ohci1394_0: OHCI-1394 1.0 (PCI): IRQ=[10] MMIO=[e8201000-e82017ff] Max Packet=[2048]
scsi0 : SCSI emulation for IEEE-1394 SBP-2 Devices
ieee1394: sbp2: Logged into SBP-2 device
ieee1394: sbp2: Node[00:1023]: Max speed [S400] - Max payload [2048]
Vendor: Maxtor 4 Model: A250J8 Rev:
Type: Direct-Access ANSI SCSI revision: 06
ieee1394: Node added: ID:BUS[0-00:1023] GUID[0004830000002cb3]
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc10160 ffc10000 00000000 7ee60404
ieee1394: Host added: ID:BUS[0-01:1023] GUID[0040630000001c47]
... snipped loading other drivers ...
SCSI device sda: 490234752 512-byte hdwr sectors (251000 MB)
sda: asking for cache data failed
sda: assuming drive cache: write through
sda: sda1
Attached scsi disk sda at scsi0, channel 0, id 0, lun 0
found reiserfs format "3.6" with standard journal
Reiserfs journal params: device sda1, size 8192, journal first block 18,
max trans len 1024, max batch 900, max commit age 30, max trans age 30
reiserfs: checking transaction log (sda1) for (sda1)
Using r5 hash to sort names
(end)
--
Torrey Hoffman <[email protected]>
On Thu, Jul 24, 2003 at 06:13:37PM -0700, Torrey Hoffman wrote:
> Sometimes the driver seems to go into an loop of "unsolicted packet
> received" messages and attempted resets. Here's what the log looks like
> when that happens: (this was on 2.5.75)
[..]
> (this sequence repeats until I turn off or unplug the drive.)
This sounds like what happens to me when I turn on my DV cam. CPU usage
goes up to 40% kernel and loops like that until the device goes off.
What hardware do you have? lspci?
Marcello's latest 2.4.22-pre8 updates to rev 1010 of the 1394 modules, so
I'm curious if I can reproduce this in 2.4 now.
-Chris
On Thu, Jul 24, 2003 at 06:27:24PM -0700, Chris Ruvolo wrote:
> On Thu, Jul 24, 2003 at 06:13:37PM -0700, Torrey Hoffman wrote:
> > Sometimes the driver seems to go into an loop of "unsolicted packet
> > received" messages and attempted resets. Here's what the log looks like
> > when that happens: (this was on 2.5.75)
> [..]
> > (this sequence repeats until I turn off or unplug the drive.)
>
> This sounds like what happens to me when I turn on my DV cam. CPU usage
> goes up to 40% kernel and loops like that until the device goes off.
>
> What hardware do you have? lspci?
>
> Marcello's latest 2.4.22-pre8 updates to rev 1010 of the 1394 modules, so
> I'm curious if I can reproduce this in 2.4 now.
Could both you guys try this workaround? Should prove or disprove my
theory.
Index: linux-2.6/drivers/ieee1394/ohci1394.c
===================================================================
--- linux-2.6/drivers/ieee1394/ohci1394.c (revision 1013)
+++ linux-2.6/drivers/ieee1394/ohci1394.c (working copy)
@@ -2366,7 +2366,7 @@
ohci1394_stop_context(ohci, d->ctrlClear,
"respTxComplete");
else
- tasklet_schedule(&d->task);
+ dma_trm_tasklet ((unsigned long)d);
event &= ~OHCI1394_respTxComplete;
}
if (event & OHCI1394_RQPkt) {
--
Debian - http://www.debian.org/
Linux 1394 - http://www.linux1394.org/
Subversion - http://subversion.tigris.org/
On Thu, Jul 24, 2003 at 09:29:08PM -0400, Ben Collins wrote:
> Could both you guys try this workaround? Should prove or disprove my
> theory.
Similar output (debug). Diff of output and then full output follows.
-Chris
--- hork.dmesg.1394 Thu Jul 24 18:54:19 2003
+++ hork.dmesg.1394-2 Thu Jul 24 18:54:45 2003
@@ -12,7 +12,7 @@
ohci1394_0: Transmit DMA ctx=0 initialized
ohci1394_0: Transmit DMA ctx=1 initialized
ohci1394_0: OHCI-1394 1.0 (PCI): IRQ=[10] MMIO=[db001000-db0017ff] Max Packet=[2048]
-ohci1394_0: request csr_rom address: c0961000
+ohci1394_0: request csr_rom address: c2aca000
ohci1394_0: IntEvent: 00030010
ohci1394_0: irq_handler: Bus reset requested
ohci1394_0: Cancel request received
ohci1394: $Rev: 986 $ Ben Collins <[email protected]>
PCI: Found IRQ 10 for device 0000:00:0b.0
ohci1394_0: Remapped memory spaces reg 0xc897a000
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: 00110600:00006a85
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=[db001000-db0017ff] Max Packet=[2048]
ohci1394_0: request csr_rom address: c2aca000
ohci1394_0: IntEvent: 00030010
ohci1394_0: irq_handler: Bus reset requested
ohci1394_0: Cancel request received
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: received packet: ffc00140 ffc0ffff f0000400
ieee1394: send packet local: ffc00160 ffc00000 00000000 60f30404
ieee1394: received packet: ffc00160 ffc00000 00000000 60f30404
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc00160 ffc00000 00000000 60f30404
ieee1394: send packet local: ffc00540 ffc0ffff f0000400
ieee1394: received packet: ffc00540 ffc0ffff f0000400
ieee1394: send packet local: ffc00560 ffc00000 00000000 60f30404
ieee1394: received packet: ffc00560 ffc00000 00000000 60f30404
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc00560 ffc00000 00000000 60f30404
ieee1394: send packet local: ffc00940 ffc0ffff f0000400
ieee1394: received packet: ffc00940 ffc0ffff f0000400
ieee1394: send packet local: ffc00960 ffc00000 00000000 60f30404
ieee1394: received packet: ffc00960 ffc00000 00000000 60f30404
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc00960 ffc00000 00000000 60f30404
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
On Thu, Jul 24, 2003 at 07:00:27PM -0700, Chris Ruvolo wrote:
> On Thu, Jul 24, 2003 at 09:29:08PM -0400, Ben Collins wrote:
> > Could both you guys try this workaround? Should prove or disprove my
> > theory.
>
> Similar output (debug). Diff of output and then full output follows.
Just noticed that this doesn't even have anything to do with ohci1394.
It's all local requests for config rom reads. Can you send me the debug
with the below patch applied?
Index: linux-2.6/drivers/ieee1394/ieee1394_core.c
===================================================================
--- linux-2.6/drivers/ieee1394/ieee1394_core.c (revision 1013)
+++ linux-2.6/drivers/ieee1394/ieee1394_core.c (working copy)
@@ -611,6 +611,7 @@
list_for_each(lh, &host->pending_packets) {
packet = list_entry(lh, struct hpsb_packet, list);
+ HPSB_DEBUG("Checking tlabel %d\n", tlabel);
if ((packet->tlabel == tlabel)
&& (packet->node_id == (data[1] >> 16))){
break;
--
Debian - http://www.debian.org/
Linux 1394 - http://www.linux1394.org/
Subversion - http://subversion.tigris.org/
On Thu, 2003-07-24 at 21:29, Ben Collins wrote:
> On Thu, Jul 24, 2003 at 06:27:24PM -0700, Chris Ruvolo wrote:
> > On Thu, Jul 24, 2003 at 06:13:37PM -0700, Torrey Hoffman wrote:
> > > Sometimes the driver seems to go into an loop of "unsolicted packet
> > > received" messages and attempted resets. Here's what the log looks like
> > > when that happens: (this was on 2.5.75)
> > [..]
> > > (this sequence repeats until I turn off or unplug the drive.)
> >
> > This sounds like what happens to me when I turn on my DV cam. CPU usage
> > goes up to 40% kernel and loops like that until the device goes off.
> >
> > What hardware do you have? lspci?
> >
> > Marcello's latest 2.4.22-pre8 updates to rev 1010 of the 1394 modules, so
> > I'm curious if I can reproduce this in 2.4 now.
>
> Could both you guys try this workaround? Should prove or disprove my
> theory.
>
> Index: linux-2.6/drivers/ieee1394/ohci1394.c
> ===================================================================
> --- linux-2.6/drivers/ieee1394/ohci1394.c (revision 1013)
> +++ linux-2.6/drivers/ieee1394/ohci1394.c (working copy)
> @@ -2366,7 +2366,7 @@
> ohci1394_stop_context(ohci, d->ctrlClear,
> "respTxComplete");
> else
> - tasklet_schedule(&d->task);
> + dma_trm_tasklet ((unsigned long)d);
> event &= ~OHCI1394_respTxComplete;
> }
> if (event & OHCI1394_RQPkt) {
For what it's worth, I'm experiencing this as well.
In the hopes of helping, I provide the dmesg
output results after applying the above patch to Rev 1013.
(Running 2.6.0-test1-ac1).
(Goes crazy after plugging in camera.)
<snip>
et received - np
ieee1394: contents: ffc11960 ffc10000 00000000 2e5e0404
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc11d60 ffc10000 00000000 2e5e0404
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc12160 ffc10000 00000000 2e5e0404
ieee1394: ConfigROM quadlet transaction error for node 0-01:1023
ieee1394: The root node is not cycle master capable; selecting a new
root node and resetting...
ieee1394: Checking tlabel 49
ieee1394: Checking tlabel 50
ieee1394: Checking tlabel 51
ieee1394: Checking tlabel 52
ieee1394: Checking tlabel 53
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc12560 ffc10000 00000000 2e5e0404
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc12960 ffc10000 00000000 2e5e0404
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc12d60 ffc10000 00000000 2e5e0404
ieee1394: ConfigROM quadlet transaction error for node 0-01:1023
ieee1394: The root node is not cycle master capable; selecting a new
root node and resetting...
ieee1394: Checking tlabel 54
ieee1394: Checking tlabel 55
ieee1394: Checking tlabel 56
ieee1394: Checking tlabel 57
ieee1394: Checking tlabel 58
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc13160 ffc10000 00000000 2e5e0404
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc13560 ffc10000 00000000 2e5e0404
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc13960 ffc10000 00000000 2e5e0404
ieee1394: ConfigROM quadlet transaction error for node 0-01:1023
ieee1394: The root node is not cycle master capable; selecting a new
root node and resetting...
ieee1394: Checking tlabel 59
ieee1394: Checking tlabel 60
ieee1394: Checking tlabel 61
ieee1394: Checking tlabel 62
ieee1394: Checking tlabel 63
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc13d60 ffc10000 00000000 2e5e0404
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc14160 ffc10000 00000000 2e5e0404
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc14560 ffc10000 00000000 2e5e0404
ieee1394: ConfigROM quadlet transaction error for node 0-01:1023
ieee1394: The root node is not cycle master capable; selecting a new
root node and resetting...
ieee1394: Checking tlabel 0
ieee1394: Checking tlabel 1
ieee1394: Checking tlabel 2
ieee1394: Checking tlabel 3
ieee1394: Checking tlabel 4
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc14960 ffc10000 00000000 2e5e0404
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc14d60 ffc10000 00000000 2e5e0404
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc15160 ffc10000 00000000 2e5e0404
ieee1394: ConfigROM quadlet transaction error for node 0-01:1023
ieee1394: The root node is not cycle master capable; selecting a new
root node and resetting...
ieee1394: Checking tlabel 5
ieee1394: Checking tlabel 6
ieee1394: Checking tlabel 7
ieee1394: Checking tlabel 8
ieee1394: Checking tlabel 9
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc15560 ffc10000 00000000 2e5e0404
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc15960 ffc10000 00000000 2e5e0404
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc15d60 ffc10000 00000000 2e5e0404
ieee1394: ConfigROM quadlet transaction error for node 0-01:1023
ieee1394: The root node is not cycle master capable; selecting a new
root node and resetting...
ieee1394: Checking tlabel 10
ieee1394: Checking tlabel 11
ieee1394: Checking tlabel 12
ieee1394: Checking tlabel 13
ieee1394: Checking tlabel 14
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc16160 ffc10000 00000000 2e5e0404
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc16560 ffc10000 00000000 2e5e0404
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc16960 ffc10000 00000000 2e5e0404
ieee1394: ConfigROM quadlet transaction error for node 0-01:1023
ieee1394: The root node is not cycle master capable; selecting a new
root node and resetting...
ieee1394: Checking tlabel 15
ieee1394: Checking tlabel 16
ieee1394: Checking tlabel 17
<snip>
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc06960 ffc00000 00000000 2e5e0404
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc06d60 ffc00000 00000000 2e5e0404
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc07160 ffc00000 00000000 2e5e0404
ieee1394: ConfigROM quadlet transaction error for node 0-00:1023
ieee1394: Node removed: ID:BUS[0-00:1023] GUID[0001687300012646]
video1394: Removed video1394 module
bad: scheduling while atomic!
Call Trace:
[<c011a0d0>] schedule+0x3a0/0x3b0
[<c01189b1>] do_page_fault+0x251/0x451
[<c011a418>] wait_for_completion+0x78/0xd0
[<c011a130>] default_wake_function+0x0/0x30
[<c011a130>] default_wake_function+0x0/0x30
[<c0126f22>] kill_proc_info+0x42/0x70
[<e4ed0245>] nodemgr_remove_host+0x55/0xa0 [ieee1394]
[<e4ecbc6b>] highlevel_remove_host+0x6b/0x80 [ieee1394]
[<e4eb3a21>] ohci1394_pci_remove+0x41/0x230 [ohci1394]
[<c01ecfeb>] pci_device_remove+0x3b/0x40
[<c0233092>] device_release_driver+0x62/0x70
[<c02330c0>] driver_detach+0x20/0x30
[<c023331d>] bus_remove_driver+0x3d/0x80
[<c0233743>] driver_unregister+0x13/0x28
[<c01ed2b6>] pci_unregister_driver+0x16/0x30
[<e4eb3edf>] ohci1394_cleanup+0xf/0x13 [ohci1394]
[<c01317b3>] sys_delete_module+0x133/0x150
[<c0144874>] sys_munmap+0x44/0x70
[<c0109087>] syscall_call+0x7/0xb
If I can provide better information, let me know.
Sam Bromley.
> For what it's worth, I'm experiencing this as well.
> In the hopes of helping, I provide the dmesg
> output results after applying the above patch to Rev 1013.
> (Running 2.6.0-test1-ac1).
Please compile with debug enabled so I can get all the output. Also,
update using this patch instead of my last one.
Index: linux-2.6/drivers/ieee1394/ieee1394_core.c
===================================================================
--- linux-2.6/drivers/ieee1394/ieee1394_core.c (revision 1013)
+++ linux-2.6/drivers/ieee1394/ieee1394_core.c (working copy)
@@ -609,8 +609,11 @@
spin_lock_irqsave(&host->pending_pkt_lock, flags);
+ HPSB_DEBUG("TLABEL: Checking for tlabel %d", tlabel);
+
list_for_each(lh, &host->pending_packets) {
packet = list_entry(lh, struct hpsb_packet, list);
+ HPSB_DEBUG("TLABEL: tlabel %d in list", packet->tlabel, tlabel);
if ((packet->tlabel == tlabel)
&& (packet->node_id == (data[1] >> 16))){
break;
@@ -622,7 +625,8 @@
dump_packet("contents:", data, 16);
spin_unlock_irqrestore(&host->pending_pkt_lock, flags);
return;
- }
+ } else
+ HPSB_DEBUG("TLABEL: Found tlabel");
switch (packet->tcode) {
case TCODE_WRITEQ:
--
Debian - http://www.debian.org/
Linux 1394 - http://www.linux1394.org/
Subversion - http://subversion.tigris.org/
On Fri, Jul 25, 2003 at 12:12:34AM -0400, Ben Collins wrote:
> Please compile with debug enabled so I can get all the output. Also,
> update using this patch instead of my last one.
The list looks empty.
-Chris
ohci1394: $Rev: 986 $ Ben Collins <[email protected]>
PCI: Found IRQ 10 for device 0000:00:0b.0
ohci1394_0: Remapped memory spaces reg 0xc897a000
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: 00110600:00006a85
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=[db001000-db0017ff] Max Packet=[2048]
ohci1394_0: request csr_rom address: c3d64000
ohci1394_0: IntEvent: 00030010
ohci1394_0: irq_handler: Bus reset requested
ohci1394_0: Cancel request received
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: received packet: ffc00140 ffc0ffff f0000400
ieee1394: send packet local: ffc00160 ffc00000 00000000 60f30404
ieee1394: received packet: ffc00160 ffc00000 00000000 60f30404
ieee1394: TLABEL: Checking for tlabel 0
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc00160 ffc00000 00000000 60f30404
ieee1394: send packet local: ffc00540 ffc0ffff f0000400
ieee1394: received packet: ffc00540 ffc0ffff f0000400
ieee1394: send packet local: ffc00560 ffc00000 00000000 60f30404
ieee1394: received packet: ffc00560 ffc00000 00000000 60f30404
ieee1394: TLABEL: Checking for tlabel 1
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc00560 ffc00000 00000000 60f30404
ieee1394: send packet local: ffc00940 ffc0ffff f0000400
ieee1394: received packet: ffc00940 ffc0ffff f0000400
ieee1394: send packet local: ffc00960 ffc00000 00000000 60f30404
ieee1394: received packet: ffc00960 ffc00000 00000000 60f30404
ieee1394: TLABEL: Checking for tlabel 2
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc00960 ffc00000 00000000 60f30404
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
Index: ieee1394_core.c
===================================================================
--- ieee1394_core.c (revision 1013)
+++ ieee1394_core.c (working copy)
@@ -421,11 +421,13 @@
if (packet->no_waiter) {
/* must not have a tlabel allocated */
+ HPSB_DEBUG("TLABEL: no_waiter, returning");
free_hpsb_packet(packet);
return;
}
if (ackcode != ACK_PENDING || !packet->expect_response) {
+ HPSB_DEBUG("TLABEL: not pending or no response expected, returning");
packet->state = hpsb_complete;
up(&packet->state_change);
up(&packet->state_change);
@@ -437,6 +439,7 @@
packet->sendtime = jiffies;
spin_lock_irqsave(&host->pending_pkt_lock, flags);
+ HPSB_DEBUG("TLABEL: appending packet to pending list");
list_add_tail(&packet->list, &host->pending_packets);
spin_unlock_irqrestore(&host->pending_pkt_lock, flags);
--
Debian - http://www.debian.org/
Linux 1394 - http://www.linux1394.org/
Subversion - http://subversion.tigris.org/
On Thu, Jul 24, 2003 at 10:39:20PM -0700, Chris Ruvolo wrote:
> On Fri, Jul 25, 2003 at 12:12:34AM -0400, Ben Collins wrote:
> > Please compile with debug enabled so I can get all the output. Also,
> > update using this patch instead of my last one.
>
> The list looks empty.
Indeed. Please apply this patch aswell.
--
Debian - http://www.debian.org/
Linux 1394 - http://www.linux1394.org/
Subversion - http://subversion.tigris.org/
Ben Collins wrote:
> On Thu, Jul 24, 2003 at 10:39:20PM -0700, Chris Ruvolo wrote:
>
>>On Fri, Jul 25, 2003 at 12:12:34AM -0400, Ben Collins wrote:
>>
>>>Please compile with debug enabled so I can get all the output. Also,
>>>update using this patch instead of my last one.
>>
>>The list looks empty.
>
>
> Indeed. Please apply this patch aswell.
>
I apologize for my ignorance. This is what I did after saving your
patches as firewire1 and firewire2 text files:
root@localhost dave # cd /usr/src/linux
root@localhost linux # ls /home/dave/patches
firewire1 firewire2
root@localhost linux # cp /home/dave/patches/* .
root@localhost linux # cat firewire1 | patch -p1
patching file drivers/ieee1394/ieee1394_core.c
Hunk #1 succeeded at 608 (offset -1 lines).
root@localhost linux # cat firewire2 | patch -p1
missing header for unified diff at line 5 of patch
can't find file to patch at input line 5
Perhaps you used the wrong -p or --strip option?
The text leading up to this was:
--------------------------
|Index: ieee1394_core.c
|===================================================================
|--- ieee1394_core.c (revision 1013)
|+++ ieee1394_core.c (working copy)
--------------------------
File to patch:
root@localhost linux #
Also, how do I compiled the modules with debug enabled? Thanks.
> root@localhost linux # cat firewire2 | patch -p1
> missing header for unified diff at line 5 of patch
> can't find file to patch at input line 5
> Perhaps you used the wrong -p or --strip option?
> The text leading up to this was:
> --------------------------
> |Index: ieee1394_core.c
> |===================================================================
> |--- ieee1394_core.c (revision 1013)
> |+++ ieee1394_core.c (working copy)
> --------------------------
> File to patch:
> root@localhost linux #
My mistake for not doing a full path diff. Do this:
patch drivers/ieee1394/ieee1394_core.c < firewire2
> Also, how do I compiled the modules with debug enabled? Thanks.
There's a config option under IEEE1394 for verbose debugging.
--
Debian - http://www.debian.org/
Linux 1394 - http://www.linux1394.org/
Subversion - http://subversion.tigris.org/
After applying both patches and enabling ieee1394 excessive debugging in
xconfig:
root@localhost linux # rmmod raw1394
root@localhost linux # rmmod ohci1394
root@localhost linux # rmmod ieee1394
root@localhost linux # make modules modules_install
...
CC [M] drivers/ieee1394/ieee1394_core.o
drivers/ieee1394/ieee1394_core.c: In function `handle_packet_response':
drivers/ieee1394/ieee1394_core.c:618: warning: too many arguments for format
CC [M] drivers/ieee1394/ieee1394_transactions.o
CC [M] drivers/ieee1394/nodemgr.o
LD [M] drivers/ieee1394/ieee1394.o
CC [M] drivers/ieee1394/ohci1394.o
CC [M] drivers/ieee1394/video1394.o
CC [M] drivers/ieee1394/raw1394.o
...
root@localhost linux # modprobe ieee1394
root@localhost linux # modprobe ohci1394
root@localhost linux # modprobe raw1394
root@localhost linux # dmesg
...
ohci1394: $Rev: 986 $ Ben Collins <[email protected]>
ohci1394_0: Remapped memory spaces reg 0xd093f800
ohci1394_0: Soft reset finished
ohci1394_0: Iso contexts reg: 000000a8 implemented: 0000000f
ohci1394_0: 4 iso receive contexts available
ohci1394_0: Iso contexts reg: 00000098 implemented: 000000ff
ohci1394_0: 8 iso transmit contexts available
ohci1394_0: GUID: 060050c5:000001ce
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=[5] MMIO=[cfffc800-cfffcfff] Max
Packet=[2048]
ohci1394_0: request csr_rom address: cce13000
ohci1394_0: IntEvent: 00020010
ohci1394_0: irq_handler: Bus reset requested
ohci1394_0: Cancel request received
ohci1394_0: Got RQPkt interrupt status=0x00008409
ohci1394_0: Single packet rcv'd
ohci1394_0: Got phy packet ctx=0 ... discarded
ohci1394_0: IntEvent: 00010000
ohci1394_0: SelfID interrupt received (phyid 0, root)
ohci1394_0: SelfID packet 0x807f8c56 received
ieee1394: Including SelfID 0x568c7f80
ohci1394_0: SelfID for this node is 0x807f8c56
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
ieee1394: Initiating ConfigROM request for node 00:1023
ieee1394: send packet local: ffc00140 ffc0ffff f0000400
ieee1394: TLABEL: appending packet to pending list
ieee1394: received packet: ffc00140 ffc0ffff f0000400
ieee1394: send packet local: ffc00160 ffc00000 00000000 dee10404
ieee1394: TLABEL: no_waiter, returning
ieee1394: received packet: ffc00160 ffc00000 00000000 dee10404
ieee1394: TLABEL: Checking for tlabel 0
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc00160 ffc00000 00000000 dee10404
ieee1394: send packet local: ffc00540 ffc0ffff f0000400
ieee1394: TLABEL: appending packet to pending list
ieee1394: received packet: ffc00540 ffc0ffff f0000400
ieee1394: send packet local: ffc00560 ffc00000 00000000 dee10404
ieee1394: TLABEL: no_waiter, returning
ieee1394: received packet: ffc00560 ffc00000 00000000 dee10404
ieee1394: TLABEL: Checking for tlabel 1
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc00560 ffc00000 00000000 dee10404
ieee1394: send packet local: ffc00940 ffc0ffff f0000400
ieee1394: TLABEL: appending packet to pending list
ieee1394: received packet: ffc00940 ffc0ffff f0000400
ieee1394: send packet local: ffc00960 ffc00000 00000000 dee10404
ieee1394: TLABEL: no_waiter, returning
ieee1394: received packet: ffc00960 ffc00000 00000000 dee10404
ieee1394: TLABEL: Checking for tlabel 2
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc00960 ffc00000 00000000 dee10404
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
raw1394: /dev/raw1394 device initialized
root@localhost linux #
On Fri, Jul 25, 2003 at 09:34:38AM -0400, Ben Collins wrote:
> > The list looks empty.
>
> Indeed. Please apply this patch aswell.
What does no_waiter indicate? That a packet should not have a response?
-Chris
ohci1394: $Rev: 986 $ Ben Collins <[email protected]>
PCI: Found IRQ 10 for device 0000:00:0b.0
ohci1394_0: Remapped memory spaces reg 0xc897a000
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: 00110600:00006a85
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=[db001000-db0017ff] Max Packet=[2048]
ohci1394_0: request csr_rom address: c6aa8000
ohci1394_0: IntEvent: 00030010
ohci1394_0: irq_handler: Bus reset requested
ohci1394_0: Cancel request received
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: received packet: ffc00140 ffc0ffff f0000400
ieee1394: send packet local: ffc00160 ffc00000 00000000 60f30404
ieee1394: TLABEL: no_waiter, returning
ieee1394: received packet: ffc00160 ffc00000 00000000 60f30404
ieee1394: TLABEL: Checking for tlabel 0
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc00160 ffc00000 00000000 60f30404
ieee1394: send packet local: ffc00540 ffc0ffff f0000400
ieee1394: TLABEL: appending packet to pending list
ieee1394: received packet: ffc00540 ffc0ffff f0000400
ieee1394: send packet local: ffc00560 ffc00000 00000000 60f30404
ieee1394: TLABEL: no_waiter, returning
ieee1394: received packet: ffc00560 ffc00000 00000000 60f30404
ieee1394: TLABEL: Checking for tlabel 1
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc00560 ffc00000 00000000 60f30404
ieee1394: send packet local: ffc00940 ffc0ffff f0000400
ieee1394: TLABEL: appending packet to pending list
ieee1394: received packet: ffc00940 ffc0ffff f0000400
ieee1394: send packet local: ffc00960 ffc00000 00000000 60f30404
ieee1394: TLABEL: no_waiter, returning
ieee1394: received packet: ffc00960 ffc00000 00000000 60f30404
ieee1394: TLABEL: Checking for tlabel 2
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc00960 ffc00000 00000000 60f30404
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
>
> What does no_waiter indicate? That a packet should not have a response?
>
Yeah. Which is usually the case for a successful ack packet. Something
is clearing the list of pending packets, but I'm not sure what. Please
revert the patches thus far and apply this patch. It should tell us
where pending_packets is getting changed.
My best guess right now is that abort_timedouts is killing packets from
the pending list too quickly. We'll cross that bridge when we see the
results here.
--
Debian - http://www.debian.org/
Linux 1394 - http://www.linux1394.org/
Subversion - http://subversion.tigris.org/
gaxt wrote:
> After applying both patches and enabling ieee1394 excessive debugging in
> xconfig:
...
Ben, is there anything else you want me to do?
Ok, so revert everything and try this patch.
Index: linux-2.6/drivers/ieee1394/ieee1394_core.c
===================================================================
--- linux-2.6/drivers/ieee1394/ieee1394_core.c (revision 1013)
+++ linux-2.6/drivers/ieee1394/ieee1394_core.c (working copy)
@@ -421,11 +421,13 @@
if (packet->no_waiter) {
/* must not have a tlabel allocated */
+ HPSB_DEBUG("TLABEL: no_waiter, returning");
free_hpsb_packet(packet);
return;
}
if (ackcode != ACK_PENDING || !packet->expect_response) {
+ HPSB_DEBUG("TLABEL: not pending or no response expected, returning");
packet->state = hpsb_complete;
up(&packet->state_change);
up(&packet->state_change);
@@ -437,6 +439,7 @@
packet->sendtime = jiffies;
spin_lock_irqsave(&host->pending_pkt_lock, flags);
+ HPSB_DEBUG("TLABEL: appending packet to pending list");
list_add_tail(&packet->list, &host->pending_packets);
spin_unlock_irqrestore(&host->pending_pkt_lock, flags);
@@ -609,8 +612,11 @@
spin_lock_irqsave(&host->pending_pkt_lock, flags);
+ HPSB_DEBUG("TLABEL: Checking for tlabel %d", tlabel);
+
list_for_each(lh, &host->pending_packets) {
packet = list_entry(lh, struct hpsb_packet, list);
+ HPSB_DEBUG("TLABEL: tlabel %d in list", packet->tlabel);
if ((packet->tlabel == tlabel)
&& (packet->node_id == (data[1] >> 16))){
break;
@@ -618,11 +624,12 @@
}
if (lh == &host->pending_packets) {
- HPSB_DEBUG("unsolicited response packet received - np");
+ HPSB_DEBUG("unsolicited response packet received - no tlabel match");
dump_packet("contents:", data, 16);
spin_unlock_irqrestore(&host->pending_pkt_lock, flags);
return;
- }
+ } else
+ HPSB_DEBUG("TLABEL: Found tlabel");
switch (packet->tcode) {
case TCODE_WRITEQ:
@@ -642,7 +649,7 @@
if (!tcode_match || (packet->tlabel != tlabel)
|| (packet->node_id != (data[1] >> 16))) {
- HPSB_INFO("unsolicited response packet received");
+ HPSB_INFO("unsolicited response packet received - tcode mismatch");
dump_packet("contents:", data, 16);
spin_unlock_irqrestore(&host->pending_pkt_lock, flags);
@@ -946,6 +953,7 @@
host->driver->devctl(host, CANCEL_REQUESTS, 0);
spin_lock_irqsave(&host->pending_pkt_lock, flags);
+ HPSB_DEBUG("TLABEL: splicing pending packets for abort_requests");
list_splice(&host->pending_packets, &llist);
INIT_LIST_HEAD(&host->pending_packets);
spin_unlock_irqrestore(&host->pending_pkt_lock, flags);
@@ -969,20 +977,16 @@
LIST_HEAD(expiredlist);
spin_lock_irqsave(&host->csr.lock, flags);
- expire = (host->csr.split_timeout_hi * 8000
- + (host->csr.split_timeout_lo >> 19))
- * HZ / 8000;
- /* Avoid shortening of timeout due to rounding errors: */
- expire++;
+ expire = host->csr.expire;
spin_unlock_irqrestore(&host->csr.lock, flags);
-
spin_lock_irqsave(&host->pending_pkt_lock, flags);
for (lh = host->pending_packets.next; lh != &host->pending_packets; lh = next) {
packet = list_entry(lh, struct hpsb_packet, list);
next = lh->next;
if (time_before(packet->sendtime + expire, jiffies)) {
+ HPSB_DEBUG("TLABEL: packet removed in abort_timedouts");
list_del(&packet->list);
list_add(&packet->list, &expiredlist);
}
Index: linux-2.6/drivers/ieee1394/csr.c
===================================================================
--- linux-2.6/drivers/ieee1394/csr.c (revision 1013)
+++ linux-2.6/drivers/ieee1394/csr.c (working copy)
@@ -89,7 +89,36 @@
0x3f1));
}
+/*
+ * HI == seconds (bits 0:2)
+ * LO == fraction units of 1/8000 of a second, as per 1394 (bits 19:31)
+ *
+ * Convert to units and then to HZ, for comparison to jiffies.
+ *
+ * BY default this will end up being 800 units, or 100ms (125usec per
+ * unit).
+ *
+ * NOTE: The spec say 1/8000, but also says we can compute based on 1/8192
+ * like CSR specifies. Should make our math less complex.
+ */
+static inline void calculate_expire(struct csr_control *csr)
+{
+ unsigned long units;
+
+ /* Take the seconds, and convert to units */
+ units = (unsigned long)(csr->split_timeout_hi & 0x07) << 13;
+ /* Add in the fractional units */
+ units += (unsigned long)(csr->split_timeout_lo >> 19);
+
+ /* Convert to jiffies */
+ csr->expire = (unsigned long)(units * HZ) >> 13UL;
+
+ /* Just to keep from rounding low */
+ csr->expire++;
+}
+
+
static void add_host(struct hpsb_host *host)
{
host->csr.lock = SPIN_LOCK_UNLOCKED;
@@ -100,6 +129,7 @@
host->csr.node_ids = 0;
host->csr.split_timeout_hi = 0;
host->csr.split_timeout_lo = 800 << 19;
+ calculate_expire(&host->csr);
host->csr.cycle_time = 0;
host->csr.bus_time = 0;
host->csr.bus_manager_id = 0x3f;
@@ -336,10 +366,12 @@
case CSR_SPLIT_TIMEOUT_HI:
host->csr.split_timeout_hi =
be32_to_cpu(*(data++)) & 0x00000007;
+ calculate_expire(&host->csr);
out;
case CSR_SPLIT_TIMEOUT_LO:
host->csr.split_timeout_lo =
be32_to_cpu(*(data++)) & 0xfff80000;
+ calculate_expire(&host->csr);
out;
/* address gap */
Index: linux-2.6/drivers/ieee1394/csr.h
===================================================================
--- linux-2.6/drivers/ieee1394/csr.h (revision 1013)
+++ linux-2.6/drivers/ieee1394/csr.h (working copy)
@@ -41,6 +41,7 @@
quadlet_t state;
quadlet_t node_ids;
quadlet_t split_timeout_hi, split_timeout_lo;
+ unsigned long expire; // Calculated from split_timeout
quadlet_t cycle_time;
quadlet_t bus_time;
quadlet_t bus_manager_id;
--
Debian - http://www.debian.org/
Linux 1394 - http://www.linux1394.org/
Subversion - http://subversion.tigris.org/
On Fri, Jul 25, 2003 at 10:29:26AM -0400, Ben Collins wrote:
> Yeah. Which is usually the case for a successful ack packet. Something
> is clearing the list of pending packets, but I'm not sure what. Please
> revert the patches thus far and apply this patch. It should tell us
> where pending_packets is getting changed.
>
> My best guess right now is that abort_timedouts is killing packets from
> the pending list too quickly. We'll cross that bridge when we see the
> results here.
Interesting. I think you forgot the patch. I'm guessing that this is what
it would have looked like. Output follows.
-Chris
--- ieee1394_core.c.orig.bak 2003-07-25 08:45:41.000000000 -0700
+++ ieee1394_core.c 2003-07-25 08:48:37.000000000 -0700
@@ -952,6 +952,7 @@
list_for_each_safe(lh, tlh, &llist) {
packet = list_entry(lh, struct hpsb_packet, list);
list_del(&packet->list);
+ HPSB_DEBUG("deleting in abort_requests()");
packet->state = hpsb_complete;
packet->ack_code = ACKX_ABORTED;
up(&packet->state_change);
@@ -982,6 +983,7 @@
packet = list_entry(lh, struct hpsb_packet, list);
next = lh->next;
if (time_before(packet->sendtime + expire, jiffies)) {
+ HPSB_DEBUG("abort_timedouts: removing tlabel %d", packet->tlabel);
list_del(&packet->list);
list_add(&packet->list, &expiredlist);
}
ohci1394: $Rev: 986 $ Ben Collins <[email protected]>
PCI: Found IRQ 10 for device 0000:00:0b.0
ohci1394_0: Remapped memory spaces reg 0xc897a000
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: 00110600:00006a85
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=[db001000-db0017ff] Max Packet=[2048]
ohci1394_0: request csr_rom address: c42a2000
ohci1394_0: IntEvent: 00030010
ohci1394_0: irq_handler: Bus reset requested
ohci1394_0: Cancel request received
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: abort_timedouts: removing tlabel 0
ieee1394: received packet: ffc00140 ffc0ffff f0000400
ieee1394: send packet local: ffc00160 ffc00000 00000000 60f30404
ieee1394: received packet: ffc00160 ffc00000 00000000 60f30404
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc00160 ffc00000 00000000 60f30404
ieee1394: send packet local: ffc00540 ffc0ffff f0000400
ieee1394: abort_timedouts: removing tlabel 1
ieee1394: received packet: ffc00540 ffc0ffff f0000400
ieee1394: send packet local: ffc00560 ffc00000 00000000 60f30404
ieee1394: received packet: ffc00560 ffc00000 00000000 60f30404
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc00560 ffc00000 00000000 60f30404
ieee1394: send packet local: ffc00940 ffc0ffff f0000400
ieee1394: abort_timedouts: removing tlabel 2
ieee1394: received packet: ffc00940 ffc0ffff f0000400
ieee1394: send packet local: ffc00960 ffc00000 00000000 60f30404
ieee1394: received packet: ffc00960 ffc00000 00000000 60f30404
ieee1394: unsolicited response packet received - np
ieee1394: contents: ffc00960 ffc00000 00000000 60f30404
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
On Fri, Jul 25, 2003 at 08:53:55AM -0700, Chris Ruvolo wrote:
> On Fri, Jul 25, 2003 at 10:29:26AM -0400, Ben Collins wrote:
> > Yeah. Which is usually the case for a successful ack packet. Something
> > is clearing the list of pending packets, but I'm not sure what. Please
> > revert the patches thus far and apply this patch. It should tell us
> > where pending_packets is getting changed.
> >
> > My best guess right now is that abort_timedouts is killing packets from
> > the pending list too quickly. We'll cross that bridge when we see the
> > results here.
>
> Interesting. I think you forgot the patch. I'm guessing that this is what
> it would have looked like. Output follows.
That's exactly what it looked like, and the info is exactly what I
thought would be produced. Could you tell me the value for HZ on your
system? Also try the patch I sent just prior to this email.
Thanks, your testing is very helpful.
--
Debian - http://www.debian.org/
Linux 1394 - http://www.linux1394.org/
Subversion - http://subversion.tigris.org/
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.
-Chris
drivers/ieee1394/raw1394.c: In function `arm_register':
drivers/ieee1394/raw1394.c:1569: warning: integer constant is too large for "long" type
drivers/ieee1394/raw1394.c:1570: warning: integer constant is too large for "long" type
ohci1394: $Rev: 986 $ Ben Collins <[email protected]>
PCI: Found IRQ 10 for device 0000:00:0b.0
ohci1394_0: Remapped memory spaces reg 0xc897a000
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: 00110600:00006a85
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=[db001000-db0017ff] Max Packet=[2048]
ohci1394_0: request csr_rom address: c1f22000
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: received packet: ffc00140 ffc0ffff f0000400
ieee1394: send packet local: ffc00160 ffc00000 00000000 60f30404
ieee1394: TLABEL: no_waiter, returning
ieee1394: received packet: ffc00160 ffc00000 00000000 60f30404
ieee1394: TLABEL: Checking for tlabel 0
ieee1394: unsolicited response packet received - no tlabel match
ieee1394: contents: ffc00160 ffc00000 00000000 60f30404
ieee1394: send packet local: ffc00540 ffc0ffff f0000400
ieee1394: TLABEL: appending packet to pending list
ieee1394: TLABEL: packet removed in abort_timedouts
ieee1394: received packet: ffc00540 ffc0ffff f0000400
ieee1394: send packet local: ffc00560 ffc00000 00000000 60f30404
ieee1394: TLABEL: no_waiter, returning
ieee1394: received packet: ffc00560 ffc00000 00000000 60f30404
ieee1394: TLABEL: Checking for tlabel 1
ieee1394: unsolicited response packet received - no tlabel match
ieee1394: contents: ffc00560 ffc00000 00000000 60f30404
ieee1394: send packet local: ffc00940 ffc0ffff f0000400
ieee1394: TLABEL: appending packet to pending list
ieee1394: TLABEL: packet removed in abort_timedouts
ieee1394: received packet: ffc00940 ffc0ffff f0000400
ieee1394: send packet local: ffc00960 ffc00000 00000000 60f30404
ieee1394: TLABEL: no_waiter, returning
ieee1394: received packet: ffc00960 ffc00000 00000000 60f30404
ieee1394: TLABEL: Checking for tlabel 2
ieee1394: unsolicited response packet received - no tlabel match
ieee1394: contents: ffc00960 ffc00000 00000000 60f30404
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
On Fri, Jul 25, 2003 at 11:47:15AM -0400, Ben Collins wrote:
> That's exactly what it looked like, and the info is exactly what I
> thought would be produced. Could you tell me the value for HZ on your
> system? Also try the patch I sent just prior to this email.
Its an x86, and I didn't do anything to change the default.. so I believe
its HZ=1000 (at least, thats what include/asm/param.h says).
> Thanks, your testing is very helpful.
Thanks for taking the time to go through this.
-Chris
Ben Collins wrote:
> Ok, so revert everything and try this patch.
>
> Index: linux-2.6/drivers/ieee1394/ieee1394_core.c
> ===================================================================
after rmmod all 1394 modules, making, and re modprobing them. I hope
this is the output you need from dmesg.
...
ieee1394: NodeMgr: Exiting thread
ohci1394_0: Soft reset finished
ohci1394_0: Freeing dma_rcv_ctx 0
ohci1394_0: Freeing dma_rcv_ctx 0
ohci1394_0: Freeing dma_trm_ctx 0
ohci1394_0: Freeing dma_trm_ctx 1
raw1394: /dev/raw1394 device initialized
ohci1394: $Rev$ Ben Collins <[email protected]>
ohci1394_0: Remapped memory spaces reg 0xd093f800
ohci1394_0: Soft reset finished
ohci1394_0: Iso contexts reg: 000000a8 implemented: 0000000f
ohci1394_0: 4 iso receive contexts available
ohci1394_0: Iso contexts reg: 00000098 implemented: 000000ff
ohci1394_0: 8 iso transmit contexts available
ohci1394_0: GUID: 060050c5:000001ce
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=[5] MMIO=[cfffc800-cfffcfff] Max
Packet=[2048]
ohci1394_0: request csr_rom address: c3efa000
ohci1394_0: IntEvent: 00020010
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: Single packet rcv'd
ohci1394_0: Got phy packet ctx=0 ... discarded
ohci1394_0: IntEvent: 00010000
ohci1394_0: SelfID interrupt received (phyid 0, root)
ohci1394_0: SelfID packet 0x807f8c56 received
ieee1394: Including SelfID 0x568c7f80
ohci1394_0: SelfID for this node is 0x807f8c56
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
ieee1394: Initiating ConfigROM request for node 0-00:1023
ieee1394: send packet local: ffc00140 ffc0ffff f0000400
ieee1394: TLABEL: appending packet to pending list
ieee1394: TLABEL: packet removed in abort_timedouts
ieee1394: received packet: ffc00140 ffc0ffff f0000400
ieee1394: send packet local: ffc00160 ffc00000 00000000 dee10404
ieee1394: TLABEL: no_waiter, returning
ieee1394: received packet: ffc00160 ffc00000 00000000 dee10404
ieee1394: TLABEL: Checking for tlabel 0
ieee1394: unsolicited response packet received - no tlabel match
ieee1394: contents: ffc00160 ffc00000 00000000 dee10404
ieee1394: send packet local: ffc00540 ffc0ffff f0000400
ieee1394: TLABEL: appending packet to pending list
ieee1394: TLABEL: packet removed in abort_timedouts
ieee1394: received packet: ffc00540 ffc0ffff f0000400
ieee1394: send packet local: ffc00560 ffc00000 00000000 dee10404
ieee1394: TLABEL: no_waiter, returning
ieee1394: received packet: ffc00560 ffc00000 00000000 dee10404
ieee1394: TLABEL: Checking for tlabel 1
ieee1394: unsolicited response packet received - no tlabel match
ieee1394: contents: ffc00560 ffc00000 00000000 dee10404
ieee1394: send packet local: ffc00940 ffc0ffff f0000400
ieee1394: TLABEL: appending packet to pending list
ieee1394: TLABEL: packet removed in abort_timedouts
ieee1394: received packet: ffc00940 ffc0ffff f0000400
ieee1394: send packet local: ffc00960 ffc00000 00000000 dee10404
ieee1394: TLABEL: no_waiter, returning
ieee1394: received packet: ffc00960 ffc00000 00000000 dee10404
ieee1394: TLABEL: Checking for tlabel 2
ieee1394: unsolicited response packet received - no tlabel match
ieee1394: contents: ffc00960 ffc00000 00000000 dee10404
ieee1394: ConfigROM quadlet transaction error for node 0-00:1023
ieee1394: send packet 100: ffff0100 ffc0ffff f0000234 1f0000c0
ohci1394_0: Inserting packet for node 0-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
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.
--
Debian - http://www.debian.org/
Linux 1394 - http://www.linux1394.org/
Subversion - http://subversion.tigris.org/
On Fri, Jul 25, 2003 at 12:18:04PM -0400, Ben Collins wrote:
> 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?
So, abort_timedouts() is called by the scheduler as part of work queue
handling? Every HZ or based on the expire timeout?
It looks like (packet->sendtime - jiffies) is always 99.
-Chris
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 612965374, expire 98, packet->sendtime 612965275
ieee1394: received packet: ffc00140 ffc0ffff f0000400
ieee1394: send packet local: ffc00160 ffc00000 00000000 60f30404
ieee1394: TLABEL: no_waiter, returning
ieee1394: received packet: ffc00160 ffc00000 00000000 60f30404
ieee1394: TLABEL: Checking for tlabel 0
ieee1394: unsolicited response packet received - no tlabel match
ieee1394: contents: ffc00160 ffc00000 00000000 60f30404
ieee1394: send packet local: ffc00540 ffc0ffff f0000400
ieee1394: TLABEL: appending packet to pending list
ieee1394: TLABEL: packet removed in abort_timedouts
ieee1394: TLABEL: jiffies 612965808, expire 98, packet->sendtime 612965709
ieee1394: received packet: ffc00540 ffc0ffff f0000400
ieee1394: send packet local: ffc00560 ffc00000 00000000 60f30404
ieee1394: TLABEL: no_waiter, returning
ieee1394: received packet: ffc00560 ffc00000 00000000 60f30404
ieee1394: TLABEL: Checking for tlabel 1
ieee1394: unsolicited response packet received - no tlabel match
ieee1394: contents: ffc00560 ffc00000 00000000 60f30404
ieee1394: send packet local: ffc00940 ffc0ffff f0000400
ieee1394: TLABEL: appending packet to pending list
ieee1394: TLABEL: packet removed in abort_timedouts
ieee1394: TLABEL: jiffies 612966242, expire 98, packet->sendtime 612966143
ieee1394: received packet: ffc00940 ffc0ffff f0000400
ieee1394: send packet local: ffc00960 ffc00000 00000000 60f30404
ieee1394: TLABEL: no_waiter, returning
ieee1394: received packet: ffc00960 ffc00000 00000000 60f30404
ieee1394: TLABEL: Checking for tlabel 2
ieee1394: unsolicited response packet received - no tlabel match
ieee1394: contents: ffc00960 ffc00000 00000000 60f30404
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
On Fri, Jul 25, 2003 at 10:02:55AM -0700, Chris Ruvolo wrote:
> On Fri, Jul 25, 2003 at 12:18:04PM -0400, Ben Collins wrote:
> > 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?
>
>
> So, abort_timedouts() is called by the scheduler as part of work queue
> handling? Every HZ or based on the expire timeout?
Hmm. It's scheduled as soon as there are pending_packets, and it is
rescheduled as long as the pending_packets list isn't empty. Maybe it
isn't relinquishing enough time to the nodemgr to get it's job done.
I think that's the problem. Let me code up a patch.
--
Debian - http://www.debian.org/
Linux 1394 - http://www.linux1394.org/
Subversion - http://subversion.tigris.org/
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 <[email protected]>
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 [email protected]).
(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
[email protected] (work) / [email protected] (home)
On Fri, Jul 25, 2003 at 10:51:24AM -0700, Torrey Hoffman wrote:
> 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.
> 02:0b.0 FireWire (IEEE 1394): VIA Technologies, Inc. IEEE 1394 Host Controller (rev 46)
Seems that you and I have the same 1394 chipset. I'm curious to see the
output from a "lspci -v -s02:0b.0".
-Chris
00:0b.0 FireWire (IEEE 1394): VIA Technologies, Inc. IEEE 1394 Host Controller (rev 46) (prog-if 10 [OHCI])
Subsystem: VIA Technologies, Inc. IEEE 1394 Host Controller
Flags: bus master, medium devsel, latency 32, IRQ 10
Memory at db001000 (32-bit, non-prefetchable) [size=2K]
I/O ports at e800 [size=128]
Capabilities: [50] Power Management version 2
On Fri, 2003-07-25 at 11:13, Chris Ruvolo wrote:
...
> Seems that you and I have the same 1394 chipset. I'm curious to see the
> output from a "lspci -v -s02:0b.0".
Yup, it looks that way. Although the PCI latency timings are different?
I think that's set up by the motherboard BIOS?
I also have a Maxtor card with the Lucent controller chip (IIRC) that I
could try out if that would be helpful.
[root@torrey root]# lspci -v -s02:0b.0
02:0b.0 FireWire (IEEE 1394): VIA Technologies, Inc. IEEE 1394 Host Controller (rev 46) (prog-if 10 [OHCI])
Subsystem: VIA Technologies, Inc. IEEE 1394 Host Controller
Flags: bus master, medium devsel, latency 64, IRQ 10
Memory at e8201000 (32-bit, non-prefetchable) [size=2K]
I/O ports at 5400 [size=128]
Capabilities: [50] Power Management version 2
> -Chris
>
> 00:0b.0 FireWire (IEEE 1394): VIA Technologies, Inc. IEEE 1394 Host Controller (rev 46) (prog-if 10 [OHCI])
> Subsystem: VIA Technologies, Inc. IEEE 1394 Host Controller
> Flags: bus master, medium devsel, latency 32, IRQ 10
> Memory at db001000 (32-bit, non-prefetchable) [size=2K]
> I/O ports at e800 [size=128]
> Capabilities: [50] Power Management version 2
--
Torrey Hoffman <[email protected]>
For what it's worth to anyone:
root@localhost linux # lspci -v -s00:0f.0
00:0f.0 FireWire (IEEE 1394): Texas Instruments FireWire Controller (rev
01) (prog-if 10 [OHCI])
Subsystem: Ads Technologies Inc: Unknown device 0000
Flags: bus master, medium devsel, latency 64, IRQ 5
Memory at cfffc800 (32-bit, non-prefetchable) [size=2K]
Memory at cfff8000 (32-bit, non-prefetchable) [size=16K]
Capabilities: [44] Power Management version 1
Give this a try. It converts the abort_timedouts to a timer that runs
every 50ms while packets are pending. I'd bet this will increase
performance a good bit for 1394.
Expect some offsets for this patch, but it should apply without rejects.
Index: linux-2.6/drivers/ieee1394/ieee1394_core.c
===================================================================
--- linux-2.6/drivers/ieee1394/ieee1394_core.c (revision 1013)
+++ linux-2.6/drivers/ieee1394/ieee1394_core.c (working copy)
@@ -30,7 +30,6 @@
#include <linux/module.h>
#include <linux/moduleparam.h>
#include <linux/bitops.h>
-#include <linux/workqueue.h>
#include <linux/kdev_t.h>
#include <asm/byteorder.h>
#include <asm/semaphore.h>
@@ -441,7 +440,10 @@
spin_unlock_irqrestore(&host->pending_pkt_lock, flags);
up(&packet->state_change);
- schedule_work(&host->timeout_tq);
+ if (!timer_pending(&host->timeout)) {
+ host->timeout.expires = jiffies + IEEE1394_TIMEOUT_INTERVAL;
+ add_timer(&host->timeout);
+ }
}
/**
@@ -960,36 +957,33 @@
}
}
-void abort_timedouts(struct hpsb_host *host)
+void abort_timedouts(unsigned long __opaque)
{
+ struct hpsb_host *host = (struct hpsb_host *)__opaque;
unsigned long flags;
struct hpsb_packet *packet;
unsigned long expire;
- struct list_head *lh, *next, *tlh;
+ struct list_head *lh, *tlh;
LIST_HEAD(expiredlist);
spin_lock_irqsave(&host->csr.lock, flags);
- expire = (host->csr.split_timeout_hi * 8000
- + (host->csr.split_timeout_lo >> 19))
- * HZ / 8000;
- /* Avoid shortening of timeout due to rounding errors: */
- expire++;
+ expire = host->csr.expire;
spin_unlock_irqrestore(&host->csr.lock, flags);
-
spin_lock_irqsave(&host->pending_pkt_lock, flags);
- for (lh = host->pending_packets.next; lh != &host->pending_packets; lh = next) {
+ list_for_each_safe(lh, tlh, &host->pending_packets) {
packet = list_entry(lh, struct hpsb_packet, list);
- next = lh->next;
if (time_before(packet->sendtime + expire, jiffies)) {
list_del(&packet->list);
list_add(&packet->list, &expiredlist);
}
}
- if (!list_empty(&host->pending_packets))
- schedule_work(&host->timeout_tq);
+ if (!list_empty(&host->pending_packets)) {
+ host->timeout.expires = jiffies + IEEE1394_TIMEOUT_INTERVAL;
+ add_timer(&host->timeout);
+ }
spin_unlock_irqrestore(&host->pending_pkt_lock, flags);
Index: linux-2.6/drivers/ieee1394/ieee1394_core.h
===================================================================
--- linux-2.6/drivers/ieee1394/ieee1394_core.h (revision 1013)
+++ linux-2.6/drivers/ieee1394/ieee1394_core.h (working copy)
@@ -87,7 +87,7 @@
return list_entry(l, struct hpsb_packet, driver_list);
}
-void abort_timedouts(struct hpsb_host *host);
+void abort_timedouts(unsigned long __opaque);
void abort_requests(struct hpsb_host *host);
struct hpsb_packet *alloc_hpsb_packet(size_t data_size);
Index: linux-2.6/drivers/ieee1394/hosts.c
===================================================================
--- linux-2.6/drivers/ieee1394/hosts.c (revision 1013)
+++ linux-2.6/drivers/ieee1394/hosts.c (working copy)
@@ -16,7 +16,6 @@
#include <linux/list.h>
#include <linux/init.h>
#include <linux/slab.h>
-#include <linux/workqueue.h>
#include "ieee1394_types.h"
#include "hosts.h"
@@ -139,7 +138,9 @@
atomic_set(&h->generation, 0);
- INIT_WORK(&h->timeout_tq, (void (*)(void*))abort_timedouts, h);
+ init_timer(&h->timeout);
+ h->timeout.data = (unsigned long) h;
+ h->timeout.function = abort_timedouts;
h->topology_map = h->csr.topology_map + 3;
h->speed_map = (u8 *)(h->csr.speed_map + 2);
Index: linux-2.6/drivers/ieee1394/hosts.h
===================================================================
--- linux-2.6/drivers/ieee1394/hosts.h (revision 1013)
+++ linux-2.6/drivers/ieee1394/hosts.h (working copy)
@@ -4,7 +4,7 @@
#include <linux/device.h>
#include <linux/wait.h>
#include <linux/list.h>
-#include <linux/workqueue.h>
+#include <linux/timer.h>
#include <asm/semaphore.h>
#include "ieee1394_types.h"
@@ -19,6 +19,11 @@
*/
#define CSR_CONFIG_ROM_SIZE 0x100
+/* The interval which our timer checks for pending packets that have timed
+ * out. This is pretty much 50ms, which is half our default split_timeout
+ * value. */
+#define IEEE1394_TIMEOUT_INTERVAL (HZ / 20)
+
struct hpsb_packet;
struct hpsb_iso;
@@ -33,7 +38,7 @@
struct list_head pending_packets;
spinlock_t pending_pkt_lock;
- struct work_struct timeout_tq;
+ struct timer_list timeout;
unsigned char iso_listen_count[64];
--
Debian - http://www.debian.org/
Linux 1394 - http://www.linux1394.org/
Subversion - http://subversion.tigris.org/
Do we put this on virgin ieee1394 or on top of the last patch?
Ben Collins wrote:
> Give this a try. It converts the abort_timedouts to a timer that runs
> every 50ms while packets are pending. I'd bet this will increase
> performance a good bit for 1394.
>
> Expect some offsets for this patch, but it should apply without rejects.
On Fri, Jul 25, 2003 at 02:43:05PM -0400, gaxt wrote:
> Do we put this on virgin ieee1394 or on top of the last patch?
Either way should work.
--
Debian - http://www.debian.org/
Linux 1394 - http://www.linux1394.org/
Subversion - http://subversion.tigris.org/
Maybe it wont. Try reverting back to stock, and apply this patch. I am
pretty sure this will fix the problem for anyone having this issue.
Index: linux-2.6/drivers/ieee1394/ieee1394_core.c
===================================================================
--- linux-2.6/drivers/ieee1394/ieee1394_core.c (revision 1013)
+++ linux-2.6/drivers/ieee1394/ieee1394_core.c (working copy)
@@ -30,7 +30,6 @@
#include <linux/module.h>
#include <linux/moduleparam.h>
#include <linux/bitops.h>
-#include <linux/workqueue.h>
#include <linux/kdev_t.h>
#include <asm/byteorder.h>
#include <asm/semaphore.h>
@@ -441,7 +440,10 @@
spin_unlock_irqrestore(&host->pending_pkt_lock, flags);
up(&packet->state_change);
- schedule_work(&host->timeout_tq);
+ if (!timer_pending(&host->timeout)) {
+ host->timeout.expires = jiffies + IEEE1394_TIMEOUT_INTERVAL;
+ add_timer(&host->timeout);
+ }
}
/**
@@ -618,7 +617,7 @@
}
if (lh == &host->pending_packets) {
- HPSB_DEBUG("unsolicited response packet received - np");
+ HPSB_DEBUG("unsolicited response packet received - no tlabel match");
dump_packet("contents:", data, 16);
spin_unlock_irqrestore(&host->pending_pkt_lock, flags);
return;
@@ -642,7 +641,7 @@
if (!tcode_match || (packet->tlabel != tlabel)
|| (packet->node_id != (data[1] >> 16))) {
- HPSB_INFO("unsolicited response packet received");
+ HPSB_INFO("unsolicited response packet received - tcode mismatch");
dump_packet("contents:", data, 16);
spin_unlock_irqrestore(&host->pending_pkt_lock, flags);
@@ -960,36 +957,33 @@
}
}
-void abort_timedouts(struct hpsb_host *host)
+void abort_timedouts(unsigned long __opaque)
{
+ struct hpsb_host *host = (struct hpsb_host *)__opaque;
unsigned long flags;
struct hpsb_packet *packet;
unsigned long expire;
- struct list_head *lh, *next, *tlh;
+ struct list_head *lh, *tlh;
LIST_HEAD(expiredlist);
spin_lock_irqsave(&host->csr.lock, flags);
- expire = (host->csr.split_timeout_hi * 8000
- + (host->csr.split_timeout_lo >> 19))
- * HZ / 8000;
- /* Avoid shortening of timeout due to rounding errors: */
- expire++;
+ expire = host->csr.expire;
spin_unlock_irqrestore(&host->csr.lock, flags);
-
spin_lock_irqsave(&host->pending_pkt_lock, flags);
- for (lh = host->pending_packets.next; lh != &host->pending_packets; lh = next) {
+ list_for_each_safe(lh, tlh, &host->pending_packets) {
packet = list_entry(lh, struct hpsb_packet, list);
- next = lh->next;
if (time_before(packet->sendtime + expire, jiffies)) {
list_del(&packet->list);
list_add(&packet->list, &expiredlist);
}
}
- if (!list_empty(&host->pending_packets))
- schedule_work(&host->timeout_tq);
+ if (!list_empty(&host->pending_packets)) {
+ host->timeout.expires = jiffies + IEEE1394_TIMEOUT_INTERVAL;
+ add_timer(&host->timeout);
+ }
spin_unlock_irqrestore(&host->pending_pkt_lock, flags);
Index: linux-2.6/drivers/ieee1394/ieee1394_core.h
===================================================================
--- linux-2.6/drivers/ieee1394/ieee1394_core.h (revision 1013)
+++ linux-2.6/drivers/ieee1394/ieee1394_core.h (working copy)
@@ -87,7 +87,7 @@
return list_entry(l, struct hpsb_packet, driver_list);
}
-void abort_timedouts(struct hpsb_host *host);
+void abort_timedouts(unsigned long __opaque);
void abort_requests(struct hpsb_host *host);
struct hpsb_packet *alloc_hpsb_packet(size_t data_size);
Index: linux-2.6/drivers/ieee1394/hosts.c
===================================================================
--- linux-2.6/drivers/ieee1394/hosts.c (revision 1013)
+++ linux-2.6/drivers/ieee1394/hosts.c (working copy)
@@ -16,7 +16,6 @@
#include <linux/list.h>
#include <linux/init.h>
#include <linux/slab.h>
-#include <linux/workqueue.h>
#include "ieee1394_types.h"
#include "hosts.h"
@@ -139,7 +138,9 @@
atomic_set(&h->generation, 0);
- INIT_WORK(&h->timeout_tq, (void (*)(void*))abort_timedouts, h);
+ init_timer(&h->timeout);
+ h->timeout.data = (unsigned long) h;
+ h->timeout.function = abort_timedouts;
h->topology_map = h->csr.topology_map + 3;
h->speed_map = (u8 *)(h->csr.speed_map + 2);
Index: linux-2.6/drivers/ieee1394/hosts.h
===================================================================
--- linux-2.6/drivers/ieee1394/hosts.h (revision 1013)
+++ linux-2.6/drivers/ieee1394/hosts.h (working copy)
@@ -4,7 +4,7 @@
#include <linux/device.h>
#include <linux/wait.h>
#include <linux/list.h>
-#include <linux/workqueue.h>
+#include <linux/timer.h>
#include <asm/semaphore.h>
#include "ieee1394_types.h"
@@ -19,6 +19,11 @@
*/
#define CSR_CONFIG_ROM_SIZE 0x100
+/* The interval which our timer checks for pending packets that have timed
+ * out. This is pretty much 50ms, which is half our default split_timeout
+ * value. */
+#define IEEE1394_TIMEOUT_INTERVAL (HZ / 20)
+
struct hpsb_packet;
struct hpsb_iso;
@@ -33,7 +38,7 @@
struct list_head pending_packets;
spinlock_t pending_pkt_lock;
- struct work_struct timeout_tq;
+ struct timer_list timeout;
unsigned char iso_listen_count[64];
Index: linux-2.6/drivers/ieee1394/csr.c
===================================================================
--- linux-2.6/drivers/ieee1394/csr.c (revision 1013)
+++ linux-2.6/drivers/ieee1394/csr.c (working copy)
@@ -89,7 +89,38 @@
0x3f1));
}
+/*
+ * HI == seconds (bits 0:2)
+ * LO == fraction units of 1/8000 of a second, as per 1394 (bits 19:31)
+ *
+ * Convert to units and then to HZ, for comparison to jiffies.
+ *
+ * By default this will end up being 800 units, or 100ms (125usec per
+ * unit).
+ *
+ * NOTE: The spec says 1/8000, but also says we can compute based on 1/8192
+ * like CSR specifies. Should make our math less complex.
+ */
+static inline void calculate_expire(struct csr_control *csr)
+{
+ unsigned long units;
+
+ /* Take the seconds, and convert to units */
+ units = (unsigned long)(csr->split_timeout_hi & 0x07) << 13;
+ /* Add in the fractional units */
+ units += (unsigned long)(csr->split_timeout_lo >> 19);
+
+ /* Convert to jiffies */
+ csr->expire = (unsigned long)(units * HZ) >> 13UL;
+
+ /* Just to keep from rounding low */
+ csr->expire++;
+
+ HPSB_VERBOSE("CSR: setting expire to %lu, HZ=%lu", csr->expire, HZ);
+}
+
+
static void add_host(struct hpsb_host *host)
{
host->csr.lock = SPIN_LOCK_UNLOCKED;
@@ -100,6 +131,7 @@
host->csr.node_ids = 0;
host->csr.split_timeout_hi = 0;
host->csr.split_timeout_lo = 800 << 19;
+ calculate_expire(&host->csr);
host->csr.cycle_time = 0;
host->csr.bus_time = 0;
host->csr.bus_manager_id = 0x3f;
@@ -336,10 +368,12 @@
case CSR_SPLIT_TIMEOUT_HI:
host->csr.split_timeout_hi =
be32_to_cpu(*(data++)) & 0x00000007;
+ calculate_expire(&host->csr);
out;
case CSR_SPLIT_TIMEOUT_LO:
host->csr.split_timeout_lo =
be32_to_cpu(*(data++)) & 0xfff80000;
+ calculate_expire(&host->csr);
out;
/* address gap */
Index: linux-2.6/drivers/ieee1394/csr.h
===================================================================
--- linux-2.6/drivers/ieee1394/csr.h (revision 1013)
+++ linux-2.6/drivers/ieee1394/csr.h (working copy)
@@ -41,6 +41,7 @@
quadlet_t state;
quadlet_t node_ids;
quadlet_t split_timeout_hi, split_timeout_lo;
+ unsigned long expire; // Calculated from split_timeout
quadlet_t cycle_time;
quadlet_t bus_time;
quadlet_t bus_manager_id;
--
Debian - http://www.debian.org/
Linux 1394 - http://www.linux1394.org/
Subversion - http://subversion.tigris.org/
Ben Collins wrote:
> Maybe it wont. Try reverting back to stock, and apply this patch. I am
> pretty sure this will fix the problem for anyone having this issue.
>
> Index: linux-2.6/drivers/ieee1394/ieee1394_core.c
...
root@localhost linux # make modules modules_install
...
drivers/ieee1394/csr.c: In function `calculate_expire':
drivers/ieee1394/csr.c:120: warning: implicit declaration of function
`HPSB_VERBOSE'
...
Building modules, stage 2.
MODPOST
*** Warning: "HPSB_VERBOSE" [drivers/ieee1394/ieee1394.ko] undefined!
LD [M] drivers/ieee1394/dv1394.ko
...
root@localhost linux # modprobe ieee1394
FATAL: Error inserting ieee1394
(/lib/modules/2.6.0-test1-mm2/kernel/drivers/ieee1394/ieee1394.ko):
Unknown symbol in module, or unknown parameter (see dmesg)
...
dmesg:
ieee1394: NodeMgr: Exiting thread
ohci1394_0: Soft reset finished
ohci1394_0: Freeing dma_rcv_ctx 0
ohci1394_0: Freeing dma_rcv_ctx 0
ohci1394_0: Freeing dma_trm_ctx 0
ohci1394_0: Freeing dma_trm_ctx 1
raw1394: /dev/raw1394 device initialized
ohci1394: $Rev$ Ben Collins <[email protected]>
ohci1394_0: Remapped memory spaces reg 0xd093f800
ohci1394_0: Soft reset finished
ohci1394_0: Iso contexts reg: 000000a8 implemented: 0000000f
ohci1394_0: 4 iso receive contexts available
ohci1394_0: Iso contexts reg: 00000098 implemented: 000000ff
ohci1394_0: 8 iso transmit contexts available
ohci1394_0: GUID: 060050c5:000001ce
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=[5] MMIO=[cfffc800-cfffcfff] Max
Packet=[2048]
ohci1394_0: request csr_rom address: c3efa000
ohci1394_0: IntEvent: 00020010
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: Single packet rcv'd
ohci1394_0: Got phy packet ctx=0 ... discarded
ohci1394_0: IntEvent: 00010000
ohci1394_0: SelfID interrupt received (phyid 0, root)
ohci1394_0: SelfID packet 0x807f8c56 received
ieee1394: Including SelfID 0x568c7f80
ohci1394_0: SelfID for this node is 0x807f8c56
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
ieee1394: Initiating ConfigROM request for node 0-00:1023
ieee1394: send packet local: ffc00140 ffc0ffff f0000400
ieee1394: TLABEL: appending packet to pending list
ieee1394: TLABEL: packet removed in abort_timedouts
ieee1394: received packet: ffc00140 ffc0ffff f0000400
ieee1394: send packet local: ffc00160 ffc00000 00000000 dee10404
ieee1394: TLABEL: no_waiter, returning
ieee1394: received packet: ffc00160 ffc00000 00000000 dee10404
ieee1394: TLABEL: Checking for tlabel 0
ieee1394: unsolicited response packet received - no tlabel match
ieee1394: contents: ffc00160 ffc00000 00000000 dee10404
ieee1394: send packet local: ffc00540 ffc0ffff f0000400
ieee1394: TLABEL: appending packet to pending list
ieee1394: TLABEL: packet removed in abort_timedouts
ieee1394: received packet: ffc00540 ffc0ffff f0000400
ieee1394: send packet local: ffc00560 ffc00000 00000000 dee10404
ieee1394: TLABEL: no_waiter, returning
ieee1394: received packet: ffc00560 ffc00000 00000000 dee10404
ieee1394: TLABEL: Checking for tlabel 1
ieee1394: unsolicited response packet received - no tlabel match
ieee1394: contents: ffc00560 ffc00000 00000000 dee10404
ieee1394: send packet local: ffc00940 ffc0ffff f0000400
ieee1394: TLABEL: appending packet to pending list
ieee1394: TLABEL: packet removed in abort_timedouts
ieee1394: received packet: ffc00940 ffc0ffff f0000400
ieee1394: send packet local: ffc00960 ffc00000 00000000 dee10404
ieee1394: TLABEL: no_waiter, returning
ieee1394: received packet: ffc00960 ffc00000 00000000 dee10404
ieee1394: TLABEL: Checking for tlabel 2
ieee1394: unsolicited response packet received - no tlabel match
ieee1394: contents: ffc00960 ffc00000 00000000 dee10404
ieee1394: ConfigROM quadlet transaction error for node 0-00:1023
ieee1394: send packet 100: ffff0100 ffc0ffff f0000234 1f0000c0
ohci1394_0: Inserting packet for node 0-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
bad: scheduling while atomic!
Call Trace:
[<c01178e6>] schedule+0x3f6/0x400
[<c0116c7e>] try_to_wake_up+0x9e/0x180
[<c0117c41>] wait_for_completion+0x91/0x110
[<c0117950>] default_wake_function+0x0/0x30
[<c0117950>] default_wake_function+0x0/0x30
[<c0124d02>] kill_proc_info+0x62/0x70
[<d0aab945>] nodemgr_remove_host+0x55/0xa0 [ieee1394]
[<d0aa70cc>] highlevel_remove_host+0x6c/0x80 [ieee1394]
[<d094c521>] ohci1394_pci_remove+0x41/0x230 [ohci1394]
[<c021eabb>] pci_device_remove+0x3b/0x40
[<c0285436>] device_release_driver+0x66/0x70
[<c0285460>] driver_detach+0x20/0x30
[<c02856bd>] bus_remove_driver+0x3d/0x80
[<c0285af3>] driver_unregister+0x13/0x28
[<c021ed96>] pci_unregister_driver+0x16/0x30
[<d094c9df>] ohci1394_cleanup+0xf/0x13 [ohci1394]
[<c012fdf2>] sys_delete_module+0x152/0x1c0
[<c0144100>] do_munmap+0x130/0x190
[<c010921b>] syscall_call+0x7/0xb
ieee1394: NodeMgr: Exiting thread
ohci1394_0: Soft reset finished
ohci1394_0: Freeing dma_rcv_ctx 0
ohci1394_0: Freeing dma_rcv_ctx 0
ohci1394_0: Freeing dma_trm_ctx 0
ohci1394_0: Freeing dma_trm_ctx 1
ieee1394: Unknown symbol HPSB_VERBOSE
root@localhost linux #
On Fri, Jul 25, 2003 at 02:45:06PM -0400, Ben Collins wrote:
> Maybe it wont. Try reverting back to stock, and apply this patch. I am
> pretty sure this will fix the problem for anyone having this issue.
Yes, I think this did it! One change: needed to change HSBP_VERBOSE to
HSBP_DEBUG in csr.c.
I will try turning on my DV camera tonight (I'm remote now) and I'll let you
know how that goes.
-Chris
ieee1394: Initiating ConfigROM request for node 00:1023
ieee1394: send packet local: ffc00140 ffc0ffff f0000400
ieee1394: received packet: ffc00140 ffc0ffff f0000400
ieee1394: send packet local: ffc00160 ffc00000 00000000 60f30404
ieee1394: received packet: ffc00160 ffc00000 00000000 60f30404
ieee1394: send packet local: ffc00540 ffc0ffff f0000404
ieee1394: received packet: ffc00540 ffc0ffff f0000404
ieee1394: send packet local: ffc00560 ffc00000 00000000 34393331
ieee1394: received packet: ffc00560 ffc00000 00000000 34393331
ieee1394: send packet local: ffc00940 ffc0ffff f0000408
ieee1394: received packet: ffc00940 ffc0ffff f0000408
ieee1394: send packet local: ffc00960 ffc00000 00000000 02a200e0
ieee1394: received packet: ffc00960 ffc00000 00000000 02a200e0
ieee1394: send packet local: ffc00d40 ffc0ffff f000040c
ieee1394: received packet: ffc00d40 ffc0ffff f000040c
ieee1394: send packet local: ffc00d60 ffc00000 00000000 00061100
ieee1394: received packet: ffc00d60 ffc00000 00000000 00061100
ieee1394: send packet local: ffc01140 ffc0ffff f0000410
ieee1394: received packet: ffc01140 ffc0ffff f0000410
ieee1394: send packet local: ffc01160 ffc00000 00000000 856a0000
ieee1394: received packet: ffc01160 ffc00000 00000000 856a0000
ieee1394: send packet local: ffc01540 ffc0ffff f0000400
ieee1394: received packet: ffc01540 ffc0ffff f0000400
ieee1394: send packet local: ffc01560 ffc00000 00000000 60f30404
ieee1394: received packet: ffc01560 ffc00000 00000000 60f30404
ieee1394: send packet local: ffc01940 ffc0ffff f0000414
ieee1394: received packet: ffc01940 ffc0ffff f0000414
ieee1394: send packet local: ffc01960 ffc00000 00000000 80840300
ieee1394: received packet: ffc01960 ffc00000 00000000 80840300
ieee1394: send packet local: ffc01d40 ffc0ffff f0000418
ieee1394: received packet: ffc01d40 ffc0ffff f0000418
ieee1394: send packet local: ffc01d60 ffc00000 00000000 63400003
ieee1394: received packet: ffc01d60 ffc00000 00000000 63400003
ieee1394: send packet local: ffc02140 ffc0ffff f000041c
ieee1394: received packet: ffc02140 ffc0ffff f000041c
ieee1394: send packet local: ffc02160 ffc00000 00000000 02000081
ieee1394: received packet: ffc02160 ffc00000 00000000 02000081
ieee1394: send packet local: ffc02540 ffc0ffff f0000424
ieee1394: received packet: ffc02540 ffc0ffff f0000424
ieee1394: send packet local: ffc02560 ffc00000 00000000 ab030600
ieee1394: received packet: ffc02560 ffc00000 00000000 ab030600
ieee1394: send packet local: ffc02940 ffc0ffff f0000420
ieee1394: received packet: ffc02940 ffc0ffff f0000420
ieee1394: send packet local: ffc02960 ffc00000 00000000 c083000c
ieee1394: received packet: ffc02960 ffc00000 00000000 c083000c
ieee1394: NodeMgr: raw=0xe000a202 irmc=1 cmc=1 isc=1 bmc=0 pmc=0 cyc_clk_acc=0 max_rec=2048 gen=0 lspd=2
ieee1394: send packet local: ffc02d40 ffc0ffff f0000400
ieee1394: received packet: ffc02d40 ffc0ffff f0000400
ieee1394: send packet local: ffc02d60 ffc00000 00000000 60f30404
ieee1394: received packet: ffc02d60 ffc00000 00000000 60f30404
ieee1394: send packet local: ffc03140 ffc0ffff f0000414
ieee1394: received packet: ffc03140 ffc0ffff f0000414
ieee1394: send packet local: ffc03160 ffc00000 00000000 80840300
ieee1394: received packet: ffc03160 ffc00000 00000000 80840300
ieee1394: send packet local: ffc03540 ffc0ffff f0000418
ieee1394: received packet: ffc03540 ffc0ffff f0000418
ieee1394: send packet local: ffc03560 ffc00000 00000000 63400003
ieee1394: received packet: ffc03560 ffc00000 00000000 63400003
ieee1394: send packet local: ffc03940 ffc0ffff f000041c
ieee1394: received packet: ffc03940 ffc0ffff f000041c
ieee1394: send packet local: ffc03960 ffc00000 00000000 02000081
ieee1394: received packet: ffc03960 ffc00000 00000000 02000081
ieee1394: send packet local: ffc03d40 ffc0ffff f0000424
ieee1394: received packet: ffc03d40 ffc0ffff f0000424
ieee1394: send packet local: ffc03d60 ffc00000 00000000 ab030600
ieee1394: received packet: ffc03d60 ffc00000 00000000 ab030600
ieee1394: send packet local: ffc04140 ffc0ffff f0000428
ieee1394: received packet: ffc04140 ffc0ffff f0000428
ieee1394: send packet local: ffc04160 ffc00000 00000000 00000000
ieee1394: received packet: ffc04160 ffc00000 00000000 00000000
ieee1394: send packet local: ffc04540 ffc0ffff f000042c
ieee1394: received packet: ffc04540 ffc0ffff f000042c
ieee1394: send packet local: ffc04560 ffc00000 00000000 00000000
ieee1394: received packet: ffc04560 ffc00000 00000000 00000000
ieee1394: send packet local: ffc04940 ffc0ffff f0000430
ieee1394: received packet: ffc04940 ffc0ffff f0000430
ieee1394: send packet local: ffc04960 ffc00000 00000000 756e694c
ieee1394: received packet: ffc04960 ffc00000 00000000 756e694c
ieee1394: send packet local: ffc04d40 ffc0ffff f0000434
ieee1394: received packet: ffc04d40 ffc0ffff f0000434
ieee1394: send packet local: ffc04d60 ffc00000 00000000 484f2078
ieee1394: received packet: ffc04d60 ffc00000 00000000 484f2078
ieee1394: send packet local: ffc05140 ffc0ffff f0000438
ieee1394: received packet: ffc05140 ffc0ffff f0000438
ieee1394: send packet local: ffc05160 ffc00000 00000000 312d4943
ieee1394: received packet: ffc05160 ffc00000 00000000 312d4943
ieee1394: send packet local: ffc05540 ffc0ffff f000043c
ieee1394: received packet: ffc05540 ffc0ffff f000043c
ieee1394: send packet local: ffc05560 ffc00000 00000000 00343933
ieee1394: received packet: ffc05560 ffc00000 00000000 00343933
ieee1394: send packet local: ffc05940 ffc0ffff f0000420
ieee1394: received packet: ffc05940 ffc0ffff f0000420
ieee1394: send packet local: ffc05960 ffc00000 00000000 c083000c
ieee1394: received packet: ffc05960 ffc00000 00000000 c083000c
ieee1394: Host added: ID:BUS[0-00:1023] GUID[0011060000006a85]
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=0x1
F0000C0 ctx=0
On Fri, Jul 25, 2003 at 12:35:15PM -0700, Chris Ruvolo wrote:
> On Fri, Jul 25, 2003 at 02:45:06PM -0400, Ben Collins wrote:
> > Maybe it wont. Try reverting back to stock, and apply this patch. I am
> > pretty sure this will fix the problem for anyone having this issue.
>
> Yes, I think this did it! One change: needed to change HSBP_VERBOSE to
> HSBP_DEBUG in csr.c.
>
> I will try turning on my DV camera tonight (I'm remote now) and I'll let you
> know how that goes.
Kick ass. I've commited this change to the 1394 repo. Linus will get the
fix soon. I'll also send it to Marcelo for 2.4.22.
Please, if you are testing, use the code at http://www.linux1394.org's viewcvs
(trunk tarball will replace drivers/ieee1394 in 2.6, branches/linux-2.4
will do the same for 2.4).
Thanks for help in tracking this down.
--
Debian - http://www.debian.org/
Linux 1394 - http://www.linux1394.org/
Subversion - http://subversion.tigris.org/
On Fri, 2003-07-25 at 12:35, Chris Ruvolo wrote:
> On Fri, Jul 25, 2003 at 02:45:06PM -0400, Ben Collins wrote:
> > Maybe it wont. Try reverting back to stock, and apply this patch. I am
> > pretty sure this will fix the problem for anyone having this issue.
>
> Yes, I think this did it! One change: needed to change HSBP_VERBOSE to
> HSBP_DEBUG in csr.c.
>
It works for me too... so far at least. I've attached and mounted my
external CDRW and 250 GB hard drives and have no errors in the system
logs... everything seems to work at first glance. I will do a little
stress testing after lunch and let you know how it goes.
Thanks!
--
Torrey Hoffman <[email protected]>
On Fri, Jul 25, 2003 at 01:48:16PM -0700, Torrey Hoffman wrote:
> On Fri, 2003-07-25 at 12:35, Chris Ruvolo wrote:
> > On Fri, Jul 25, 2003 at 02:45:06PM -0400, Ben Collins wrote:
> > > Maybe it wont. Try reverting back to stock, and apply this patch. I am
> > > pretty sure this will fix the problem for anyone having this issue.
> >
> > Yes, I think this did it! One change: needed to change HSBP_VERBOSE to
> > HSBP_DEBUG in csr.c.
> >
>
> It works for me too... so far at least. I've attached and mounted my
> external CDRW and 250 GB hard drives and have no errors in the system
> logs... everything seems to work at first glance. I will do a little
> stress testing after lunch and let you know how it goes.
Thanks for testing. Really though, you need to use the code in the repo.
I switched to doing the right thing by using mod_timer(). You will hit a
race every so often under heavy load if you don't use the newer code.
--
Debian - http://www.debian.org/
Linux 1394 - http://www.linux1394.org/
Subversion - http://subversion.tigris.org/
Hi Ben. Firewire is working here too- iPod is running again :-) Pleasure
working with you on the testing. I'm using the tarballed ieee1394 code
from http://www.linux1394.org's viewcvs
Ben Collins wrote:
> On Fri, Jul 25, 2003 at 12:35:15PM -0700, Chris Ruvolo wrote:
>
>>On Fri, Jul 25, 2003 at 02:45:06PM -0400, Ben Collins wrote:
>>
>>>Maybe it wont. Try reverting back to stock, and apply this patch. I am
>>>pretty sure this will fix the problem for anyone having this issue.
>>
>>Yes, I think this did it! One change: needed to change HSBP_VERBOSE to
>>HSBP_DEBUG in csr.c.
>>
>>I will try turning on my DV camera tonight (I'm remote now) and I'll let you
>>know how that goes.
>
>
> Kick ass. I've commited this change to the 1394 repo. Linus will get the
> fix soon. I'll also send it to Marcelo for 2.4.22.
>
> Please, if you are testing, use the code at http://www.linux1394.org's viewcvs
> (trunk tarball will replace drivers/ieee1394 in 2.6, branches/linux-2.4
> will do the same for 2.4).
>
>
> Thanks for help in tracking this down.
>
On Fri, 2003-07-25 at 16:11, Ben Collins wrote:
> On Fri, Jul 25, 2003 at 12:35:15PM -0700, Chris Ruvolo wrote:
> > On Fri, Jul 25, 2003 at 02:45:06PM -0400, Ben Collins wrote:
> > > Maybe it wont. Try reverting back to stock, and apply this patch. I am
> > > pretty sure this will fix the problem for anyone having this issue.
> >
> > Yes, I think this did it! One change: needed to change HSBP_VERBOSE to
> > HSBP_DEBUG in csr.c.
> >
> > I will try turning on my DV camera tonight (I'm remote now) and I'll let you
> > know how that goes.
>
> Kick ass. I've commited this change to the 1394 repo. Linus will get the
> fix soon. I'll also send it to Marcelo for 2.4.22.
>
> Please, if you are testing, use the code at http://www.linux1394.org's viewcvs
> (trunk tarball will replace drivers/ieee1394 in 2.6, branches/linux-2.4
> will do the same for 2.4).
>
>
> Thanks for help in tracking this down.
Hi,
First, thank you all for being so diligent.
The unsolicited packet problem seems to have
been resolved. However, by running gscanbus,
then unplugging a camera and replugging it in,
I got the following oops:
Unable to handle kernel paging request at virtual address 08103a8c
printing eip:
402fd1de
*pde = 07b1c067
*pte = 00000000
Oops: 0006 [#1]
CPU: 0
EIP: 0073:[<402fd1de>] Not tainted
EFLAGS: 00010202
EIP is at 0x402fd1de
eax: 00001579 ebx: 4039ff60 ecx: 00001009 edx: 08103a88
esi: 00000004 edi: 00000000 ebp: bfffc788 esp: bfffc760
ds: 007b es: 007b ss: 007b
Process gscanbus (pid: 2525, threadinfo=c2314000 task=dc4af000)
<6>note: gscanbus[2525] exited with preempt_count 1
-----------
Ok, you'll have to forgive me here, as I've never used
ksymoops before, but here is my attempt:
ksymoops 2.4.8 on i686 2.6.0-test1-ac1. Options used
-v /boot/vmlinuz-2.6.0-test1-ac2 (specified)
-k /proc/ksyms (default)
-l /proc/modules (default)
-o /lib/modules/2.6.0-test1-ac1/ (default)
-m /boot/System.map-2.6.0-test1-ac2 (specified)
/usr/bin/nm: /boot/vmlinuz-2.6.0-test1-ac2: File format not recognized
Error (pclose_local): read_nm_symbols pclose failed 0x100
Warning (read_vmlinux): no kernel symbols in vmlinux, is
/boot/vmlinuz-2.6.0-test1-ac2 a valid vmlinux file?
Error (regular_file): read_ksyms stat /proc/ksyms failed
ksymoops: No such file or directory
No modules in ksyms, skipping objects
No ksyms, skipping lsmod
Reading Oops report from the terminal
402fd1de
*pde = 07b1c067
*pte = 00000000
Oops: 0006 [#1]
CPU: 0
EIP: 0073:[<402fd1de>] Not tainted
EFLAGS: 00010202
EIP is at 0x402fd1de
eax: 00001579 ebx: 4039ff60 ecx: 00001009 edx: 08103a88
esi: 00000004 edi: 00000000 ebp: bfffc788 esp: bfffc760
ds: 007b es: 007b ss: 007b
Process gscanbus (pid: 2525, threadinfo=c2314000 task=dc4af000)
<6>note: gscanbus[2525] exited with preempt_count 1
402fd1de
*pde = 07b1c067
Oops: 0006 [#1]
CPU: 0
EIP: 0073:[<402fd1de>] Not tainted
Using defaults from ksymoops -t elf32-i386 -a i386
EFLAGS: 00010202
eax: 00001579 ebx: 4039ff60 ecx: 00001009 edx: 08103a88
esi: 00000004 edi: 00000000 ebp: bfffc788 esp: bfffc760
ds: 007b es: 007b ss: 007b
Warning (Oops_read): Code line not seen, dumping what data is available
>>EIP; 402fd1de <__crc_param_set_short+2b6895/75bf8f> <=====
>>ebx; 4039ff60 <__crc_param_set_short+359617/75bf8f>
>>edx; 08103a88 <__crc_ip_finish_output+23c39/133bb1>
>>ebp; bfffc788 <__crc_class_device_add+4dfb67/51fa16>
>>esp; bfffc760 <__crc_class_device_add+4dfb3f/51fa16>
2 warnings and 2 errors issued. Results may not be reliable.
--------
Please point me to a quick reference to the proper
usage of ksymoops if this info is at your finger tips.
Since I see the preempt bit above, I'll try compiling
without a preemtible kernel and will report the results
tomorrow.
Cheers,
Sam.
> >>EIP; 402fd1de <__crc_param_set_short+2b6895/75bf8f> <=====
>
> >>ebx; 4039ff60 <__crc_param_set_short+359617/75bf8f>
> >>edx; 08103a88 <__crc_ip_finish_output+23c39/133bb1>
> >>ebp; bfffc788 <__crc_class_device_add+4dfb67/51fa16>
> >>esp; bfffc760 <__crc_class_device_add+4dfb3f/51fa16>
This doesn't make much sense. I'm not sure what to make of it.
--
Debian - http://www.debian.org/
Linux 1394 - http://www.linux1394.org/
Subversion - http://subversion.tigris.org/
On Fri, Jul 25, 2003 at 04:11:29PM -0400, Ben Collins wrote:
> Kick ass. I've commited this change to the 1394 repo. Linus will get the
> fix soon. I'll also send it to Marcelo for 2.4.22.
>
> Please, if you are testing, use the code at http://www.linux1394.org's viewcvs
> (trunk tarball will replace drivers/ieee1394 in 2.6, branches/linux-2.4
> will do the same for 2.4).
Its all working! Compiled the 1014 rev, and everything looks good. dvgrab,
kino, gscanbus, even GnomeMeeting 0.98 with /dev/video1394.
Thanks for all your help, and the time spent tracking down this problem!
-Chris
ohci1394: $Rev$ Ben Collins <[email protected]>
PCI: Found IRQ 10 for device 0000:00:0b.0
ohci1394_0: OHCI-1394 1.0 (PCI): IRQ=[10] MMIO=[db001000-db0017ff] Max Packet=[2048]
ieee1394: Host added: ID:BUS[0-00:1023] GUID[0011060000006a85]
ieee1394: Node added: ID:BUS[0-00:1023] GUID[0010950010090143]
ieee1394: Node changed: 0-00:1023 -> 0-01:1023
ieee1394: Node changed: 0-01:1023 -> 0-00:1023
ieee1394: Node removed: ID:BUS[0-00:1023] GUID[0010950010090143]
On Sat, 2003-07-26 at 11:12, Ben Collins wrote:
> > >>EIP; 402fd1de <__crc_param_set_short+2b6895/75bf8f> <=====
> >
> > >>ebx; 4039ff60 <__crc_param_set_short+359617/75bf8f>
> > >>edx; 08103a88 <__crc_ip_finish_output+23c39/133bb1>
> > >>ebp; bfffc788 <__crc_class_device_add+4dfb67/51fa16>
> > >>esp; bfffc760 <__crc_class_device_add+4dfb3f/51fa16>
>
> This doesn't make much sense. I'm not sure what to make of it.
Well, I compiled without preempt and the problem went away.
Everything now seems to work (using Rev 1016). The oops
upon unloading ohci1394 is gone as well. Are others
having success *with* a preemptibe kernel?
Cheers,
Sam.
On Sat, Jul 26, 2003 at 09:52:59AM -0700, Chris Ruvolo wrote:
> On Fri, Jul 25, 2003 at 04:11:29PM -0400, Ben Collins wrote:
> > Kick ass. I've commited this change to the 1394 repo. Linus will get the
> > fix soon. I'll also send it to Marcelo for 2.4.22.
> >
> > Please, if you are testing, use the code at http://www.linux1394.org's viewcvs
> > (trunk tarball will replace drivers/ieee1394 in 2.6, branches/linux-2.4
> > will do the same for 2.4).
>
> Its all working! Compiled the 1014 rev, and everything looks good. dvgrab,
> kino, gscanbus, even GnomeMeeting 0.98 with /dev/video1394.
>
> Thanks for all your help, and the time spent tracking down this problem!
Thanks for the feedback. I'm glad this is finally fixed.
--
Debian - http://www.debian.org/
Linux 1394 - http://www.linux1394.org/
Subversion - http://subversion.tigris.org/
On Sat, Jul 26, 2003 at 01:41:12PM -0400, Sam Bromley wrote:
> On Sat, 2003-07-26 at 11:12, Ben Collins wrote:
> > > >>EIP; 402fd1de <__crc_param_set_short+2b6895/75bf8f> <=====
> > >
> > > >>ebx; 4039ff60 <__crc_param_set_short+359617/75bf8f>
> > > >>edx; 08103a88 <__crc_ip_finish_output+23c39/133bb1>
> > > >>ebp; bfffc788 <__crc_class_device_add+4dfb67/51fa16>
> > > >>esp; bfffc760 <__crc_class_device_add+4dfb3f/51fa16>
> >
> > This doesn't make much sense. I'm not sure what to make of it.
>
>
> Well, I compiled without preempt and the problem went away.
> Everything now seems to work (using Rev 1016). The oops
> upon unloading ohci1394 is gone as well. Are others
> having success *with* a preemptibe kernel?
I'm not sure how to get around the problem with unload. I call
wait_for_completion() to make sure the kernel thread in nodemgr is dead,
but it ends up sleeping and that causes the problem. I am under a
read_lock when this occurs, and I'm not sure I can get around that fact.
--
Debian - http://www.debian.org/
Linux 1394 - http://www.linux1394.org/
Subversion - http://subversion.tigris.org/