Re: half a loop
Brought to you by:
aeb,
bencollins
From: Carl K. <ca...@pe...> - 2011-12-18 22:54:13
|
On Sun, Dec 18, 2011 at 7:57 AM, Stefan Richter <st...@s5...> wrote: > On Dec 17 Carl Karsten wrote: >> same hardware, but new flavor of problem: 2 controllers in one box, >> cable looped from one to the other. (it is the 2m cable that seems to >> cause the "isochronous cycle inconsistent" in the other thread. > > I don't think it causes the isoch cycle inconsistency, the topology change > does. See Clemens' explanation. It may however cause the Configuration > ROM read failure. > >> juser@pc8:~$ ls /dev/fw? >> /dev/fw0 /dev/fw1 /dev/fw2 >> >> juser@pc8:~$ uname -a >> Linux pc8 3.2.0-4-generic #10-Ubuntu SMP Sat Dec 10 17:46:09 UTC 2011 x86_64 x86_64 x86_64 GNU/Linux >> >> juser@pc8:~$ dmesg |grep fire >> >> [ 1.935578] firewire_ohci 0000:02:05.0: PCI INT A -> Link[LNK1] -> GSI 5 (level, low) -> IRQ 5 >> [ 1.988295] firewire_ohci: Added fw-ohci device 0000:02:05.0, OHCI v1.10, 4 IR + 4 IT contexts, quirks 0x1 >> [ 1.988453] firewire_ohci: isochronous cycle inconsistent >> [ 1.993092] firewire_ohci 0000:04:00.0: PCI INT A -> Link[LK1E] -> GSI 16 (level, low) -> IRQ 16 >> [ 1.993098] firewire_ohci 0000:04:00.0: setting latency timer to 64 >> [ 2.051121] firewire_ohci: Added fw-ohci device 0000:04:00.0, OHCI v1.10, 8 IR + 8 IT contexts, quirks 0x10 >> [ 2.051204] firewire_ohci: isochronous cycle inconsistent >> [ 2.488158] firewire_core: created device fw0: GUID 00241b00964cac00, S400 >> [ 2.552154] firewire_core: created device fw1: GUID 0108000000006351, S800 >> [ 23.608055] firewire_ohci: AT spd 0 tl 06, ffc1 -> ffc0, ack_pending , QR req, fffff0000400 > > With firewire-ohci debug=3, there should be a few log lines from the > self-ID reception DMA between the two last lines above. Why are they > missing? wold the log lines contain "firewire"? If not, that's why they are missing, to keep the dmesg post under 50K. anything else I should include? > > (By the way, I have a patch here waiting to be posted which adds device > prefixes to firewire-ohci's debug messages --- for us folk who have more > than one controller in the PC and wonder which controller is emitting > what messages.) My one and only accepted kernel contribution is the same thing for a v4l device. > >> [ 23.608064] firewire_ohci: AR spd 0 tl 06, ffc0 -> ffc1, ack_complete, QR resp = 0404e334 >> [ 23.608083] firewire_ohci: AT spd 0 tl 07, ffc1 -> ffc0, ack_pending , QR req, fffff0000404 >> [ 23.608090] firewire_ohci: AR spd 0 tl 07, ffc0 -> ffc1, ack_complete, QR resp = 31333934 >> [ 23.608128] firewire_ohci: AT spd 0 tl 08, ffc1 -> ffc0, ack_pending , QR req, fffff0000408 >> [ 23.608135] firewire_ohci: AR spd 0 tl 08, ffc0 -> ffc1, ack_complete, QR resp = f000a222 >> [ 23.608160] firewire_ohci: AT spd 0 tl 09, ffc1 -> ffc0, ack_pending , QR req, fffff000040c >> [ 23.608167] firewire_ohci: AR spd 0 tl 09, ffc0 -> ffc1, ack_complete, QR resp = 00241b00 >> [ 23.608192] firewire_ohci: AT spd 0 tl 0a, ffc1 -> ffc0, ack_pending , QR req, fffff0000410 >> [ 23.608199] firewire_ohci: AR spd 0 tl 0a, ffc0 -> ffc1, ack_complete, QR resp = 964cac00 >> [ 23.608232] firewire_ohci: AT spd 2 tl 0b, ffc1 -> ffc0, evt_missing_ack, QR req, fffff0000414 >> [ 23.648054] firewire_ohci: AT spd 0 tl 04, ffc0 -> ffc1, ack_pending , QR req, fffff0000400 >> [ 23.648064] firewire_ohci: AR spd 0 tl 04, ffc1 -> ffc0, ack_complete, QR resp = 0404fb9d >> [ 23.648092] firewire_ohci: AT spd 0 tl 05, ffc0 -> ffc1, ack_pending , QR req, fffff0000404 >> [ 23.648099] firewire_ohci: AR spd 0 tl 05, ffc1 -> ffc0, ack_complete, QR resp = 31333934 >> [ 23.648133] firewire_ohci: AT spd 0 tl 06, ffc0 -> ffc1, ack_pending , QR req, fffff0000408 >> [ 23.648140] firewire_ohci: AR spd 0 tl 06, ffc1 -> ffc0, ack_complete, QR resp = f000b223 >> [ 23.648165] firewire_ohci: AT spd 0 tl 07, ffc0 -> ffc1, ack_pending , QR req, fffff000040c >> [ 23.648171] firewire_ohci: AR spd 0 tl 07, ffc1 -> ffc0, ack_complete, QR resp = 01080000 >> [ 23.648196] firewire_ohci: AT spd 0 tl 08, ffc0 -> ffc1, ack_pending , QR req, fffff0000410 >> [ 23.648203] firewire_ohci: AR spd 0 tl 08, ffc1 -> ffc0, ack_complete, QR resp = 00006351 >> [ 23.648229] firewire_ohci: AT spd 2 tl 09, ffc0 -> ffc1, evt_missing_ack, QR req, fffff0000414 > [...] >> [ 32.632258] firewire_ohci: AT spd 2 tl 1d, ffc1 -> ffc0, evt_missing_ack, QR req, fffff0000414 >> [ 32.632272] firewire_core: giving up on config rom for node id ffc0 >> [ 32.672061] firewire_ohci: AR spd 0 tl 16, ffc1 -> ffc0, ack_complete, QR resp = 0404fb9d >> [ 32.672068] firewire_ohci: AT spd 0 tl 16, ffc0 -> ffc1, pending/cancelled, QR req, fffff0000400 >> [ 32.672109] firewire_ohci: AR spd 0 tl 17, ffc1 -> ffc0, ack_complete, QR resp = 31333934 >> [ 32.672116] firewire_ohci: AT spd 0 tl 17, ffc0 -> ffc1, pending/cancelled, QR req, fffff0000404 >> [ 32.672142] firewire_ohci: AT spd 0 tl 18, ffc0 -> ffc1, ack_pending , QR req, fffff0000408 >> [ 32.672150] firewire_ohci: AR spd 0 tl 18, ffc1 -> ffc0, ack_complete, QR resp = f000b223 >> [ 32.672173] firewire_ohci: AT spd 0 tl 19, ffc0 -> ffc1, ack_pending , QR req, fffff000040c >> [ 32.672179] firewire_ohci: AR spd 0 tl 19, ffc1 -> ffc0, ack_complete, QR resp = 01080000 >> [ 32.672204] firewire_ohci: AT spd 0 tl 1a, ffc0 -> ffc1, ack_pending , QR req, fffff0000410 >> [ 32.672210] firewire_ohci: AR spd 0 tl 1a, ffc1 -> ffc0, ack_complete, QR resp = 00006351 >> [ 32.672262] firewire_ohci: AT spd 2 tl 1b, ffc0 -> ffc1, evt_missing_ack, QR req, fffff0000414 >> [ 32.672269] firewire_core: giving up on config rom for node id ffc1 > > Up to this point, the S800 controller fails to read from the S400 > controller, and the S400 controller fails to read from the S800 > controller, always with the read request to the 6th quadlet of the > Configuration ROM, always at S400 ( = "spd 2", whereas the first 5 > quadlets are always successfully read at S100 = "spd 0"), always with > transaction failure due to missing ACK in the request subaction. > > Im my experience, an "evt_missing_ack" can occur > - with an electrically unstable bus, e.g. caused by a bad cable, > - if the gap count at one or more nodes is too low, > - if a packet is sent at a larger speed than the peer node (or any > repeater node between sender and receiver) can handle. > > Gap count /should/ not be the issue here, because both PHYs were just > switched on and are supposed to feature a gap count of 63, which is the > power reset value and the absolute maximum. > > A mismatch of transmission speed vs. supported speed cannot be the issue > here, according to your log from after reboot (below). > > By the way, firewire-core always reads the first 5 quadlets ( = one header > quadlet and the four quadlets of bus information of the Configuration ROM > register) only at S100 as the only speed that is guaranteed to be > supported. The rest of the Configuration ROM is read at a higher speed > which is either determined from self-ID data of all PHYs and link speed > from the bus information block (the latter taken with a grain of salt; > this is not the actual link speed but the one that the firmware writer is > wanting us to believe) or determined from a speed probe, using read tests > at fffff0000400 at several speeds. In case of your two particular cards > plugged together, firewire-core does not perform a speed probe but decides > that both devices can talk to each other at S400. > > After the above, one of the two nodes performs bus management, > particularly decides to switch all PHYs to a lower gap count to increase > asynchronous bandwidth: > >> [ 32.672275] firewire_core: phy config: card 0, new root=ffc0, gap_count=5 >> [ 32.672295] firewire_ohci: AT ack_complete, PHY 00c50000 ff3affff >> [ 32.672299] firewire_ohci: AR ack_complete, PHY 00c50000 ff3affff >> [ 32.672324] firewire_ohci: AR evt_bus_reset, generation 5 >> [ 32.672327] firewire_ohci: AR evt_bus_reset, generation 3 >> [ 32.672335] firewire_ohci: 2 selfIDs, generation 5, local node ID ffc0 >> [ 32.672339] firewire_ohci: selfID 0: 8045cc94, phy 0 [p--] beta gc=5 -3W Lc >> [ 32.672342] firewire_ohci: selfID 0: 814588c2, phy 1 [c..] S400 gc=5 +0W Lci >> [ 32.672356] firewire_ohci: 2 selfIDs, generation 3, local node ID ffc1 >> [ 32.672359] firewire_ohci: selfID 0: 8045cc94, phy 0 [p--] beta gc=5 -3W Lc >> [ 32.672362] firewire_ohci: selfID 0: 814588c2, phy 1 [c..] S400 gc=5 +0W Lci > > This involves transmission of a PHY packet by one node, reception of that > packet by the other one, bus reset by the former node, and self-ID > reception by both nodes. Then there is arbitration for bus manager role, > with ffc0 as requester and ffc1 (which is the IRM) as responder: > >> [ 32.928047] firewire_ohci: AR spd 0 tl 1e, ffc1 -> ffc0, ack_complete, Lk resp 4,2 >> [ 32.928052] firewire_ohci: AT spd 0 tl 1e, ffc0 -> ffc1, pending/cancelled, Lk req, fffff000021c 8,2 > > The fact that node ffc1 (phy 1) issued a bus reset is taken as a signal to > firewire-core on node ffc0 (phy 0) to re-read the Configuration ROM of > node ffc1: > >> [ 33.172042] firewire_ohci: AR spd 0 tl 1f, ffc1 -> ffc0, ack_complete, QR resp = 0404e334 >> [ 33.172047] firewire_ohci: AT spd 0 tl 1f, ffc0 -> ffc1, pending/cancelled, QR req, fffff0000400 >> [ 33.172070] firewire_ohci: AT spd 0 tl 20, ffc0 -> ffc1, ack_pending , QR req, fffff0000404 >> [ 33.172078] firewire_ohci: AR spd 0 tl 20, ffc1 -> ffc0, ack_complete, QR resp = 31333934 >> [ 33.172097] firewire_ohci: AR spd 0 tl 21, ffc1 -> ffc0, ack_complete, QR resp = f000a222 >> [ 33.172102] firewire_ohci: AT spd 0 tl 21, ffc0 -> ffc1, pending/cancelled, QR req, fffff0000408 >> [ 33.172121] firewire_ohci: AT spd 0 tl 22, ffc0 -> ffc1, ack_pending , QR req, fffff000040c >> [ 33.172128] firewire_ohci: AR spd 0 tl 22, ffc1 -> ffc0, ack_complete, QR resp = 00241b00 >> [ 33.172148] firewire_ohci: AR spd 0 tl 23, ffc1 -> ffc0, ack_complete, QR resp = 964cac00 >> [ 33.172152] firewire_ohci: AT spd 0 tl 23, ffc0 -> ffc1, pending/cancelled, QR req, fffff0000410 >> [ 33.172170] firewire_ohci: AR spd 2 tl 24, ffc1 -> ffc0, ack_complete, QR resp = 0005dd0b >> [ 33.172174] firewire_ohci: AT spd 2 tl 24, ffc0 -> ffc1, pending/cancelled, QR req, fffff0000414 >> [ 33.172192] firewire_ohci: AT spd 2 tl 25, ffc0 -> ffc1, ack_pending , QR req, fffff0000418 >> [ 33.172199] firewire_ohci: AR spd 2 tl 25, ffc1 -> ffc0, ack_complete, QR resp = 0c0083c0 >> [ 33.172217] firewire_ohci: AT spd 2 tl 26, ffc0 -> ffc1, ack_pending , QR req, fffff000041c >> [ 33.172224] firewire_ohci: AR spd 2 tl 26, ffc1 -> ffc0, ack_complete, QR resp = 03d00d1e > [...] >> [ 33.172531] firewire_ohci: AT spd 2 tl 33, ffc0 -> ffc1, ack_pending , QR req, fffff0000440 >> [ 33.172537] firewire_ohci: AR spd 2 tl 33, ffc1 -> ffc0, ack_complete, QR resp = 72657769 >> [ 33.172555] firewire_ohci: AT spd 2 tl 34, ffc0 -> ffc1, ack_pending , QR req, fffff0000444 >> [ 33.172562] firewire_ohci: AR spd 2 tl 34, ffc1 -> ffc0, ack_complete, QR resp = 72650000 >> [ 33.172679] firewire_core: created device fw2: GUID 00241b00964cac00, S400 > > Curiously, now all of the Configuration ROM can be read without incident! > >> [ 33.172698] firewire_ohci: AT spd 2 tl 35, ffc0 -> ffc1, ack_pending , QR req, fffff0000234 >> [ 33.172704] firewire_ohci: AR spd 2 tl 35, ffc0 -> ffc1, ack_pending , QR req, fffff0000234 >> [ 33.172724] firewire_ohci: AR spd 2 tl 35, ffc1 -> ffc0, ack_complete, QR resp = c000001f >> [ 33.172729] firewire_ohci: AT spd 2 tl 35, ffc1 -> ffc0, ack_complete, QR resp = c000001f >> [ 33.172753] firewire_ohci: AT spd 2 tl 36, ffc0 -> ffc1, ack_pending , QW req, fffff0000234 = c000001f >> [ 33.172758] firewire_ohci: AR spd 2 tl 36, ffc0 -> ffc1, ack_pending , QW req, fffff0000234 = c000001f >> [ 33.172776] firewire_ohci: AR spd 2 tl 36, ffc1 -> ffc0, ack_complete, W resp >> [ 33.172781] firewire_ohci: AT spd 2 tl 36, ffc1 -> ffc0, ack_complete, W resp >> [ 33.172804] firewire_ohci: AT spd 0 tl 37, ffc0 -> ffc1, ack_pending , Lk req, fffff000021c 8,2 >> [ 33.172811] firewire_ohci: AR spd 0 tl 37, ffc1 -> ffc0, ack_complete, Lk resp 4,2 > > These lines show a few requests from ffc0 to ffc1 and their responses, > which are routinely done when firewire-core probed a new node. Again no > missing ACK anymore. > > Carl, > can you try this once more and check which gap counts are reported in the > self ID reception event right after you plugged the cable in == right > before the nodes unsuccessfully attempt to get each other's Configuration > ROM? > [ 2.040261] firewire_core: phy config: card 1, new root=ffc1, gap_count=5 > Furthermore, tell us whether you end up with two or three /dev/fw* again > (i.e. whether neither node succeeded to probe the other, or one of them > succeeded to probe the other). So I have been gathering stats on what seams to do what. What I really need is a way to un/plug the firewire cable, and hit the power button. (which isn't out of the question given Jason is a friend of mine: http://www.ubergizmo.com/2011/10/robot-plays-angry-birds) Till then, we have my scripts and occasional human interaction. I am doing the best I can to keep the hardware in a consistent state: same laptop, pcie card, cable, network, etc. and not moving things around, so the cable is always in the same proximity to the laptop power supply and lcd. given the results I have seen, I don't think the cable is picking up noise. I would hope that it isn't susceptible to such sources. I have the box looping: # /etc/rc.local printf "$(date --rfc-3339=ns)" >> /home/juser/fwx.txt ls -C /dev/fw? >> /home/juser/fwx.txt reboot which gives me: 2011-12-18 13:41:37.406091760-06:00 /dev/fw0 /dev/fw1 /dev/fw2 2011-12-18 13:44:59.911457999-06:00 /dev/fw0 /dev/fw1 ... 2011-12-18 14:10:03.532900719-06:00 /dev/fw0 /dev/fw1 2011-12-18 14:13:50.814516139-06:00 /dev/fw0 /dev/fw1 After 6 hours of this, still just fw0 and 1. If I run shutdown, then hit the 'power' button, (which I have done 10+ times) it seems (I am not taking careful notes on this one) that seems to inject some randomness that causes it to maybe change from 0,1,2 connections being completed. If I then run the log/reboot loop, it goes back to just fw0,1 (0 connections). un/re plugging the firewire cable also seems to have the same random 0,1,2 connections. > Then, run either gscanbus seems pretty buggy. should I try and report bugs given the unstable state of my box? > or firecontrol http://firecontrol.svn.sourceforge.net/viewvc/firecontrol/trunk/ configure.in ... how do I automake configure? anyone around here able to make a .deb for this? Then I can stick it in my ppa and apt-get it when needed. I'll even push it into the debconf-video team land and see if it can get into the propper repos. > on _each_ "port" and use it to trigger a bus reset, then watch if this > results in all four expected /dev/fw* becoming available. > >> rebooted, now both ends show up: >> >> >> juser@pc8:~$ dmesg |grep fire > [...] >> [ 2.125123] firewire_ohci: Added fw-ohci device 0000:04:00.0, OHCI v1.10, 8 IR + 8 IT contexts, quirks 0x10 >> [ 2.125154] firewire_ohci: isochronous cycle inconsistent >> [ 2.568156] firewire_core: created device fw0: GUID 00241b00964cac00, S400 >> [ 2.568172] firewire_core: phy config: card 0, new root=ffc1, gap_count=5 >> [ 2.624160] firewire_core: created device fw1: GUID 0108000000006351, S800 >> [ 2.624724] firewire_core: created device fw2: GUID 00241b00964cac00, S400 >> [ 5.576653] firewire_core: created device fw3: GUID 0108000000006351, S400, 1 config ROM retries >> >> juser@pc8:~$ ls /dev/fw? >> /dev/fw0 /dev/fw1 /dev/fw2 /dev/fw3 > > The "1 config ROM retries" is a hint that the connection still is not > fully stable. > -- > Stefan Richter > -=====-==-== ==-- =--=- > http://arcgraph.de/sr/ -- Carl K |