View Issue Details

IDProjectCategoryView StatusLast Update
0003207ardourbugspublic2010-12-14 19:06
Reportercolinf Assigned To 
PrioritynormalSeveritymajorReproducibilityrandom
Status confirmedResolutionopen 
Product VersionSVN/2.0-ongoing 
Summary0003207: Ardour sometimes won't enter 'play'
DescriptionI'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 InformationThis is on Ubuntu 9.10, with ardour2 r7183, vanilla kernel 2.6.34, jack1 svn 4017.
TagsNo tags attached.

Activities

colinf

2010-05-31 14:41

updater   ~0008105

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?

colinf

2010-06-03 12:48

updater   ~0008143

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) 

ardour-wont-play-bt (8,693 bytes)   

colinf

2010-06-05 09:27

updater   ~0008156

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.

lincoln

2010-06-05 17:58

reporter   ~0008167

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.

cth103

2010-06-06 10:22

administrator   ~0008174

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...

colinf

2010-06-06 18:14

updater   ~0008177

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...

cth103

2010-06-06 23:57

administrator   ~0008178

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.

cth103

2010-06-07 12:57

administrator   ~0008180

I've just seen this on 3.0 too.

colinf

2010-06-09 16:55

updater   ~0008216

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);
 }

colinf

2010-06-09 17:19

updater   ~0008217

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...

colinf

2010-07-01 11:24

updater   ~0008370

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.

paul

2010-07-02 21:08

administrator   ~0008375

believed fixed as of 7362 in ardour 2.X

colinf

2010-07-05 17:05

updater   ~0008397

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-ongoingcolinf@starling-recording-pc:~/src/ardour2/2.0-ongoing$ gtk2_ardour/ardev ~/test/
/test.ardour
]0;colinf@starling-recording-pc: ~/src/ardour2/2.0-ongoingcolinf@starling-recording-pc:~/src/ardour2/2.0-ongoing$ tail -F zzz.log 

gtk2_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-ongoingcolinf@starling-recording-pc:~/src/ardour2/2.0-ongoing$ exit

Script done on Mon 05 Jul 2010 18:45:29 BST
r7361-bad.log (10,459 bytes)   

2010-07-05 17:56

 

r7361-good.log (808,716 bytes)

colinf

2010-07-05 18:08

updater   ~0008398

And here's the debug output from r7361, both in the case where the bug occurs, and a working run for comparison.

colinf

2010-12-14 19:06

updater   ~0009627

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.

Issue History

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