From: Stefan R. <st...@s5...> - 2013-08-22 13:57:43
|
On Aug 22 Jonathan Woithe wrote: [Ilia wrote:] > > I had tried to start jackd, but it failed again. It reported that > > "calculateRate: rate more that 10% off nominal" and after that it had > > continuously repeat this message: > > " > > 1377091825940565: Debug (fireface_hw.cpp)[ 345] get_hardware_state: State reported by hardware: > > 1377091825940597: Debug (fireface_hw.cpp)[ 346] get_hardware_state: is_streaming: 0 > > 1377091825940603: Debug (fireface_hw.cpp)[ 347] get_hardware_state: clock_mode: master > > 1377091825940607: Debug (fireface_hw.cpp)[ 348] get_hardware_state: autosync source: 0 > > 1377091825940610: Debug (fireface_hw.cpp)[ 349] get_hardware_state: autosync freq: 0 > > 1377091825940614: Debug (fireface_hw.cpp)[ 350] get_hardware_state: spdif freq: 0 > > 1377091825940617: Debug (fireface_hw.cpp)[ 351] get_hardware_state: ADAT 1/2 status: 0, 0 > > 1377091825940621: Debug (fireface_hw.cpp)[ 352] get_hardware_state: SDPIF status: 0 > > 1377091825940625: Debug (fireface_hw.cpp)[ 353] get_hardware_state: Wclk/tco status: 0, 0 > > " > > I killed it manually after ~1 minute. > > There are a few things to point out here. Firstly, it's clear that > get_hardware_state() is being called a little more frequently than I > remembered at the time I added that debug output. I should throttle that > debug output to prevent it getting in the road during normal operation. The > calls to this function, however, are not an error in and of themselves. > > Of greater concern are some other things which appear in that output. > Firstly, the 10% messages you're getting seem to be indicating that the > effective rate of the device is closer to 44.1 kHz than 48 kHz. The "rate" > of 512 is what would be seen if the ff800 was running at exactly 48 kHz > relative to the firewire clock (in reality it's never exactly this value, so > rates I typically see are between 511 and 513). The rate corresponding to > 44.1 kHz is 557.28 or there abouts. The per-packet values we're seeing from > your device are bounding around between approximately 563 (43651 Hz) and 570 > (43115 Hz) which indicates a "real" frequency of perhaps 43383 Hz. While > this is close to 44.1 kHz it's clearly not 44.1 kHz (unless of course your > firewire's bus clock is *way* off frequency, which is unlikely). > > It seems from the debug log that the device is being set to run at 48000 Hz: > both setSamplingFrequency() and hardware_init_streaming() report this as the > rate now, which is good. The only thing I can think of is that under > another OS the DDS control has been used to shift the ff800's operating > frequency. In theory this shouldn't matter to ffado since we reprogram the > hardware to suit our purposes, but perhaps there's a subtle detail that I've > missed. Even so, from memory the DDS controls on other OSes have a maximum > deviation of +/- 0.1% (I'll check the manual tonight), and the difference > we're seeing here is more like 1.7%. Isn't it also possible that the FF800 really does stream at 48 kHz, but that the PC's notion of realtime is 10...11% off? > All that aside, something else went wrong in the latter part of the startup > procedure. Apart from the strange effective rate discussed above everything > was more or less normal up until line 2661 (for future reference a relatively > small number of those calculateRate() lines is also normal during startup). > On this line we see: > > ieee1394service.cpp)[ 616] readNoLock: raw1394_read failed: node 0xFFC0, > addr = 0x00000000801C0000, length = 2 That's quite a low address. Does the RME firmware indeed work in such a low address space? > This means that ffado attempted to read a register from the ff800 and the > read failed. Somewhat curiously there is no error reported from a higher > level function as a result of this problem (there are a few call sites of > get_hardware_state() which are sloppy with return values - I've fixed this > in r2381). Soon after (at line 2774, when ffado starts to set up for a > retry due to sync taking too long to achieve) the read error occurs again to > prove that the previous failure was no accident. Then at line 2796 we get > > IsoHandlerManager.cpp)[1389] iterate: IsoHandler (0x1c324f0): Failed to > iterate handler: Permission denied > > which is starting to sound like the device has disappeared from the firewire > bus (I think it indicates that the kernel has denied access to the device > node which usually happens if that node disappears). However, > get_hardware_state() evidently does not have a problem reading its registers > because successful status reads are reported at line 2806 and following. [...] Maybe these are weaker symptoms of the very kernel bug which Ilia reported in other posts (the soft lock-up and allocation failures). -- Stefan Richter -=====-===-= =--- =-==- http://arcgraph.de/sr/ |