View Issue Details
| ID | Project | Category | View Status | Date Submitted | Last Update |
|---|---|---|---|---|---|
| 0003207 | ardour | bugs | public | 2010-05-29 08:57 | 2010-12-14 19:06 |
| Reporter | colinf | Assigned To | |||
| Priority | normal | Severity | major | Reproducibility | random |
| Status | confirmed | Resolution | open | ||
| Product Version | SVN/2.0-ongoing | ||||
| Summary | 0003207: Ardour sometimes won't enter 'play' | ||||
| Description | I've had this happen a few times: on starting ardour, the transport won't enter 'play'. I've seen it when 'Positional sync source' is set to 'internal': I haven't managed to reproduce it yet with this set to 'Jack', but it's a bit random so that might not mean anything. When this happens, most controls in the UI are still responsive, but trying to close ardour causes it to freeze, and eventually the Gnome 'Ardour is not responding' dialog appears. Anyone any ideas how to go about debugging this kind of thing? | ||||
| Additional Information | This is on Ubuntu 9.10, with ardour2 r7183, vanilla kernel 2.6.34, jack1 svn 4017. | ||||
| Tags | No tags attached. | ||||
|
|
This was happening pretty regularly for me (once every 2 or 3 times I started ardour) on a 2.8GHz Pentium 4 desktop machine. However, when I disable hyperthreading in the BIOS I'm unable to reproduce the problem. Smells like some kind of deadlock to me. Would a backtrace be useful? |
|
|
This occasionally happens while ardour is running too, even if it starts up OK. |
|
2010-06-05 09:24
|
ardour-wont-play-bt (8,693 bytes)
(gdb) r Starting program: /home/colinf/src/ardour2/2.0-ongoing/gtk2_ardour/ardour-2.8.8 [Thread debugging using libthread_db enabled] Ardour 2.8.8 (built using 7183 and GCC version 4.4.1) Copyright (C) 1999-2008 Paul Davis Some portions Copyright (C) Steve Harris, Ari Johnson, Brett Viren, Joel Baker Ardour comes with ABSOLUTELY NO WARRANTY not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. This is free software, and you are welcome to redistribute it under certain conditions; see the source for copying conditions. Cannot install SIGPIPE error handler loading default ui configuration file gtk2_ardour/ardour2_ui_default.conf loading user ui configuration file /home/colinf/.ardour2/ardour2_ui.conf Loading ui configuration file gtk2_ardour/ardour2_ui_dark.rc theme_init() called from internal clearlooks engine ardour: [INFO]: Ardour will be limited to 8192 open files loading system configuration file ./ardour_system.rc loading user configuration file /home/colinf/.ardour2/ardour.rc ardour: [INFO]: Using SSE optimized routines [New Thread 0xb597fb70 (LWP 2225)] [New Thread 0xb517eb70 (LWP 2226)] [New Thread 0xb497db70 (LWP 2227)] ardour: [INFO]: looking for control protocols in /home/colinf/.ardour2/surfaces/:/usr/local/lib/ardour2/surfaces/ ardour: [INFO]: Control surface protocol discovered: "Generic MIDI" powermate: Opening of powermate failed - No such file or directory ardour: [INFO]: Control protocol powermate not usable ardour: [INFO]: Control protocol Tranzport not usable ardour: [INFO]: Control surface protocol discovered: "Mackie" [New Thread 0xb36bdb70 (LWP 2228)] [New Thread 0xb2ebcb70 (LWP 2229)] [New Thread 0xb24ffb70 (LWP 2230)] [Thread 0xb24ffb70 (LWP 2230) exited] [New Thread 0xb24ffb70 (LWP 2233)] [New Thread 0xb1cfeb70 (LWP 2234)] [New Thread 0xb14fdb70 (LWP 2235)] [New Thread 0xb0cfcb70 (LWP 2236)] [New Thread 0xb04fbb70 (LWP 2237)] [New Thread 0xafcfab70 (LWP 2238)] [New Thread 0xaf4f9b70 (LWP 2239)] [Thread 0xafcfab70 (LWP 2238) exited] [Thread 0xb14fdb70 (LWP 2235) exited] [Thread 0xb2ebcb70 (LWP 2229) exited] [Thread 0xb04fbb70 (LWP 2237) exited] [Thread 0xb36bdb70 (LWP 2228) exited] [Thread 0xaf4f9b70 (LWP 2239) exited] [Thread 0xb0cfcb70 (LWP 2236) exited] [Thread 0xb1cfeb70 (LWP 2234) exited] [Thread 0xb24ffb70 (LWP 2233) exited] [New Thread 0xb24ffb70 (LWP 2240)] loading bindings from gtk2_ardour/mnemonic-us.bindings (ardour-2.8.8:2222): Gtk-WARNING **: EnableTranslation: missing action EnableTranslation [New Thread 0xb3425b70 (LWP 2243)] [New Thread 0xb336ec90 (LWP 2244)] Session writable based on /home/colinf/test/ [New Thread 0xb30c1c90 (LWP 2245)] [New Thread 0xb3046c90 (LWP 2246)] ARDOUR_UI::parameter_changed(): font-scale set to 81920 [New Thread 0xb1cfeb70 (LWP 2247)] [New Thread 0xb0cfcb70 (LWP 2248)] [Thread 0xb1cfeb70 (LWP 2247) exited] ^C Program received signal SIGINT, Interrupt. 0xb7fe2424 in __kernel_vsyscall () (gdb) thread apply all bt Thread 21 (Thread 0xb0cfcb70 (LWP 2248)): #0 0xb7fe2424 in __kernel_vsyscall () #1 0xb6e9f142 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib/tls/i686/cmov/libpthread.so.0 #2 0xb79350ce in ?? () from /usr/lib/libgthread-2.0.so.0 #3 0xb7886c9c in ?? () from /lib/libglib-2.0.so.0 #4 0xb7886da1 in g_async_queue_timed_pop () from /lib/libglib-2.0.so.0 #5 0xb78d791e in ?? () from /lib/libglib-2.0.so.0 #6 0xb78d637f in ?? () from /lib/libglib-2.0.so.0 #7 0xb6e9a80e in start_thread () from /lib/tls/i686/cmov/libpthread.so.0 #8 0xb6735a0e in clone () from /lib/tls/i686/cmov/libc.so.6 Thread 19 (Thread 0xb3046c90 (LWP 2246)): #0 0xb7fe2424 in __kernel_vsyscall () #1 0xb6727d96 in poll () from /lib/tls/i686/cmov/libc.so.6 #2 0xb7f2a2ec in ARDOUR::Session::midi_thread_work() () from libs/ardour/libardour.so #3 0xb7f2aac3 in ARDOUR::Session::_midi_thread_work(void*) () from libs/ardour/libardour.so #4 0xb6e9a80e in start_thread () from /lib/tls/i686/cmov/libpthread.so.0 #5 0xb6735a0e in clone () from /lib/tls/i686/cmov/libc.so.6 ---Type <return> to continue, or q <return> to quit--- Thread 18 (Thread 0xb30c1c90 (LWP 2245)): #0 0xb7fe2424 in __kernel_vsyscall () #1 0xb6727d96 in poll () from /lib/tls/i686/cmov/libc.so.6 #2 0xb7edf40d in ARDOUR::Session::butler_thread_work() () from libs/ardour/libardour.so #3 0xb7ee05a2 in ARDOUR::Session::_butler_thread_work(void*) () from libs/ardour/libardour.so #4 0xb6e9a80e in start_thread () from /lib/tls/i686/cmov/libpthread.so.0 #5 0xb6735a0e in clone () from /lib/tls/i686/cmov/libc.so.6 Thread 17 (Thread 0xb336ec90 (LWP 2244)): #0 0xb7fe2424 in __kernel_vsyscall () #1 0xb6ea2466 in nanosleep () from /lib/tls/i686/cmov/libpthread.so.0 #2 0xb78d86b2 in g_usleep () from /lib/libglib-2.0.so.0 #3 0xb78469bb in Glib::usleep(unsigned long) () from libs/glibmm2/libglibmm2.so #4 0xb7dce879 in ARDOUR::AudioEngine::meter_thread() () from libs/ardour/libardour.so #5 0xb7dd474c in sigc::internal::slot_call0<sigc::bound_mem_functor0<void, ARDOUR::AudioEngine>, void>::call_it(sigc::internal::slot_rep*) () from libs/ardour/libardour.so #6 0xb78607a2 in call_thread_entry_slot () from libs/glibmm2/libglibmm2.so #7 0xb78d637f in ?? () from /lib/libglib-2.0.so.0 ---Type <return> to continue, or q <return> to quit--- #8 0xb6e9a80e in start_thread () from /lib/tls/i686/cmov/libpthread.so.0 #9 0xb6735a0e in clone () from /lib/tls/i686/cmov/libc.so.6 Thread 16 (Thread 0xb3425b70 (LWP 2243)): #0 0xb7fe2424 in __kernel_vsyscall () #1 0xb6727d96 in poll () from /lib/tls/i686/cmov/libc.so.6 #2 0xb6eb6c57 in jack_client_core_wait () from /usr/lib/libjack.so.0 #3 0x037f0c7f in ?? () Backtrace stopped: previous frame inner to this frame (corrupt stack?) Thread 15 (Thread 0xb24ffb70 (LWP 2240)): #0 0xb7fe2424 in __kernel_vsyscall () #1 0xb6e9ee15 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/tls/i686/cmov/libpthread.so.0 #2 0xb6eb8e0c in mb_thread_func () from /usr/lib/libjack.so.0 #3 0xb24ffb70 in ?? () #4 0xb6f3b5e8 in ?? () Backtrace stopped: previous frame inner to this frame (corrupt stack?) Thread 4 (Thread 0xb497db70 (LWP 2227)): #0 0xb7fe2424 in __kernel_vsyscall () #1 0xb6e9ee15 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/tls/i686/cmov/libpthread.so.0 ---Type <return> to continue, or q <return> to quit--- #2 0xb785fdb7 in Glib::Cond::wait(Glib::Mutex&) () from libs/glibmm2/libglibmm2.so #3 0xb7db8b1c in ARDOUR::Analyser::work() () from libs/ardour/libardour.so #4 0xb7db90c4 in analyser_work() () from libs/ardour/libardour.so #5 0xb78607a2 in call_thread_entry_slot () from libs/glibmm2/libglibmm2.so #6 0xb78d637f in ?? () from /lib/libglib-2.0.so.0 #7 0xb6e9a80e in start_thread () from /lib/tls/i686/cmov/libpthread.so.0 #8 0xb6735a0e in clone () from /lib/tls/i686/cmov/libc.so.6 Thread 3 (Thread 0xb517eb70 (LWP 2226)): #0 0xb7fe2424 in __kernel_vsyscall () #1 0xb6e9ee15 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/tls/i686/cmov/libpthread.so.0 #2 0xb785fdb7 in Glib::Cond::wait(Glib::Mutex&) () from libs/glibmm2/libglibmm2.so #3 0xb7f5b70c in peak_thread_work() () from libs/ardour/libardour.so #4 0xb78607a2 in call_thread_entry_slot () from libs/glibmm2/libglibmm2.so #5 0xb78d637f in ?? () from /lib/libglib-2.0.so.0 #6 0xb6e9a80e in start_thread () from /lib/tls/i686/cmov/libpthread.so.0 #7 0xb6735a0e in clone () from /lib/tls/i686/cmov/libc.so.6 Thread 2 (Thread 0xb597fb70 (LWP 2225)): #0 0xb7fe2424 in __kernel_vsyscall () ---Type <return> to continue, or q <return> to quit--- #1 0xb6e9ee15 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/tls/i686/cmov/libpthread.so.0 #2 0xb785fdb7 in Glib::Cond::wait(Glib::Mutex&) () from libs/glibmm2/libglibmm2.so #3 0xb7f5b70c in peak_thread_work() () from libs/ardour/libardour.so #4 0xb78607a2 in call_thread_entry_slot () from libs/glibmm2/libglibmm2.so #5 0xb78d637f in ?? () from /lib/libglib-2.0.so.0 #6 0xb6e9a80e in start_thread () from /lib/tls/i686/cmov/libpthread.so.0 #7 0xb6735a0e in clone () from /lib/tls/i686/cmov/libc.so.6 Thread 1 (Thread 0xb5e20960 (LWP 2222)): #0 0xb7fe2424 in __kernel_vsyscall () #1 0xb6727d96 in poll () from /lib/tls/i686/cmov/libc.so.6 #2 0xb78bc54b in g_poll () from /lib/libglib-2.0.so.0 #3 0xb78af56b in ?? () from /lib/libglib-2.0.so.0 #4 0xb78afb9f in g_main_loop_run () from /lib/libglib-2.0.so.0 #5 0xb759e419 in gtk_main () from /usr/lib/libgtk-x11-2.0.so.0 #6 0xb70a9154 in Gtk::Main::run_impl() () from libs/gtkmm2/gtk/libgtkmm2.so #7 0xb70a8f5f in Gtk::Main::run() () from libs/gtkmm2/gtk/libgtkmm2.so #8 0xb6f0bb82 in Gtkmm2ext::UI::run(Receiver&) () from libs/gtkmm2ext/libgtkmm2ext.so #9 0x08387039 in main () (gdb) |
|
|
Just in case any wiser minds than mine can spot anything amiss, here's a backtrace of ardour when it's in the "stuck" state. |
|
|
Came across this today on 2.8.9. I had ardour on sync Jack. Switched to internal and I could not engage play. Had to restart ardour. |
|
|
I can't get any insight from that trace; it may be necessary to do some printf debugging to see why the play isn't starting. If you can reproduce this fairly often you could perhaps put some debug output in to see how far ardour gets in trying to start playback... |
|
|
Well, it looks like the Event::SetTransportSpeed that's queued in Session::request_transport_speed() is never seen by Session::process_event(). I can't yet see why this might be: I'll keep digging... |
|
|
Hmm; assuming the pending_events.write() in queue_event() is succeeding, I guess it would be interesting to see if process_with_events() is subsequently being called... if not I think it must be a deadlock in the process thread. |
|
|
I've just seen this on 3.0 too. |
|
|
The pending_events_write() in queue_event() returns 1 whether or not ardour is "stuck", which I assume means it's succeeded. When ardour is stuck, process_with_events() doesn't get called after this. In fact, it seems to only get called about nine times after startup, and then never again. I can post a log of my debug output in the working and non-working cases, along with the patch to generate the output, if that's helpful. |
|
2010-06-09 17:13
|
ardour-process-with-events-stuck.log (3,355 bytes)
colinf@starling-recording-pc:~/src/ardour2/2.0-ongoing$ gtk2_ardour/ardev ~/test/test.ardour
USING OLD CLEARLOOKS
Ardour 2.8.8
(built using 7183 and GCC version 4.4.1)
Copyright (C) 1999-2008 Paul Davis
Some portions Copyright (C) Steve Harris, Ari Johnson, Brett Viren, Joel Baker
Ardour comes with ABSOLUTELY NO WARRANTY
not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.
This is free software, and you are welcome to redistribute it
under certain conditions; see the source for copying conditions.
loading default ui configuration file gtk2_ardour/ardour2_ui_default.conf
loading user ui configuration file /home/colinf/.ardour2/ardour2_ui.conf
Loading ui configuration file gtk2_ardour/ardour2_ui_dark.rc
theme_init() called from internal clearlooks engine
ardour: [INFO]: Ardour will be limited to 8192 open files
loading system configuration file ./ardour_system.rc
loading user configuration file /home/colinf/.ardour2/ardour.rc
ardour: [INFO]: Using SSE optimized routines
ardour: [INFO]: looking for control protocols in /home/colinf/.ardour2/surfaces/:/usr/local/lib/ardour2/surfaces/
ardour: [INFO]: Control surface protocol discovered: "Generic MIDI"
powermate: Opening of powermate failed - No such file or directory
ardour: [INFO]: Control protocol powermate not usable
ardour: [INFO]: Control protocol Tranzport not usable
ardour: [INFO]: Control surface protocol discovered: "Mackie"
JACK COMMAND: /usr/bin/jackd -p 128 -R -P 60 -T -d alsa -n 3 -r 44100 -p 128 -d hw:1,0
jackd 0.119.0
Copyright 2001-2009 Paul Davis, Stephane Letz, Jack O'Quinn, Torben Hohn and others.
jackd comes with ABSOLUTELY NO WARRANTY
This is free software, and you are welcome to redistribute it
under certain conditions; see the file COPYING for details
Memory locking is unlimited - this is dangerous. You should probably alter the line:
@audio - memlock unlimited
in your /etc/limits.conf to read:
@audio - memlock 672264
no message buffer overruns
JACK compiled with System V SHM support.
loading driver ..
apparent rate = 44100
creating alsa driver ... hw:1,0|hw:1,0|128|3|44100|0|0|nomon|swmeter|-|32bit
control device hw:1
configuring for 44100Hz, period = 128 frames (2.9 ms), buffer = 3 periods
ALSA: final selected sample format for capture: 32bit integer little-endian
ALSA: use 3 periods for capture
ALSA: final selected sample format for playback: 32bit integer little-endian
ALSA: use 3 periods for playback
loading bindings from gtk2_ardour/mnemonic-us.bindings
(ardour-2.8.8:2234): Gtk-WARNING **: EnableTranslation: missing action EnableTranslation
Session writable based on /home/colinf/test/
Session::merge_event(), type=16
Session::merge_event(), type=6
Session::merge_event(), type=7
Session::merge_event(), type=6
Session::merge_event(), type=7
Session::merge_event(), type=13
process_event(), type = 13
pwe()...
pwe()...
pwe()...
pwe()...
pwe()...
pwe()...
pwe()...
pwe()...
pwe()...
subgraph starting at ardour timed out (subgraph_wait_fd=12, status = 0, state = Running, pollret = 0 revents = 0x0)
pending_events.write (2) returns 1
ARDOUR_UI::map_transport_state()...
pending_events.write (11) returns 1
ARDOUR_UI::transport_roll()...
rolling= 0
Session::request_transport_speed (1)
pending_events.write (0) returns 1
ARDOUR_UI::map_transport_state()...
jack main caught signal 12
Killed
|
|
2010-06-09 17:14
|
ardour-process-with-events-good.log (5,667 bytes)
colinf@starling-recording-pc:~/src/ardour2/2.0-ongoing$ gtk2_ardour/ardev ~/test/test.ardour
USING OLD CLEARLOOKS
Ardour 2.8.8
(built using 7183 and GCC version 4.4.1)
Copyright (C) 1999-2008 Paul Davis
Some portions Copyright (C) Steve Harris, Ari Johnson, Brett Viren, Joel Baker
Ardour comes with ABSOLUTELY NO WARRANTY
not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.
This is free software, and you are welcome to redistribute it
under certain conditions; see the source for copying conditions.
loading default ui configuration file gtk2_ardour/ardour2_ui_default.conf
loading user ui configuration file /home/colinf/.ardour2/ardour2_ui.conf
Loading ui configuration file gtk2_ardour/ardour2_ui_dark.rc
theme_init() called from internal clearlooks engine
ardour: [INFO]: Ardour will be limited to 8192 open files
loading system configuration file ./ardour_system.rc
loading user configuration file /home/colinf/.ardour2/ardour.rc
ardour: [INFO]: Using SSE optimized routines
ardour: [INFO]: looking for control protocols in /home/colinf/.ardour2/surfaces/:/usr/local/lib/ardour2/surfaces/
ardour: [INFO]: Control surface protocol discovered: "Generic MIDI"
powermate: Opening of powermate failed - No such file or directory
ardour: [INFO]: Control protocol powermate not usable
ardour: [INFO]: Control protocol Tranzport not usable
ardour: [INFO]: Control surface protocol discovered: "Mackie"
JACK COMMAND: /usr/bin/jackd -p 128 -R -P 60 -T -d alsa -n 3 -r 44100 -p 128 -d hw:1,0
jackd 0.119.0
Copyright 2001-2009 Paul Davis, Stephane Letz, Jack O'Quinn, Torben Hohn and others.
jackd comes with ABSOLUTELY NO WARRANTY
This is free software, and you are welcome to redistribute it
under certain conditions; see the file COPYING for details
Memory locking is unlimited - this is dangerous. You should probably alter the line:
@audio - memlock unlimited
in your /etc/limits.conf to read:
@audio - memlock 672264
no message buffer overruns
JACK compiled with System V SHM support.
loading driver ..
apparent rate = 44100
creating alsa driver ... hw:1,0|hw:1,0|128|3|44100|0|0|nomon|swmeter|-|32bit
control device hw:1
configuring for 44100Hz, period = 128 frames (2.9 ms), buffer = 3 periods
ALSA: final selected sample format for capture: 32bit integer little-endian
ALSA: use 3 periods for capture
ALSA: final selected sample format for playback: 32bit integer little-endian
ALSA: use 3 periods for playback
loading bindings from gtk2_ardour/mnemonic-us.bindings
(ardour-2.8.8:2267): Gtk-WARNING **: EnableTranslation: missing action EnableTranslation
Session writable based on /home/colinf/test/
Session::merge_event(), type=16
Session::merge_event(), type=6
Session::merge_event(), type=7
Session::merge_event(), type=6
Session::merge_event(), type=7
Session::merge_event(), type=13
process_event(), type = 13
pwe()...
[ x 20]
pwe()...
[ x 20]
subgraph starting at ardour timed out (subgraph_wait_fd=12, status = 0, state = Running, pollret = 0 revents = 0x0)
pwe()...
[ x 20]
pwe()...
[ x 20]
pwe()...
pwe()...
pending_events.write (2) returns 1
pwe()...
Session::merge_event(), type=2
process_event(), type = 2
pwe()...
[ x 500]
pwe()...
[ x 100]
pwe()...
[ x 100]
pwe()...
[ x 100]
pwe()...
[ x 100]
pwe()...
[ x 20]
pwe()...
[ x 20]
pwe()...
[ x 20]
pwe()...
pwe()...
pwe()...
subgraph starting at ardour timed out (subgraph_wait_fd=12, status = 0, state = Triggered, pollret = 0 revents = 0x0)
**** alsa_pcm: xrun of at least 0.345 msecs
pwe()...
[ x 20]
pwe()...
pwe()...
pwe()...
pwe()...
pwe()...
pwe()...
subgraph starting at ardour timed out (subgraph_wait_fd=12, status = 0, state = Triggered, pollret = 0 revents = 0x0)
pwe()...
**** alsa_pcm: xrun of at least 0.406 msecs
pwe()...
[ x 20]
pwe()...
pwe()...
pwe()...
pwe()...
pwe()...
subgraph starting at ardour timed out (subgraph_wait_fd=12, status = 0, state = Triggered, pollret = 0 revents = 0x0)
pwe()...
[ x 500]
pwe()...
[ x 100]
pwe()...
[ x 100]
pwe()...
[ x 100]
pwe()...
[ x 100]
pwe()...
pwe()...
pwe()...
pwe()...
ARDOUR_UI::map_transport_state()...
pwe()...
[ x 100]
pwe()...
[ x 100]
pwe()...
[ x 100]
pwe()...
[ x 20]
pwe()...
pwe()...
pwe()...
pending_events.write (11) returns 1
pwe()...
Session::merge_event(), type=11
process_event(), type = 11
pwe()...
[ x 1000]
pwe()...
[ x 100]
pwe()...
[ x 100]
pwe()...
[ x 20]
pwe()...
[ x 20]
pwe()...
[ x 20]
pwe()...
[ x 20]
pwe()...
pwe()...
ARDOUR_UI::map_transport_state()...
pwe()...
[ x 1000]
pwe()...
[ x 1000]
pwe()...
[ x 1000]
pwe()...
[ x 100]
pwe()...
[ x 100]
pwe()...
[ x 20]
pwe()...
[ x 20]
pwe()...
[ x 20]
pwe()...
[ x 20]
ARDOUR_UI::transport_roll()...
rolling= 0
Session::request_transport_speed (1)
pending_events.write (0) returns 1
ARDOUR_UI::map_transport_state()...
pwe()...
Session::merge_event(), type=0
process_event(), type = 0
Event::SetTransportSpeed 1
pwe()...
pwe()...
ARDOUR_UI::map_transport_state()...
pwe()...
[ x 1000]
pwe()...
[ x 100]
pwe()...
[ x 20]
pwe()...
[ x 20]
pwe()...
pwe()...
pwe()...
pwe()...
pwe()...
pwe()...
pwe()...
pwe()...
pwe()...
pending_events.write (0) returns 1
pwe()...
Session::merge_event(), type=0
process_event(), type = 0
Event::SetTransportSpeed 0
pending_events.write (16) returns 1
pwe()...
Session::merge_event(), type=16
pwe()...
pwe()...
pwe()...
pwe()...
pwe()...
pwe()...
ARDOUR_UI::map_transport_state()...
pwe()...
[ x 1000]
pwe()...
[ x 500]
pwe()...
[ x 100]
pwe()...
[ x 100]
pwe()...
[ x 100]
pwe()...
[ x 100]
pwe()...
[ x 20]
pwe()...
pwe()...
pwe()...
pwe()...
pwe()...
pwe()...
pwe()...
pwe()...
pwe()...
jack main caught signal 12
colinf@starling-recording-pc:~/src/ardour2/2.0-ongoing$
|
|
2010-06-09 17:14
|
process-with-events-debug.patch (3,323 bytes)
Index: gtk2_ardour/ardour_ui.cc
===================================================================
--- gtk2_ardour/ardour_ui.cc (revision 7183)
+++ gtk2_ardour/ardour_ui.cc (working copy)
@@ -204,7 +204,6 @@
session_loaded = false;
last_speed_displayed = -1.0f;
ignore_dual_punch = false;
- _mixer_on_top = false;
roll_button.unset_flags (Gtk::CAN_FOCUS);
stop_button.unset_flags (Gtk::CAN_FOCUS);
@@ -1469,6 +1468,8 @@
void
ARDOUR_UI::transport_roll ()
{
+ cerr << "ARDOUR_UI::transport_roll()...\n";
+
if (!session) {
return;
}
@@ -1488,10 +1489,13 @@
bool rolling = session->transport_rolling();
+ cerr << "rolling= " << rolling << "\n";
+
if (session->get_play_loop()) {
/* XXX it is not possible to just leave seamless loop and keep
playing at present (nov 4th 2009)
*/
+ cerr << "get_play_loop true\n";
if (!Config->get_seamless_loop()) {
/* off, and stop */
session->request_play_loop (false, true);
@@ -1679,6 +1683,9 @@
void
ARDOUR_UI::map_transport_state ()
{
+
+ cerr << "ARDOUR_UI::map_transport_state()...\n";
+
if (!session) {
auto_loop_button.set_visual_state (0);
play_selection_button.set_visual_state (0);
Index: libs/ardour/session_events.cc
===================================================================
--- libs/ardour/session_events.cc (revision 7183)
+++ libs/ardour/session_events.cc (working copy)
@@ -95,13 +95,18 @@
if (_state_of_the_state & Loading) {
merge_event (ev);
} else {
- pending_events.write (&ev, 1);
+ guint v;
+ v = pending_events.write (&ev, 1);
+ cerr << "pending_events.write (" << ev->type << ") returns " << v << "\n";
+
}
}
void
Session::merge_event (Event* ev)
{
+ cerr << "Session::merge_event(), type=" << ev->type << "\n";
+
switch (ev->action) {
case Event::Remove:
_remove_event (ev);
@@ -283,11 +288,15 @@
event for a time when the change is complete.
*/
+ cerr << "process_event(), type = " << ev->type << "\n";
+
if (non_realtime_work_pending()) {
/* except locates, which we have the capability to handle */
if (ev->type != Event::Locate) {
+ cerr << "non_realtime_work_pending() is true, requeuing\n";
+
immediate_events.insert (immediate_events.end(), ev);
_remove_event (ev);
return;
@@ -337,6 +346,7 @@
case Event::SetTransportSpeed:
+ cerr << "Event::SetTransportSpeed " << ev->speed << "\n";
set_transport_speed (ev->speed, ev->yes_or_no, ev->second_yes_or_no);
break;
Index: libs/ardour/session_process.cc
===================================================================
--- libs/ardour/session_process.cc (revision 7183)
+++ libs/ardour/session_process.cc (working copy)
@@ -261,6 +261,8 @@
/* make sure the auditioner is silent */
+ cerr << "pwe()...\n";
+
if (auditioner) {
auditioner->silence (nframes);
}
Index: libs/ardour/session_transport.cc
===================================================================
--- libs/ardour/session_transport.cc (revision 7183)
+++ libs/ardour/session_transport.cc (working copy)
@@ -84,6 +84,9 @@
void
Session::request_transport_speed (float speed)
{
+
+ cerr << "Session::request_transport_speed (" << speed << ")\n";
+
Event* ev = new Event (Event::SetTransportSpeed, Event::Add, Event::Immediate, 0, speed);
queue_event (ev);
}
|
|
|
Sorry about the rather silly -good log format: I didn't want to chop out all of the process_with_events() trace output, though I realised as I hit upload that it's elmost entirely superfluous... |
|
|
A few further observations, in case they help: This bug seems to depend on jack's -p and -n settings: it happens much more at lower latencies. It's also dependent on the number of plugins in the session: the more there are, the more often it happens. It seems not to be any specific plugin: the test session I've been using reproduces the bug 100% when Autotalent is enabled on one track, and less frequently when it is disabled, but I've observed the same bug with other sessions without that particular plugin. |
|
|
believed fixed as of 7362 in ardour 2.X |
|
|
Sorry to report that r7375 still exhibits the same problem for me here. |
|
2010-07-05 17:55
|
r7361-bad.log (10,459 bytes)
Script started on Mon 05 Jul 2010 18:45:02 BST ]0;colinf@starling-recording-pc: ~/src/ardour2/2.0-ongoing[01;32mcolinf@starling-recording-pc[00m:[01;34m~/src/ardour2/2.0-ongoing[00m$ gtk2_ardour/ardev ~/test/ /test.ardour[A ]0;colinf@starling-recording-pc: ~/src/ardour2/2.0-ongoing[01;32mcolinf@starling-recording-pc[00m:[01;34m~/src/ardour2/2.0-ongoing[00m$ [8Ptail -F zzz.log [K[A[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[Cgtk2_ardour/ardev ~/test/ /test.ardour USING OLD CLEARLOOKS Ardour 2.8.10 (built using 7361 and GCC version 4.4.1) Copyright (C) 1999-2008 Paul Davis Some portions Copyright (C) Steve Harris, Ari Johnson, Brett Viren, Joel Baker Ardour comes with ABSOLUTELY NO WARRANTY not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. This is free software, and you are welcome to redistribute it under certain conditions; see the source for copying conditions. loading default ui configuration file gtk2_ardour/ardour2_ui_default.conf loading user ui configuration file /home/colinf/.ardour2/ardour2_ui.conf Loading ui configuration file gtk2_ardour/ardour2_ui_dark.rc theme_init() called from internal clearlooks engine ardour: [INFO]: Ardour will be limited to 8192 open files loading system configuration file ./ardour_system.rc loading user configuration file /home/colinf/.ardour2/ardour.rc ardour: [INFO]: Using SSE optimized routines ardour: [INFO]: looking for control protocols in /home/colinf/.ardour2/surfaces/:/usr/local/lib/ardour2/surfaces/ ardour: [INFO]: Control surface protocol discovered: "Generic MIDI" powermate: Opening of powermate failed - No such file or directory ardour: [INFO]: Control protocol powermate not usable ardour: [INFO]: Control protocol Tranzport not usable ardour: [INFO]: Control surface protocol discovered: "Mackie" loading bindings from gtk2_ardour/mnemonic-us.bindings (ardour-2.8.10:5940): Gtk-WARNING **: EnableTranslation: missing action EnableTranslation JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) Session writable based on /home/colinf/test/ JACK says PROCESS (128) P2 pf = pwe JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) Butler sleeps with DWO = 0 JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) %*%*%*%*%*% PROCESS EVENT TYPE InputConfigurationChange Butler awake RUN request transport work = 1 Do transport work JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) JACK says PROCESS (128) ++PWE JACK says PROCESS (128) EVENT DUMP at 956383 16 target = 105840 Next event: at 956383 16 target = 105840 Immediate events pending: END EVENT_DUMP ++PWE out 1 ++PWE EVENT DUMP at 956383 16 target = 105840 Next event: at 956383 16 target = 105840 Immediate events pending: END EVENT_DUMP ++PWE out 1 ++PWE EVENT DUMP at 956383 16 target = 105840 Next event: at 956383 16 target = 105840 Immediate events pending: END EVENT_DUMP ++PWE out 1 ++PWE EVENT DUMP at 956383 16 target = 105840 Next event: at 956383 16 target = 105840 Immediate events pending: END EVENT_DUMP ++PWE out 1 ++PWE EVENT DUMP at 956383 16 target = 105840 Next event: at 956383 16 target = 105840 Immediate events pending: END EVENT_DUMP ++PWE out 1 ++PWE EVENT DUMP at 956383 16 target = 105840 Next event: at 956383 16 target = 105840 Immediate events pending: END EVENT_DUMP ++PWE out 1 ++PWE EVENT DUMP at 956383 16 target = 105840 Next event: at 956383 16 target = 105840 Immediate events pending: END EVENT_DUMP ++PWE out 1 ++PWE EVENT DUMP at 956383 16 target = 105840 Next event: at 956383 16 target = 105840 Immediate events pending: END EVENT_DUMP ++PWE out 1 JACK says PROCESS (128) ++PWE EVENT DUMP at 956383 16 target = 105840 Next event: at 956383 16 target = 105840 Immediate events pending: END EVENT_DUMP ++PWE out 1 JACK says PROCESS (128) ++PWE EVENT DUMP at 956383 16 target = 105840 Next event: at 956383 16 target = 105840 Immediate events pending: END EVENT_DUMP ++PWE out 1 JACK says PROCESS (128) ++PWE EVENT DUMP at 956383 16 target = 105840 Next event: at 956383 16 target = 105840 Immediate events pending: END EVENT_DUMP ++PWE out 1 JACK says PROCESS (128) ++PWE EVENT DUMP at 956383 16 target = 105840 Next event: at 956383 16 target = 105840 Immediate events pending: END EVENT_DUMP ++PWE out 1 JACK says PROCESS (128) ++PWE EVENT DUMP at 956383 16 target = 105840 Next event: at 956383 16 target = 105840 Immediate events pending: END EVENT_DUMP ++PWE out 1 JACK says PROCESS (128) ++PWE EVENT DUMP at 956383 16 target = 105840 Next event: at 956383 16 target = 105840 Immediate events pending: END EVENT_DUMP ++PWE out 1 JACK says PROCESS (128) ++PWE EVENT DUMP at 956383 16 target = 105840 Next event: at 956383 16 target = 105840 Immediate events pending: END EVENT_DUMP ++PWE out 1 JACK says PROCESS (128) ++PWE EVENT DUMP at 956383 16 target = 105840 Next event: at 956383 16 target = 105840 Immediate events pending: END EVENT_DUMP ++PWE out 1 JACK says PROCESS (128) ++PWE EVENT DUMP at 956383 16 target = 105840 Next event: at 956383 16 target = 105840 Immediate events pending: END EVENT_DUMP ++PWE out 1 done with that 1234 not completely written, DWO = true JACK says PROCESS (128) ++PWE EVENT DUMP at 956383 16 target = 105840 Next event: at 956383 16 target = 105840 Immediate events pending: END EVENT_DUMP ++PWE out 3 bassline not completely written, DWO = true teacup not completely written, DWO = true JACK says PROCESS (128) ++PWE EVENT DUMP at 956383 16 target = 105840 Next event: at 956383 16 target = 105840 Immediate events pending: END EVENT_DUMP guitar not completely written, DWO = true ++PWE out 3 Audio 1 not completely written, DWO = true JACK says PROCESS (128) ++PWE EVENT DUMP at 956383 16 target = 105840 Next event: at 956383 16 target = 105840 Immediate events pending: END EVENT_DUMP auditioner not completely written, DWO = true Loop done, but BSR = 1 DWO = 1 TWR = 0 so back to restart transport work = 0 no transport work to do ++PWE out 3 JACK says PROCESS (128) ++PWE EVENT DUMP at 956383 16 target = 105840 Next event: at 956383 16 target = 105840 Immediate events pending: END EVENT_DUMP ++PWE out 3 Butler loop done Butler sleeps with DWO = 0 ********** push event action 0 type Locate to pending ********** push event action 0 type SetSlaveSource to pending ********** push event action 0 type SetTransportSpeed to pending Killed ]0;colinf@starling-recording-pc: ~/src/ardour2/2.0-ongoing[01;32mcolinf@starling-recording-pc[00m:[01;34m~/src/ardour2/2.0-ongoing[00m$ exit Script done on Mon 05 Jul 2010 18:45:29 BST |
|
2010-07-05 17:56
|
|
|
|
And here's the debug output from r7361, both in the case where the bug occurs, and a working run for comparison. |
|
|
I've now observed that setting jackd timeout to 2000 mS ( -t2000 ) seems to prevent this bug from happening with a session and other jackd parameters that exhibit the bug 90% of the time with the default 500 mS timeout. I don't know whether that's useful info for fixing the bug, or whether it even really is a bug at all rather than just user error, but I'm happy anyway now that I've found a workaround. |
| Date Modified | Username | Field | Change |
|---|---|---|---|
| 2010-05-29 08:57 | colinf | New Issue | |
| 2010-05-31 14:41 | colinf | Note Added: 0008105 | |
| 2010-06-03 12:48 | colinf | Note Added: 0008143 | |
| 2010-06-05 09:24 | colinf | File Added: ardour-wont-play-bt | |
| 2010-06-05 09:27 | colinf | Note Added: 0008156 | |
| 2010-06-05 17:58 | lincoln | Note Added: 0008167 | |
| 2010-06-06 10:22 | cth103 | Note Added: 0008174 | |
| 2010-06-06 18:14 | colinf | Note Added: 0008177 | |
| 2010-06-06 23:57 | cth103 | Note Added: 0008178 | |
| 2010-06-07 12:57 | cth103 | Note Added: 0008180 | |
| 2010-06-07 12:57 | cth103 | Status | new => confirmed |
| 2010-06-09 16:55 | colinf | Note Added: 0008216 | |
| 2010-06-09 17:13 | colinf | File Added: ardour-process-with-events-stuck.log | |
| 2010-06-09 17:14 | colinf | File Added: ardour-process-with-events-good.log | |
| 2010-06-09 17:14 | colinf | File Added: process-with-events-debug.patch | |
| 2010-06-09 17:19 | colinf | Note Added: 0008217 | |
| 2010-07-01 11:24 | colinf | Note Added: 0008370 | |
| 2010-07-02 21:08 | paul | Note Added: 0008375 | |
| 2010-07-05 17:05 | colinf | Note Added: 0008397 | |
| 2010-07-05 17:55 | colinf | File Added: r7361-bad.log | |
| 2010-07-05 17:56 | colinf | File Added: r7361-good.log | |
| 2010-07-05 18:08 | colinf | Note Added: 0008398 | |
| 2010-12-14 19:06 | colinf | Note Added: 0009627 |
