From: Yves G. <yve...@nu...> - 2012-05-16 18:00:30
|
Hi Starting ffado may cause jackd to crash, depending on the order in which both were started: Case 1) I start jackd, then I start ffado-mixer: jack crashes (below is the log, obtained with "-v 4") Case 2) I first start ffado-mixer, then I start jackd, everything goes well, I may even stop and restart ffado-mixer. My configuration: Focusrite Saffire Pro 24 jackdmp, version 1.9.8 (ubuntu precise 12.04 package) ffado compiled from svn, revision 2149 Is this the same problem as the one reported in ticket #345? Regards Yves ************************ log with jackd -d firewire -v 4 ffado_streaming_wait ============================================ Xruns: 0 ============================================ ---------------------------------------------------- Dumping StreamProcessorManager information... Period count: 918 Data type: float Receive processors... StreamProcessor 0x9565488, Receive: Port, Channel : 0, 0 Packets, Dropped, Skipped : 158848, 0, 0 Now : 01372904688 (055s 6909c 0240t) Xrun? : False State : ePS_Running Buffer : 0x9565658 Framerate : Nominal: 48000, Sync: 47998.775513, Buffer 47998.775513 TimestampedBuffer (0x9565658): 0048 frames, 0048 events Timestamps : head: 1372697136.379, Tail: 1372721713.006, Next tail: 1372725809.110 Head - Tail : -24576.627 (-48.000002 frames) DLL Rate : 4096.104345 (512.013043) DLL Bandwidth : 4.069011e-09 1/ticks (0.100000 Hz) Transmit processors... StreamProcessor 0x95652f0, Transmit: Port, Channel : 0, 1 Packets, Dropped, Skipped : 158994, 0, 0 Now : 01372908497 (055s 6910c 0977t) Xrun? : False State : ePS_Running Buffer : 0x9565d20 Framerate : Nominal: 48000, Sync: 47998.775513, Buffer 47998.775513 TimestampedBuffer (0x9565d20): 2184 frames, 2184 events Timestamps : head: 1373205052.003, Tail: 1374323288.503, Next tail: 1374847589.869 Head - Tail : -1118236.500 (-2184.000024 frames) DLL Rate : 524301.356822 (512.013044) DLL Bandwidth : 4.069011e-09 1/ticks (0.100000 Hz) ---------------------------------------------------- 02048552522: Warning (IsoHandlerManager.cpp)[ 292] Execute: Timeout while waiting for activity 02049508559: Fatal (IsoHandlerManager.cpp)[ 348] Execute: (0x953ec40, Receive) Handler died: now: 77929513, last: 738FF965, diff: 49279918 (max: 49152000) 02049508609: Warning (StreamProcessor.cpp)[ 173] handlerDied: Handler died for 0x9565488 02049508665: Debug (StreamProcessorManager.cpp)[1397] waitForPeriod: Xrun on RECV SP 0x9565488 due to ISO side xrun StreamProcessor 0x9565488, Receive: Port, Channel : 0, 0 Packets, Dropped, Skipped : 174400, 0, 0 Now : 01469775639 (059s 6442c 1815t) Xrun? : True State : ePS_Stopped (Next: ePS_Running) transition at : 2164 Buffer : 0x9565658 Framerate : Nominal: 48000, Sync: 47998.775513, Buffer 47998.775513 TimestampedBuffer (0x9565658): 0176 frames, 0176 events Timestamps : head: 1420408560.471, Tail: 1420498674.768, Next tail: 1420502770.873 Head - Tail : -90114.297 (-176.000001 frames) DLL Rate : 4096.104380 (512.013047) DLL Bandwidth : 4.069011e-09 1/ticks (0.100000 Hz) 02049508793: Debug (StreamProcessorManager.cpp)[1402] waitForPeriod: Xrun on RECV SP 0x9565488 due to buffer side xrun StreamProcessor 0x9565488, Receive: Port, Channel : 0, 0 Packets, Dropped, Skipped : 174400, 0, 0 Now : 01469778539 (059s 6443c 1643t) Xrun? : True State : ePS_Stopped (Next: ePS_Running) transition at : 2164 Buffer : 0x9565658 Framerate : Nominal: 48000, Sync: 47998.775513, Buffer 47998.775513 TimestampedBuffer (0x9565658): 0176 frames, 0176 events Timestamps : head: 1420408560.471, Tail: 1420498674.768, Next tail: 1420502770.873 Head - Tail : -90114.297 (-176.000001 frames) DLL Rate : 4096.104380 (512.013047) DLL Bandwidth : 4.069011e-09 1/ticks (0.100000 Hz) 02049508901: Warning (devicemanager.cpp)[ 998] waitForPeriod: XRUN detected ---------------------------------------------------- Dumping StreamProcessorManager information... Period count: 1010 Data type: float Receive processors... StreamProcessor 0x9565488, Receive: Port, Channel : 0, 0 Packets, Dropped, Skipped : 174400, 0, 0 Now : 01469781931 (059s 6444c 1963t) Xrun? : True State : ePS_Stopped (Next: ePS_Running) transition at : 2164 Buffer : 0x9565658 Framerate : Nominal: 48000, Sync: 47998.775513, Buffer 47998.775513 TimestampedBuffer (0x9565658): 0176 frames, 0176 events Timestamps : head: 1420408560.471, Tail: 1420498674.768, Next tail: 1420502770.873 Head - Tail : -90114.297 (-176.000001 frames) DLL Rate : 4096.104380 (512.013047) DLL Bandwidth : 4.069011e-09 1/ticks (0.100000 Hz) Transmit processors... StreamProcessor 0x95652f0, Transmit: Port, Channel : 0, 1 Packets, Dropped, Skipped : 174898, 0, 0 Now : 01469784806 (059s 6445c 1766t) Xrun? : False State : ePS_Running Buffer : 0x9565d20 Framerate : Nominal: 48000, Sync: 47998.775513, Buffer 47998.775513 TimestampedBuffer (0x9565d20): 0000 frames, 0000 events Timestamps : head: 1422034712.712, Tail: 1422034712.712, Next tail: 1422559014.079 Head - Tail : 0.000 (0.000000 frames) DLL Rate : 524301.361698 (512.013049) DLL Bandwidth : 4.069011e-09 1/ticks (0.100000 Hz) ---------------------------------------------------- 02049509214: Error (IsoHandlerManager.cpp)[1913] requestEnable: Enable requested on stream 'Receive' with state: 2 02049509226: Error (StreamProcessor.cpp)[1244] scheduleStartDryRunning: Could not start handler for SP 0x9565488 02049509241: Error (StreamProcessorManager.cpp)[ 514] startDryRunning: Could not put 'Receive' SP 0x9565488 into the dry-running state 02049509256: Error (IsoHandlerManager.cpp)[1913] requestEnable: Enable requested on stream 'Receive' with state: 2 02049509268: Error (StreamProcessor.cpp)[1244] scheduleStartDryRunning: Could not start handler for SP 0x9565488 02049509274: Error (StreamProcessorManager.cpp)[ 514] startDryRunning: Could not put 'Receive' SP 0x9565488 into the dry-running state 02049509292: Error (IsoHandlerManager.cpp)[1913] requestEnable: Enable requested on stream 'Receive' with state: 2 02049509298: Error (StreamProcessor.cpp)[1244] scheduleStartDryRunning: Could not start handler for SP 0x9565488 02049509309: Error (StreamProcessorManager.cpp)[ 514] startDryRunning: Could not put 'Receive' SP 0x9565488 into the dry-running state 02049509322: Error (IsoHandlerManager.cpp)[1913] requestEnable: Enable requested on stream 'Receive' with state: 2 02049509332: Error (StreamProcessor.cpp)[1244] scheduleStartDryRunning: Could not start handler for SP 0x9565488 02049509338: Error (StreamProcessorManager.cpp)[ 514] startDryRunning: Could not put 'Receive' SP 0x9565488 into the dry-running state 02049509355: Error (IsoHandlerManager.cpp)[1913] requestEnable: Enable requested on stream 'Receive' with state: 2 02049509362: Error (StreamProcessor.cpp)[1244] scheduleStartDryRunning: Could not start handler for SP 0x9565488 02049509372: Error (StreamProcessorManager.cpp)[ 514] startDryRunning: Could not put 'Receive' SP 0x9565488 into the dry-running state 02049509385: Error (IsoHandlerManager.cpp)[1913] requestEnable: Enable requested on stream 'Receive' with state: 2 02049509396: Error (StreamProcessor.cpp)[1244] scheduleStartDryRunning: Could not start handler for SP 0x9565488 02049509402: Error (StreamProcessorManager.cpp)[ 514] startDryRunning: Could not put 'Receive' SP 0x9565488 into the dry-running state 02049509419: Error (IsoHandlerManager.cpp)[1913] requestEnable: Enable requested on stream 'Receive' with state: 2 02049509426: Error (StreamProcessor.cpp)[1244] scheduleStartDryRunning: Could not start handler for SP 0x9565488 02049509437: Error (StreamProcessorManager.cpp)[ 514] startDryRunning: Could not put 'Receive' SP 0x9565488 into the dry-running state 02049509450: Error (IsoHandlerManager.cpp)[1913] requestEnable: Enable requested on stream 'Receive' with state: 2 02049509461: Error (StreamProcessor.cpp)[1244] scheduleStartDryRunning: Could not start handler for SP 0x9565488 02049509467: Error (StreamProcessorManager.cpp)[ 514] startDryRunning: Could not put 'Receive' SP 0x9565488 into the dry-running state 02049509484: Error (IsoHandlerManager.cpp)[1913] requestEnable: Enable requested on stream 'Receive' with state: 2 02049509490: Error (StreamProcessor.cpp)[1244] scheduleStartDryRunning: Could not start handler for SP 0x9565488 02049509505: Error (StreamProcessorManager.cpp)[ 514] startDryRunning: Could not put 'Receive' SP 0x9565488 into the dry-running state 02049509518: Error (IsoHandlerManager.cpp)[1913] requestEnable: Enable requested on stream 'Receive' with state: 2 02049509534: Error (StreamProcessor.cpp)[1244] scheduleStartDryRunning: Could not start handler for SP 0x9565488 02049509540: Error (StreamProcessorManager.cpp)[ 514] startDryRunning: Could not put 'Receive' SP 0x9565488 into the dry-running state 02049509551: Fatal (StreamProcessorManager.cpp)[1190] handleXrun: Could not syncStartAll... 02049509557: Error (devicemanager.cpp)[1003] waitForPeriod: Could not handle XRUN 02049509567: Error (ffado.cpp)[ 273] ffado_streaming_wait: Error condition while waiting (Unhandled XRUN) JackFFADODriver::ffado_driver_wait - unhandled xrun firewire ERR: wait status < 0! (= -1) JackAudioDriver::ProcessAsync: read error, stopping... 02051573910: Fatal (IsoHandlerManager.cpp)[ 348] Execute: (0x953eb10, Transmit) Handler died: now: 7BB3440E, last: 77AF17F4, diff: 49356826 (max: 49152000) 02051573956: Warning (StreamProcessor.cpp)[ 173] handlerDied: Handler died for 0x95652f0 |
From: Philippe C. <la-...@or...> - 2012-05-16 18:21:52
|
Le mercredi 16 mai 2012 à 20:00 +0200, Yves Grenier a écrit : > Hi > > Starting ffado may cause jackd to crash, depending on the order in which > both were started: > > Case 1) I start jackd, then I start ffado-mixer: jack crashes (below is > the log, obtained with "-v 4") > > Case 2) I first start ffado-mixer, then I start jackd, everything goes > well, I may even stop and restart ffado-mixer. > > My configuration: > Focusrite Saffire Pro 24 > jackdmp, version 1.9.8 (ubuntu precise 12.04 package) > ffado compiled from svn, revision 2149 > > Is this the same problem as the one reported in ticket #345? > > Regards > > Yves > I confirm the behaviour; more precisely this is the ffado-dbus-server start-up which leads to jack crash. I have no sufficient knowledge about streaming and I did not recover entirely my laptop to test anything. In a few days, possibly. Regards, Phil -- Philippe Carriere <la-...@or...> |
From: Stefan R. <st...@s5...> - 2012-05-16 18:26:41
|
On May 16 Yves Grenier wrote: > Starting ffado may cause jackd to crash, depending on the order in which > both were started: [...] > Is this the same problem as the one reported in ticket #345? I very much think so, yes. -- Stefan Richter -=====-===-- -=-= =---- http://arcgraph.de/sr/ |
From: Jonathan W. <jw...@ju...> - 2012-05-17 00:11:42
|
On Wed, May 16, 2012 at 08:26:27PM +0200, Stefan Richter wrote: > On May 16 Yves Grenier wrote: > > Starting ffado may cause jackd to crash, depending on the order in which > > both were started: > [...] > > Is this the same problem as the one reported in ticket #345? > > I very much think so, yes. It definitely is. jonathan |
From: Jonathan W. <jw...@ju...> - 2012-05-17 00:36:17
|
On Wed, May 16, 2012 at 08:21:29PM +0200, Philippe Carriere wrote: > Le mercredi 16 mai 2012 à 20:00 +0200, Yves Grenier a écrit : > > > > Starting ffado may cause jackd to crash, depending on the order in which > > both were started: > > > > Case 1) I start jackd, then I start ffado-mixer: jack crashes (below is > > the log, obtained with "-v 4") > > > > Case 2) I first start ffado-mixer, then I start jackd, everything goes > > well, I may even stop and restart ffado-mixer. > > > > My configuration: > > Focusrite Saffire Pro 24 > > jackdmp, version 1.9.8 (ubuntu precise 12.04 package) > > ffado compiled from svn, revision 2149 > > > I confirm the behaviour; more precisely this is the ffado-dbus-server > start-up which leads to jack crash. Indeed. It appears to be ffado-dbus-server in combination with the saffire devices which cause this issue for some as yet unknown reason. To test this explicitly, could one of you start streaming via jackd and then manually start ffado-dbus-server? If it's the ffado-dbus-server startup that's causing the trouble then you'll get a jack crash. Also, could you run "ffado-dbus-server -v 6" and post the resulting output? I'd like to take a look at what goes on at the start. This could be done both with and without jackd running so a comparison could be made. I don't yet know whether the saffire devices are the only ones affected. I have tested this with my MOTU and RME deviecs and they don't encounter the problem. It remains to be seen whether this indicates that these devices are truly unaffected - for some reason my development system may be immune from the problem. At this point I really can't see how ffado-dbus-server is capable of taking the streaming out like this. With devices like the saffire there are possibly a lot of dbus controls to set up, but I wouldn't have expected there to be significantly more than the RME/MOTUs. As far as I know dbus is fully in userspace and as such it should behave as any other userspace application and not be capable of upsetting the realtime audio threads in jackd and libffado. Clearly there's an important piece of the puzzle which remains hidden. What I find interesting about the debug output provided by Philippe is that the cause of the trouble seems to be a lack of incoming data from the interface: 02048552522: Warning (IsoHandlerManager.cpp)[ 292] Execute: Timeout while waiting for activity 02049508559: Fatal (IsoHandlerManager.cpp)[ 348] Execute: (0x953ec40, Receive) Handler died: now: 77929513, last: 738FF965, diff: 49279918 (max: 49152000) On the face of it, this indicates that something done by ffado-dbus-server on startup locked the kernel's interface with the device and prevented iso packets being delivered to FFADO. But if it were this then we'd see it on every device - unless there's something about the saffires which cause things to be locked for a far longer period of time compared to other interfaces. Another option is that ffado-dbus-server does something during startup which causes the saffire devices to reset (or at least come out of streaming mode). A quick glance through the DICE code doesn't turn up anything, but it would require a more careful evaluation before we can be sure. For example, I notice that the saffires define an extensive lock() method. However, as far as I can tell this is only ever called by the DeviceManager::initStreaming() method and therefore would not be expected to be activated during ffado-dbus-server startup (since it doesn't do streaming). The Saffires also make use of ARMs and these are done during lower level device setup - and therefore ffado-dbus-server will attempt to set them up. Perhaps doing this while streaming is running causes trouble (but that would require that the ARMs form an integral part of the saffire streaming functionality). Regards jonathan |
From: Stefan R. <st...@s5...> - 2012-05-17 09:18:12
|
On May 17 Jonathan Woithe wrote: > What I find interesting about the debug output provided by Philippe is that > the cause of the trouble seems to be a lack of incoming data from the > interface: > > 02048552522: Warning (IsoHandlerManager.cpp)[ 292] Execute: Timeout > while waiting for activity > 02049508559: Fatal (IsoHandlerManager.cpp)[ 348] Execute: (0x953ec40, > Receive) Handler died: now: 77929513, last: 738FF965, diff: 49279918 > (max: 49152000) > > On the face of it, this indicates that something done by ffado-dbus-server > on startup locked the kernel's interface with the device and prevented iso > packets being delivered to FFADO. But if it were this then we'd see it on > every device - unless there's something about the saffires which cause > things to be locked for a far longer period of time compared to other > interfaces. The kernel does not block between initiation and completion of I/Os. Some of the libraw1394 calls do but this of course is local to raw1394handle instances. If the ffado iso handlers do not communicate with ffado-dbus-server, then the conclusion is that the blocking or break-up of the stream is perpetrated on the other side of the cable: > Another option is that ffado-dbus-server does something during startup which > causes the saffire devices to reset (or at least come out of streaming > mode). A quick glance through the DICE code doesn't turn up anything, It is likely an issue of the Saffire PRO 24 and 40 firmwares --- possibly of some other DICE device firmwares too but there was no such report yet. Somebody with one of those devices should run a ffado-dbus-server which has breakpoints or pauses inserted between what could be called DICE protocol transactions --- or simply between all 1394 asynchronous transactions --- to find out which one correlate with the iso handler timeout in jackd. (I have got a Saffire PRO 24 but almost no experience with debuggers, little spare time, and little motivation to get to the bottom of this issue since I rarely use the Saffire and almost never use ffado-dbus-server.) -- Stefan Richter -=====-===-- -=-= =---= http://arcgraph.de/sr/ |
From: Yves G. <yve...@nu...> - 2012-05-18 14:03:43
|
Le 17/05/2012 02:36, Jonathan Woithe a écrit : > On Wed, May 16, 2012 at 08:21:29PM +0200, Philippe Carriere wrote: >> Le mercredi 16 mai 2012 à 20:00 +0200, Yves Grenier a écrit : >>> Starting ffado may cause jackd to crash, depending on the order in which >>> both were started: >>> >>> Case 1) I start jackd, then I start ffado-mixer: jack crashes (below is >>> the log, obtained with "-v 4") >>> >>> Case 2) I first start ffado-mixer, then I start jackd, everything goes >>> well, I may even stop and restart ffado-mixer. >>> >>> My configuration: >>> Focusrite Saffire Pro 24 >>> jackdmp, version 1.9.8 (ubuntu precise 12.04 package) >>> ffado compiled from svn, revision 2149 >>> >> I confirm the behaviour; more precisely this is the ffado-dbus-server >> start-up which leads to jack crash. > Indeed. It appears to be ffado-dbus-server in combination with the saffire > devices which cause this issue for some as yet unknown reason. To test > this explicitly, could one of you start streaming via jackd and then > manually start ffado-dbus-server? If it's the ffado-dbus-server startup > that's causing the trouble then you'll get a jack crash. > > Also, could you run "ffado-dbus-server -v 6" and post the resulting output? > I'd like to take a look at what goes on at the start. This could be done > both with and without jackd running so a comparison could be made. Hi Jonathan I have done these tests. I will send them to you joined to a private message (the logs are too large to be sent to the list). Regards Yves |
From: Yves G. <yve...@nu...> - 2012-05-18 14:48:49
|
Hello I am pursuing these tests with Saffire Pro 24 and svn (rev 2149) and am facing yet another problem. My Pro 24 is powered, jack is not yet started, I start the command "ffado-test BusReset". It prints several lines up to "Doing busreset on port 0" and then nothing... Never gives back control to the terminal! A side effect is that I may start jack in a terminal with "jackd -d firewire" but I cannot start jack with qjackctl, since qjackctl gets blocked and does not respond after I clicked on start. I need to kill qjackctl, qjackctl.real before I can start jackd again inthe terminal. Other options of ffado-test like Discover or ListDevices work as expected. Regards Yves |
From: Stefan R. <st...@s5...> - 2012-05-18 16:23:09
|
On May 18 Yves Grenier wrote: > Hello > > I am pursuing these tests with Saffire Pro 24 and svn (rev 2149) and am > facing yet another problem. > > My Pro 24 is powered, jack is not yet started, I start the command > "ffado-test BusReset". It prints several lines up to "Doing busreset on > port 0" and then nothing... Never gives back control to the terminal! If you use raw1394 etc., or firewire-core from kernel 2.6.35 or older, then this action immediately resets the bus by writing and reading some controller registers. If you use firewire-core from kernel 2.6.36 or newer, then this action only queues a job within the kernel which some time later (can be immediately after queueing; it depends on how long ago the last bus reset happened) sends a PHY configuration packet in order to preserve the current gap count, waits for the packet to be transmitted, then resets the bus. This is all done in a kernel thread; the application is not blocked by this. What kernel version do you use, and what FireWire controller do you have? You could try whether resetting the bus with another program works: # firecontrol <<< br or # gscanbus -> Control -> Force Bus Reset Firecontrol and gscanbus need to be run as root, or as a user who has access to all /dev/fw* (or to /dev/raw1394 if you still use the old kernel drivers). Furthermore, you can watch what happens with # echo -1 > /sys/module/firewire_ohci/parameters/debug # tail -f /var/log/messages running in another terminal (provided you use the newer kernel drivers). > A side effect is that I may start jack in a terminal with "jackd -d > firewire" but I cannot start jack with qjackctl, since qjackctl gets > blocked and does not respond after I clicked on start. I need to kill > qjackctl, qjackctl.real before I can start jackd again inthe terminal. Sounds like the bus went into a reset loop. It is not supposed to though. -- Stefan Richter -=====-===-- -=-= =--=- http://arcgraph.de/sr/ |
From: Yves G. <yve...@nu...> - 2012-05-18 17:27:28
|
Le 18/05/2012 18:22, Stefan Richter a écrit : > On May 18 Yves Grenier wrote: >> Hello >> >> I am pursuing these tests with Saffire Pro 24 and svn (rev 2149) and am >> facing yet another problem. >> >> My Pro 24 is powered, jack is not yet started, I start the command >> "ffado-test BusReset". It prints several lines up to "Doing busreset on >> port 0" and then nothing... Never gives back control to the terminal! > If you use raw1394 etc., or firewire-core from kernel 2.6.35 or older, then > this action immediately resets the bus by writing and reading some > controller registers. > > If you use firewire-core from kernel 2.6.36 or newer, then this action > only queues a job within the kernel which some time later (can be > immediately after queueing; it depends on how long ago the last bus reset > happened) sends a PHY configuration packet in order to preserve the > current gap count, waits for the packet to be transmitted, then resets the > bus. This is all done in a kernel thread; the application is not blocked > by this. > > What kernel version do you use, and what FireWire controller do you have? $ uname -r 3.2.0-23-lowlatency ffado-test BusReset remains blocked (I waited several minutes before typing Ctrl-C). > > You could try whether resetting the bus with another program works: > > # firecontrol<<< br > > or > > # gscanbus > -> Control -> Force Bus Reset > > Firecontrol and gscanbus need to be run as root, or as a user who has > access to all /dev/fw* (or to /dev/raw1394 if you still use the old kernel > drivers). I tried with scanbus. I see no error message, but do not know what is happening. > > Furthermore, you can watch what happens with > # echo -1> /sys/module/firewire_ohci/parameters/debug > # tail -f /var/log/messages > running in another terminal (provided you use the newer kernel drivers). I see messages neither when resetting with scanbus, nor when trying to reset with ffado-test. But now, I can give more details: - once the bus has been reset by scanbus, "ffado-test BusReset" works and ends as usual, - when the Saffire Pro 24 is swiched off then on, "ffado-test BusReset" never ends (until a new reset is done with gscanbus). Regards Yves |
From: Jonathan W. <jw...@ju...> - 2012-05-19 06:23:28
|
Hi all On Fri, May 18, 2012 at 04:48:37PM +0200, Yves Grenier wrote: > I am pursuing these tests with Saffire Pro 24 and svn (rev 2149) and am > facing yet another problem. > > My Pro 24 is powered, jack is not yet started, I start the command > "ffado-test BusReset". It prints several lines up to "Doing busreset on > port 0" and then nothing... Never gives back control to the terminal! Hmm, this is most interesting because of something else that I've noted recently. I'm presently running a preempt 3.2.4 kernel, and I've noticed that if I carry out the following steps with a Fireface 800 the computer locks hard: 1) Boot PC 2) Power up ff800 3) Start jack. It runs normally. 4) Ctrl-C jack. It exits just fine with no errors. 5) Turn off the FF800 6) Within 10 seconds the computer has locked up I'm yet to test whether steps 3 and 4 are necessary - it's on my list of things to do. Similarly, I haven't tested other interfaces to see if they give rise to similar problems. I mention this because turning a device off will produce a bus reset, and it seems I'm seeing some odd behaviour in connection with this, as Yves is. I have no idea whether this observation is linked to what Yves is seeing or not. There is a point in common - bus resets - but I'll see if I can narrow things down further over the coming days. My workaround at present is to simply not power the FF800 off. > A side effect is that I may start jack in a terminal with "jackd -d > firewire" but I cannot start jack with qjackctl, since qjackctl gets > blocked and does not respond after I clicked on start. I need to kill > qjackctl, qjackctl.real before I can start jackd again inthe terminal. That's odd. I can't see how any of this would affect qjackctl and yet not jackd itself. Hmm. Regards jonathan |
From: Stefan R. <st...@s5...> - 2012-05-19 07:58:28
|
On May 19 Jonathan Woithe wrote: > I'm presently running a preempt 3.2.4 kernel, and I've noticed > that if I carry out the following steps with a Fireface 800 the computer > locks hard: > > 1) Boot PC > 2) Power up ff800 > 3) Start jack. It runs normally. > 4) Ctrl-C jack. It exits just fine with no errors. > 5) Turn off the FF800 > 6) Within 10 seconds the computer has locked up > > I'm yet to test whether steps 3 and 4 are necessary - it's on my list of > things to do. Similarly, I haven't tested other interfaces to see if they > give rise to similar problems. I mention this because turning a device off > will produce a bus reset, and it seems I'm seeing some odd behaviour in > connection with this, as Yves is. It is not comparable with Yves' issue. There the application is simply waiting for something to happen but can still be interrupted with Ctrl-C. I.e. it is not stuck in an interruptible kernel call. In contrast, the computer locking up usually means there is a kernel bug. It could also be a hardware fault. > I have no idea whether this observation is linked to what Yves is seeing or > not. There is a point in common - bus resets - but I'll see if I can narrow > things down further over the coming days. Best would be if you could insert the netconsole kernel module on the faulty PC and get it to log kernel messages to a second PC (on which syslogd is configured to listen for remote log messages). If you don't have another PC, at least the following may give at least some messages before the crash: After step 4), switch from X11 to a text console (Ctr-Alt-F1), log in as root, run # dmesg -n 7 # echo -1 > /sys/module/firewire_ohci/parameters/debug then turn off the FF800. If you get anything from that, photograph it and upload the screenshot to bugzilla.kernel.org or to some other site that's convenient to you. More things to find out: - Does it make a difference if you unplug the FF800 rather than switch it off? - After jackd exited, does "lsof /dev/fw*" still show any process holding one or more of such files open? - Does the FF800 expose an SBP-2 storage unit alongside the audio unit? -- Stefan Richter -=====-===-- -=-= =--== http://arcgraph.de/sr/ |
From: Stefan R. <st...@s5...> - 2012-05-19 08:20:08
|
On May 18 Yves Grenier wrote: > Le 18/05/2012 18:22, Stefan Richter a écrit : > > Furthermore, you can watch what happens with > > # echo -1 > /sys/module/firewire_ohci/parameters/debug > > # tail -f /var/log/messages > > running in another terminal (provided you use the newer kernel drivers). > > I see messages neither when resetting with scanbus, nor when trying to > reset with ffado-test. Then the kernel messages are logged to a different syslog file which you may be able to find with "grep -lr firewire /var/log", or syslogd does not receive kernel messages at all, which would be odd. In any case, you can read current kernel messages by "dmesg" (or "dmesg | tail -40" to get just the last part of the message buffer). The convenient "tail -f" to watch for new messages as they happen does not work with dmesg though. (Or you could use the trick that I mentioned in the orther mail --- switch to text console, get live kernel messages logged there after "dmesg -n 7" --- but then you are limited to command line programs, e.g. firecontrol instead of gscanbus.) Of course nothing of that will do anything if there are in fact no kernel messages at all. But I doubt that, given that gscanbus seems to have /some/ effect. > But now, I can give more details: > - once the bus has been reset by scanbus, "ffado-test BusReset" works > and ends as usual, > - when the Saffire Pro 24 is swiched off then on, "ffado-test BusReset" > never ends (until a new reset is done with gscanbus). Since it hangs after "Doing busreset on port 0", and the libffado + libraw1394 + firewire-core code which initiates a bus reset is so simple, the hang certainly occurs in the libffado debugmodule. -- Stefan Richter -=====-===-- -=-= =--== http://arcgraph.de/sr/ |
From: Stefan R. <st...@s5...> - 2012-05-19 09:35:42
|
> > Le 18/05/2012 18:22, Stefan Richter a écrit : > > > # echo -1 > /sys/module/firewire_ohci/parameters/debug > > > # tail -f /var/log/messages PS: To show you what is expected to happen, this is what I get when I run "ffado-test BusReset" on a bus consisting of a FireWire 800 controller (phy ID 1, node ID ffc1, = root node) and a Saffire PRO 24 (phy ID 0, node ID ffc0): May 19 10:34:53 stein kernel: firewire_ohci 0000:05:00.0: IRQ 00000001 AT_req May 19 10:34:53 stein kernel: firewire_ohci 0000:05:00.0: AT ack_complete, PHY 00450000 ffbaffff May 19 10:34:53 stein kernel: firewire_ohci 0000:05:00.0: IRQ 00000010 AR_req May 19 10:34:53 stein kernel: firewire_ohci 0000:05:00.0: AR evt_bus_reset, generation 24 May 19 10:34:53 stein kernel: firewire_ohci 0000:05:00.0: IRQ 00010000 selfID May 19 10:34:53 stein kernel: firewire_ohci 0000:05:00.0: 2 selfIDs, generation 24, local node ID ffc1 May 19 10:34:53 stein kernel: firewire_ohci 0000:05:00.0: selfID 0: 80458f80, phy 0 [p..] S400 gc=5 -3..-10W Lc May 19 10:34:53 stein kernel: firewire_ohci 0000:05:00.0: selfID 0: 8145cc76, phy 1 [-c-] beta gc=5 -3W Lci May 19 10:34:53 stein kernel: firewire_ohci 0000:05:00.0: IRQ 00000001 AT_req May 19 10:34:53 stein kernel: firewire_ohci 0000:05:00.0: AT spd 2 tl 12, ffc1 -> ffc0, ack_pending , QR req, fffff0000234 May 19 10:35:12 stein kernel: firewire_ohci 0000:05:00.0: IRQ 00200000 cycle64Seconds (Kernels 3.3 and older do not show the numeric ID of the card at the beginning of the message.) Curious; this highlights an apparent quirk of the Saffire PRO 24 firmware wich I never noticed before: The kernel asks the Saffire to show its BROADCAST_CHANNEL register contents (quadlet read request to address fffff0000234), the Saffire ACKs the request, but never sends a response. Here is the same after I made the Saffire to be root node (phy ID 1; the FireWire 800 controller is now at phy ID 0): May 19 11:18:02 stein kernel: firewire_ohci 0000:05:00.0: IRQ 00000001 AT_req May 19 11:18:02 stein kernel: firewire_ohci 0000:05:00.0: AT ack_complete, PHY 00450000 ffbaffff May 19 11:18:02 stein kernel: firewire_ohci 0000:05:00.0: IRQ 00000010 AR_req May 19 11:18:02 stein kernel: firewire_ohci 0000:05:00.0: AR evt_bus_reset, generation 40 May 19 11:18:02 stein kernel: firewire_ohci 0000:05:00.0: IRQ 00010000 selfID May 19 11:18:02 stein kernel: firewire_ohci 0000:05:00.0: 2 selfIDs, generation 40, local node ID ffc0 May 19 11:18:02 stein kernel: firewire_ohci 0000:05:00.0: selfID 0: 8045cc66, phy 0 [-p-] beta gc=5 -3W Lci May 19 11:18:02 stein kernel: firewire_ohci 0000:05:00.0: selfID 0: 81458fc0, phy 1 [c..] S400 gc=5 -3..-10W Lc May 19 11:18:02 stein kernel: firewire_ohci 0000:05:00.0: IRQ 00000001 AT_req May 19 11:18:02 stein kernel: firewire_ohci 0000:05:00.0: AT spd 0 tl 3f, ffc0 -> ffc1, ack_pending , Lk req, fffff000021c 8,2 May 19 11:18:02 stein kernel: firewire_ohci 0000:05:00.0: IRQ 00000020 AR_resp May 19 11:18:02 stein kernel: firewire_ohci 0000:05:00.0: AR spd 0 tl 3f, ffc1 -> ffc0, ack_complete, Lk resp 4,0 May 19 11:18:02 stein kernel: firewire_ohci 0000:05:00.0: IRQ 00000001 AT_req May 19 11:18:02 stein kernel: firewire_ohci 0000:05:00.0: AT spd 0 tl 00, ffc0 -> ffc1, ack_pending , QW req, fffff0000004 = 00000100 May 19 11:18:02 stein kernel: firewire_ohci 0000:05:00.0: IRQ 00000020 AR_resp May 19 11:18:02 stein kernel: firewire_ohci 0000:05:00.0: AR spd 0 tl 00, ffc1 -> ffc0, ack_complete, W resp May 19 11:18:55 stein kernel: firewire_ohci 0000:05:00.0: IRQ 00200000 cycle64Seconds After self-identification, the Linux kernel accesses the Saffire's BUS_MANAGER_ID and STATE_SET registers (lock request to address fffff000021c, quadlet write request to address fffff0000004, both are ACKed and responded to). So that works fully as expected here. The BROADCAST_CHANNEL access is not attempted this time because the Linux node is not isochronous resource manager, unlike in the previous session. In both sessions, "ffado-test BusReset" wrote... ----------------------------------------------- FFADO test and diagnostic utility Part of the FFADO project -- www.ffado.org Version: 2.999.0-2125 (C) 2008, Daniel Wagner, Pieter Palmers This program comes with ABSOLUTELY NO WARRANTY. ----------------------------------------------- Doing busreset on port 0 no message buffer overruns ...and exited. A brief lag of less than a second was noticeable between the last two lines. -- Stefan Richter -=====-===-- -=-= =--== http://arcgraph.de/sr/ |
From: Yves G. <yve...@nu...> - 2012-05-19 09:56:56
|
Le 19/05/2012 10:19, Stefan Richter a écrit : > On May 18 Yves Grenier wrote: >> Le 18/05/2012 18:22, Stefan Richter a écrit : >>> Furthermore, you can watch what happens with >>> # echo -1> /sys/module/firewire_ohci/parameters/debug >>> # tail -f /var/log/messages >>> running in another terminal (provided you use the newer kernel drivers). >> I see messages neither when resetting with scanbus, nor when trying to >> reset with ffado-test. > Then the kernel messages are logged to a different syslog file which you > may be able to find with "grep -lr firewire /var/log", or syslogd does not > receive kernel messages at all, which would be odd. In any case, you can > read current kernel messages by "dmesg" (or "dmesg | tail -40" to get just > the last part of the message buffer). The convenient "tail -f" to watch > for new messages as they happen does not work with dmesg though. > Hi Stefan The relevant file was /var/log/kern.log And here is the log from the moment where I switch the Focusrite Saffire Pro 24 OFF then ON. The final line is obtained after ffado-test BusReset prints "Doing busreset on port 0" and does not give back control to the terminal. I waited a quarter of an hour to be sure that nothing else would appear in kern.log and I copied the following lines. Regards Yves ****************May 19 11:27:54 pc-manou kernel: [ 3464.679671] firewire_ohci: AT spd 2 tl 08, ffc1 -> ffc0, ack_pending , QR req, fffff0000454 May 19 11:27:54 pc-manou kernel: [ 3464.681410] firewire_ohci: AR spd 2 tl 08, ffc0 -> ffc1, ack_complete, QR resp = 73726974 May 19 11:27:54 pc-manou kernel: [ 3464.681471] firewire_ohci: AT spd 2 tl 09, ffc1 -> ffc0, ack_pending , QR req, fffff0000458 May 19 11:27:54 pc-manou kernel: [ 3464.682953] firewire_ohci: AR spd 2 tl 09, ffc0 -> ffc1, ack_complete, QR resp = 65000000 May 19 11:27:54 pc-manou kernel: [ 3464.683233] firewire_core: created device fw1: GUID 00130e0401c00f89, S400, 1 config ROM retries May 19 11:27:54 pc-manou kernel: [ 3464.683271] firewire_ohci: AT spd 2 tl 0a, ffc1 -> ffc0, ack_pending , QR req, fffff0000234 May 19 11:27:54 pc-manou kernel: [ 3464.794124] firewire_ohci: AT spd 2 tl 0e, ffc1 -> ffc0, ack_pending , QR req, fffff0000234 May 19 11:28:03 pc-manou kernel: [ 3473.628084] firewire_ohci: AT ack_complete, PHY 00450000 ffbaffff May 19 11:28:03 pc-manou kernel: [ 3473.628182] firewire_ohci: AR evt_bus_reset, generation 19 May 19 11:28:03 pc-manou kernel: [ 3473.628509] firewire_ohci: AT spd 2 tl 1a, ffc1 -> ffc0, ack_pending , QR req, fffff0000234 May 19 11:54:09 pc-manou kernel: [ 5040.054821] firewire_ohci: IRQ 00010010 selfID AR_req May 19 11:54:09 pc-manou kernel: [ 5040.054837] firewire_ohci: AR evt_bus_reset, generation 20 May 19 11:54:09 pc-manou kernel: [ 5040.054881] firewire_ohci: 1 selfIDs, generation 20, local node ID ffc0 May 19 11:54:09 pc-manou kernel: [ 5040.054889] firewire_ohci: selfID 0: 807f8952, phy 0 [--.] S400 gc=63 +15W Lci May 19 11:54:23 pc-manou kernel: [ 5054.255290] firewire_ohci: IRQ 00000010 AR_req May 19 11:54:23 pc-manou kernel: [ 5054.255302] firewire_ohci: AR evt_bus_reset, generation 21 May 19 11:54:23 pc-manou kernel: [ 5054.255307] firewire_ohci: AR evt_bus_reset, generation 21 May 19 11:54:23 pc-manou kernel: [ 5054.255470] firewire_ohci: IRQ 00810000 selfID cycleInconsistent May 19 11:54:23 pc-manou kernel: [ 5054.255480] firewire_ohci: isochronous cycle inconsistent May 19 11:54:23 pc-manou kernel: [ 5054.255506] firewire_ohci: 2 selfIDs, generation 22, local node ID ffc0 May 19 11:54:23 pc-manou kernel: [ 5054.255514] firewire_ohci: selfID 0: 807f8990, phy 0 [p-.] S400 gc=63 +15W Lc May 19 11:54:23 pc-manou kernel: [ 5054.255521] firewire_ohci: selfID 0: 817f87c2, phy 1 [c..] S400 gc=63 -3..-10W Li May 19 11:54:23 pc-manou kernel: [ 5054.255526] firewire_core: skipped bus generations, destroying all nodes May 19 11:54:24 pc-manou kernel: [ 5054.756110] firewire_core: rediscovered device fw0 May 19 11:54:24 pc-manou kernel: [ 5054.756166] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:24 pc-manou kernel: [ 5054.756177] firewire_ohci: AT spd 0 tl 3d, ffc0 -> ffc1, ack_pending , QR req, fffff0000400 May 19 11:54:27 pc-manou kernel: [ 5057.692809] firewire_ohci: IRQ 00000010 AR_req May 19 11:54:27 pc-manou kernel: [ 5057.692819] firewire_ohci: AR evt_bus_reset, generation 23 May 19 11:54:27 pc-manou kernel: [ 5057.692987] firewire_ohci: IRQ 00010000 selfID May 19 11:54:27 pc-manou kernel: [ 5057.693048] firewire_ohci: 2 selfIDs, generation 23, local node ID ffc0 May 19 11:54:27 pc-manou kernel: [ 5057.693060] firewire_ohci: selfID 0: 807f8990, phy 0 [p-.] S400 gc=63 +15W Lc May 19 11:54:27 pc-manou kernel: [ 5057.693071] firewire_ohci: selfID 0: 817f8fc2, phy 1 [c..] S400 gc=63 -3..-10W Lci May 19 11:54:27 pc-manou kernel: [ 5057.693121] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:27 pc-manou kernel: [ 5057.693135] firewire_ohci: AT spd 0 tl 3e, ffc0 -> ffc1, ack_pending , Lk req, fffff000021c 8,2 May 19 11:54:29 pc-manou kernel: [ 5059.696020] firewire_core: BM lock failed, making local node (ffc0) root. May 19 11:54:29 pc-manou kernel: [ 5059.696028] firewire_core: phy config: card 0, new root=ffc0, gap_count=5 May 19 11:54:29 pc-manou kernel: [ 5059.696061] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.696069] firewire_ohci: AT ack_complete, PHY 00c50000 ff3affff May 19 11:54:29 pc-manou kernel: [ 5059.696126] firewire_ohci: IRQ 00010010 selfID AR_req May 19 11:54:29 pc-manou kernel: [ 5059.696137] firewire_ohci: AR evt_bus_reset, generation 24 May 19 11:54:29 pc-manou kernel: [ 5059.696175] firewire_ohci: 2 selfIDs, generation 24, local node ID ffc1 May 19 11:54:29 pc-manou kernel: [ 5059.696183] firewire_ohci: selfID 0: 80458f80, phy 0 [p..] S400 gc=5 -3..-10W Lc May 19 11:54:29 pc-manou kernel: [ 5059.696190] firewire_ohci: selfID 0: 814589d2, phy 1 [c-.] S400 gc=5 +15W Lci May 19 11:54:29 pc-manou kernel: [ 5059.768050] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.768059] firewire_ohci: AT spd 0 tl 05, ffc1 -> ffc0, ack_pending , QR req, fffff0000400 May 19 11:54:29 pc-manou kernel: [ 5059.769242] firewire_ohci: IRQ 00000020 AR_resp May 19 11:54:29 pc-manou kernel: [ 5059.769249] firewire_ohci: AR spd 0 tl 05, ffc0 -> ffc1, ack_complete, QR resp = 040410e0 May 19 11:54:29 pc-manou kernel: [ 5059.769281] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.769287] firewire_ohci: AT spd 0 tl 06, ffc1 -> ffc0, ack_pending , QR req, fffff0000404 May 19 11:54:29 pc-manou kernel: [ 5059.770989] firewire_ohci: IRQ 00000020 AR_resp May 19 11:54:29 pc-manou kernel: [ 5059.770995] firewire_ohci: AR spd 0 tl 06, ffc0 -> ffc1, ack_complete, QR resp = 31333934 May 19 11:54:29 pc-manou kernel: [ 5059.771033] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.771079] firewire_ohci: AT spd 0 tl 07, ffc1 -> ffc0, ack_pending , QR req, fffff0000408 May 19 11:54:29 pc-manou kernel: [ 5059.772777] firewire_ohci: IRQ 00000020 AR_resp May 19 11:54:29 pc-manou kernel: [ 5059.772783] firewire_ohci: AR spd 0 tl 07, ffc0 -> ffc1, ack_complete, QR resp = e0ff8112 May 19 11:54:29 pc-manou kernel: [ 5059.772813] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.772819] firewire_ohci: AT spd 0 tl 08, ffc1 -> ffc0, ack_pending , QR req, fffff000040c May 19 11:54:29 pc-manou kernel: [ 5059.774571] firewire_ohci: IRQ 00000020 AR_resp May 19 11:54:29 pc-manou kernel: [ 5059.774577] firewire_ohci: AR spd 0 tl 08, ffc0 -> ffc1, ack_complete, QR resp = 00130e04 May 19 11:54:29 pc-manou kernel: [ 5059.774607] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.774612] firewire_ohci: AT spd 0 tl 09, ffc1 -> ffc0, ack_pending , QR req, fffff0000410 May 19 11:54:29 pc-manou kernel: [ 5059.776604] firewire_ohci: IRQ 00000020 AR_resp May 19 11:54:29 pc-manou kernel: [ 5059.776609] firewire_ohci: AR spd 0 tl 09, ffc0 -> ffc1, ack_complete, QR resp = 01c00f89 May 19 11:54:29 pc-manou kernel: [ 5059.776638] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.776643] firewire_ohci: AT spd 2 tl 0a, ffc1 -> ffc0, ack_pending , QR req, fffff0000414 May 19 11:54:29 pc-manou kernel: [ 5059.778111] firewire_ohci: IRQ 00000020 AR_resp May 19 11:54:29 pc-manou kernel: [ 5059.778117] firewire_ohci: AR spd 2 tl 0a, ffc0 -> ffc1, ack_complete, QR resp = 00061371 May 19 11:54:29 pc-manou kernel: [ 5059.778145] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.778150] firewire_ohci: AT spd 2 tl 0b, ffc1 -> ffc0, ack_pending , QR req, fffff0000418 May 19 11:54:29 pc-manou kernel: [ 5059.779876] firewire_ohci: IRQ 00000020 AR_resp May 19 11:54:29 pc-manou kernel: [ 5059.779881] firewire_ohci: AR spd 2 tl 0b, ffc0 -> ffc1, ack_complete, QR resp = 0300130e May 19 11:54:29 pc-manou kernel: [ 5059.779910] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.779915] firewire_ohci: AT spd 2 tl 0c, ffc1 -> ffc0, ack_pending , QR req, fffff000041c May 19 11:54:29 pc-manou kernel: [ 5059.781632] firewire_ohci: IRQ 00000020 AR_resp May 19 11:54:29 pc-manou kernel: [ 5059.781638] firewire_ohci: AR spd 2 tl 0c, ffc0 -> ffc1, ack_complete, QR resp = 8100000a May 19 11:54:29 pc-manou kernel: [ 5059.781666] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.781671] firewire_ohci: AT spd 2 tl 0d, ffc1 -> ffc0, ack_pending , QR req, fffff0000420 May 19 11:54:29 pc-manou kernel: [ 5059.783141] firewire_ohci: IRQ 00000020 AR_resp May 19 11:54:29 pc-manou kernel: [ 5059.783147] firewire_ohci: AR spd 2 tl 0d, ffc0 -> ffc1, ack_complete, QR resp = 17000007 May 19 11:54:29 pc-manou kernel: [ 5059.783175] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.783180] firewire_ohci: AT spd 2 tl 0e, ffc1 -> ffc0, ack_pending , QR req, fffff0000424 May 19 11:54:29 pc-manou kernel: [ 5059.784903] firewire_ohci: IRQ 00000020 AR_resp May 19 11:54:29 pc-manou kernel: [ 5059.784909] firewire_ohci: AR spd 2 tl 0e, ffc0 -> ffc1, ack_complete, QR resp = 8100000e May 19 11:54:29 pc-manou kernel: [ 5059.784940] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.784945] firewire_ohci: AT spd 2 tl 0f, ffc1 -> ffc0, ack_pending , QR req, fffff0000428 May 19 11:54:29 pc-manou kernel: [ 5059.787634] firewire_ohci: IRQ 00000020 AR_resp May 19 11:54:29 pc-manou kernel: [ 5059.787640] firewire_ohci: AR spd 2 tl 0f, ffc0 -> ffc1, ack_complete, QR resp = 0c0087c0 May 19 11:54:29 pc-manou kernel: [ 5059.787670] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.787676] firewire_ohci: AT spd 2 tl 10, ffc1 -> ffc0, ack_pending , QR req, fffff000042c May 19 11:54:29 pc-manou kernel: [ 5059.789177] firewire_ohci: IRQ 00000020 AR_resp May 19 11:54:29 pc-manou kernel: [ 5059.789183] firewire_ohci: AR spd 2 tl 10, ffc0 -> ffc1, ack_complete, QR resp = d1000001 May 19 11:54:29 pc-manou kernel: [ 5059.789214] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.789219] firewire_ohci: AT spd 2 tl 11, ffc1 -> ffc0, ack_pending , QR req, fffff0000430 May 19 11:54:29 pc-manou kernel: [ 5059.790927] firewire_ohci: IRQ 00000020 AR_resp May 19 11:54:29 pc-manou kernel: [ 5059.790935] firewire_ohci: AR spd 2 tl 11, ffc0 -> ffc1, ack_complete, QR resp = 0004a2d0 May 19 11:54:29 pc-manou kernel: [ 5059.790984] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.790990] firewire_ohci: AT spd 2 tl 12, ffc1 -> ffc0, ack_pending , QR req, fffff0000434 May 19 11:54:29 pc-manou kernel: [ 5059.792711] firewire_ohci: IRQ 00000020 AR_resp May 19 11:54:29 pc-manou kernel: [ 5059.792717] firewire_ohci: AR spd 2 tl 12, ffc0 -> ffc1, ack_complete, QR resp = 1200130e May 19 11:54:29 pc-manou kernel: [ 5059.792760] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.792766] firewire_ohci: AT spd 2 tl 13, ffc1 -> ffc0, ack_pending , QR req, fffff0000438 May 19 11:54:29 pc-manou kernel: [ 5059.794254] firewire_ohci: IRQ 00000020 AR_resp May 19 11:54:29 pc-manou kernel: [ 5059.794260] firewire_ohci: AR spd 2 tl 13, ffc0 -> ffc1, ack_complete, QR resp = 13000001 May 19 11:54:29 pc-manou kernel: [ 5059.794302] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.794307] firewire_ohci: AT spd 2 tl 14, ffc1 -> ffc0, ack_pending , QR req, fffff000043c May 19 11:54:29 pc-manou kernel: [ 5059.796262] firewire_ohci: IRQ 00000020 AR_resp May 19 11:54:29 pc-manou kernel: [ 5059.796268] firewire_ohci: AR spd 2 tl 14, ffc0 -> ffc1, ack_complete, QR resp = 17000007 May 19 11:54:29 pc-manou kernel: [ 5059.796310] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.796315] firewire_ohci: AT spd 2 tl 15, ffc1 -> ffc0, ack_pending , QR req, fffff0000440 May 19 11:54:29 pc-manou kernel: [ 5059.798038] firewire_ohci: IRQ 00000020 AR_resp May 19 11:54:29 pc-manou kernel: [ 5059.798044] firewire_ohci: AR spd 2 tl 15, ffc0 -> ffc1, ack_complete, QR resp = 8100000e May 19 11:54:29 pc-manou kernel: [ 5059.798086] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.798091] firewire_ohci: AT spd 2 tl 16, ffc1 -> ffc0, ack_pending , QR req, fffff0000478 May 19 11:54:29 pc-manou kernel: [ 5059.799835] firewire_ohci: IRQ 00000020 AR_resp May 19 11:54:29 pc-manou kernel: [ 5059.799840] firewire_ohci: AR spd 2 tl 16, ffc0 -> ffc1, ack_complete, QR resp = 0006200a May 19 11:54:29 pc-manou kernel: [ 5059.799883] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.799888] firewire_ohci: AT spd 2 tl 17, ffc1 -> ffc0, ack_pending , QR req, fffff000047c May 19 11:54:29 pc-manou kernel: [ 5059.801634] firewire_ohci: IRQ 00000020 AR_resp May 19 11:54:29 pc-manou kernel: [ 5059.801640] firewire_ohci: AR spd 2 tl 17, ffc0 -> ffc1, ack_complete, QR resp = 00000000 May 19 11:54:29 pc-manou kernel: [ 5059.801687] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.801693] firewire_ohci: AT spd 2 tl 18, ffc1 -> ffc0, ack_pending , QR req, fffff0000480 May 19 11:54:29 pc-manou kernel: [ 5059.803176] firewire_ohci: IRQ 00000020 AR_resp May 19 11:54:29 pc-manou kernel: [ 5059.803182] firewire_ohci: AR spd 2 tl 18, ffc0 -> ffc1, ack_complete, QR resp = 00000000 May 19 11:54:29 pc-manou kernel: [ 5059.803226] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.803232] firewire_ohci: AT spd 2 tl 19, ffc1 -> ffc0, ack_pending , QR req, fffff0000484 May 19 11:54:29 pc-manou kernel: [ 5059.804957] firewire_ohci: IRQ 00000020 AR_resp May 19 11:54:29 pc-manou kernel: [ 5059.804965] firewire_ohci: AR spd 2 tl 19, ffc0 -> ffc1, ack_complete, QR resp = 53414646 May 19 11:54:29 pc-manou kernel: [ 5059.805022] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.805028] firewire_ohci: AT spd 2 tl 1a, ffc1 -> ffc0, ack_pending , QR req, fffff0000488 May 19 11:54:29 pc-manou kernel: [ 5059.807644] firewire_ohci: IRQ 00000020 AR_resp May 19 11:54:29 pc-manou kernel: [ 5059.807654] firewire_ohci: AR spd 2 tl 1a, ffc0 -> ffc1, ack_complete, QR resp = 4952455f May 19 11:54:29 pc-manou kernel: [ 5059.807690] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.807695] firewire_ohci: AT spd 2 tl 1b, ffc1 -> ffc0, ack_pending , QR req, fffff000048c May 19 11:54:29 pc-manou kernel: [ 5059.809184] firewire_ohci: IRQ 00000020 AR_resp May 19 11:54:29 pc-manou kernel: [ 5059.809192] firewire_ohci: AR spd 2 tl 1b, ffc0 -> ffc1, ack_complete, QR resp = 50524f5f May 19 11:54:29 pc-manou kernel: [ 5059.809250] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.809256] firewire_ohci: AT spd 2 tl 1c, ffc1 -> ffc0, ack_pending , QR req, fffff0000490 May 19 11:54:29 pc-manou kernel: [ 5059.810981] firewire_ohci: IRQ 00000020 AR_resp May 19 11:54:29 pc-manou kernel: [ 5059.810990] firewire_ohci: AR spd 2 tl 1c, ffc0 -> ffc1, ack_complete, QR resp = 32340000 May 19 11:54:29 pc-manou kernel: [ 5059.811064] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.811070] firewire_ohci: AT spd 2 tl 1d, ffc1 -> ffc0, ack_pending , QR req, fffff000045c May 19 11:54:29 pc-manou kernel: [ 5059.812802] firewire_ohci: IRQ 00000020 AR_resp May 19 11:54:29 pc-manou kernel: [ 5059.812812] firewire_ohci: AR spd 2 tl 1d, ffc0 -> ffc1, ack_complete, QR resp = 0006200a May 19 11:54:29 pc-manou kernel: [ 5059.812874] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.812880] firewire_ohci: AT spd 2 tl 1e, ffc1 -> ffc0, ack_pending , QR req, fffff0000460 May 19 11:54:29 pc-manou kernel: [ 5059.814616] firewire_ohci: IRQ 00000020 AR_resp May 19 11:54:29 pc-manou kernel: [ 5059.814625] firewire_ohci: AR spd 2 tl 1e, ffc0 -> ffc1, ack_complete, QR resp = 00000000 May 19 11:54:29 pc-manou kernel: [ 5059.814687] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.814692] firewire_ohci: AT spd 2 tl 1f, ffc1 -> ffc0, ack_pending , QR req, fffff0000464 May 19 11:54:29 pc-manou kernel: [ 5059.816654] firewire_ohci: IRQ 00000020 AR_resp May 19 11:54:29 pc-manou kernel: [ 5059.816662] firewire_ohci: AR spd 2 tl 1f, ffc0 -> ffc1, ack_complete, QR resp = 00000000 May 19 11:54:29 pc-manou kernel: [ 5059.816725] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.816730] firewire_ohci: AT spd 2 tl 20, ffc1 -> ffc0, ack_pending , QR req, fffff0000468 May 19 11:54:29 pc-manou kernel: [ 5059.818214] firewire_ohci: IRQ 00000020 AR_resp May 19 11:54:29 pc-manou kernel: [ 5059.818223] firewire_ohci: AR spd 2 tl 20, ffc0 -> ffc1, ack_complete, QR resp = 53414646 May 19 11:54:29 pc-manou kernel: [ 5059.818287] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.818292] firewire_ohci: AT spd 2 tl 21, ffc1 -> ffc0, ack_pending , QR req, fffff000046c May 19 11:54:29 pc-manou kernel: [ 5059.820030] firewire_ohci: IRQ 00000020 AR_resp May 19 11:54:29 pc-manou kernel: [ 5059.820042] firewire_ohci: AR spd 2 tl 21, ffc0 -> ffc1, ack_complete, QR resp = 4952455f May 19 11:54:29 pc-manou kernel: [ 5059.820129] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.820135] firewire_ohci: AT spd 2 tl 22, ffc1 -> ffc0, ack_pending , QR req, fffff0000470 May 19 11:54:29 pc-manou kernel: [ 5059.821847] firewire_ohci: IRQ 00000020 AR_resp May 19 11:54:29 pc-manou kernel: [ 5059.821858] firewire_ohci: AR spd 2 tl 22, ffc0 -> ffc1, ack_complete, QR resp = 50524f5f May 19 11:54:29 pc-manou kernel: [ 5059.821926] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.821931] firewire_ohci: AT spd 2 tl 23, ffc1 -> ffc0, ack_pending , QR req, fffff0000474 May 19 11:54:29 pc-manou kernel: [ 5059.823669] firewire_ohci: IRQ 00000020 AR_resp May 19 11:54:29 pc-manou kernel: [ 5059.823678] firewire_ohci: AR spd 2 tl 23, ffc0 -> ffc1, ack_complete, QR resp = 32340000 May 19 11:54:29 pc-manou kernel: [ 5059.823749] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.823755] firewire_ohci: AT spd 2 tl 24, ffc1 -> ffc0, ack_pending , QR req, fffff0000444 May 19 11:54:29 pc-manou kernel: [ 5059.825245] firewire_ohci: IRQ 00000020 AR_resp May 19 11:54:29 pc-manou kernel: [ 5059.825255] firewire_ohci: AR spd 2 tl 24, ffc0 -> ffc1, ack_complete, QR resp = 00056f3b May 19 11:54:29 pc-manou kernel: [ 5059.825318] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.825323] firewire_ohci: AT spd 2 tl 25, ffc1 -> ffc0, ack_pending , QR req, fffff0000448 May 19 11:54:29 pc-manou kernel: [ 5059.827825] firewire_ohci: IRQ 00000020 AR_resp May 19 11:54:29 pc-manou kernel: [ 5059.827835] firewire_ohci: AR spd 2 tl 25, ffc0 -> ffc1, ack_complete, QR resp = 00000000 May 19 11:54:29 pc-manou kernel: [ 5059.827909] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.827915] firewire_ohci: AT spd 2 tl 26, ffc1 -> ffc0, ack_pending , QR req, fffff000044c May 19 11:54:29 pc-manou kernel: [ 5059.829643] firewire_ohci: IRQ 00000020 AR_resp May 19 11:54:29 pc-manou kernel: [ 5059.829650] firewire_ohci: AR spd 2 tl 26, ffc0 -> ffc1, ack_complete, QR resp = 00000000 May 19 11:54:29 pc-manou kernel: [ 5059.829704] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.829709] firewire_ohci: AT spd 2 tl 27, ffc1 -> ffc0, ack_pending , QR req, fffff0000450 May 19 11:54:29 pc-manou kernel: [ 5059.831201] firewire_ohci: IRQ 00000020 AR_resp May 19 11:54:29 pc-manou kernel: [ 5059.831208] firewire_ohci: AR spd 2 tl 27, ffc0 -> ffc1, ack_complete, QR resp = 466f6375 May 19 11:54:29 pc-manou kernel: [ 5059.831258] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.831264] firewire_ohci: AT spd 2 tl 28, ffc1 -> ffc0, ack_pending , QR req, fffff0000454 May 19 11:54:29 pc-manou kernel: [ 5059.832994] firewire_ohci: IRQ 00000020 AR_resp May 19 11:54:29 pc-manou kernel: [ 5059.833011] firewire_ohci: AR spd 2 tl 28, ffc0 -> ffc1, ack_complete, QR resp = 73726974 May 19 11:54:29 pc-manou kernel: [ 5059.833065] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.833071] firewire_ohci: AT spd 2 tl 29, ffc1 -> ffc0, ack_pending , QR req, fffff0000458 May 19 11:54:29 pc-manou kernel: [ 5059.834797] firewire_ohci: IRQ 00000020 AR_resp May 19 11:54:29 pc-manou kernel: [ 5059.834805] firewire_ohci: AR spd 2 tl 29, ffc0 -> ffc1, ack_complete, QR resp = 65000000 May 19 11:54:29 pc-manou kernel: [ 5059.834995] firewire_core: created device fw1: GUID 00130e0401c00f89, S400, 1 config ROM retries May 19 11:54:29 pc-manou kernel: [ 5059.835025] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.835031] firewire_ohci: AT spd 2 tl 2a, ffc1 -> ffc0, ack_pending , QR req, fffff0000234 May 19 11:54:29 pc-manou kernel: [ 5059.946080] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:29 pc-manou kernel: [ 5059.946093] firewire_ohci: AT spd 2 tl 2e, ffc1 -> ffc0, ack_pending , QR req, fffff0000234 May 19 11:54:35 pc-manou kernel: [ 5065.879044] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:35 pc-manou kernel: [ 5065.879051] firewire_ohci: AT ack_complete, PHY 00450000 ffbaffff May 19 11:54:35 pc-manou kernel: [ 5065.879079] firewire_ohci: IRQ 00000010 AR_req May 19 11:54:35 pc-manou kernel: [ 5065.879084] firewire_ohci: AR evt_bus_reset, generation 25 May 19 11:54:35 pc-manou kernel: [ 5065.879247] firewire_ohci: IRQ 00010000 selfID May 19 11:54:35 pc-manou kernel: [ 5065.879268] firewire_ohci: 2 selfIDs, generation 25, local node ID ffc1 May 19 11:54:35 pc-manou kernel: [ 5065.879273] firewire_ohci: selfID 0: 80458f80, phy 0 [p..] S400 gc=5 -3..-10W Lc May 19 11:54:35 pc-manou kernel: [ 5065.879277] firewire_ohci: selfID 0: 814589d2, phy 1 [c-.] S400 gc=5 +15W Lci May 19 11:54:35 pc-manou kernel: [ 5065.879352] firewire_ohci: IRQ 00000001 AT_req May 19 11:54:35 pc-manou kernel: [ 5065.879358] firewire_ohci: AT spd 2 tl 3a, ffc1 -> ffc0, ack_pending , QR req, fffff0000234 May 19 11:55:26 pc-manou kernel: [ 5117.316352] firewire_ohci: IRQ 00200000 cycle64Seconds |
From: Stefan R. <st...@s5...> - 2012-05-19 10:55:38
|
On May 19 Yves Grenier wrote: > The relevant file was /var/log/kern.log > And here is the log from the moment where I switch the Focusrite Saffire > Pro 24 OFF then ON. The final line is obtained after ffado-test BusReset > prints "Doing busreset on port 0" and does not give back control to the > terminal. I waited a quarter of an hour to be sure that nothing else > would appear in kern.log and I copied the following lines. [...] OK. Unless I missed something, this all looks like it is expected to look like. Does anybody have more ideas how to inspect what ffado-test is waiting for? Maybe strace could give a hint. Again for comparison, below is how the tail of the syscall trace looks for me. I put the full trace at http://paste.debian.net/170095/. $ strace ffado-test BusReset [...about 450 lines deleted...] open("/dev/raw1394", O_RDWR) = -1 ENOENT (No such file or directory) open("/dev/raw1394", O_RDWR) = -1 ENOENT (No such file or directory) epoll_create(16) = 27 pipe([29, 30]) = 0 inotify_init() = 31 inotify_add_watch(31, "/dev", IN_CREATE) = 1 epoll_ctl(27, EPOLL_CTL_ADD, 29, {EPOLLIN, {u32=36404288, u64=36404288}}) = 0 epoll_ctl(27, EPOLL_CTL_ADD, 31, {EPOLLIN, {u32=36404296, u64=36404296}}) = 0 open("/dev", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 32 getdents(32, /* 164 entries */, 32768) = 4712 open("/dev/fw4", O_RDWR) = 33 ioctl(33, FW_CDEV_IOC_GET_INFO, 0x7fff311f28c0) = 0 close(33) = 0 open("/dev/fw5", O_RDWR) = -1 EACCES (Permission denied) open("/dev/fw3", O_RDWR) = -1 EACCES (Permission denied) open("/dev/fw2", O_RDWR) = -1 EACCES (Permission denied) open("/dev/fw1", O_RDWR) = -1 EACCES (Permission denied) open("/dev/fw0", O_RDWR) = -1 EACCES (Permission denied) getdents(32, /* 0 entries */, 32768) = 0 close(32) = 0 close(31) = 0 close(29) = 0 close(30) = 0 close(27) = 0 ioctl(28, FW_CDEV_IOC_GET_CYCLE_TIMER, 0x7fff311f2830) = 0 clock_nanosleep(CLOCK_REALTIME, 0, {0, 1000000}, NULL) = 0 ioctl(28, FW_CDEV_IOC_GET_CYCLE_TIMER, 0x7fff311f2730) = 0 mmap(NULL, 8392704, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x7fcd3b28e000 mprotect(0x7fcd3b28e000, 4096, PROT_NONE) = 0 clone(child_stack=0x7fcd3ba8dfd0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x7fcd3ba8e9d0, tls=0x7fcd3ba8e700, child_tidptr=0x7fcd3ba8e9d0) = 19504 futex(0x22b7948, FUTEX_WAKE_PRIVATE, 1) = 1 mmap(NULL, 8392704, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x7fcd3aa8d000 mprotect(0x7fcd3aa8d000, 4096, PROT_NONE) = 0 clone(child_stack=0x7fcd3b28cfd0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x7fcd3b28d9d0, tls=0x7fcd3b28d700, child_tidptr=0x7fcd3b28d9d0) = 19505 futex(0x22b7d48, FUTEX_WAKE_PRIVATE, 1) = 1 mmap(NULL, 8392704, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x7fcd3a28c000 mprotect(0x7fcd3a28c000, 4096, PROT_NONE) = 0 clone(child_stack=0x7fcd3aa8bfd0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x7fcd3aa8c9d0, tls=0x7fcd3aa8c700, child_tidptr=0x7fcd3aa8c9d0) = 19506 futex(0x22b7f68, FUTEX_WAKE_PRIVATE, 1) = 1 sched_setscheduler(19505, SCHED_OTHER, { 0 }) = 0 sched_setscheduler(19506, SCHED_OTHER, { 0 }) = 0 sched_setscheduler(19504, SCHED_OTHER, { 0 }) = 0 sched_setscheduler(19503, SCHED_OTHER, { 0 }) = 0 write(1, "Doing busreset on port 0\n", 25Doing busreset on port 0 ) = 25 ioctl(8, FW_CDEV_IOC_INITIATE_BUS_RESET, 0x7fff311f2ab0) = 0 futex(0x7fcd3b28d9d0, FUTEX_WAIT, 19505, NULL) = 0 futex(0x7fcd3aa8c9d0, FUTEX_WAIT, 19506, NULL) = 0 futex(0x7fcd3ba8e9d0, FUTEX_WAIT, 19504, NULL) = 0 write(10, "\0\0\0\0", 4) = 4 futex(0x7fcd3d2919d0, FUTEX_WAIT, 19501, NULL) = 0 write(15, "\0\0\0\0", 4) = 4 futex(0x7fcd3ca909d0, FUTEX_WAIT, 19502, NULL) = 0 munmap(0x7fcd3aa8d000, 8392704) = 0 write(20, "\0\0\0\0", 4) = 4 futex(0x7fcd3c28f9d0, FUTEX_WAIT, 19503, NULL) = 0 munmap(0x7fcd3a28c000, 8392704) = 0 tgkill(19497, 19500, SIGRTMIN) = 0 futex(0x7fcd3da929d0, FUTEX_WAIT, 19500, NULL) = 0 munmap(0x7fcd3b28e000, 8392704) = 0 tgkill(19497, 19499, SIGRTMIN) = 0 futex(0x7fcd3e2939d0, FUTEX_WAIT, 19499, NULL) = 0 munmap(0x7fcd3ca91000, 8392704) = 0 close(6) = 0 close(4) = 0 close(5) = 0 close(8) = 0 close(3) = 0 close(11) = 0 close(9) = 0 close(10) = 0 close(13) = 0 close(7) = 0 close(16) = 0 close(14) = 0 close(15) = 0 close(18) = 0 close(12) = 0 close(21) = 0 close(19) = 0 close(20) = 0 close(23) = 0 close(17) = 0 close(26) = 0 close(24) = 0 close(25) = 0 close(28) = 0 close(22) = 0 futex(0x7fcd3ec95078, FUTEX_WAKE_PRIVATE, 1) = 1 munmap(0x7fcd3c290000, 8392704) = 0 write(2, "no message buffer overruns\n", 27no message buffer overruns ) = 27 munmap(0x7fcd3ea95000, 2101248) = 0 exit_group(0) = ? $ -- Stefan Richter -=====-===-- -=-= =--== http://arcgraph.de/sr/ |
From: Yves G. <yve...@nu...> - 2012-05-19 17:24:36
|
Le 19/05/2012 12:55, Stefan Richter a écrit : > On May 19 Yves Grenier wrote: >> The relevant file was /var/log/kern.log >> And here is the log from the moment where I switch the Focusrite Saffire >> Pro 24 OFF then ON. The final line is obtained after ffado-test BusReset >> prints "Doing busreset on port 0" and does not give back control to the >> terminal. I waited a quarter of an hour to be sure that nothing else >> would appear in kern.log and I copied the following lines. > [...] > > OK. Unless I missed something, this all looks like it is expected to look > like. Does anybody have more ideas how to inspect what ffado-test is > waiting for? > > Maybe strace could give a hint. Again for comparison, below is how the > tail of the syscall trace looks for me. I put the full trace at > http://paste.debian.net/170095/. > > Hi Here are the last lines of the strace. I ended ffado-test BusReset after several minutes by Ctrl-C. I should add that yesterday all my trials with ffado-test had to be interupted, but today some of them go to a normal end, and others, like the one below never end. Regards Yves -------------------------------- open("/dev/fw0", O_RDWR) = 18 ioctl(18, FW_CDEV_IOC_GET_INFO, 0xbf8da368) = 0 close(18) = 0 getdents(17, /* 0 entries */, 32768) = 0 close(17) = 0 openat(AT_FDCWD, "/dev", O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY|O_CLOEXEC) = 17 getdents(17, /* 213 entries */, 32768) = 4040 open("/dev/fw0", O_RDWR) = 18 ioctl(18, FW_CDEV_IOC_GET_INFO, 0xbf8da368) = 0 epoll_ctl(12, EPOLL_CTL_ADD, 18, {EPOLLIN, {u32=134928836, u64=134928836}}) = 0 getdents(17, /* 0 entries */, 32768) = 0 close(17) = 0 open("/dev/raw1394", O_RDWR) = -1 ENOENT (No such file or directory) open("/dev/raw1394", O_RDWR) = -1 ENOENT (No such file or directory) epoll_create(16) = 17 pipe([19, 20]) = 0 inotify_init() = 21 inotify_add_watch(21, "/dev", IN_CREATE) = 1 epoll_ctl(17, EPOLL_CTL_ADD, 19, {EPOLLIN, {u32=134948556, u64=134948556}}) = 0 epoll_ctl(17, EPOLL_CTL_ADD, 21, {EPOLLIN, {u32=134948560, u64=134948560}}) = 0 openat(AT_FDCWD, "/dev", O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY|O_CLOEXEC) = 22 getdents(22, /* 213 entries */, 32768) = 4040 open("/dev/fw0", O_RDWR) = 23 ioctl(23, FW_CDEV_IOC_GET_INFO, 0xbf8da358) = 0 close(23) = 0 getdents(22, /* 0 entries */, 32768) = 0 close(22) = 0 openat(AT_FDCWD, "/dev", O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY|O_CLOEXEC) = 22 getdents(22, /* 213 entries */, 32768) = 4040 open("/dev/fw0", O_RDWR) = 23 ioctl(23, FW_CDEV_IOC_GET_INFO, 0xbf8da358) = 0 epoll_ctl(17, EPOLL_CTL_ADD, 23, {EPOLLIN, {u32=134948564, u64=134948564}}) = 0 getdents(22, /* 0 entries */, 32768) = 0 close(22) = 0 mmap2(NULL, 8392704, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0xb51ff000 mprotect(0xb51ff000, 4096, PROT_NONE) = 0 clone(child_stack=0xb59ff424, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0xb59ffba8, {entry_number:6, base_addr:0xb59ffb40, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}, child_tidptr=0xb59ffba8) = 3047 mmap2(NULL, 8392704, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0xb49fe000 mprotect(0xb49fe000, 4096, PROT_NONE) = 0 clone(child_stack=0xb51fe424, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0xb51feba8, {entry_number:6, base_addr:0xb51feb40, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}, child_tidptr=0xb51feba8) = 3048 mmap2(NULL, 8392704, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0xb41fd000 mprotect(0xb41fd000, 4096, PROT_NONE) = 0 clone(child_stack=0xb49fd424, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0xb49fdba8, {entry_number:6, base_addr:0xb49fdb40, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}, child_tidptr=0xb49fdba8) = 3049 open("/dev/raw1394", O_RDWR) = -1 ENOENT (No such file or directory) open("/dev/raw1394", O_RDWR) = -1 ENOENT (No such file or directory) epoll_create(16) = 22 pipe([24, 25]) = 0 inotify_init() = 26 inotify_add_watch(26, "/dev", IN_CREATE) = 1 epoll_ctl(22, EPOLL_CTL_ADD, 24, {EPOLLIN, {u32=134968604, u64=134968604}}) = 0 epoll_ctl(22, EPOLL_CTL_ADD, 26, {EPOLLIN, {u32=134968608, u64=134968608}}) = 0 openat(AT_FDCWD, "/dev", O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY|O_CLOEXEC) = 27 brk(0x80e4000) = 0x80e4000 getdents(27, /* 213 entries */, 32768) = 4040 open("/dev/fw0", O_RDWR) = 28 ioctl(28, FW_CDEV_IOC_GET_INFO, 0xbf8da3a8) = 0 close(28) = 0 getdents(27, /* 0 entries */, 32768) = 0 brk(0x80dc000) = 0x80dc000 close(27) = 0 openat(AT_FDCWD, "/dev", O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY|O_CLOEXEC) = 27 getdents(27, /* 213 entries */, 32768) = 4040 open("/dev/fw0", O_RDWR) = 28 ioctl(28, FW_CDEV_IOC_GET_INFO, 0xbf8da3a8) = 0 epoll_ctl(22, EPOLL_CTL_ADD, 28, {EPOLLIN, {u32=134968612, u64=134968612}}) = 0 getdents(27, /* 0 entries */, 32768) = 0 close(27) = 0 ioctl(28, FW_CDEV_IOC_GET_CYCLE_TIMER, 0xbf8da444) = 0 open("/dev/raw1394", O_RDWR) = -1 ENOENT (No such file or directory) open("/dev/raw1394", O_RDWR) = -1 ENOENT (No such file or directory) epoll_create(16) = 27 pipe([29, 30]) = 0 inotify_init() = 31 inotify_add_watch(31, "/dev", IN_CREATE) = 1 epoll_ctl(27, EPOLL_CTL_ADD, 29, {EPOLLIN, {u32=134988196, u64=134988196}}) = 0 epoll_ctl(27, EPOLL_CTL_ADD, 31, {EPOLLIN, {u32=134988200, u64=134988200}}) = 0 openat(AT_FDCWD, "/dev", O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY|O_CLOEXEC) = 32 getdents(32, /* 213 entries */, 32768) = 4040 open("/dev/fw0", O_RDWR) = 33 ioctl(33, FW_CDEV_IOC_GET_INFO, 0xbf8da398) = 0 close(33) = 0 getdents(32, /* 0 entries */, 32768) = 0 close(32) = 0 close(31) = 0 close(29) = 0 close(30) = 0 close(27) = 0 ioctl(8, FW_CDEV_IOC_SEND_REQUEST, 0x80a4924) = 0 epoll_wait(3, {{EPOLLIN, {u32=134889412, u64=134889412}}}, 32, -1) = 1 read(8, "\210\276\v\10\0\0\0\0\1\0\0\0\0\0\0\0\4\0\0\0\0\0\0\2", 16384) = 24 epoll_wait(3, {}, 32, 0) = 0 ioctl(8, FW_CDEV_IOC_SEND_REQUEST, 0x80a4924) = 0 epoll_wait(3, {{EPOLLIN, {u32=134889412, u64=134889412}}}, 32, -1) = 1 read(8, "\210\276\v\10\0\0\0\0\1\0\0\0\0\0\0\0\4\0\0\0\0\0\0\0", 16384) = 24 epoll_wait(3, {}, 32, 0) = 0 ioctl(28, FW_CDEV_IOC_GET_CYCLE_TIMER, 0xbf8da354) = 0 clock_nanosleep(CLOCK_REALTIME, 0, {0, 1000000}, NULL) = 0 ioctl(28, FW_CDEV_IOC_GET_CYCLE_TIMER, 0xbf8da244) = 0 mmap2(NULL, 8392704, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0xb39fc000 mprotect(0xb39fc000, 4096, PROT_NONE) = 0 clone(child_stack=0xb41fc424, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0xb41fcba8, {entry_number:6, base_addr:0xb41fcb40, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}, child_tidptr=0xb41fcba8) = 3050 mmap2(NULL, 8392704, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0xb31fb000 mprotect(0xb31fb000, 4096, PROT_NONE) = 0 clone(child_stack=0xb39fb424, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0xb39fbba8, {entry_number:6, base_addr:0xb39fbb40, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}, child_tidptr=0xb39fbba8) = 3051 mmap2(NULL, 8392704, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0xb29fa000 mprotect(0xb29fa000, 4096, PROT_NONE) = 0 clone(child_stack=0xb31fa424, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0xb31faba8, {entry_number:6, base_addr:0xb31fab40, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}, child_tidptr=0xb31faba8) = 3052 sched_setscheduler(3051, SCHED_OTHER, { 0 }) = 0 sched_setscheduler(3052, SCHED_OTHER, { 0 }) = 0 sched_setscheduler(3050, SCHED_OTHER, { 0 }) = 0 sched_setscheduler(3049, SCHED_OTHER, { 0 }) = 0 write(1, "Doing busreset on port 0\n", 25) = 25 ioctl(8, FW_CDEV_IOC_INITIATE_BUS_RESET, 0xbf8da4fc) = 0 futex(0xb39fbba8, FUTEX_WAIT, 3051, NULL) = ? ERESTARTSYS (To be restarted) --- SIGINT (Interrupt) @ 0 (0) --- +++ killed by SIGINT +++ |