From: Jonathan W. <jw...@ju...> - 2014-01-29 23:55:09
|
Hi Ilia On Wed, Jan 29, 2014 at 04:09:40PM +0400, ???????? wrote: > >IIRC there are some problems in r2240, and now I will compile and test > >ffado library only. > > I compiled ffado r2470 and tested it. > > Here is a full output > > rghost.net/download/private/52030396/90094fffac5ecefd9a7630fb6f08cb75/3a69068f4c846edc91970625d1af48a61d29b953/new_build3.txt > > There is no 1khz test tone output and it produce a real error after a lot > of warnings. Thanks for testing this and providing this log file. Having a "real" error is instructive since it gives us something concrete to work with. During the initial startup sequence things look reasonably normal. We have a few "wait extended" messages and a number of "incrementFrameCounter" messages. The latter report a "diff" of the order of 10000 which is ok at startup. After the expected length of time FFADO syncs with the device and normal operation commenced. We see this by virtue of the message: 00799342572: Debug (StreamProcessorManager.cpp)[1032] start: Started... in the log. Accompanying the start message is a status dump of the stream processors which report believable sync rates: StreamProcessor 0x1293a50, Receive: : Framerate : Nominal: 48000, Sync: 48023.408856, Buffer 48023.408856 StreamProcessor 0x1294fc0, Transmit: : Framerate : Nominal: 48000, Sync: 48023.408856, Buffer 48013.897150 That all looks sensible and is what I would expect. Once started, we continue to see the "incrementFrameCounter" message for quite some time. This is a little strange because normally this will cease fairly soon after sync is obtained. The diff creeps up to around 15000 before falling back around 10000. By 00800683666 it has stopped. So while that took a little longer than I am accustomed to, there is no cause for concern at this point. At the end of the day the diff was sufficiently small about a second after startup, which should be fine. Where things become concerning is at 00800911783, where we see this: 00800911783: Debug (StreamProcessor.cpp)[ 491] putPacket: cy 2105 rather large TSP difference TS=01774709760 => TS=01775929344 (1219584, nom 3585) This constitutes a significant jump in the timestamp which at this point in the session is unexpected. "incrementFrameCounter" messages then start reappearing as a consequence of this timestamp discontinuity: 00800911793: ESC[31mWarning (TimestampedBuffer.cpp)[1064] incrementFrameCounter: (0x1293c60) difference rather large (+): diff=1220195.597, max= 10000.000, 1775929344.000, 1774709148.403 The difference here is *massive*, around 100 times what would be considered normal. Curiously enough there is no other hint in the log around this time as to why this might have occurred. Things get more interesting at the 00800996616 point, where we see this: Warning (TimestampedBuffer.cpp)[ 511] writeFrames: ringbuffer full, 784, 127 In other words, FFADO has run out of internal buffer space. This is very rare and indicates that for some reason data wasn't being cleared fast enough. Anyway, the above error triggers and xrun and soon after we get a dump of the stream processor status again. This is the interesting bit. StreamProcessor 0x1293a50, Receive: : Framerate : Nominal: 48000, Sync: 43670.219944, Buffer 43670.219944 StreamProcessor 0x1293a50, Receive: : Framerate : Nominal: 48000, Sync: 43670.219944, Buffer 43670.219944 Note the rather strange sync rate: around 43.7 kHz. While this is suspiciously close to 44.1 kHz, it is is nevertheless quite different from the rate which was originally detected during startup. It is almost as if the RME changed to a different sample rate spontaneously (possibly around the 00800911783 mark, coincident with the "large TSP difference" message). Whatever the root cause, FFADO seems to be detecting a very different sample rate at the time of failure compared to startup, was unable to recover and shut down soon after. This raises a number of issues, not the least of which is why FFADO 2.1 on the live distribution worked while your compiled r2470 experienced the above problem. As far as I recall neither the RME streaming system nor the core FFADO streaming system have seen any functional changes between these two versions. Adding to the confusion is that I have never seen log sequences like this before. Furthermore, r2470 works perfectly well on the two machines I regularly use to test FFADO. Although it's a long shot, I wonder whether your installation with r2470 has a CPU frequency setting which allows frequency scaling to occur. If for example the system frequency changes while FFADO is streaming it can trigger some strange timing related issues. Admittedly we haven't seen your precise mix of messages before, but at this stage a connection with CPU frequency scaling can't be ruled out. Another thing to check is whether FFADO 2.1 works when installed on the same system that r2470 gives trouble. The reason I ask this is that there is a possibility that the configuration of the live distribution (where you tested 2.1) could be different to the installed system. Testing 2.1 on the installed system in place of r2470 will tell us something. If you have already tested this, apologies: I've managed to miss the result in previous emails. Please refresh my memory in this case. :-) Regards jonathan |