View Issue Details

Jump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0004098ardourbugspublic2011-06-06 19:352012-10-20 19:07
Reporterrealhangman Assigned ToSaBer  
PriorityurgentSeveritymajorReproducibilityalways
Status closedResolutionfixed 
Product Version3.0-alpha5 
Target Version3.0 
Summary0004098: Export delay compensation does not work properly
DescriptionAs In A3 rev. 9608, Ardour does not compensate the latency correctly.

If you use e.g. 2048 frames and export something via "file -> export", the exported file will start 2048 frames too early, or whatever frames you used.

Have a look at http://septimbears.de/A3-rev-9609delay-compensation.jpg:
The upper track was exported with 64 frames, the lower with 2048 (A3 was closed in between, jackd killed and started with the new frames/period). The lower track starts too early.
Tagscompensation, delay, export, latency

Activities

realhangman

2011-10-14 11:23

reporter   ~0011688

Happens with Jack 1.9.7.

Still the same in A3 rev. 10208. The problem also existed for a short time in A2-svn, in a pre version Paul sent to the mailing list, but was fixed for the final 2.8.12 release. Maybe the same fix can be used for A3?

realhangman

2012-02-02 16:50

reporter   ~0012749

I hoped that it would be resolved with jack 1.9.8 like in 0004312, but it's still an issue.

A3 rev 11378

realhangman

2012-07-23 23:47

reporter   ~0013912

This is still an issue in beta5

x42

2012-07-25 16:38

administrator   ~0013927

Last edited: 2012-07-25 16:40

 Same problem - Ardour beta5, with either jackd-0.122.0 or jackdmp-1.9.8.

Actually the problem sits deeper. For period-sizes < 255 the offset is erratic (both jack1 and jack2) and not necessarily a power of two (e.g. 192 samples) I have not yet been able to establish a pattern.


With jack-1.9.8 using the dummy driver in synchronous mode and the master output connected to system:playback*, export behaves correctly -- until the period-size is changed that is.

system:playback_1
    port latency = 1024 frames
    port playback latency = [ 1024 1024 ] frames
    port capture latency = [ 0 0 ] frames


jackd 0.122's "dummy" driver reports zero latency for the port and the exported sound is always ahead of time.

x42

2012-07-25 16:54

administrator   ~0013928

Last edited: 2012-07-25 16:59

 To track this down, I attach a small session.

It has two short beeps at exactly 00:00:01:00 and 00:00:02:00 and is 3 sec long.

The session comes with a tiny tool that prints the time of the first non-zero audio-sample. (firstNZsample.c)

 cd /tmp
 tar xjf /path/to/xtest.tar.bz2
 cd xtest
 gcc -o firstNZsample firstNZsample.c -lsndfile
 ardour3 xtest.ardour &
 # export session to /tmp/Session.wav
 ./firstNZsample /tmp/Session.wav


When running jackd-1.9.8 with -p 1024 the output of firstNZsample is 
First non-zero sample: 46977 (chn:1)
Offset to 1sec in audio-samples 1023


It is off by one sample (-1023 instead of -1024) because ardour adds a short fade-in to the audio-sample at 00:00:01:00).

2012-07-25 16:55

 

xtest.tar.bz2 (162,007 bytes)

x42

2012-07-25 20:13

administrator   ~0013929

Last edited: 2012-07-25 20:44

 I found the problem, but I'm no closer to fixing it:

AudioEngine::process_callback() is executed (at least once) after starting the transport and before jack enters freewheeling mode.

Thus, when Session::process_export_fw() is called the first time to save audio-data, the transport has already moved on. The first N * jack_period_size audio-frames are lost and not included in the exported session.

Debug trace created with attached patch (a3_svn13072-debug_export_transport.diff) and annotated afterwards

DEBUG::Transport: Normal PROCESS @1172 ; +1024 frames            # AudioEngine::process_callback()
DEBUG::Transport: Normal PROCESS @1172 ; +1024 frames
DEBUG::Transport: Normal PROCESS @1172 ; +1024 frames
DEBUG::Transport: Export START @0                                # Session::start_audio_export()
DEBUG::Transport: @ 0 Set transport speed to 1, abort = 0 clear_state = 0, current = 0 as_default 0
DEBUG::Transport: start_transport
DEBUG::Transport: send TSC4 with speed = 1
DEBUG::Transport: Butler transport work, todo =
DEBUG::Transport: Butler transport work all done
DEBUG::Transport: Normal PROCESS @0 ; +1024 frames               # AudioEngine::process_callback()
DEBUG::Transport: Freewheel PROCESS @1024 ; +1024 frames         # AudioEngine::process_callback()
DEBUG::Transport: Export transport @1024                         # Session::process_export_fw()
DEBUG::Transport: Freewheel PROCESS @2048 ; +1024 frames
DEBUG::Transport: Export transport @2048
DEBUG::Transport: Freewheel PROCESS @3072 ; +1024 frames
...


x42

2012-07-25 20:14

administrator   ~0013930

To further complicate matters: the port-latency is only updated in the cycle after jack enters freewheeling mode.
Although in my simple session this is a NOOP.

Continuing output from above:

DEBUG::Transport: Export transport @3072
DEBUG::Latency: GET PORT asec440/audio_in 1 capture PRIVATE latency now [0 - 0]
DEBUG::Latency: port asec440 has CAPTURE latency of 1024 - use
DEBUG::Latency: asec440: max CAPTURE latency from 1 ports = 1024
DEBUG::Transport: Freewheel PROCESS @4096 ; +1024 frames
DEBUG::Transport: Export transport @4096
DEBUG::Latency: JACK latency callback: CAPTURE
DEBUG::Latency: asec440/audio_in 1: not connected to anything
DEBUG::Latency: asec440/audio_in 1: final connected latency range [ 0 .. 0 ]
DEBUG::Latency: SET PORT asec440/audio_in 1 capture PRIVATE latency now [0 - 0]
DEBUG::Latency: SET PORT asec440/audio_in 1 CAPTURE PUBLIC latency now [0 - 0]
DEBUG::Latency: SET PORT asec440/audio_out 1 capture PRIVATE latency now [0 - 0]
DEBUG::Latency: SET PORT asec440/audio_out 1 CAPTURE PUBLIC latency now [0 - 0]
DEBUG::Latency: SET PORT asec440/audio_out 2 capture PRIVATE latency now [0 - 0]
DEBUG::Latency: SET PORT asec440/audio_out 2 CAPTURE PUBLIC latency now [0 - 0]
DEBUG::Latency: master/audio_in 1: 1 connections to check for latency range
DEBUG::Latency: GET PORT asec440/audio_out 1 capture PRIVATE latency now [0 - 0]
DEBUG::Latency:   master/audio_in 1 <-LOCAL-> ardour:asec440/audio_out 1 : latter has latency range 0 .. 0
DEBUG::Latency: master/audio_in 1: final connected latency range [ 0 .. 0 ]
DEBUG::Latency: master/audio_in 2: 1 connections to check for latency range
DEBUG::Latency: GET PORT asec440/audio_out 2 capture PRIVATE latency now [0 - 0]
DEBUG::Latency:   master/audio_in 2 <-LOCAL-> ardour:asec440/audio_out 2 : latter has latency range 0 .. 0
DEBUG::Latency: master/audio_in 2: final connected latency range [ 0 .. 0 ]
DEBUG::Latency: SET PORT master/audio_in 1 capture PRIVATE latency now [0 - 0]
DEBUG::Latency: SET PORT master/audio_in 1 CAPTURE PUBLIC latency now [0 - 0]
DEBUG::Latency: SET PORT master/audio_in 2 capture PRIVATE latency now [0 - 0]
DEBUG::Latency: SET PORT master/audio_in 2 CAPTURE PUBLIC latency now [0 - 0]
DEBUG::Latency: SET PORT master/audio_out 1 capture PRIVATE latency now [0 - 0]
DEBUG::Latency: SET PORT master/audio_out 1 CAPTURE PUBLIC latency now [0 - 0]
DEBUG::Latency: SET PORT master/audio_out 2 capture PRIVATE latency now [0 - 0]
DEBUG::Latency: SET PORT master/audio_out 2 CAPTURE PUBLIC latency now [0 - 0]
DEBUG::Latency: Set public port latencies to 0
DEBUG::Latency: SET PORT asec440/audio_in 1 CAPTURE PUBLIC latency now [0 - 0]
DEBUG::Latency: SET PORT asec440/audio_out 1 CAPTURE PUBLIC latency now [0 - 0]
DEBUG::Latency: SET PORT asec440/audio_out 2 CAPTURE PUBLIC latency now [0 - 0]
DEBUG::Latency: SET PORT master/audio_in 1 CAPTURE PUBLIC latency now [0 - 0]
DEBUG::Latency: SET PORT master/audio_in 2 CAPTURE PUBLIC latency now [0 - 0]
DEBUG::Latency: SET PORT master/audio_out 1 CAPTURE PUBLIC latency now [0 - 0]
DEBUG::Latency: SET PORT master/audio_out 2 CAPTURE PUBLIC latency now [0 - 0]
DEBUG::Latency: GET PORT asec440/audio_in 1 capture PRIVATE latency now [0 - 0]
DEBUG::Latency: asec440: max CAPTURE latency from 1 ports = 0
DEBUG::Latency: GET PORT master/audio_in 1 capture PRIVATE latency now [0 - 0]
DEBUG::Latency: GET PORT master/audio_in 2 capture PRIVATE latency now [0 - 0]
DEBUG::Latency: master: max CAPTURE latency from 2 ports = 0
DEBUG::Latency: Worst input latency: 0
DEBUG::Latency: GET PORT asec440/audio_in 1 capture PRIVATE latency now [0 - 0]
DEBUG::Latency: asec440: max CAPTURE latency from 1 ports = 0
DEBUG::Latency: JACK latency callback: DONE
DEBUG::Transport: Freewheel PROCESS @5120 ; +1024 frames
DEBUG::Transport: Export transport @5120
DEBUG::Latency: JACK latency callback: PLAYBACK
DEBUG::Latency: master/audio_out 1: not connected to anything
DEBUG::Latency: master/audio_out 1: final connected latency range [ 0 .. 0 ]
DEBUG::Latency: master/audio_out 2: not connected to anything
DEBUG::Latency: master/audio_out 2: final connected latency range [ 0 .. 0 ]
DEBUG::Latency: SET PORT master/audio_out 1 playback PRIVATE latency now [0 - 0]
DEBUG::Latency: SET PORT master/audio_out 1 PLAYBACK PUBLIC latency now [0 - 0]
DEBUG::Latency: SET PORT master/audio_out 2 playback PRIVATE latency now [0 - 0]
DEBUG::Latency: SET PORT master/audio_out 2 PLAYBACK PUBLIC latency now [0 - 0]
DEBUG::Latency: SET PORT master/audio_in 1 playback PRIVATE latency now [0 - 0]
DEBUG::Transport: Freewheel PROCESS @6144 ; +1024 frames
DEBUG::Transport: Export transport @6144
DEBUG::Latency: SET PORT master/audio_in 1 PLAYBACK PUBLIC latency now [0 - 0]
DEBUG::Latency: SET PORT master/audio_in 2 playback PRIVATE latency now [0 - 0]
DEBUG::Latency: SET PORT master/audio_in 2 PLAYBACK PUBLIC latency now [0 - 0]
DEBUG::Latency: asec440/audio_out 1: 1 connections to check for latency range
DEBUG::Latency: GET PORT master/audio_in 1 playback PRIVATE latency now [0 - 0]
DEBUG::Latency:   asec440/audio_out 1 <-LOCAL-> ardour:master/audio_in 1 : latter has latency range 0 .. 0
DEBUG::Latency: asec440/audio_out 1: final connected latency range [ 0 .. 0 ]
DEBUG::Latency: asec440/audio_out 2: 1 connections to check for latency range
DEBUG::LatencyDEBUG::Transport: Freewheel PROCESS @7168 ; +1024 frames
DEBUG::Transport: Export transport @7168
: GET PORT master/audio_in 2 playback PRIVATE latency now [0 - 0]
DEBUG::Latency:   asec440/audio_out 2 <-LOCAL-> ardour:master/audio_in 2 : latter has latency range 0 .. 0
DEBUG::Latency: asec440/audio_out 2: final connected latency range [ 0 .. 0 ]
DEBUG::Latency: SET PORT asec440/audio_out 1 playback PRIVATE latency now [0 - 0]
DEBUG::Latency: SET PORT asec440/audio_out 1 PLAYBACK PUBLIC latency now [0 - 0]
DEBUG::Latency: SET PORT asec440/audio_out 2 playback PRIVATE latency now [0 - 0]
DEBUG::Latency: SET PORT asec440/audio_out 2 PLAYBACK PUBLIC latency now [0 - 0]
DEBUG::Latency: SET PORT asec440/audio_in 1 playback PRIVATE latency now [0 - 0]
DEBUG::Latency: SET PORT asec440/audio_in 1 PLAYBACK PUBLIC latency now [0 - 0]
DEBUG::Latency: Set public port latencies to 0
DEBUG::Latency: SET PORT master/audio_in 1 PLAYBACK PUBLIC latency now [0 - 0]
DEBUG::Latency: SET PORT master/audio_in 2 PLAYBACK PUBLIC latency now [0 - 0]
DEBUG::Latency: SET PORT master/audio_out 1 PLAYBACK PUBLIC latency now [0 - 0]
DEBUG::Latency: SET PORT master/audio_out 2 PLAYBACK PUBLIC latency now [0 - 0]
DEBUG::Latency: SET PORT asec440/audio_in 1 PLAYBACK PUBLIC latency now [0 - 0]
DEBUG::Latency: SET PORT asec440/audio_out 1 PLAYBACK PUBLIC latency now [0 - 0]
DEBUG::Latency: SET PORT asec440/audio_out 2 PLAYBACK PUBLIC latency now [0 - 0]
DEBUG::Latency: GET PORT asec440/audio_out 1 playback PRIVATE latency now [0 - 0]
DEBUG::Latency: GET PORT asec440/audio_out 2 playback PRIVATE latency now [0 - 0]
DEBUG::Latency: asec440: max PLAYBACK latency from 2 ports = 0
DEBUG::Latency: GET PORT master/audio_out 1 playback PRIVATE latency now [0 - 0]
DEBUG::Latency: GET PORT master/audio_out 2 playback PRIVATE latency now [0 - 0]
DEBUG::Latency: master: max PLAYBACK latency from 2 ports = 0
DEBUG::Latency: Worst output latency: 0
DEBUG::Latency: asec440: internal signal latency = 0
DEBUG::Latency: master: internal signal latency = 0
DEBUG::Latency: asec440: compensate for maximum latency of 0,given own latency of 0, using initial delay of 0
DEBUG::Latency: master: compensate for maximum latency of 0,given own latency of 0, using initial delay of 0
DEBUG::Latency: JACK latency callback: DONE
DEBUG::Transport: Freewheel PROCESS @8192 ; +1024 frames
DEBUG::Transport: Export transport @8192 
DEBUG::Transport: Freewheel PROCESS @9216 ; +1024 frames
DEBUG::Transport: Export transport @9216 
DEBUG::Transport: Freewheel PROCESS @10240 ; +1024 frames
...

2012-07-25 20:15

 

a3_svn13072-debug_export_transport.diff (1,982 bytes)    
diff --git a/libs/ardour/audioengine.cc b/libs/ardour/audioengine.cc
index 004ba33..c4801b7 100644
--- a/libs/ardour/audioengine.cc
+++ b/libs/ardour/audioengine.cc
@@ -48,6 +48,7 @@
 #include "ardour/port.h"
 #include "ardour/process_thread.h"
 #include "ardour/session.h"
+#include "ardour/debug.h"
 
 #include "i18n.h"
 
@@ -544,12 +545,14 @@ AudioEngine::process_callback (pframes_t nframes)
 	if (_freewheeling && !Freewheel.empty()) {
 		/* emit the Freewheel signal and stop freewheeling in the event of trouble
 		 */
+		DEBUG_TRACE (DEBUG::Transport, string_compose ("Freewheel PROCESS @%1 ; +%2 frames\n", _session->_transport_frame, nframes));
                 boost::optional<int> r = Freewheel (nframes);
 		if (r.get_value_or (0)) {
 			jack_set_freewheel (_priv_jack, false);
 		}
 
 	} else {
+		DEBUG_TRACE (DEBUG::Transport, string_compose ("Normal PROCESS @%1 ; +%2 frames\n", _session->_transport_frame, nframes));
 		MIDI::Manager::instance()->cycle_start(nframes);
 
 		if (_session) {
diff --git a/libs/ardour/session_export.cc b/libs/ardour/session_export.cc
index acb23ae..362a315 100644
--- a/libs/ardour/session_export.cc
+++ b/libs/ardour/session_export.cc
@@ -31,6 +31,7 @@
 #include "ardour/process_thread.h"
 #include "ardour/session.h"
 #include "ardour/track.h"
+#include "ardour/debug.h"
 
 #include "i18n.h"
 
@@ -145,6 +146,7 @@ Session::start_audio_export (framepos_t position)
 	   since then has re-awakened it.
 	 */
 
+	DEBUG_TRACE (DEBUG::Transport, string_compose ("Export START @%1\n", _transport_frame));
 	set_transport_speed (1.0, false);
 	butler_transport_work ();
 	g_atomic_int_set (&_butler->should_do_transport_work, 0);
@@ -194,6 +196,7 @@ int
 Session::process_export_fw (pframes_t nframes)
 {
         _engine.main_thread()->get_buffers ();
+	DEBUG_TRACE (DEBUG::Transport, string_compose ("Export transport @%1 \n", _transport_frame));
 	process_export (nframes);
         _engine.main_thread()->drop_buffers ();
 	return 0;
a3_svn13072-debug_export_transport.diff (1,982 bytes)   

x42

2012-07-25 21:40

administrator   ~0013931

I managed to come up with a practical fix.

Idea: start the transport in the process_export_fw() callback and ignore all audio before that.

It's not nice, but it works and does not need any fancy thread synchronization mechanism.

Cheers!
robin


PS. maybe the new flag '_export_started' can be consolidated with '_export_rolling' somehow.

I did not walk all possible call-graphs but currently it can't because there's a possibility that an abort signal arrives simultaneously with the first process_export_fw() callback -- at least Session::process_export() would need to be updated somehow.

2012-07-25 21:40

 

a3_svn13072-export_transport_fix.diff (1,628 bytes)    
diff --git a/libs/ardour/ardour/session.h b/libs/ardour/ardour/session.h
index 780c68f..0464fbe 100644
--- a/libs/ardour/ardour/session.h
+++ b/libs/ardour/ardour/session.h
@@ -964,6 +964,7 @@ class Session : public PBD::StatefulDestructible, public PBD::ScopedConnectionLi
 	framepos_t post_export_position;
 
 	bool _exporting;
+	bool _export_started;
 	bool _export_rolling;
 
 	boost::shared_ptr<ExportHandler> export_handler;
diff --git a/libs/ardour/session_export.cc b/libs/ardour/session_export.cc
index acb23ae..244daeb 100644
--- a/libs/ardour/session_export.cc
+++ b/libs/ardour/session_export.cc
@@ -106,6 +106,7 @@ Session::start_audio_export (framepos_t position)
 {
 	if (!_exporting) {
 		pre_export ();
+		_export_started = false;
 	}
 
 	/* We're about to call Track::seek, so the butler must have finished everything
@@ -145,11 +146,6 @@ Session::start_audio_export (framepos_t position)
 	   since then has re-awakened it.
 	 */
 
-	set_transport_speed (1.0, false);
-	butler_transport_work ();
-	g_atomic_int_set (&_butler->should_do_transport_work, 0);
-	post_transport ();
-
 	/* we are ready to go ... */
 
 	if (!_engine.connected()) {
@@ -193,6 +189,16 @@ Session::process_export (pframes_t nframes)
 int
 Session::process_export_fw (pframes_t nframes)
 {
+
+	if (!_export_started) {
+		_export_started=true;
+		set_transport_speed (1.0, false);
+		butler_transport_work ();
+		g_atomic_int_set (&_butler->should_do_transport_work, 0);
+		post_transport ();
+		return 0;
+	}
+
         _engine.main_thread()->get_buffers ();
 	process_export (nframes);
         _engine.main_thread()->drop_buffers ();
a3_svn13072-export_transport_fix.diff (1,628 bytes)   

realhangman

2012-10-16 14:03

reporter   ~0014070

Still an issue in SVN 13265, I think this is very release-critical.

x42

2012-10-19 20:42

administrator   ~0014109

should be fixed in rev13305. Works here.

realhangman, please confirm and close.

realhangman

2012-10-20 18:26

reporter   ~0014115

Wow, Yes!!! I can confirm this, great work! Thanks!

x42

2012-10-20 19:07

administrator   ~0014116

fix confirmed. closing issue.

Issue History

Date Modified Username Field Change
2011-06-06 19:35 realhangman New Issue
2011-06-07 21:41 cth103 cost => 0.00
2011-06-07 21:41 cth103 Target Version => 3.0-beta1
2011-08-12 22:27 realhangman Tag Attached: delay
2011-08-12 22:27 realhangman Tag Attached: latency
2011-08-12 22:27 realhangman Tag Attached: compensation
2011-08-12 22:27 realhangman Tag Attached: export
2011-10-14 11:23 realhangman Note Added: 0011688
2011-11-14 20:31 cth103 Target Version 3.0-beta1 => 3.0-beta2
2012-01-10 20:46 cth103 Target Version 3.0-beta2 => 3.0-beta3
2012-02-02 16:50 realhangman Note Added: 0012749
2012-02-14 17:20 paul Target Version 3.0-beta3 => 3.0 beta4
2012-05-23 15:09 cth103 Target Version 3.0 beta4 => 3.0
2012-07-23 23:47 realhangman Note Added: 0013912
2012-07-25 16:38 x42 Note Added: 0013927
2012-07-25 16:40 x42 Note Edited: 0013927
2012-07-25 16:54 x42 Note Added: 0013928
2012-07-25 16:55 x42 File Added: xtest.tar.bz2
2012-07-25 16:59 x42 Note Edited: 0013928
2012-07-25 20:13 x42 Note Added: 0013929
2012-07-25 20:14 x42 Note Added: 0013930
2012-07-25 20:15 x42 File Added: a3_svn13072-debug_export_transport.diff
2012-07-25 20:44 x42 Note Edited: 0013929
2012-07-25 21:40 x42 Note Added: 0013931
2012-07-25 21:40 x42 File Added: a3_svn13072-export_transport_fix.diff
2012-10-16 14:03 realhangman Note Added: 0014070
2012-10-17 22:13 oofus Assigned To => SaBer
2012-10-17 22:13 oofus Status new => assigned
2012-10-17 22:16 oofus Priority normal => urgent
2012-10-19 20:42 x42 Note Added: 0014109
2012-10-19 20:42 x42 Status assigned => resolved
2012-10-19 20:42 x42 Resolution open => fixed
2012-10-20 18:26 realhangman Note Added: 0014115
2012-10-20 19:07 x42 Note Added: 0014116
2012-10-20 19:07 x42 Status resolved => closed