Ticket #384 (closed bug: wontfix)

Opened 6 years ago

Last modified 6 years ago

ffado-mixer (2.2.1) crashes/freezes when starting DAW Ardour

Reported by: wsl Assigned to: arnonym
Priority: major Milestone:
Component: ffado-mixer Version: FFADO 2.2.1
Keywords: Cc:
The device the bug applies to: Focusrite Saffire PRO 24

Description

The problem is that ffado-mixer (2.2.1) crashes/freezes when starting the DAW Ardour - the contents of the ffado-mixer window disappear and all that is left is the frame. The window cannot be closed, nor is a a PID shown for ffado-mixer when running the command line ps -A in a terminal. killall -9 ffado-mixer returns that this program does not exist. Re-starting ffado-mixer fails with the error message that an instance of ffado-mixer already exists.

The steps I took leading up to the crash (which is 100% repeatable) are:

- Before booting the laptop, attach a Focusrite Saffire PRO 24 to the 1394 connection on the laptop

- Switch on the Focusrite Saffire PRO 24 and wait for the green power LED to light

- Boot the Laptop (KXStudio 14.04b + latest updates)

- When the desktop shows start ffado-mixer, visually check that Crossbar Routing is as needed

- In Cadence start jackd using the FireWire? driver (ffado-mixer is still working at this stage and adjustments can be made in the monitoring section)

- Now start Ardour, select a new project and click on open - ffado-mixer crashes

Attachments

terminal output - ffado-mixer.txt (17.7 kB) - added by wsl on 01/07/15 00:39:10.
terniminal output of ffado mixer crash
test 1 - terminal output.txt (16.9 kB) - added by wsl on 01/07/15 07:50:37.
Test 1 - Terminal outputs for ffado-dbus-serv, ffado-mixer, cadence and ardour
201501081152_debug.log (253.6 kB) - added by wsl on 01/08/15 02:56:05.
Here the debug log from jackd - jack main caught signal 12
201501081305_debug.log (244.8 kB) - added by wsl on 01/08/15 04:13:04.
jackd debug log with higher priority and rtirq service running.
201501081306_ffado-diag.log (6.2 kB) - added by wsl on 01/08/15 04:13:47.
ffado-diag
201501111004_firewire-ohci_syslog.log (30.8 kB) - added by wsl on 01/11/15 01:07:00.
Details of firwire card
201501111627_debug.log (264.7 kB) - added by wsl on 01/11/15 07:44:54.
jackd messages (with networking disabled)
201501171205_debug_beg-end_only.log (282.5 kB) - added by wsl on 01/17/15 03:34:41.
Latest debug after configuration with rtctl
201501181611_debug_beg-end.log (114.7 kB) - added by wsl on 01/18/15 07:30:13.
debug log with default settings, i.e. without rtirq or rtctl disabled
201501191713_debug_full.log (0.8 MB) - added by wsl on 01/19/15 08:23:21.
jackd debug log without ffado-dbus-serv and ffado-mixer

Change History

01/06/15 14:50:33 changed by jwoithe

This sounds really strange, especially since the streaming component (which ardour uses) operates more or less independently of ffado-mixer (and its associated ffado-dbus-server process). Phil: any ideas? Can you reproduce it?

To the original reporter, could you provide any messages produced by ffado-mixer at the time of the crash? You may have to run ffado-mixer from a terminal window in order to see these.

I don't think this is a generic problem since I have carried out the same sequence of actions for other interfaces on a regular basis and have not seen ffado-mixer crash. However, anything's possible at this point.

01/07/15 00:35:37 changed by wsl

Here is the terminal output from ffado-mixer:

simon@simon-Precision-M4300:~$ ffado-mixer


FFADO Control DBUS service Part of the FFADO project -- www.ffado.org Version: 2.2.1- (C) 2008, Pieter Palmers This program comes with ABSOLUTELY NO WARRANTY.


1420618058606872: (ffado-dbus-server.cpp)[ 270] main: Discovering devices... 00171613353: (dice_avdevice.cpp)[ 706] showDevice: DICE Parameter Space info: 00171613443: (dice_avdevice.cpp)[ 707] showDevice: Global : offset=0x0028 size=0360 00171613481: (dice_avdevice.cpp)[ 708] showDevice: TX : offset=0x0190 size=0568 00171613526: (dice_avdevice.cpp)[ 709] showDevice: nb= 1 size=0280 00171613562: (dice_avdevice.cpp)[ 710] showDevice: RX : offset=0x03C8 size=1128 00171613605: (dice_avdevice.cpp)[ 711] showDevice: nb= 1 size=0280 00171613637: (dice_avdevice.cpp)[ 712] showDevice: UNUSED1 : offset=0x0830 size=0016 00171613678: (dice_avdevice.cpp)[ 713] showDevice: UNUSED2 : offset=0x0000 size=0000 00171613710: (dice_avdevice.cpp)[ 715] showDevice: Global param space: 00171614990: (dice_avdevice.cpp)[ 718] showDevice: Owner : 0x00000000FFFF0000 00171616356: (dice_avdevice.cpp)[ 721] showDevice: Notification : 0x00000040 00171620215: (dice_avdevice.cpp)[ 724] showDevice: Nick name : Pro24-007336 00171621822: (dice_avdevice.cpp)[ 728] showDevice: Clock Select : 0x02 0x0C 00171623212: (dice_avdevice.cpp)[ 732] showDevice: Enable : false 00171624838: (dice_avdevice.cpp)[ 736] showDevice: Clock Status : locked 0x02 00171626255: (dice_avdevice.cpp)[ 739] showDevice: Extended Status : 0x00000000 00171627807: (dice_avdevice.cpp)[ 742] showDevice: Samplerate : 0x0000BB80 (48000) 00171629679: (dice_avdevice.cpp)[ 745] showDevice: Version : 0x01000400 00171631074: (dice_avdevice.cpp)[ 754] showDevice: Version : 0x01000400 (1.0.4.0) 00171632707: (dice_avdevice.cpp)[ 757] showDevice: Clock caps : 0x112C001E 00171634345: (dice_avdevice.cpp)[ 760] showDevice: Clock sources : 00171634430: (dice_avdevice.cpp)[ 766] showDevice: AES1 00171634463: (dice_avdevice.cpp)[ 766] showDevice: AES2 00171634504: (dice_avdevice.cpp)[ 766] showDevice: SPDIF-OPT 00171634532: (dice_avdevice.cpp)[ 766] showDevice: SPDIF 00171634568: (dice_avdevice.cpp)[ 766] showDevice: AES_ANY 00171634597: (dice_avdevice.cpp)[ 766] showDevice: ADAT 00171634638: (dice_avdevice.cpp)[ 766] showDevice: ADAT_AUX 00171634665: (dice_avdevice.cpp)[ 766] showDevice: Word Clock 00171634703: (dice_avdevice.cpp)[ 766] showDevice: Unused 00171634731: (dice_avdevice.cpp)[ 766] showDevice: Unused 00171634797: (dice_avdevice.cpp)[ 766] showDevice: Unused 00171634820: (dice_avdevice.cpp)[ 766] showDevice: Unused 00171634847: (dice_avdevice.cpp)[ 766] showDevice: Internal 00171634868: (dice_avdevice.cpp)[ 769] showDevice: TX param space: 00171634895: (dice_avdevice.cpp)[ 770] showDevice: Nb of xmit : 1 00171634916: (dice_avdevice.cpp)[ 772] showDevice: Transmitter 0: 00171636176: (dice_avdevice.cpp)[ 775] showDevice: ISO channel : -1 00171637824: (dice_avdevice.cpp)[ 777] showDevice: ISO speed : 2 00171640113: (dice_avdevice.cpp)[ 780] showDevice: Nb audio channels : 16 00171641725: (dice_avdevice.cpp)[ 782] showDevice: Nb midi channels : 1 00171643060: (dice_avdevice.cpp)[ 785] showDevice: AC3 caps : 0x00000000 00171644765: (dice_avdevice.cpp)[ 787] showDevice: AC3 enable : 0x00000000 00171646383: (dice_avdevice.cpp)[ 790] showDevice: Channel names : 00171646395: (dice_avdevice.cpp)[ 795] showDevice: IP 1 00171646407: (dice_avdevice.cpp)[ 795] showDevice: IP 2 00171646412: (dice_avdevice.cpp)[ 795] showDevice: IP 3 00171646420: (dice_avdevice.cpp)[ 795] showDevice: IP 4 00171646424: (dice_avdevice.cpp)[ 795] showDevice: SPDIF L 00171646430: (dice_avdevice.cpp)[ 795] showDevice: SPDIF R 00171646434: (dice_avdevice.cpp)[ 795] showDevice: ADAT 1 00171646440: (dice_avdevice.cpp)[ 795] showDevice: ADAT 2 00171646444: (dice_avdevice.cpp)[ 795] showDevice: ADAT 3 00171646451: (dice_avdevice.cpp)[ 795] showDevice: ADAT 4 00171646454: (dice_avdevice.cpp)[ 795] showDevice: ADAT 5 00171646461: (dice_avdevice.cpp)[ 795] showDevice: ADAT 6 00171646464: (dice_avdevice.cpp)[ 795] showDevice: ADAT 7 00171646475: (dice_avdevice.cpp)[ 795] showDevice: ADAT 8 00171646479: (dice_avdevice.cpp)[ 795] showDevice: Loop 1 00171646486: (dice_avdevice.cpp)[ 795] showDevice: Loop 2 00171646493: (dice_avdevice.cpp)[ 799] showDevice: RX param space: 00171646502: (dice_avdevice.cpp)[ 800] showDevice: Nb of recv : 1 00171646506: (dice_avdevice.cpp)[ 802] showDevice: Receiver 0: 00171647971: (dice_avdevice.cpp)[ 805] showDevice: ISO channel : 1 00171649819: (dice_avdevice.cpp)[ 807] showDevice: Sequence start : 0 00171651148: (dice_avdevice.cpp)[ 810] showDevice: Nb audio channels : 8 00171652760: (dice_avdevice.cpp)[ 812] showDevice: Nb midi channels : 1 00171654128: (dice_avdevice.cpp)[ 815] showDevice: AC3 caps : 0x00000000 00171655746: (dice_avdevice.cpp)[ 817] showDevice: AC3 enable : 0x00000000 00171657316: (dice_avdevice.cpp)[ 820] showDevice: Channel names : 00171657345: (dice_avdevice.cpp)[ 825] showDevice: Mon 1 00171657374: (dice_avdevice.cpp)[ 825] showDevice: Mon 2 00171657395: (dice_avdevice.cpp)[ 825] showDevice: Line 3 00171657421: (dice_avdevice.cpp)[ 825] showDevice: Line 4 00171657441: (dice_avdevice.cpp)[ 825] showDevice: Line 5 00171657467: (dice_avdevice.cpp)[ 825] showDevice: Line 6 00171657488: (dice_avdevice.cpp)[ 825] showDevice: SPDIF L 00171657513: (dice_avdevice.cpp)[ 825] showDevice: SPDIF R 00171667395: (ffado-dbus-server.cpp)[ 329] main: DBUS service running 00171667411: (ffado-dbus-server.cpp)[ 330] main: press ctrl-c to stop it & exit 00171667414: Debug (ffado-dbus-server.cpp)[ 333] main: dispatching... 09:16:16 panelmanager ERROR error in pollPanels 09:16:41 panelmanager ERROR The communication with ffado-dbus-server was lost. CrossbarRouter?.del() 09:17:06 dbus.proxies ERROR Introspect error on :1.66:/org/ffado/Control/DeviceManager: dbus.exceptions.DBusException: org.freedesktop.DBus.Error.NoReply?: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken. Traceback (most recent call last):

File "/usr/share/ffado-mixer-qt4/ffado/panelmanager.py", line 372, in updatePanels

nbDevices = self.devmgr.getNbDevices()

File "/usr/share/ffado-mixer-qt4/ffado/dbus_util.py", line 271, in getNbDevices

return self.iface.getNbElements()

File "/usr/lib/python2.7/dist-packages/dbus/proxies.py", line 70, in call

return self._proxy_method(*args, **keywords)

File "/usr/lib/python2.7/dist-packages/dbus/proxies.py", line 145, in call

**keywords)

File "/usr/lib/python2.7/dist-packages/dbus/connection.py", line 651, in call_blocking

message, timeout)

dbus.exceptions.DBusException: org.freedesktop.DBus.Error.NoReply?: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken. 09:17:56 panelmanager ERROR The communication with ffado-dbus-server was lost. 09:18:21 dbus.proxies ERROR Introspect error on :1.66:/org/ffado/Control/DeviceManager: dbus.exceptions.DBusException: org.freedesktop.DBus.Error.NoReply?: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken. Traceback (most recent call last):

File "/usr/share/ffado-mixer-qt4/ffado/panelmanager.py", line 372, in updatePanels

nbDevices = self.devmgr.getNbDevices()

File "/usr/share/ffado-mixer-qt4/ffado/dbus_util.py", line 271, in getNbDevices

return self.iface.getNbElements()

File "/usr/lib/python2.7/dist-packages/dbus/proxies.py", line 70, in call

return self._proxy_method(*args, **keywords)

File "/usr/lib/python2.7/dist-packages/dbus/proxies.py", line 145, in call

**keywords)

File "/usr/lib/python2.7/dist-packages/dbus/connection.py", line 651, in call_blocking

message, timeout)

dbus.exceptions.DBusException: org.freedesktop.DBus.Error.NoReply?: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken. 09:19:11 panelmanager ERROR The communication with ffado-dbus-server was lost.

01/07/15 00:39:10 changed by wsl

  • attachment terminal output - ffado-mixer.txt added.

terniminal output of ffado mixer crash

01/07/15 04:11:27 changed by jwoithe

Thanks for this output. It shows that the dbus connection to the ffado-dbus-server (which is the component responsible for communicating with the Saffire when controlling the onboard mixer) has failed. The most likely cause would be ffado-dbus-server crashing.

Ffado-mixer will start ffado-dbus-server automatically if it's not already running, but it's possible to manually start it yourself in a terminal. Doing this may provide some clues as to why it's apparently crashing. Could you therefore repeat the test, but before starting ffado-mixer, in another terminal, run ffado-dbus-server first? Please post the terminal output produced by ffado-dbus-server at the time of the crash.

Another interesting test would be to see if ffado-dbus-server crashes without ffado-mixer running. To test this, start only ffado-dbus-server prior to the other audio programs and see what happens.

01/07/15 07:48:38 changed by wsl

Test 1 - start ffado-dbus-serv before ffado-mixer before cadence before ardour

Note: ffado-mixer crashed when assigning channel inputs and outputs in ardour's tracks and busses dialog.

Terminal output for ffado-dbus-serv:

simon@simon-Precision-M4300:~$ ffado-dbus-server


FFADO Control DBUS service Part of the FFADO project -- www.ffado.org Version: 2.2.1- (C) 2008, Pieter Palmers This program comes with ABSOLUTELY NO WARRANTY.


1420644082652988: (ffado-dbus-server.cpp)[ 270] main: Discovering devices... 00178540065: Debug (devicemanager.cpp)[ 354] discover: Starting discovery... 00178628105: Debug (Configuration.cpp)[ 163] showSetting: Group: (null) 00178628169: Debug (Configuration.cpp)[ 185] showSetting: vendorid = 4878 (0x0000130E) 00178628190: Debug (Configuration.cpp)[ 185] showSetting: modelid = 7 (0x00000007) 00178628205: Debug (Configuration.cpp)[ 209] showSetting: vendorname = Focusrite 00178628220: Debug (Configuration.cpp)[ 209] showSetting: modelname = Saffire PRO 24 00178628228: Debug (Configuration.cpp)[ 209] showSetting: driver = DICE 00178628242: Debug (Configuration.cpp)[ 209] showSetting: mixer = Saffire_Dice 00178643227: Debug (Configuration.cpp)[ 163] showSetting: Group: (null) 00178643253: Debug (Configuration.cpp)[ 185] showSetting: vendorid = 4878 (0x0000130E) 00178643266: Debug (Configuration.cpp)[ 185] showSetting: modelid = 7 (0x00000007) 00178643274: Debug (Configuration.cpp)[ 209] showSetting: vendorname = Focusrite 00178643277: Debug (Configuration.cpp)[ 209] showSetting: modelname = Saffire PRO 24 00178643283: Debug (Configuration.cpp)[ 209] showSetting: driver = DICE 00178643286: Debug (Configuration.cpp)[ 209] showSetting: mixer = Saffire_Dice 00178644054: Debug (Configuration.cpp)[ 163] showSetting: Group: (null) 00178644060: Debug (Configuration.cpp)[ 185] showSetting: vendorid = 4878 (0x0000130E) 00178644075: Debug (Configuration.cpp)[ 185] showSetting: modelid = 7 (0x00000007) 00178644079: Debug (Configuration.cpp)[ 209] showSetting: vendorname = Focusrite 00178644085: Debug (Configuration.cpp)[ 209] showSetting: modelname = Saffire PRO 24 00178644088: Debug (Configuration.cpp)[ 209] showSetting: driver = DICE 00178644093: Debug (Configuration.cpp)[ 209] showSetting: mixer = Saffire_Dice 00178644160: Debug (Configuration.cpp)[ 163] showSetting: Group: (null) 00178644169: Debug (Configuration.cpp)[ 185] showSetting: vendorid = 4878 (0x0000130E) 00178644173: Debug (Configuration.cpp)[ 185] showSetting: modelid = 7 (0x00000007) 00178644179: Debug (Configuration.cpp)[ 209] showSetting: vendorname = Focusrite 00178644182: Debug (Configuration.cpp)[ 209] showSetting: modelname = Saffire PRO 24 00178644188: Debug (Configuration.cpp)[ 209] showSetting: driver = DICE 00178644191: Debug (Configuration.cpp)[ 209] showSetting: mixer = Saffire_Dice 00178645039: Debug (Configuration.cpp)[ 163] showSetting: Group: (null) 00178645045: Debug (Configuration.cpp)[ 185] showSetting: vendorid = 4878 (0x0000130E) 00178645060: Debug (Configuration.cpp)[ 185] showSetting: modelid = 7 (0x00000007) 00178645064: Debug (Configuration.cpp)[ 209] showSetting: vendorname = Focusrite 00178645069: Debug (Configuration.cpp)[ 209] showSetting: modelname = Saffire PRO 24 00178645073: Debug (Configuration.cpp)[ 209] showSetting: driver = DICE 00178645078: Debug (Configuration.cpp)[ 209] showSetting: mixer = Saffire_Dice 00178645896: Debug (devicemanager.cpp)[ 616] discover: driver found for device 0 00178645961: Debug (Configuration.cpp)[ 163] showSetting: Group: (null) 00178645967: Debug (Configuration.cpp)[ 185] showSetting: vendorid = 4878 (0x0000130E) 00178645973: Debug (Configuration.cpp)[ 185] showSetting: modelid = 7 (0x00000007) 00178645977: Debug (Configuration.cpp)[ 209] showSetting: vendorname = Focusrite 00178645984: Debug (Configuration.cpp)[ 209] showSetting: modelname = Saffire PRO 24 00178645988: Debug (Configuration.cpp)[ 209] showSetting: driver = DICE 00178645993: Debug (Configuration.cpp)[ 209] showSetting: mixer = Saffire_Dice 00178746802: Debug (devicemanager.cpp)[ 653] discover: discovery of node 0 on port 0 done... 00178746893: Debug (devicemanager.cpp)[ 661] discover: Discovery finished... 00178746925: Debug (devicemanager.cpp)[1258] showDeviceInfo: ===== Device Manager ===== 00178746958: Debug (Element.cpp)[ 121] show: Element DeviceManager? 00178746981: Debug (devicemanager.cpp)[1266] showDeviceInfo: --- IEEE1394 Service 0 --- 00178747080: Debug (devicemanager.cpp)[1276] showDeviceInfo: --- Device 0 --- 00178747111: Debug (dice_avdevice.cpp)[ 703] showDevice: Device is a DICE device 00178747143: (dice_avdevice.cpp)[ 706] showDevice: DICE Parameter Space info: 00178747168: (dice_avdevice.cpp)[ 707] showDevice: Global : offset=0x0028 size=0360 00178747187: (dice_avdevice.cpp)[ 708] showDevice: TX : offset=0x0190 size=0568 00178747201: (dice_avdevice.cpp)[ 709] showDevice: nb= 1 size=0280 00178747225: (dice_avdevice.cpp)[ 710] showDevice: RX : offset=0x03C8 size=1128 00178747239: (dice_avdevice.cpp)[ 711] showDevice: nb= 1 size=0280 00178747257: (dice_avdevice.cpp)[ 712] showDevice: UNUSED1 : offset=0x0830 size=0016 00178747270: (dice_avdevice.cpp)[ 713] showDevice: UNUSED2 : offset=0x0000 size=0000 00178747288: (dice_avdevice.cpp)[ 715] showDevice: Global param space: 00178748527: (dice_avdevice.cpp)[ 718] showDevice: Owner : 0x00000000FFFF0000 00178750121: (dice_avdevice.cpp)[ 721] showDevice: Notification : 0x00000000 00178753929: (dice_avdevice.cpp)[ 724] showDevice: Nick name : Pro24-007336 00178755289: (dice_avdevice.cpp)[ 728] showDevice: Clock Select : 0x02 0x0C 00178757022: (dice_avdevice.cpp)[ 732] showDevice: Enable : false 00178758413: (dice_avdevice.cpp)[ 736] showDevice: Clock Status : locked 0x02 00178759933: (dice_avdevice.cpp)[ 739] showDevice: Extended Status : 0x00000000 00178761326: (dice_avdevice.cpp)[ 742] showDevice: Samplerate : 0x0000BB80 (48000) 00178763083: (dice_avdevice.cpp)[ 745] showDevice: Version : 0x01000400 00178764577: (dice_avdevice.cpp)[ 754] showDevice: Version : 0x01000400 (1.0.4.0) 00178766197: (dice_avdevice.cpp)[ 757] showDevice: Clock caps : 0x112C001E 00178767976: (dice_avdevice.cpp)[ 760] showDevice: Clock sources : 00178768021: (dice_avdevice.cpp)[ 766] showDevice: AES1 00178768051: (dice_avdevice.cpp)[ 766] showDevice: AES2 00178768072: (dice_avdevice.cpp)[ 766] showDevice: SPDIF-OPT 00178768098: (dice_avdevice.cpp)[ 766] showDevice: SPDIF 00178768120: (dice_avdevice.cpp)[ 766] showDevice: AES_ANY 00178768147: (dice_avdevice.cpp)[ 766] showDevice: ADAT 00178768167: (dice_avdevice.cpp)[ 766] showDevice: ADAT_AUX 00178768192: (dice_avdevice.cpp)[ 766] showDevice: Word Clock 00178768213: (dice_avdevice.cpp)[ 766] showDevice: Unused 00178768239: (dice_avdevice.cpp)[ 766] showDevice: Unused 00178768259: (dice_avdevice.cpp)[ 766] showDevice: Unused 00178768285: (dice_avdevice.cpp)[ 766] showDevice: Unused 00178768305: (dice_avdevice.cpp)[ 766] showDevice: Internal 00178768330: (dice_avdevice.cpp)[ 769] showDevice: TX param space: 00178768351: (dice_avdevice.cpp)[ 770] showDevice: Nb of xmit : 1 00178768378: (dice_avdevice.cpp)[ 772] showDevice: Transmitter 0: 00178769920: (dice_avdevice.cpp)[ 775] showDevice: ISO channel : -1 00178771231: (dice_avdevice.cpp)[ 777] showDevice: ISO speed : 2 00178773227: (dice_avdevice.cpp)[ 780] showDevice: Nb audio channels : 16 00178775128: (dice_avdevice.cpp)[ 782] showDevice: Nb midi channels : 1 00178777518: (dice_avdevice.cpp)[ 785] showDevice: AC3 caps : 0x00000000 00178778985: (dice_avdevice.cpp)[ 787] showDevice: AC3 enable : 0x00000000 00178780613: (dice_avdevice.cpp)[ 790] showDevice: Channel names : 00178780692: (dice_avdevice.cpp)[ 795] showDevice: IP 1 00178780725: (dice_avdevice.cpp)[ 795] showDevice: IP 2 00178780773: (dice_avdevice.cpp)[ 795] showDevice: IP 3 00178780805: (dice_avdevice.cpp)[ 795] showDevice: IP 4 00178780843: (dice_avdevice.cpp)[ 795] showDevice: SPDIF L 00178780873: (dice_avdevice.cpp)[ 795] showDevice: SPDIF R 00178780912: (dice_avdevice.cpp)[ 795] showDevice: ADAT 1 00178780944: (dice_avdevice.cpp)[ 795] showDevice: ADAT 2 00178780981: (dice_avdevice.cpp)[ 795] showDevice: ADAT 3 00178781038: (dice_avdevice.cpp)[ 795] showDevice: ADAT 4 00178781080: (dice_avdevice.cpp)[ 795] showDevice: ADAT 5 00178781109: (dice_avdevice.cpp)[ 795] showDevice: ADAT 6 00178781147: (dice_avdevice.cpp)[ 795] showDevice: ADAT 7 00178781178: (dice_avdevice.cpp)[ 795] showDevice: ADAT 8 00178781217: (dice_avdevice.cpp)[ 795] showDevice: Loop 1 00178781247: (dice_avdevice.cpp)[ 795] showDevice: Loop 2 00178781291: (dice_avdevice.cpp)[ 799] showDevice: RX param space: 00178781321: (dice_avdevice.cpp)[ 800] showDevice: Nb of recv : 1 00178781360: (dice_avdevice.cpp)[ 802] showDevice: Receiver 0: 00178783053: (dice_avdevice.cpp)[ 805] showDevice: ISO channel : -1 00178784582: (dice_avdevice.cpp)[ 807] showDevice: Sequence start : 0 00178786131: (dice_avdevice.cpp)[ 810] showDevice: Nb audio channels : 8 00178787526: (dice_avdevice.cpp)[ 812] showDevice: Nb midi channels : 1 00178789065: (dice_avdevice.cpp)[ 815] showDevice: AC3 caps : 0x00000000 00178790447: (dice_avdevice.cpp)[ 817] showDevice: AC3 enable : 0x00000000 00178792479: (dice_avdevice.cpp)[ 820] showDevice: Channel names : 00178792522: (dice_avdevice.cpp)[ 825] showDevice: Mon 1 00178792539: (dice_avdevice.cpp)[ 825] showDevice: Mon 2 00178792559: (dice_avdevice.cpp)[ 825] showDevice: Line 3 00178792575: (dice_avdevice.cpp)[ 825] showDevice: Line 4 00178792599: (dice_avdevice.cpp)[ 825] showDevice: Line 5 00178792614: (dice_avdevice.cpp)[ 825] showDevice: Line 6 00178792639: (dice_avdevice.cpp)[ 825] showDevice: SPDIF L 00178792654: (dice_avdevice.cpp)[ 825] showDevice: SPDIF R 00178792682: Debug (devicemanager.cpp)[1279] showDeviceInfo: Clock sync sources: 00178800209: Debug (devicemanager.cpp)[1288] showDeviceInfo: Type: AES , Id: 2, Valid: 1, Active: 0, Locked 0, Slipping: 0, Description: SPDIF-OPT 00178800270: Debug (devicemanager.cpp)[1288] showDeviceInfo: Type: AES , Id: 3, Valid: 1, Active: 0, Locked 0, Slipping: 0, Description: SPDIF 00178800275: Debug (devicemanager.cpp)[1288] showDeviceInfo: Type: ADAT , Id: 5, Valid: 1, Active: 0, Locked 0, Slipping: 0, Description: ADAT 00178800283: Debug (devicemanager.cpp)[1288] showDeviceInfo: Type: Compound Syt Match, Id: 8, Valid: 1, Active: 0, Locked 0, Slipping: 0, Description: Unused 00178800287: Debug (devicemanager.cpp)[1288] showDeviceInfo: Type: Internal , Id: 12, Valid: 1, Active: 1, Locked 1, Slipping: 0, Description: Internal 00178807920: (ffado-dbus-server.cpp)[ 329] main: DBUS service running 00178807937: (ffado-dbus-server.cpp)[ 330] main: press ctrl-c to stop it & exit 00178807946: Debug (ffado-dbus-server.cpp)[ 333] main: dispatching...

Terminal output for ffado-mixer:

simon@simon-Precision-M4300:~$ ffado-mixer 16:29:09 panelmanager ERROR error in pollPanels 16:29:34 panelmanager ERROR The communication with ffado-dbus-server was lost. CrossbarRouter?.del() 16:29:59 dbus.proxies ERROR Introspect error on :1.60:/org/ffado/Control/DeviceManager: dbus.exceptions.DBusException: org.freedesktop.DBus.Error.NoReply?: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken. Traceback (most recent call last):

File "/usr/share/ffado-mixer-qt4/ffado/panelmanager.py", line 372, in updatePanels

nbDevices = self.devmgr.getNbDevices()

File "/usr/share/ffado-mixer-qt4/ffado/dbus_util.py", line 271, in getNbDevices

return self.iface.getNbElements()

File "/usr/lib/python2.7/dist-packages/dbus/proxies.py", line 70, in call

return self._proxy_method(*args, **keywords)

File "/usr/lib/python2.7/dist-packages/dbus/proxies.py", line 145, in call

**keywords)

File "/usr/lib/python2.7/dist-packages/dbus/connection.py", line 651, in call_blocking

message, timeout)

dbus.exceptions.DBusException: org.freedesktop.DBus.Error.NoReply?: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken. 16:30:49 panelmanager ERROR The communication with ffado-dbus-server was lost.

Terminal output for cadence:

simon@simon-Precision-M4300:~$ cadence Using Tray Engine 'Qt' JackSettingsW::loadServerSettings() - Unimplemented server attribute 'no-mem-lock', value: '0' JackSettingsW::loadServerSettings() - Unimplemented server attribute 'no-zombies', value: '0' JackSettingsW::loadServerSettings() - Unimplemented server attribute 'libs-unlock', value: '0' JackSettingsW::loadServerSettings() - Unimplemented server attribute 'debug-timer', value: '0' JackSettingsW::loadServerSettings() - Unimplemented server attribute 'midi-bufsize', value: '0' JackSettingsW::loadServerSettings() - Unimplemented server attribute 'timeout-threshold', value: '0' JackSettingsW::loadDriverSettings() - Unimplemented driver attribute 'slave', value: '0' JackSettingsW::loadDriverSettings() - Unimplemented driver attribute 'slave', value: '0' JackSettingsW::loadDriverSettings() - Unimplemented driver attribute 'slave', value: '0' JackSettingsW::loadDriverSettings() - Unimplemented driver attribute 'slave', value: '0' cadence-aloop-daemon started, using alsa_in/out and 2 channels

Terminal output for ardour:

simon@simon-Precision-M4300:~$ ardour3 a1= a2= a3= a4= aend= bnd txt domain [gtk2_ardour3] to /opt/ardour3/share/locale Ardour3.5.403 (kompiliert mit Version 3.5-403-gec2cb31 und GCC Version4.4.6) ardour: [INFO]: Ihre Systemkonfiguration beschränkt Ardour auf nur 4096 offene Dateien ardour: [INFO]: Lade Systemkonfigurationsdatei /opt/ardour3/etc/ardour_system.rc Lade Benutzerkonfiguration /home/simon/.config/ardour3/ardour.rc Using SSE optimized routines

01/07/15 07:50:37 changed by wsl

  • attachment test 1 - terminal output.txt added.

Test 1 - Terminal outputs for ffado-dbus-serv, ffado-mixer, cadence and ardour

01/07/15 08:12:42 changed by wsl

Test 2 - start ffado-dbus-serv without ffado-mixer before cadence before ardour

Didn't get very far with test - it seems that jackd needs to have ffado-mixer running...

01/07/15 14:54:30 changed by jwoithe

  • version changed from FFADO 2.1.0 to FFADO 2.2.1.

Thanks for sending doing these additional tests. Based on the ffado-dbus-server output it appears that this did not crash. Is that true? That means something else went bad between ffado-dbus-server and ffado-mixer. At this point I think we'll have to defer to Phil to see if he can at least reproduce this behaviour.

Regarding comment:5, jackd does not require ffado-mixer, nor does ffado-mixer need jackd. Both programs are independent (or at least are meant to be). What did jackd report in this particular circumstance? If this test was run immediately after the others without a firewire bus reset being manually triggered I expect there might have been a case of bus resource exhaustion.

With firewire, users of the bus (like FFADO) must request bus resources when setting up. These include the bandwidth required for its data streams. When FFADO exits these resources are normally freed. However, if FFADO crashes there is no opportunity to free them and the bus continues to assumes that the bandwidth is still in use by something. After a few FFADO crashes (that is, FFADO start ups without a clean stop) the bus bandwidth will be completely allocated. Further attempts by subsequent FFADO invocations will then fail since the bus will refuse the bandwidth request.

Bus resets can be triggered by several things. Power cycling the audio interface will do it. Alternatively you can run "ffado-test BusReset" to trigger one from software.

Could you please re-test "test 2" with the above in mind? If there are still issues please post the output produced by jackd in this case. Jackd should run fine without ffado-mixer running, so if on your system this isn't the case then it points to something very unexpected going on.

An aside: FFADO 2.2.1 has been added to trac now (see ticket:385, comment 5), so I have taken the liberty of updating the version associated with this ticket accordingly.

(follow-up: ↓ 8 ) 01/08/15 01:46:49 changed by wsl

After many hours of testing I did eventually manage to record a few minutes of an audio track in Ardour from the Saffire PRO 24! The sound was jerky.

I attempt to describe here how I did this and have added my observations with each step. Please do read this and give me your feedback.

Step 1 – Start ffado-dbus-server from the terminal

Observations:

- The ffado-bus-server is running without any errors or warnings.

- The firewire communication LED on the Saffire PRO 24 is not lit.

- jackd cannot be started at this point in time (start fails with signal 12 caught, jackd stopped).

Step 2 – Start ffado-mixer from the terminal

Observations:

- The control elements in ffado-mixer's GUI can be selected, settings modified make no changes to the configuration in the Saffire PRO 24 at this time (see step 3).

- The firewire communication LED on the Saffire PRO 24 is not lit.

Step 3 – Start jackd from the terminal with jackd -P70 -dfirewire -p128 -n2

Observations:

- jackd is running without any errors or warnings.

- The firewire communication LED on the Saffire PRO 24 is lit.

- The Saffire PRO 24 can be controlled from ffado-mixer's GUI, e.g. changing the routing in the Saffire PRO 24 with Crossbar Router or changing the gain / mode of the analogue inputs of the Saffire PRO 24.

Questions:

- jackd runs with -n equal to 2 or 3, what is the correct / best value

- I tried increasing -p to 256 or even 512, in both cases jackd stops with signal 12 or sometines 15 caught. How to reduce the jerkyness in the audio (approx. one XRUM pro second)

- Is jackd synchronised with the internal clack in the Saffire PRO 24? (Or is jackd2 just fudging this?)

Step 4 – Check the signal levels in Crossbar Router view of ffado-mixer, if necessary click on the Switch Peak Meters button

Observations:

- This seems to be important, this is where the magic begins..

- If the meters are not functioning in Crossbar Router view of ffado-mixer, then the data will not be streamed in step 6.

- More than 1 click is often needed!

Step 5 – Close (Stop) the ffado-mixer window

Observations:

- The dbus activity from ffado-mixer seems to clash with Ardour

- The logging in the terminal for ffado-dbus-server, ffado-mixer and ardour just stops so I can't give you any error messages.

- When this occurs ffado-mixer and ardour windows can not be closed and must be killed.

Step 6 – Start Ardour from the terminal

Observations:

- When the select project diaglog appears, expand the options and delete the automatic connection of inputs and outputs

- Audio tracks in Ardour can be inserted, audio tracks and master track can be connected to Saffire PRO 24 inputs and outputs

- Audio tracks can be primed for recording, recording mode can be primed, click on play and recording starts...

Limitations:

No easy way to switch between Saffire PRO 24 inputs as ffado-mixer is not running, e.g. lay down mic, guitar, synth and stage piano parts one after the other.

Each time the following sequence must be performed:

- Close Ardour

- Stop jackd

- Reset ffado-dbus (ffado-test BusReset?)

- Start ffado-dbus-server

- Repeat steps 1 through 6 above.

Question:

- How to kill jackd when the jackd server is running but no application can connect.

Finally, this is a KXStudio version 14.0b 64bit installation, installed from the live CD. updated with all official (not testing) updates from ubuntu /KXStudio.

Questions:

- Which linux distros are the Ffado team using?

- How to build deb packages with patchs for local install? (I have 17 years experience with openSUSE / Fedora and can build rpm packages on fedora, but I don't understand the debian package system.)

Sorry for the long post.

(in reply to: ↑ 7 ) 01/08/15 02:22:19 changed by jwoithe

Replying to wsl:

Step 1 – Start ffado-dbus-server from the terminal Observations:
- The ffado-bus-server is running without any errors or warnings.
- The firewire communication LED on the Saffire PRO 24 is not lit.
- jackd cannot be started at this point in time (start fails with signal 12 caught, jackd stopped).

Whether the LED should be lit at this point I cannot say: I have never used any Saffire device. I expect the LED is activated when audio streaming is running, in which case it would be expected that it not be lit at this point.

The jackd behaviour at this point is unexpected, at least to me. Jackd should be able to start since it is meant to be independent of ffado-dbus-server. Another curiosity is that it is ffado-dbus-server which communicates with the Saffire, and whether ffado-mixer is running should have no impact on the Saffire. Perhaps capture the debug output from jackd at this point and make it available ("jackd -dfirewire -p512 -n3 -v6 >& /tmp/debug.log", and make debug.log's contents available).

Note that the output you're posting into the comments seem to be missing their end-of-line character, which makes them very hard to read. Either enclose the output inside {{{ ... !}}} brackets, or just attach the log file to the ticket.

Step 2 – Start ffado-mixer from the terminal Observations:
- The control elements in ffado-mixer's GUI can be selected, settings modified make no changes to the configuration in the Saffire PRO 24 at this time (see step 3).
- The firewire communication LED on the Saffire PRO 24 is not lit.

No surprises about the LED - see above. I'm surprised that the Saffire doesn't respond to ffado-mixer at this point in time as I would expect it to. Maybe there's a quirk about the Saffire devices which I am not aware of. Hopefully Phil can put me straight if this is the case.

Step 3 – Start jackd from the terminal with jackd -P70 -dfirewire -p128 -n2 Observations:
- jackd is running without any errors or warnings.
- The firewire communication LED on the Saffire PRO 24 is lit.
- The Saffire PRO 24 can be controlled from ffado-mixer's GUI, e.g. changing the routing in the Saffire PRO 24 with Crossbar Router or changing the gain / mode of the analogue inputs of the Saffire PRO 24. Questions: - jackd runs with -n equal to 2 or 3, what is the correct / best value

There's no hard and fast rule. However, experience suggests strongly that more reliable operation is obtained with firewire interfaces if you use "-n3". This also taxes the system less.

- I tried increasing -p to 256 or even 512, in both cases jackd stops with signal 12 or sometines 15 caught. How to reduce the jerkyness in the audio (approx. one XRUM pro second)

You should be able to run "-p256" or "-p512". Jackd really shouldn't be stopping like this with these parameters. Once again, please collect the debug output and make it available so we can see what might be happening.

- Is jackd synchronised with the internal clack in the Saffire PRO 24? (Or is jackd2 just fudging this?)

It is syncrhonised. In fact a great deal of FFADO's complexity comes from the need to synchronise with the internal clock of the Saffire. There is no fudging going on. Note that when using "-dfirewire", jackd is making use of FFADO to communicate with the Saffire.

Step 4 – Check the signal levels in Crossbar Router view of ffado-mixer, if necessary click on the Switch Peak Meters button Observations:
- This seems to be important, this is where the magic begins..
- If the meters are not functioning in Crossbar Router view of ffado-mixer, then the data will not be streamed in step 6.
- More than 1 click is often needed!

This is device-specific. I'll have to leave this one to someone else who has experience with the Saffire devices.

Step 5 – Close (Stop) the ffado-mixer window Observations:
- The dbus activity from ffado-mixer seems to clash with Ardour
- The logging in the terminal for ffado-dbus-server, ffado-mixer and ardour just stops so I can't give you any error messages.
- When this occurs ffado-mixer and ardour windows can not be closed and must be killed.

This really doesn't make sense. Something very strange is going on.

You said ffado-mixer "seems to clash with Ardour" but at this point ardour isn't running, is it? You only try to start it in step 6.

Can you check to ensure that your system definitely has only one version of FFADO installed? Perhaps post the output of the command "ls -la /usr/lib*/libffado*".

Step 6 – Start Ardour from the terminal Observations:
- When the select project diaglog appears, expand the options and delete the automatic connection of inputs and outputs
- Audio tracks in Ardour can be inserted, audio tracks and master track can be connected to Saffire PRO 24 inputs and outputs
- Audio tracks can be primed for recording, recording mode can be primed, click on play and recording starts...
Limitations: No easy way to switch between Saffire PRO 24 inputs as ffado-mixer is not running, e.g. lay down mic, guitar, synth and stage piano parts one after the other. Each time the following sequence must be performed:
- Close Ardour
- Stop jackd
- Reset ffado-dbus (ffado-test BusReset?)
- Start ffado-dbus-server
- Repeat steps 1 through 6 above.

This should not be necessary and suggests that something is wrong.

Question: - How to kill jackd when the jackd server is running but no application can connect.

The more significant question is why jackd/ffado-dbus-server/ffado-mixer/ardour are getting themselves into such a tangled knot. None of this behaviour is expected.

Finally, this is a KXStudio version 14.0b 64bit installation, installed from the live CD. updated with all official (not testing) updates from ubuntu /KXStudio.

That should be ok. I assume you're using the FFADO package which came with the distribution.

Questions: - Which linux distros are the Ffado team using?

I'm not sure. Personally I'm using various versions of Slackware. Others are on Ubuntu, Debian or one of their AV derivatives.

- How to build deb packages with patchs for local install? (I have 17 years experience with openSUSE / Fedora and can build rpm packages on fedora, but I don't understand the debian package system.)

Me neither - I have never used Debian. This question will have to wait for Debian people. :-)

01/08/15 02:47:39 changed by wsl

Many, many thanks for your quick responses. I will try to gather the data you require but I can only look at this at the later part of next weekend.

For now the lib versions...

simon@simon-Precision-M4300:~$ ls -la /usr/lib*/libffado*
lrwxrwxrwx 1 root root      17 Nov  3 21:35 /usr/lib/libffado.so.2 -> libffado.so.2.2.1
-rw-r--r-- 1 root root 2398168 Nov  3 21:35 /usr/lib/libffado.so.2.2.1

/usr/lib/libffado2:
insgesamt 3584
drwxr-xr-x   2 root root    4096 Jan  6 11:47 .
drwxr-xr-x 143 root root   36864 Jan  6 12:11 ..
lrwxrwxrwx   1 root root      17 Nov  3 21:35 libffado.so.2 -> libffado.so.2.2.1
-rw-r--r--   1 root root 3628432 Nov  3 21:35 libffado.so.2.2.1
simon@simon-Precision-M4300:~$ 

01/08/15 02:56:05 changed by wsl

  • attachment 201501081152_debug.log added.

Here the debug log from jackd - jack main caught signal 12

01/08/15 03:15:46 changed by wsl

Adding an attachement dosn't automatically send out an e-mail, so here is the notification...

ffado streaming seems to trip over a xrun...

01039882181: Debug (StreamProcessorManager.cpp)[1348] waitForPeriod: exit due to xrun...
01039882205: Warning (StreamProcessorManager.cpp)[ 913] alignReceivedStreams: xrun while aligning streams...
01039882213: Error (StreamProcessorManager.cpp)[ 877] syncStartAll: Could not align streams...
firewire ERR: wait status < 0! (= -1)
DRIVER NT: could not run driver cycle
01039882220: Debug (StreamProcessorManager.cpp)[1194] handleXrun: Sync start try 9 failed...
01039882228: Fatal (StreamProcessorManager.cpp)[1198] handleXrun: Could not syncStartAll...
01039882235: Error (devicemanager.cpp)[ 999] waitForPeriod: Could not handle XRUN
01039882242: Error (ffado.cpp)[ 273] ffado_streaming_wait: Error condition while waiting (Unhandled XRUN)
01039882299: Debug (ffado.cpp)[ 227] ffado_streaming_stop: ------------- Stop -------------

Full debug in attachment 201501081152_debug.log

Cheers, Simon

01/08/15 03:36:41 changed by jwoithe

Thanks for the additional debug. As you mentioned, the root cause of trouble is this:

01032654989: Debug (StreamProcessor.cpp)[ 641] getPacket: dropped packets xrun (1)

Although it usually makes no difference, could you try bumping up the jackd priority a little using the "-P" option. For example, "jackd -P70 -dfirewire ...". Also please attach the output produced by the ffado-diag command.

A delayed response is fine - I myself will find it difficult to respond quickly during next week.

Regarding the library files, that all seems consistent. I've never understood why we have libffado.so.* in /usr/lib/ and /usr/lib/libffado2/, especially given that the sizes are different. In any case, the system doesn't seem to have multiple versions lying around. To be sure, could you do "ls -la /usr/local/lib*/libffado*" to ensure there are no other versions in that area?

01/08/15 04:13:04 changed by wsl

  • attachment 201501081305_debug.log added.

jackd debug log with higher priority and rtirq service running.

01/08/15 04:13:47 changed by wsl

  • attachment 201501081306_ffado-diag.log added.

ffado-diag

01/08/15 04:21:32 changed by wsl

This really, really, really is the last comment for today..

I noticed that the rtirq service does not start automatically on KXStudio (filled a bug under https://bugs.launchpad.net/kxstudio/+bug/1408629)

Created new attachments for jackd with a priority of -P70 and ffado-diag.

There are no directories corresponding to the pattern /usr/local/lib*/libffado*

The ffado streaming still trips over a xrun

Cheers, Simon

(follow-up: ↓ 14 ) 01/10/15 03:02:37 changed by jwoithe

Another brief thought to add. Looking at your ffado-diag output it seems you're using a firewire card based on the "O2 Micron" chipset. Such chips have been known to cause issues for audio users in the past. We should definitely work through the issues I raised in comment:8 (and following), but it's something else to keep in mind.

(in reply to: ↑ 13 ) 01/10/15 23:47:39 changed by wsl

I've checked the installed KXStudo configuration and I think it is pretty much well set-up for an audio workstation...

simon@simon-Precision-M4300:~/bin/realtimeconfigquickscan-master$ perl ./realTimeConfigQuickScan.pl
== GUI-enabled checks ==
Checking if you are root... no - good
Checking filesystem 'noatime' parameter... 3.13.0 kernel - good
(relatime is default since 2.6.30)
Checking CPU Governors... CPU 0: 'performance' CPU 1: 'performance'  - good
Checking swappiness... 10 - good
Checking for resource-intensive background processes... none found - good
Checking checking sysctl inotify max_user_watches... >= 524288 - good
Checking access to the high precision event timer... readable - good
Checking access to the real-time clock... readable - good
Checking whether you're in the 'audio' group... yes - good
Checking for multiple 'audio' groups... no - good
Checking the ability to prioritize processes with chrt... yes - good
Checking kernel support for high resolution timers... found - good
Kernel with Real-Time Preemption... not found - not good
Kernel without real-time capabilities found
For more information, see http://wiki.linuxaudio.org/wiki/system_configuration#installing_a_real-time_kernel
Checking if kernel system timer is set to 1000 hz... found - good
Checking kernel support for tickless timer... found - good
== Other checks ==
Checking filesystem types... ok.
not found.
** Warning: no tmpfs partition mounted on /tmp
   For more information, see:
   - http://wiki.linuxaudio.org/wiki/system_configuration#tmpfs
   - http://lowlatency.linuxaudio.org
** Set $SOUND_CARD_IRQ to the IRQ of your soundcard to enable more checks.
   Find your sound card's IRQ by looking at '/proc/interrupts' and lspci.
simon@simon-Precision-M4300:~/bin/realtimeconfigquickscan-master$ 
simon@simon-Precision-M4300:~/bin/realtimeconfigquickscan-master$ /etc/init.d/rtirq status

  PID CLS RTPRIO  NI PRI %CPU STAT COMMAND
  149 FF      90   - 130  0.0 S    irq/19-firewire
  443 FF      85   - 125  0.0 S    irq/46-snd_hda_
   70 FF      80   - 120  0.1 S    irq/20-uhci_hcd                                                                                                                                 
   71 FF      79   - 119  0.0 S    irq/21-uhci_hcd                                                                                                                                 
   72 FF      79   - 119  0.2 S    irq/20-uhci_hcd                                                                                                                                 
   73 FF      78   - 118  0.0 S    irq/21-uhci_hcd                                                                                                                                 
   74 FF      78   - 118  0.0 S    irq/22-uhci_hcd                                                                                                                                 
   76 FF      75   - 115  0.0 S    irq/1-i8042                                                                                                                                     
   75 FF      74   - 114  0.0 S    irq/12-i8042
   31 FF      50   -  90  0.0 S    irq/9-acpi
   58 FF      50   -  90  0.0 S    irq/14-ata_piix
   59 FF      50   -  90  0.0 S    irq/15-ata_piix
   64 FF      50   -  90  0.0 S    irq/17-ata_piix
   68 FF      50   -  90  0.0 S    irq/22-ehci_hcd
   69 FF      50   -  90  0.0 S    irq/20-ehci_hcd
   77 FF      50   -  90  0.0 S    irq/8-rtc0
  176 FF      50   -  90  0.6 S    irq/45-nouveau
  436 FF      50   -  90  0.0 S    irq/19-yenta
  502 FF      50   -  90  0.3 S    irq/47-iwl3945
 1238 FF      50   -  90  0.0 S    irq/48-eth0
    3 TS       -   0  19  0.1 S    ksoftirqd/0
   20 TS       -   0  19  0.1 R    ksoftirqd/1

simon@simon-Precision-M4300:~/bin/realtimeconfigquickscan-master$
simon@simon-Precision-M4300:~/bin/realtimeconfigquickscan-master$ ulimit -r -l
real-time priority              (-r) 95
max locked memory       (kbytes, -l) unlimited
simon@simon-Precision-M4300:~/bin/realtimeconfigquickscan-master$ 
simon@simon-Precision-M4300:~/bin/realtimeconfigquickscan-master$ cat /proc/cpuinfo | grep MHz
cpu MHz         : 2401.000
cpu MHz         : 2401.000
simon@simon-Precision-M4300:~/bin/realtimeconfigquickscan-master$ 

The question is how to determine what is causing the XRUNs?

01/11/15 01:07:00 changed by wsl

  • attachment 201501111004_firewire-ohci_syslog.log added.

Details of firwire card

01/11/15 01:07:56 changed by jwoithe

Yes, that is a very good question. If possible, as mentioned earlier it would be helpful to run your test after disabling wireless networking and removing the wireless kernel driver (iwl3945). Even though the corresponding IRQ has a lower priority some wireless drivers have been known to cause trouble.

Since I'm travelling at present I am unable to re-run FFADO against my Traveler to explicitly confirm that it does still work. I will try to do that as soon as possible after I return next weekend. Given that the system does appear reasonably well configured, I am now starting to seriously think that perhaps the "O2 Micron" firewire chip might be to blame. However, let's wait and see what the remaining tests show.

01/11/15 07:44:54 changed by wsl

  • attachment 201501111627_debug.log added.

jackd messages (with networking disabled)

01/11/15 07:51:32 changed by wsl

The XRUNs do not seem to be related to networking..!

Attachment 201501111627_debug.log was obtained after disabling wireless networking and removing the wireless kernel drivers (I also stopped the Bluetooth - don't usually use this) as follows:

simon@simon-Precision-M4300:~$ sudo /etc/init.d/networking stop
[sudo] password for simon: 
simon@simon-Precision-M4300:~$ sudo modprobe -r iwl3945
simon@simon-Precision-M4300:~$ sudo modprobe -r iwlegacy
simon@simon-Precision-M4300:~$ sudo modprobe -r mac80211
simon@simon-Precision-M4300:~$ sudo modprobe -r cfg80211
simon@simon-Precision-M4300:~$ sudo /etc/init.d/bluetooth stop
 * Stopping bluetooth                                                                                                                                                       [ OK ] 
simon@simon-Precision-M4300:~$ sudo modprobe -r btusb
simon@simon-Precision-M4300:~$ sudo modprobe -r rfcomm

01/17/15 03:34:41 changed by wsl

  • attachment 201501171205_debug_beg-end_only.log added.

Latest debug after configuration with rtctl

01/17/15 03:51:53 changed by wsl

I've just spent the last week replacing rtirq with rtctl which allows a differentiate setting of rtprios based on rtgroups.

The hardwire irqs are now prioritised as follows.

simon@simon-Precision-M4300:~$ rtctl show hardirq
   31     85 FF  [irq/9-acpi]
   58     85 FF  [irq/14-ata_piix]
   59     85 FF  [irq/15-ata_piix]
   64     85 FF  [irq/18-ata_piix]
   68     85 FF  [irq/22-ehci_hcd]
   69     85 FF  [irq/20-ehci_hcd]
   70     85 FF  [irq/20-uhci_hcd]
   71     85 FF  [irq/21-uhci_hcd]
   72     85 FF  [irq/20-uhci_hcd]
   73     85 FF  [irq/21-uhci_hcd]
   74     85 FF  [irq/22-uhci_hcd]
   75     85 FF  [irq/12-i8042]
   76     85 FF  [irq/1-i8042]
   77     90 FF  [irq/8-rtc0]
  147     88 FF  [irq/19-firewire]
  176     85 FF  [irq/45-nouveau]
  435     89 FF  [irq/19-yenta]
  600     85 FF  [irq/46-snd_hda_]
  611     85 FF  [irq/47-iwl3945]
 1150     50 FF  [irq/48-eth0]
simon@simon-Precision-M4300:~$ 

The rtgroups that I have assigned are as follows:

kthreads:*:1:*:\[.*\]$
watchdog:f:99:*:\[watchdog.*\]
migration:f:99:*:\[migration\/.*\]
softirq:f:70:*:\[.*(softirq|sirq).*\]
softirq-net-tx:f:75:*:\[(softirq|sirq)-net-tx.*\]
softirq-net-rx:f:75:*:\[(softirq|sirq)-net-rx.*\]
softirq-sched:f:1:*:\[(softirq|sirq)-sched\/.*\]
rpciod:f:65:*:\[rpciod.*\]
lockd:f:65:*:\[lockd.*\]
nfsd:f:65:*:\[nfsd.*\]
hardirq:f:85:*:\[(irq|IRQ)[\-_/].*\]
cardctl:f:88:*:\[irq/19-firewire]
hostctl:f:89:*:\[irq/19-yenta]
timer:f:90:*:\[irq/8-rtc0]

Format is: <groupname>:<sched>:<prio>:affinity:<regex>

sched 'f' is fifo otherwise '*' (leave alone) is cfs

The prcocess names that can be chosen can be found with:

$ ps -eo cmd

The synchronisation between ffado and jackd still keeps slipping due to xruns (see latest attachement).

The number of xruns has however dropped significantly.

I would welcome any tips to find the culprite causing the xruns.

Simon

(follow-up: ↓ 19 ) 01/18/15 02:25:09 changed by jwoithe

I have just returned from travelling and will try to look through the new logs in detail later this week. A brief glance at the latest shows that the initial setup is running to completion now, but as you said xruns are triggered soon after.

What values for "-p" (frames per buffer) and "-n" (number of buffers) were you using for this latest round of tests? I can't tell from the logs because the lines which can be used to infer this are not present.

As far as I am aware, all your tests to date have been done with either rtirq or rtctl in use. Could you temporarily disable these so no manipulations of IRQ handlers is done and re-test? That is, please test jackd/ffado with a system running with the default IRQ priorities.

01/18/15 07:30:13 changed by wsl

  • attachment 201501181611_debug_beg-end.log added.

debug log with default settings, i.e. without rtirq or rtctl disabled

(in reply to: ↑ 18 ) 01/18/15 07:35:29 changed by wsl

Replying to jwoithe:

What values for "-p" (frames per buffer) and "-n" (number of buffers) were you using..?


-p512 -n3


...please test jackd/ffado with a system running with the default IRQ priorities.


See attachment 201501181611_debug_beg-end.log

ffado-mixer trashed out on starting jackd

(follow-ups: ↓ 21 ↓ 22 ) 01/18/15 23:21:08 changed by jwoithe

Thanks for your response.

Can you please provide the full text of the log. Providing the "end" details only after the xrun has occurred is not entirely useful because we have no way of knowing what happened in the time leading up to this. Often it is things in the leadup which are important.

Also, to reduce the number of variables, could you please try running just jackd at this point? Don't start ffado-mixer and/or ffado-dbus-server. Jackd should run fine without ffado-mixer, and if it does not this tells us something about your setup. Before starting jackd, please confirm that these additional programs are not running using "ps aux | grep ffado" or something similar.

01/19/15 08:23:21 changed by wsl

  • attachment 201501191713_debug_full.log added.

jackd debug log without ffado-dbus-serv and ffado-mixer

(in reply to: ↑ 20 ) 01/19/15 08:26:47 changed by wsl

Replying to jwoithe:

To reduce the number of variables, could you please try running just jackd at this point?

See attachment 201501191713_debug_full.log

(in reply to: ↑ 20 ) 01/19/15 08:36:33 changed by wsl

Replying to jwoithe:

please confirm that these additional programs are not running using "ps aux | grep ffado" or something similar.


simon@simon-Precision-M4300:~$ ps aux | grep ffado
simon     1843  0.0  0.0  13252   916 pts/2    D+   17:31   0:00 grep --color=auto ffado
simon@simon-Precision-M4300:~$ 

01/19/15 17:38:20 changed by jwoithe

Thanks for the revised complete log. The first xrun is clearly occurring during the initial streaming setup, very soon after packets start flowing from the device. The transmit stream (0x1cbf630) is running by 00103098538 with the rx stream (0x1cbf840) following at 00103114531 (a difference of just under 16 ms). The stream alignment process starts and seems to run normally for around 73 ms before the first "dropped packets xrun" occurs at 00103187840. I notice that at 00103130228 the ARM handler is called, this being 15.5 ms after the approximate start time of the alignment process. I am not sure whether this is significant or not, given that it was a further 57 ms before the xrun occurred. I also note that the time to the ARM callback was around the same time as that between the tx and rx streams starting. Again though this is probably a coincidence.

Note that the alignment is averaging over 37 periods. In this case there were 512 frames per period, so the expected time for the alignment to complete is around 394 ms at 48 kHz.

This was not the end of the story though. When an xrun occurs in this situation FFADO will attempt to recover. Starting at 00103523866 we see the next start up attempt. Once again, roughly 16 ms elapses between the start of the two streams and at 00103539910 the alignment procedure starts again. An ARM callback occurs at 00103550331 which doesn't seem to cause any trouble this time around. At 00103939123 the alignment process is completed (having taken around 399 ms, as expected) and FFADO concludes that the streaming is running.

We get a dump of the stream processor status which reports a total of 44 periods having been processed. The sync numbers look sensible, as does the rest of the status. Note that it is normal for all ports to be labelled as "on" during the first status report.

At 00104909899 we see another dropped packets xrun. This comes nearly 1 second after the streaming system was successfully started. As for the other timing it is far from clear whether this is significant.

So where does this leave us? The system as a whole is capable of starting the audio streaming and running it for some time (up to a second according to the latest log dump). getPacket() is called in the transmit path and the particular xrun being logged is being reported to FFADO from the kernel via libraw1394. As far as I know these xruns are either due to the kernel not getting the packets into the hardware on time or the packets being supplied too late (giving the kernel insufficient time to get them onto the wire in their designated cycle). The former could be caused by a delay within the kernel or something in the firewire hardware creating a longer than usual wait. The latter would usually be caused by scheduling latencies preventing FFADO delivering the packet on time (although normally in this situation other sections of FFADO would flag the problem).

Given that you are running a low latency kernel, are using moderate values for "-p" and have jackd running with priority 70 it seems unlikely that scheduling latencies are causing this problem. Many others have run with the same basic approach and found success.

As a result, I am now starting to seriously suspect that your Firewire host controller (the card based on the O2 Micron chipset) may be at fault here. I can give no guarantees of course, but given what seems to be happening and the configuration you are running it appears to be the most likely cause of the problems noted in this ticket.

Is there any chance you can borrow a different firewire card to test this theory?

01/20/15 00:40:48 changed by wsl

Thank you for your detailed and professional reply and the time you are taking to look at this. Regarding a different firewire card - it will have to be an external card for a laptop, any recomendations?

Incidently, whilst waiting for your reply, I tried out a KaOS live DVD (very impressive). Interestingly, running the "Live" CD I added ffado / jack / Ardour in the package management and had the Saffire PRO 24 up and running in 5 minutes. I could record for several minutes. Synchronisation was only lost when I moved the mouse (to another window), keeping the mouse still the sychronisation between jack and ffado returned after a couple of seconds and everything would run without XRUNs for another couple of minutes before moving the mouse caused further XRUNs.

This suggests to me that there is nothing fundamentally wrong with O2 Micron chipset but rather the way it is being serviced by linux / kernal / apps.

Is there any tool I can use to see how all the devices and cards, internally and external, are connected together in this laptop? I know the O2 Micron chipset shares a hard IRQ with a "yenta" compatible card bus controller.

It's probably a stupid question, but should I try to assign the desktop / display to one CPU and jack / ffado to another CPU?.

Cheers, Simon

01/22/15 16:14:25 changed by jwoithe

I am not across the options when it comes to CardBus? firewire cards for laptops these days. Generally speaking you'll want something based on a Texas Instruments (TI) or a "recent" LSI/Agere chipset. See our host controllers page for additional information. It will probably be easier for you to find out what options you have in your part of the world and then ask here whether a particular choice is expected to be any good.

Regarding the experiment with KaOS, it's impossible to know what to make of that. Moving the mouse does cause activity on the PCI/PCIe bus. The Firewire card is also on the PCIe bus (probably via a PCI-PCIe bridge chip); if it has bus-related trouble then any activity on the PCIe bus could trigger this. The fact that the behaviour under KaOS was different to the installed system is interesting but may not be significant. Being a totally different distribution the order that drivers are loaded, the version of everything and the way the system is being driven at the hardware level are all likely to be slightly different. This can easily cause marginal devices to behave differently.

Is there any tool I can use to see how all the devices and cards, internally and external, are connected together ...

I'm not sure. Doing "cat /etc/interrupts" will show you all the interrupt routing in a textual table - is that what you were after? If you instead want the PCIe/PCI bus topology I think this can be inferred from the IDs reported by lspci. Whether there's a utility which takes this and interprets it for you I don't know - I am not a PCIe bus expert. :-)

the O2 Micron chipset shares a hard IRQ with a "yenta" compatible card bus controller.

That's certainly not ideal, although I can't recall off-hand whether it's created this sort of trouble in the past. I think it's possible to get yenta to operate in polled move rather than interrupt mode; if this is true it might be worth trying that.

should I try to assign the desktop / display to one CPU and jack / ffado to another CPU?

I guess you could try it but I suspect it won't make any difference. FFADO users generally do not need to resort to these optimisations. If it works it is probably only because it covers up some other underlying issue.

01/29/15 04:18:43 changed by wsl

  • status changed from new to closed.
  • resolution set to wontfix.
  • milestone deleted.

Alternative solution found...

For dice based audio interface users I would recommend the following link and procedure for back-porting the alsa modules for firewire devices into their installtation

https://github.com/takaswie/snd-firewire-improve

My experience is that:
- The modules build perfectly.
- The Focusrite Saffire PRO 24 is detected on-plug in.
- Using QjackCtl?, jackd started and run correctly using alsa as the driver and PRO 24 as the interface.
- All the PRO 24 audio ins and outs could be routed to/from Ardour3.
- Ardour3 records unendlessly without a single XRUN.

This is truly a cool piece of programming...

Just need ALSA to provide a generic mixer GUI for diced based audio interfaces...

01/29/15 20:57:14 changed by jwoithe

Thanks for the success report. Regarding the mixer, it is likely that such a mixer GUI will not be provided as part of the core ALSA modules, but will instead continue to be provided by something like ffado-mixer. For this to happen with DICE-based interfaces some additional support infrastructure in ALSA is required, but Takashi S is working on this. The reason for this approach is that even amongst DICE-based interfaces the mixer requirements are highly varied, and the resulting complex code really doesn't need to be in the kernel. This becomes even more significant once more FFADO streaming engines are ported into the kernel. However, this is just how things look at the moment: who knows how things might progress in the future.

Once again, thanks for your report and explanation of a workaround.