From: FFADO <ffa...@ff...> - 2012-06-26 12:52:50
|
#242: ntp interferes with ffado ------------------------+--------------------------------------------------- Reporter: ppalmers | Owner: ppalmers Type: bug | Status: new Priority: major | Milestone: FFADO 2.x Component: | Version: FFADO 2.0-rc2 (1.999.42) Resolution: | Keywords: Device_name: all | ------------------------+--------------------------------------------------- Comment (by stefanr): Same result with DICE driver, Saffire PRO 24, and three different controllers (TI XIO2213A/B, LSI/Agere FW643e, JMicron JMB381). r2166 is fine, r2174 not. Tested without ntpd, current libraw1394 of course (double-checked that no older versions exist in {/usr,/usr/local}/{include,lib}), and performance CPU frequency scaling governor (although ondemand works on my system too). Here is the tail of a session with r2174, Saffire PRO24, JMB381: {{{ 2602487413684: Warning (IsoHandlerManager.cpp)[1568] putPacket: reconstructed CTR counter discrepacy 2602487413689: Warning (IsoHandlerManager.cpp)[1574] putPacket: ingredients: 50, 28050000, 2A05012, 2A025550, 2A023192, 20, 21, 21, 516342162 2602487413693: Warning (IsoHandlerManager.cpp)[1575] putPacket: diffcy = 45 2602487413697: Warning (IsoHandlerManager.cpp)[1568] putPacket: reconstructed CTR counter discrepacy 2602487413701: Warning (IsoHandlerManager.cpp)[1574] putPacket: ingredients: 51, 28051000, 2A05112, 2A0256A8, 2A023192, 20, 21, 21, 516345234 2602487413705: Warning (IsoHandlerManager.cpp)[1575] putPacket: diffcy = 46 2602487413710: Warning (IsoHandlerManager.cpp)[1568] putPacket: reconstructed CTR counter discrepacy 2602487413716: Warning (IsoHandlerManager.cpp)[1574] putPacket: ingredients: 52, 28052000, 2A05212, 2A0257CF, 2A023192, 20, 21, 21, 516348306 2602487413720: Warning (IsoHandlerManager.cpp)[1575] putPacket: diffcy = 47 2602487413724: Warning (IsoHandlerManager.cpp)[1568] putPacket: reconstructed CTR counter discrepacy 2602487413729: Warning (IsoHandlerManager.cpp)[1574] putPacket: ingredients: 53, 28053000, 2A05312, 2A025940, 2A023192, 20, 21, 21, 516351378 2602487413733: Warning (IsoHandlerManager.cpp)[1575] putPacket: diffcy = 48 2602487413740: Warning (IsoHandlerManager.cpp)[1568] putPacket: reconstructed CTR counter discrepancy 2602487413743: Warning (IsoHandlerManager.cpp)[1574] putPacket: ingredients: 54, 28054000, 2A054192, 2A025AB0, 2A023192, 20, 21, 21, 516354450 2602487413749: Warning (IsoHandlerManager.cpp)[1575] putPacket: diffcy = 49 2602487413855: Warning (StreamProcessorManager.cpp)[ 909] alignReceivedStreams: xrun while aligning streams... 2602487413865: Error (StreamProcessorManager.cpp)[ 873] syncStartAll: Could not align streams... 2602487413870: Fatal (StreamProcessorManager.cpp)[1021] start: Could not syncStartAll... 2602487413877: Warning (devicemanager.cpp)[ 929] startStreaming: Failed to start SPM! firewire ERR: Could not start streaming threads: -1 2602487424170: Fatal (ffado.cpp)[ 220] ffado_streaming_start: Could not start the streaming system DRIVER NT: could not start driver cannot start driver 2602487575860: Error (CycleTimerHelper.cpp)[ 508] Execute: negative step: -7282477201442.834961! (correcting to nominal) 2602487776199: Error (CycleTimerHelper.cpp)[ 508] Execute: negative step: -7282477126033.470703! (correcting to nominal) 2602487975504: Error (CycleTimerHelper.cpp)[ 508] Execute: negative step: -7282477045726.331055! (correcting to nominal) 2602488173988: Error (CycleTimerHelper.cpp)[ 508] Execute: negative step: -7282476960558.433594! (correcting to nominal) 2602488374161: Error (CycleTimerHelper.cpp)[ 508] Execute: negative step: -7282476870401.022461! (correcting to nominal) 2602488573279: Error (CycleTimerHelper.cpp)[ 508] Execute: negative step: -7282476775365.975586! (correcting to nominal) 2602488776155: Error (CycleTimerHelper.cpp)[ 508] Execute: negative step: -7282476675226.498047! (correcting to nominal) 2602488973224: Error (CycleTimerHelper.cpp)[ 508] Execute: negative step: -7282476570374.581055! (correcting to nominal) 2602489176290: Error (CycleTimerHelper.cpp)[ 508] Execute: negative step: -7282476460376.753906! (correcting to nominal) 2602489373550: Error (CycleTimerHelper.cpp)[ 508] Execute: negative step: -7282476345654.441406! (correcting to nominal) 2602489429428: Fatal (IsoHandlerManager.cpp)[ 348] Execute: (0xd2b8d0, Receive) Handler died: now: 2E0A348B, last: 2A054192, diff: 49395449 (max: 49152000) 2602489429448: Warning (StreamProcessor.cpp)[ 173] handlerDied: Handler died for 0xd62af0 2602489438844: Warning (ieee1394service.cpp)[1498] freeIsoChannel: Invalid channel number: -1 2602489438862: Error (dice_avdevice.cpp)[1365] startstopStreamByIndex: Could not deallocate iso channel for SP 0 (ATX 0) 2602489438867: Warning (devicemanager.cpp)[ 963] stopStreamingOnDevice: Could not stop stream 0 of device 0xd59bc0 2602489440436: Error (dice_avdevice.cpp)[1352] startstopStreamByIndex: ISO_CHANNEL register != 0xFFFFFFFF (=0x00000001) for ARX 0 2602489440444: Warning (devicemanager.cpp)[ 963] stopStreamingOnDevice: Could not stop stream 1 of device 0xd59bc0 2602489576091: Error (CycleTimerHelper.cpp)[ 508] Execute: negative step: -7282476225792.833984! (correcting to nominal) no message buffer overruns stefan@stein ~ $ }}} It looked the same on the other two controllers. This and the prior tests were on the PC with the exceedingly bad clock which causes ntpd to force a jump by about two seconds every two minutes. I don't know if this is of any importance: Due to ntpd usage for most of the time prior to this test session, a considerable offset from CLOCK_MONOTONIC_RAW to CLOCK_MONOTONIC has accumulated now. Here is a part of the output of testlibraw: {{{ - cycle timer: 70 seconds, 7026 cycles, 1937 sub-cycles local time from CLOCK_REALTIME: 1340714283538424 us = Tue Jun 26 14:38:03 2012 cycle timer: 70 seconds, 7027 cycles, 771 sub-cycles local time from CLOCK_MONOTONIC: 2604599289565 us cycle timer: 70 seconds, 7027 cycles, 943 sub-cycles local time from CLOCK_MONOTONIC_RAW: 2603303207421 us }}} (30 days uptime, 22 minutes difference between the two monotonic clocks) To do: Test on my second PC which has a normally working RTC. -- Ticket URL: <http://subversion.ffado.org/ticket/242#comment:25> FFADO <http://subversion.ffado.org/index.fcgi> Free Firewire Audio Drivers |
From: FFADO <ffa...@ff...> - 2012-06-26 13:05:23
|
#242: ntp interferes with ffado ------------------------+--------------------------------------------------- Reporter: ppalmers | Owner: ppalmers Type: bug | Status: new Priority: major | Milestone: FFADO 2.x Component: | Version: FFADO 2.0-rc2 (1.999.42) Resolution: | Keywords: Device_name: all | ------------------------+--------------------------------------------------- Comment (by jwoithe): I've been running further tests. Although I can't reproduce the negative step errors you're seeing, I do observe glitches in the playback with the FF800 if I use "-p256 -n3". By way of comparison, "-p1024 -n4" works fine. The glitches with "-p256 -n3" go away if I force the clock source to be CLOCK_REALTIME. CLOCK_MONOTONIC behaves in much the same way as does CLOCK_MONOTONIC_RAW. The result of testlibraw on this system is: {{{ - cycle timer: 29 seconds, 1124 cycles, 1245 sub-cycles local time from CLOCK_REALTIME: 1340715422771679 us = Tue Jun 26 22:27:02 2012 cycle timer: 29 seconds, 1125 cycles, 471 sub-cycles local time from CLOCK_MONOTONIC: 10345790071 us cycle timer: 29 seconds, 1125 cycles, 1098 sub-cycles local time from CLOCK_MONOTONIC_RAW: 10345780173 us }}} Uptime is only a shade under 3 hours but in any case the clock on this PC is quite good so I wouldn't expect to see the massive differences that you see. It smells as if something somewhere is still using a clock that's not the same as that used by the SystemTimeSource object. Investigations along these lines have so far come up empty (places where usleep() etc are called are either part of device setup or don't impact on DLL operation). I will keep looking. -- Ticket URL: <http://subversion.ffado.org/ticket/242#comment:26> FFADO <http://subversion.ffado.org/index.fcgi> Free Firewire Audio Drivers |
From: FFADO <ffa...@ff...> - 2012-06-26 13:14:01
|
#242: ntp interferes with ffado ------------------------+--------------------------------------------------- Reporter: ppalmers | Owner: ppalmers Type: bug | Status: new Priority: major | Milestone: FFADO 2.x Component: | Version: FFADO 2.0-rc2 (1.999.42) Resolution: | Keywords: Device_name: all | ------------------------+--------------------------------------------------- Comment (by stefanr): I don't know if it is related: Why does ffado-test Discover -v6 on my system complain about "Debug (CycleTimerHelper.cpp)[ 393] Execute: (0x81e7b0) have to retry CTR read, diff unrealistic: diff: 13598, max: +/- 3072 (try: 5) 203949968"? Both r2166 and r2174 show those ten cycle timer read retries due to "unrealistic" difference. -- Ticket URL: <http://subversion.ffado.org/ticket/242#comment:27> FFADO <http://subversion.ffado.org/index.fcgi> Free Firewire Audio Drivers |
From: FFADO <ffa...@ff...> - 2012-06-26 13:30:04
|
#242: ntp interferes with ffado ------------------------+--------------------------------------------------- Reporter: ppalmers | Owner: ppalmers Type: bug | Status: new Priority: major | Milestone: FFADO 2.x Component: | Version: FFADO 2.0-rc2 (1.999.42) Resolution: | Keywords: Device_name: all | ------------------------+--------------------------------------------------- Comment (by stefanr): {{{ jackd -P66 -t2000 -dfirewire -r44100 -p1024 -n4 -v3 }}} dies after about 15 seconds, {{{ jackd -P66 -t2000 -dfirewire -r44100 -p1024 -n4 }}} dies after about 20 seconds, {{{ jackd -P66 -t2000 -dfirewire -r44100 -p2048 -n4 }}} dies after about 45 seconds, {{{ jackd -P66 -t2000 -dfirewire -r44100 -p4096 -n4 }}} dies after about 100 seconds, with "firewire ERR: wait status < 0! (= -1)", "DRIVER NT: could not run driver cycle". During runtime my untrained ear did not hear glitches in playback. -- Ticket URL: <http://subversion.ffado.org/ticket/242#comment:28> FFADO <http://subversion.ffado.org/index.fcgi> Free Firewire Audio Drivers |
From: FFADO <ffa...@ff...> - 2012-06-26 14:03:38
|
#242: ntp interferes with ffado ------------------------+--------------------------------------------------- Reporter: ppalmers | Owner: ppalmers Type: bug | Status: new Priority: major | Milestone: FFADO 2.x Component: | Version: FFADO 2.0-rc2 (1.999.42) Resolution: | Keywords: Device_name: all | ------------------------+--------------------------------------------------- Comment (by jwoithe): In relation to [comment:27 comment 27], I noticed that both your "working" (r2166) and "nonworking (r2174) logs showed those "diff unrealistic" messages. The fact that they occur in both leads me to believe that they are not the root cause of the issues we see when switching the clock to CLOCK_MONOTONIC / CLOCK_MONOTONIC_RAW. FYI there is a thread which periodically reads the cycle timer; it's set to wake up once every 200000 microseconds (according to the ffado- test_Discover_-v6_DICE_r2174_new-libraw1394.txt dump) to do this. Before it goes to sleep it estimates what time it should be woken and what "tick" value this corresponds to. When it wakes it compares the actual time/ticks with the predicted ones and if the difference is "too much" you get the message we're talking about. "Too much" here means a single cycle - 3072 ticks. The inclusion of detection attempts for unrealistic cycle counter values seems to stem from buggy hardware hardware - see comments in CycleTimerHelper.cpp, CycleTimerHelper::Execute(). In your case we're seeing positive diffs, which means wake-up occurred quite a bit later than was expected. Thinking this through, I wonder whether the difficulties we're seeing are related to the fact that while we can read the clock from CLOCK_MONOTONIC_RAW we can't use that clock to time a sleep. Currently the fallback is to use CLOCK_MONOTONIC for the sleeps, but if the speed of the two clocks differ (1) it's feasible that this could upset some of the FFADO timing code - especially those parts which attempt to predict wake up times. This doesn't, however, explain why r2166 showed the "diff unrealistic" messages. In r2166 everything to my knowledge used CLOCK_REALTIME, so there should be no difference between the clock used to source localtime and that used to time sleeps. It wouldn't surprise me if it turns out there is more than one gremlin at work here. (1) Off-hand, I can't see how the speed of CLOCK_MONOTONIC and CLOCK_MONOTONIC_RAW could be different in the absence of ntpd; my understanding was that the two only differed due to ntp-induced clock slew of the former. -- Ticket URL: <http://subversion.ffado.org/ticket/242#comment:29> FFADO <http://subversion.ffado.org/index.fcgi> Free Firewire Audio Drivers |
From: FFADO <ffa...@ff...> - 2012-06-26 14:44:31
|
#242: ntp interferes with ffado ------------------------+--------------------------------------------------- Reporter: ppalmers | Owner: ppalmers Type: bug | Status: new Priority: major | Milestone: FFADO 2.x Component: | Version: FFADO 2.0-rc2 (1.999.42) Resolution: | Keywords: Device_name: all | ------------------------+--------------------------------------------------- Comment (by adi): CLOCK_MONOTONIC_RAW cannot sleep. From the kernel's kernel/posix-timers.c: {{{ struct k_clock clock_monotonic_raw = { .clock_getres = hrtimer_get_res, .clock_get = posix_get_monotonic_raw, }; }}} while CLOCK_MONOTONIC has an nsleep entry: {{{ struct k_clock clock_monotonic = { .clock_getres = hrtimer_get_res, .clock_get = posix_ktime_get_ts, .nsleep = common_nsleep, .nsleep_restart = hrtimer_nanosleep_restart, .timer_create = common_timer_create, .timer_set = common_timer_set, .timer_get = common_timer_get, .timer_del = common_timer_del, }; }}} -- Ticket URL: <http://subversion.ffado.org/ticket/242#comment:30> FFADO <http://subversion.ffado.org/index.fcgi> Free Firewire Audio Drivers |
From: FFADO <ffa...@ff...> - 2012-06-26 15:06:24
|
#242: ntp interferes with ffado ------------------------+--------------------------------------------------- Reporter: ppalmers | Owner: ppalmers Type: bug | Status: new Priority: major | Milestone: FFADO 2.x Component: | Version: FFADO 2.0-rc2 (1.999.42) Resolution: | Keywords: Device_name: all | ------------------------+--------------------------------------------------- Comment (by adi): Addendum: r2174 works fine on my DICE-based io14. Let me know if I should test other devices, too. -- Ticket URL: <http://subversion.ffado.org/ticket/242#comment:31> FFADO <http://subversion.ffado.org/index.fcgi> Free Firewire Audio Drivers |
From: FFADO <ffa...@ff...> - 2012-06-26 19:20:44
|
#242: ntp interferes with ffado ------------------------+--------------------------------------------------- Reporter: ppalmers | Owner: ppalmers Type: bug | Status: new Priority: major | Milestone: FFADO 2.x Component: | Version: FFADO 2.0-rc2 (1.999.42) Resolution: | Keywords: Device_name: all | ------------------------+--------------------------------------------------- Comment (by stefanr): Addendum to my comment on jackd_r2174_new-libraw1394_Mac-mini_bebob- driver.txt: While r2174 consistently fails to start on my 2nd PC with -p256 -n3 (new libraw1394, ntpd off or on), it actually works flawless on this 2nd PC with -p2048 -n4 (new libraw1394, ntpd off or on). The "Warning (TimestampedBuffer.cpp)[1068] incrementFrameCounter: (0x9fdb940) difference rather large" which is seen in the log with the smaller buffer setting message never occured in a session with the larger buffer setting which is now running for an hour already. In this good session, there was actually no warning at all (except for the usual SPLIT_TIMEOUT thing, the two "updateState: ignoring identity state update from/to ePS_Created", and the one "getPacket: Instantanous samplerate more than 1% off nominal" directly at sturtup). ''1st PC with bad RTC:'' ASUS M3A78-EM, Phenom II x4 2.5 GHz, 8 GB RAM, kernel 3.3.1 with a few kernel debugging options and firewire drivers circa at version 3.5, x86-64 kernel (mainline) and x86-64 userland (Gentoo, except for mainline libraw1394 and ffado), 30 days uptime ''2nd PC with good RTC:''¹ Apple Mac mini, Core 2 Duo 2.33 GHz, 2 GB RAM, kernel 3.4 with some more kernel debugging options than on the 1st PC, same firewire drivers like on 1st PC, x86-32 kernel and x86-32 userland, 1.5 hours uptime ¹) ffado has always been working on this 2nd PC while ntpd was running; ntpd never had to resort to clock reset on this PC. -- Ticket URL: <http://subversion.ffado.org/ticket/242#comment:32> FFADO <http://subversion.ffado.org/index.fcgi> Free Firewire Audio Drivers |
From: FFADO <ffa...@ff...> - 2012-06-27 00:10:54
|
#242: ntp interferes with ffado ------------------------+--------------------------------------------------- Reporter: ppalmers | Owner: ppalmers Type: bug | Status: new Priority: major | Milestone: FFADO 2.x Component: | Version: FFADO 2.0-rc2 (1.999.42) Resolution: | Keywords: Device_name: all | ------------------------+--------------------------------------------------- Comment (by jwoithe): Replying to [comment:30 adi]: > CLOCK_MONOTONIC_RAW cannot sleep. Indeed - see [comment:20 comment 20]. This is precisely why I've used CLOCK_MONOTONIC for sleeps as of r2172. -- Ticket URL: <http://subversion.ffado.org/ticket/242#comment:33> FFADO <http://subversion.ffado.org/index.fcgi> Free Firewire Audio Drivers |
From: FFADO <ffa...@ff...> - 2012-06-27 00:14:44
|
#242: ntp interferes with ffado ------------------------+--------------------------------------------------- Reporter: ppalmers | Owner: ppalmers Type: bug | Status: new Priority: major | Milestone: FFADO 2.x Component: | Version: FFADO 2.0-rc2 (1.999.42) Resolution: | Keywords: Device_name: all | ------------------------+--------------------------------------------------- Comment (by jwoithe): Replying to [comment:31 adi]: > Addendum: r2174 works fine on my DICE-based io14. That's interesting. What period size was used, and how many buffers were requested? I've found with the RME that "-p1024 -n256" works great with r2174, but "-p256 -n3" produces choppy audio. > Let me know if I should test other devices, too. If it's easy to arrange it might be useful to build up a more complete picture of what's going on. In any case, there's something about the use of CLOCK_MONOTONIC_RAW that's messing things up, and somewhat confusingly the symptoms seem to vary between devices and/or drivers. -- Ticket URL: <http://subversion.ffado.org/ticket/242#comment:34> FFADO <http://subversion.ffado.org/index.fcgi> Free Firewire Audio Drivers |
From: FFADO <ffa...@ff...> - 2012-06-27 00:20:56
|
#242: ntp interferes with ffado ------------------------+--------------------------------------------------- Reporter: ppalmers | Owner: ppalmers Type: bug | Status: new Priority: major | Milestone: FFADO 2.x Component: | Version: FFADO 2.0-rc2 (1.999.42) Resolution: | Keywords: Device_name: all | ------------------------+--------------------------------------------------- Comment (by jwoithe): Replying to [comment:32 stefanr]: > While r2174 consistently fails to start on my 2nd PC with -p256 -n3 (new libraw1394, ntpd off or on), it actually works flawless on this 2nd PC with -p2048 -n4 (new libraw1394, ntpd off or on). The result on the second PC more or less mirrors what I've found: with CLOCK_MONOTONIC_RAW (or CLOCK_MONOTONIC) in use, larger buffers seem to work considerably better than smaller ones. Of course with CLOCK_REALTIME the smaller buffers work so there's definitely a regression when we shift to these alternative clocks. > The "Warning (TimestampedBuffer.cpp)(1068) incrementFrameCounter: (0x9fdb940) difference rather large" which is seen in the log with the smaller buffer setting message never occured in a session with the larger buffer setting ... Again, that's similar to what I've seen with the RME (I don't get this particular message at small buffer sizes, but I do see others related to timing issues). > ... the one "getPacket: Instantanous samplerate more than 1% off nominal" directly at sturtup). This will occur in many cases right at the start while things adjust to the actual clock values delivered by the system. It's not, as far as I can tell, implicated in the monotonic clock issues. -- Ticket URL: <http://subversion.ffado.org/ticket/242#comment:35> FFADO <http://subversion.ffado.org/index.fcgi> Free Firewire Audio Drivers |
From: FFADO <ffa...@ff...> - 2012-06-27 20:10:06
|
#242: ntp interferes with ffado ------------------------+--------------------------------------------------- Reporter: ppalmers | Owner: ppalmers Type: bug | Status: new Priority: major | Milestone: FFADO 2.x Component: | Version: FFADO 2.0-rc2 (1.999.42) Resolution: | Keywords: Device_name: all | ------------------------+--------------------------------------------------- Comment (by stefanr): Is this perhaps a startup race? (Something uses SystemTimeSource::clock_id before it was initialized? And large buffers defer the first critical use long enough to put it fater initialization...) -- Ticket URL: <http://subversion.ffado.org/ticket/242#comment:36> FFADO <http://subversion.ffado.org/index.fcgi> Free Firewire Audio Drivers |
From: FFADO <ffa...@ff...> - 2012-06-27 21:01:45
|
#242: ntp interferes with ffado ------------------------+--------------------------------------------------- Reporter: ppalmers | Owner: ppalmers Type: bug | Status: new Priority: major | Milestone: FFADO 2.x Component: | Version: FFADO 2.0-rc2 (1.999.42) Resolution: | Keywords: Device_name: all | ------------------------+--------------------------------------------------- Comment (by stefanr): Tested a few things again on my "bad" PC and noticed: - "jackd -dfirewire -p256 -n3 -v3" failed as before. - Surprisingly, one atttempt of "jackd -dfirewire -p2048 -n4 -v3" worked for half an hour without problem. A few minutes into this session I started ntpd and forced realtime clock reset by means of ntp-client and "date -s ...", which did not disturb the session as expected. - I stopped this good session and then tried "jackd -dfirewire -r44100 -p2048 -n4 -v3". This went fine for about 10 minutes, then suddenly the series of "negative step"s showed up and jackd died. After this, I was unable to restart jackd, no matter what parameters I tried. Tested with Saffire PRO 24 on Agere FW643e which I also used yesterday, among other combinations. -- Ticket URL: <http://subversion.ffado.org/index.fcgi/ticket/242#comment:37> FFADO <http://subversion.ffado.org/index.fcgi> Free Firewire Audio Drivers |
From: FFADO <ffa...@ff...> - 2012-06-27 22:02:55
|
#242: ntp interferes with ffado ------------------------+--------------------------------------------------- Reporter: ppalmers | Owner: ppalmers Type: bug | Status: new Priority: major | Milestone: FFADO 2.x Component: | Version: FFADO 2.0-rc2 (1.999.42) Resolution: | Keywords: Device_name: all | ------------------------+--------------------------------------------------- Comment (by stefanr): Re clock_monotonic.patch: The syntax highlighting viewer is broken, it misses a hunk in src/libutil/SystemTimeSource.cpp. Please view the patch in "[http://subversion.ffado.org/attachment/ticket/242/clock_monotonic.patch?format=raw original format]". Replying to [comment:37 stefanr]: > Tested a few things again on my "bad" PC and noticed: > - "jackd -dfirewire -p256 -n3 -v3" failed as before. > - Surprisingly, one atttempt of "jackd -dfirewire -p2048 -n4 -v3" worked for half an hour without problem. A few minutes into this session I started ntpd and forced realtime clock reset by means of ntp-client and "date -s ...", which did not disturb the session as expected. Actually, this first bad session and second good session was with clock_monotonic.patch applied on top of r2174. I reverted that patch, then ran the following session which lasted only 10 minutes and could not be recovered: > - I stopped this good session and then tried "jackd -dfirewire -r44100 -p2048 -n4 -v3". This went fine for about 10 minutes, then suddenly the series of "negative step"s showed up and jackd died. After this, I was unable to restart jackd, no matter what parameters I tried. After this, I applied clock_monotonic.patch again and "jackd -dfirewire -p2048 -n3 -v3" worked again immediately and ran nicely for another hour. So at the moment it looks like my bad PC and r2174 really do not cope well with the mixture of CLOCK_MONOTONIC_RAW and CLOCK_MONOTONIC, whereas using CLOCK_MONOTONIC alone seems to work (with large buffers). Note that CLOCK_MONOTONIC is indeed supposed to be sufficient: The gradual clock shifts which ntpd induced never were a problem on my two PCs (and anybody else's I presume), only clock resets are the issue. Now on to tackle the problem with small buffers. -- Ticket URL: <http://subversion.ffado.org/ticket/242#comment:38> FFADO <http://subversion.ffado.org/index.fcgi> Free Firewire Audio Drivers |
From: FFADO <ffa...@ff...> - 2012-06-27 22:14:30
|
#242: ntp interferes with ffado ------------------------+--------------------------------------------------- Reporter: ppalmers | Owner: ppalmers Type: bug | Status: new Priority: major | Milestone: FFADO 2.x Component: | Version: FFADO 2.0-rc2 (1.999.42) Resolution: | Keywords: Device_name: all | ------------------------+--------------------------------------------------- Comment (by stefanr): On kernel-version-recommendation.patch: The firewire-core/-ohci drivers of kernel 2.6.28 don't actually work for FFADO. Version 2.6.32 was the very first that worked; kernel 2.6.36 had several issues fixed that affected some audio related use cases. (And raw1394 of the old linux1394 stack never gained a request which lets clients choose a clock other than CLOCK_REALTIME.) -- Ticket URL: <http://subversion.ffado.org/ticket/242#comment:39> FFADO <http://subversion.ffado.org/index.fcgi> Free Firewire Audio Drivers |
From: FFADO <ffa...@ff...> - 2012-06-28 14:19:34
|
#242: ntp interferes with ffado ------------------------+--------------------------------------------------- Reporter: ppalmers | Owner: ppalmers Type: bug | Status: new Priority: major | Milestone: FFADO 2.x Component: | Version: FFADO 2.0-rc2 (1.999.42) Resolution: | Keywords: Device_name: all | ------------------------+--------------------------------------------------- Comment (by jwoithe): Replying to [comment:36 stefanr]: > Is this perhaps a startup race? (Something uses SystemTimeSource::clock_id before it was initialized? I thought of this possiblity, but as far as I can see none of the streaming code can possibly be started before SystemTimeSource::clock_id is initialised by Ieee1394Service::initialize(). If anything earlier did happen to use SystemTimeSource::clock_id earlier it would use CLOCK_REALTIME (that's what clock_id is set to on startup), but since none of those times could propagate into the streaming system it would be irrelevant if it did. While this is my present understanding, I could well be wrong. -- Ticket URL: <http://subversion.ffado.org/ticket/242#comment:40> FFADO <http://subversion.ffado.org/index.fcgi> Free Firewire Audio Drivers |
From: FFADO <ffa...@ff...> - 2012-06-28 14:23:28
|
#242: ntp interferes with ffado ------------------------+--------------------------------------------------- Reporter: ppalmers | Owner: ppalmers Type: bug | Status: new Priority: major | Milestone: FFADO 2.x Component: | Version: FFADO 2.0-rc2 (1.999.42) Resolution: | Keywords: Device_name: all | ------------------------+--------------------------------------------------- Comment (by jwoithe): Regarding clock_monotonic.patch, your findings are interesting. I tried precisely this approach at one point and observed the same problematic behaviour as when CLOCK_MONOTONIC_RAW was used. I therefore discounted the use of CLOCK_MONOTONIC as a fix because my testing seemed to indicate that it didn't fix the problem. However, given that it seems to work for you I will re-test after forcing the use of CLOCK_MONOTONIC to make sure the result I observed wasn't due to some other issue at the time. -- Ticket URL: <http://subversion.ffado.org/ticket/242#comment:41> FFADO <http://subversion.ffado.org/index.fcgi> Free Firewire Audio Drivers |
From: FFADO <ffa...@ff...> - 2012-06-28 14:30:51
|
#242: ntp interferes with ffado ------------------------+--------------------------------------------------- Reporter: ppalmers | Owner: ppalmers Type: bug | Status: new Priority: major | Milestone: FFADO 2.x Component: | Version: FFADO 2.0-rc2 (1.999.42) Resolution: | Keywords: Device_name: all | ------------------------+--------------------------------------------------- Comment (by jwoithe): Replying to [comment:38 stefanr]: > Note that CLOCK_MONOTONIC is indeed supposed to be sufficient: The gradual clock shifts which ntpd induced never were a problem on my two PCs (and anybody else's I presume), only clock resets are the issue. Hmm, ok. I was concerned that the time slews also created issues. > Now on to tackle the problem with small buffers. I think this is related to the use of CLOCK_MONOTONIC (or CLOCK_MONOTONIC_RAW). In [comment:41 comment 41] I mentioned that CLOCK_MONOTONIC was broken for me; on reflection I think this was probably tested with small buffers (-p256 -n3). However, if CLOCK_REALTIME was forced then "-p256 -n3" worked perfectly - this suggests to me that it's not the small buffer sizes which are the problem. So even if CLOCK_MONOTONIC works for large buffer sizes, it still seems to be the cause of some underlying problem. That problem, it seems, is papered over by the use of large buffer sizes, but is almost certainly still lurking under the surface even then. In light of these things I will re-test all this on my setup so we can be definite about what's going on. It may be a few days before I get a chance to do so though since I'm busy for a couple of days with other things. -- Ticket URL: <http://subversion.ffado.org/ticket/242#comment:42> FFADO <http://subversion.ffado.org/index.fcgi> Free Firewire Audio Drivers |
From: FFADO <ffa...@ff...> - 2012-06-28 14:36:34
|
#242: ntp interferes with ffado ------------------------+--------------------------------------------------- Reporter: ppalmers | Owner: ppalmers Type: bug | Status: new Priority: major | Milestone: FFADO 2.x Component: | Version: FFADO 2.0-rc2 (1.999.42) Resolution: | Keywords: Device_name: all | ------------------------+--------------------------------------------------- Comment (by jwoithe): Replying to [comment:39 stefanr]: regarding kernel-version- recommendation.patch: that makes sense to me. Applied as r2175. Thanks for the background info and the patch. -- Ticket URL: <http://subversion.ffado.org/ticket/242#comment:43> FFADO <http://subversion.ffado.org/index.fcgi> Free Firewire Audio Drivers |
From: FFADO <ffa...@ff...> - 2012-06-28 21:27:40
|
#242: ntp interferes with ffado ------------------------+--------------------------------------------------- Reporter: ppalmers | Owner: ppalmers Type: bug | Status: new Priority: major | Milestone: FFADO 2.x Component: | Version: FFADO 2.0-rc2 (1.999.42) Resolution: | Keywords: Device_name: all | ------------------------+--------------------------------------------------- Comment (by stefanr): The -p2048 -n3 session which I started yesterday with r2174 + [attachment:clock_monotonic.patch?format=raw clock_monotonic.patch] on my bad PC is still running --- now for 24 hours, with ntpd doing its thing. During this session, just one recoverable xrun occurred when I ran "emerge-webrsync" on my root filesystem which is a reiserfs filesystem for historical reasons. -- Ticket URL: <http://subversion.ffado.org/ticket/242#comment:44> FFADO <http://subversion.ffado.org/index.fcgi> Free Firewire Audio Drivers |
From: FFADO <ffa...@ff...> - 2012-06-28 21:57:43
|
#242: ntp interferes with ffado ------------------------+--------------------------------------------------- Reporter: ppalmers | Owner: ppalmers Type: bug | Status: new Priority: major | Milestone: FFADO 2.x Component: | Version: FFADO 2.0-rc2 (1.999.42) Resolution: | Keywords: Device_name: all | ------------------------+--------------------------------------------------- Comment (by stefanr): For what it's worth, I applied this hack on top of r2175 + clock_monotonic.patch: {{{ --- a/src/libutil/SystemTimeSource.cpp +++ b/src/libutil/SystemTimeSource.cpp @@ -38,7 +38,7 @@ DECLARE_GLOBAL_DEBUG_MODULE; namespace Util { -static clockid_t clock_id = CLOCK_REALTIME; +static clockid_t clock_id = CLOCK_MONOTONIC; bool SystemTimeSource::setSource(clockid_t id) }}} With this, "jackd -dfirewire -p256 -n3 -v3" still fails to start. Similar to or same as before, lots of "reconstructed CTR counter discrepancy" warnings and "Execute: Timeout while waiting for activity" precede the ending in "Could not align streams..." ... "Could not syncStartAll..." ... "Could not start the streaming system" ... "cannot start driver". -- Ticket URL: <http://subversion.ffado.org/ticket/242#comment:45> FFADO <http://subversion.ffado.org/index.fcgi> Free Firewire Audio Drivers |
From: FFADO <ffa...@ff...> - 2012-06-28 23:29:05
|
#242: ntp interferes with ffado ------------------------+--------------------------------------------------- Reporter: ppalmers | Owner: ppalmers Type: bug | Status: new Priority: major | Milestone: FFADO 2.x Component: | Version: FFADO 2.0-rc2 (1.999.42) Resolution: | Keywords: Device_name: all | ------------------------+--------------------------------------------------- Comment (by stefanr): Some more data: The "reconstructed CTR counter discrepancy" came from IsoHandlerManager.cpp line 1657 in getPacket, not from line 1568 in put_packet. Back on r2175 + clock_monotonic.patch. I noticed that the threshold of successful startup for my 1st PC + Saffire PRO 24 + Agere controller is around -p256 -n4. - "jackd -dfirewire -p256 -n3 -v3" = throws lots of "reconstructed CTR counter discrepancy" and "Execute: Timeout while waiting for activity", then dies soon. - "jackd -dfirewire -p256 -n4 -v3" = starts and client applications can connect to jackd, but ffado throws a loop of "Execute: Timeout while waiting for activity", audio playback may or may not be heard, - "jackd -dfirewire -p256 -n5 -v3" = good, - "jackd -dfirewire -p512 -n3 -v3" = good, (good meaning it does start normally and keeps running for 15 minutes or longer without warnings after start and without perceivable glitches). ---- Questions: - Is there any exchange of timestamps going on between ffado and upper jack layers or client processes? - Do the nanosleep() and gettimeofday() calls in debugmodule or the usleep() calls in libieee1394 and elsewhere matter? - Could there be some arithmetic going on somehwere in FFADO which relies on absolute system timestamps being a few decades greater than 0, rather than just some weeks or hours? - Is it that smaller buffers cause FFADO to call clock_nanosleep() for briefer sleeping periods which happen to work with CLOCK_REALTIME but not with CLOCK_MONOTONIC? (Would be counter intuitive; and clock_getres() advertizes 1 ns precision for CLOCK_REALTIME, CLOCK_MONOTONIC, and CLOCK_MONOTONIC_RAW on my PC.) - Could it be that CLOCK_REALTIME is synchronous on all CPUs but CLOCK_MONOTONIC and CLOCK_MONOTONIC_RAW differ between CPUs (cf. man clock_getres), and FFADO gets confused by that when being moved from CPU to CPU? -- Ticket URL: <http://subversion.ffado.org/ticket/242#comment:46> FFADO <http://subversion.ffado.org/index.fcgi> Free Firewire Audio Drivers |
From: FFADO <ffa...@ff...> - 2012-06-29 00:00:34
|
#242: ntp interferes with ffado ------------------------+--------------------------------------------------- Reporter: ppalmers | Owner: ppalmers Type: bug | Status: new Priority: major | Milestone: FFADO 2.x Component: | Version: FFADO 2.0-rc2 (1.999.42) Resolution: | Keywords: Device_name: all | ------------------------+--------------------------------------------------- Comment (by stefanr): Replying to [comment:46 stefanr]: > - Could it be that CLOCK_REALTIME is synchronous on all CPUs but CLOCK_MONOTONIC and CLOCK_MONOTONIC_RAW differ between CPUs (cf. man clock_getres), and FFADO gets confused by that when being moved from CPU to CPU? Note to self: Determine the threshold between "doesn't-start" and "starts" on the 2nd PC. Reboot and test again to see whether the threshold shifted notably. Reboot again but with "nosmp" kernel parameter and retest smaller buffer settings. -- Ticket URL: <http://subversion.ffado.org/ticket/242#comment:47> FFADO <http://subversion.ffado.org/index.fcgi> Free Firewire Audio Drivers |
From: FFADO <ffa...@ff...> - 2012-06-29 00:49:06
|
#242: ntp interferes with ffado ------------------------+--------------------------------------------------- Reporter: ppalmers | Owner: ppalmers Type: bug | Status: new Priority: major | Milestone: FFADO 2.x Component: | Version: FFADO 2.0-rc2 (1.999.42) Resolution: | Keywords: Device_name: all | ------------------------+--------------------------------------------------- Comment (by jwoithe): Replying to [comment:45 stefanr]: > For what it's worth, I applied this hack on top of r2175 + clock_monotonic.patch: ... > With this, "jackd -dfirewire -p256 -n3 -v3" still fails to start. Similar to or same as before ... I'm not surprised. In reality the value this is initialised to will only ever be used if the new libraw1394 API is not detected. If the new API is present then SystemTimeSource::setSource(CLOCK_MONOTONIC_RAW) will be called before any other SystemTimeSource calls are made (assuming my earlier analysis is correct regarding calling order). Therefore on your system - which has the new API - there will be no runtime difference when you made this change; by the time any SystemTimeSource timer functions are called clock_id will be CLOCK_MONOTONIC_RAW (or CLOCK_MONOTONIC if you've forced it to this in ieee1394service). In other words, with the new libraw1394 API present the value of clock_id at the time SystemTimeSource is used to get time values (or instigate sleeps) will be that which is set via SystemTimeSource::setSource() as called from ieee1394service. If you want to override the actual clock used, the best way is to simply add a SystemTimeSource::setSource() call of your choosing to the ieee1394service initialization method to override the setting made by the code that's already there. -- Ticket URL: <http://subversion.ffado.org/ticket/242#comment:48> FFADO <http://subversion.ffado.org/index.fcgi> Free Firewire Audio Drivers |
From: FFADO <ffa...@ff...> - 2012-06-29 01:03:56
|
#242: ntp interferes with ffado ------------------------+--------------------------------------------------- Reporter: ppalmers | Owner: ppalmers Type: bug | Status: new Priority: major | Milestone: FFADO 2.x Component: | Version: FFADO 2.0-rc2 (1.999.42) Resolution: | Keywords: Device_name: all | ------------------------+--------------------------------------------------- Comment (by jwoithe): Replying to [comment:46 stefanr]: > - Is there any exchange of timestamps going on between ffado and upper jack layers or client processes? No. The generated timestamps are only used internally by the streaming layer within FFADO itself. > - Do the nanosleep() and gettimeofday() calls in debugmodule or the usleep() calls in libieee1394 and elsewhere matter? I don't think so. Those in debugmodule seem to exist only to induce delays in the processing of the debug messages. Since this is entirely isolated within the debugmodule it really doesn't matter if the actual sleep time varies slightly from what's requested or what timer is used to measure the sleep. THe usleep() calls are similar in that they are acting outside of the streaming system: either during device setup, configuration or control. The streaming layer doesn't see any of this so their presence is irrelevant as far as I can tell. > - Could there be some arithmetic going on somehwere in FFADO which relies on absolute system timestamps being a few decades greater than 0, rather than just some weeks or hours? I don't know but I suspect not. I can't think of a case where this would be significant. When dealing with timestamps the only arithmetic issue I can think of is overflow, but this is the opposite scenario to what we're dealing with (that is, if overflow were a problem it would be worse for larger timestamp values). > - Is it that smaller buffers cause FFADO to call clock_nanosleep() for briefer sleeping periods which happen to work with CLOCK_REALTIME but not with CLOCK_MONOTONIC? (Would be counter intuitive; and clock_getres() advertizes 1 ns precision for CLOCK_REALTIME, CLOCK_MONOTONIC, and CLOCK_MONOTONIC_RAW on my PC.) It's certainly possible that smaller buffer sizes are causing certain clock_nanosleep() calls to be briefer. I agree that it's counter- intuitive that this would work for CLOCK_REALTIME and not the others, especially since the resolutions are all reported identically. However, perhaps it's worth exploring this, if for no other reason than to definitely rule it out. > - Could it be that CLOCK_REALTIME is synchronous on all CPUs but CLOCK_MONOTONIC and CLOCK_MONOTONIC_RAW differ between CPUs (cf. man clock_getres), and FFADO gets confused by that when being moved from CPU to CPU? That's also a good point. This is getting into the lower level detail of the clock implementations which I'm not familar with: I'll have to do some reading. If CLOCK_MONOTONIC and CLOCK_MONOTONIC_RAW are not synchronous across CPUs then that would certainly give trouble if FFADO was migrated. How often would migration occur though? We're seeing the problem occcur pretty much immediately and continuously; if caused by migration there's a lot of migration going on. Of course different FFADO threads could be running on different CPUs. However, I don't think the issues we're seeing are associated with timestamps which are passed between the streaming threads. I'll take a look at this though since it's worth checking. -- Ticket URL: <http://subversion.ffado.org/ticket/242#comment:49> FFADO <http://subversion.ffado.org/index.fcgi> Free Firewire Audio Drivers |