Timestamp audio emissions from butler and hence discard very late

audio in FilmViewer.  This should help with the case where lots
of video frames are rapidly discarded when they are late but the
corresponding audio is not, hence audio buffers get overfilled.

7 files changed, 74 insertions, 44 deletions

diff --git a/src/lib/audio_ring_buffers.cc b/src/lib/audio_ring_buffers.cc
index 42115efa3..f51ff8a38 100644
--- a/src/lib/audio_ring_buffers.cc
+++ b/src/lib/audio_ring_buffers.cc
@@ -1,5 +1,5 @@
 /*
-    Copyright (C) 2016-2017 Carl Hetherington <cth@carlh.net>
+    Copyright (C) 2016-2018 Carl Hetherington <cth@carlh.net>
 
     This file is part of DCP-o-matic.
 
@@ -26,7 +26,11 @@
 
 using std::min;
 using std::cout;
+using std::make_pair;
+using std::pair;
+using std::list;
 using boost::shared_ptr;
+using boost::optional;
 
 AudioRingBuffers::AudioRingBuffers ()
 	: _used_in_head (0)
@@ -35,23 +39,26 @@ AudioRingBuffers::AudioRingBuffers ()
 }
 
 void
-AudioRingBuffers::put (shared_ptr<const AudioBuffers> data)
+AudioRingBuffers::put (shared_ptr<const AudioBuffers> data, DCPTime time)
 {
 	boost::mutex::scoped_lock lm (_mutex);
 
-	if (!_buffers.empty ()) {
-		DCPOMATIC_ASSERT (_buffers.front()->channels() == data->channels());
+	if (!_buffers.empty()) {
+		DCPOMATIC_ASSERT (_buffers.front().first->channels() == data->channels());
+		DCPOMATIC_ASSERT ((_buffers.back().second + DCPTime::from_frames(_buffers.back().first->frames(), 48000)) == time);
 	}
 
-	_buffers.push_back (data);
+	_buffers.push_back(make_pair(data, time));
 }
 
-/** @return true if there was an underrun, otherwise false */
-bool
+/** @return time of the returned data; if it's not set this indicates an underrun */
+optional<DCPTime>
 AudioRingBuffers::get (float* out, int channels, int frames)
 {
 	boost::mutex::scoped_lock lm (_mutex);
 
+	optional<DCPTime> time;
+
 	while (frames > 0) {
 		if (_buffers.empty ()) {
 			for (int i = 0; i < frames; ++i) {
@@ -60,14 +67,17 @@ AudioRingBuffers::get (float* out, int channels, int frames)
 				}
 			}
 			cout << "audio underrun; missing " << frames << "!\n";
-			return true;
+			return time;
 		}
 
-		shared_ptr<const AudioBuffers> front = _buffers.front ();
+		pair<shared_ptr<const AudioBuffers>, DCPTime> front = _buffers.front ();
+		if (!time) {
+			time = front.second + DCPTime::from_frames(_used_in_head, 48000);
+		}
 
-		int const to_do = min (frames, front->frames() - _used_in_head);
-		float** p = front->data();
-		int const c = min (front->channels(), channels);
+		int const to_do = min (frames, front.first->frames() - _used_in_head);
+		float** p = front.first->data();
+		int const c = min (front.first->channels(), channels);
 		for (int i = 0; i < to_do; ++i) {
 			for (int j = 0; j < c; ++j) {
 				*out++ = p[j][i + _used_in_head];
@@ -79,13 +89,13 @@ AudioRingBuffers::get (float* out, int channels, int frames)
 		_used_in_head += to_do;
 		frames -= to_do;
 
-		if (_used_in_head == front->frames()) {
+		if (_used_in_head == front.first->frames()) {
 			_buffers.pop_front ();
 			_used_in_head = 0;
 		}
 	}
 
-	return false;
+	return time;
 }
 
 void
@@ -101,8 +111,8 @@ AudioRingBuffers::size () const
 {
 	boost::mutex::scoped_lock lm (_mutex);
 	Frame s = 0;
-	BOOST_FOREACH (shared_ptr<const AudioBuffers> i, _buffers) {
-		s += i->frames ();
+	for (list<pair<shared_ptr<const AudioBuffers>, DCPTime> >::const_iterator i = _buffers.begin(); i != _buffers.end(); ++i) {
+		s += i->first->frames();
 	}
 	return s - _used_in_head;
 }
diff --git a/src/lib/audio_ring_buffers.h b/src/lib/audio_ring_buffers.h
index 3c726425c..53236cb32 100644
--- a/src/lib/audio_ring_buffers.h
+++ b/src/lib/audio_ring_buffers.h
@@ -33,15 +33,15 @@ class AudioRingBuffers : public boost::noncopyable
 public:
 	AudioRingBuffers ();
 
-	void put (boost::shared_ptr<const AudioBuffers> data);
-	bool get (float* out, int channels, int frames);
+	void put (boost::shared_ptr<const AudioBuffers> data, DCPTime time);
+	boost::optional<DCPTime> get (float* out, int channels, int frames);
 
 	void clear ();
 	Frame size () const;
 
 private:
 	mutable boost::mutex _mutex;
-	std::list<boost::shared_ptr<const AudioBuffers> > _buffers;
+	std::list<std::pair<boost::shared_ptr<const AudioBuffers>, DCPTime> > _buffers;
 	int _used_in_head;
 };
 
diff --git a/src/lib/butler.cc b/src/lib/butler.cc
index 63fe729ae..aee584654 100644
--- a/src/lib/butler.cc
+++ b/src/lib/butler.cc
@@ -62,7 +62,7 @@ Butler::Butler (shared_ptr<Player> player, shared_ptr<Log> log, AudioMapping aud
 	, _disable_audio (false)
 {
 	_player_video_connection = _player->Video.connect (bind (&Butler::video, this, _1, _2));
-	_player_audio_connection = _player->Audio.connect (bind (&Butler::audio, this, _1));
+	_player_audio_connection = _player->Audio.connect (bind (&Butler::audio, this, _1, _2));
 	_player_changed_connection = _player->Changed.connect (bind (&Butler::player_changed, this, _1));
 	_thread = new boost::thread (bind (&Butler::thread, this));
 #ifdef DCPOMATIC_LINUX
@@ -258,7 +258,7 @@ Butler::video (shared_ptr<PlayerVideo> video, DCPTime time)
 }
 
 void
-Butler::audio (shared_ptr<AudioBuffers> audio)
+Butler::audio (shared_ptr<AudioBuffers> audio, DCPTime time)
 {
 	{
 		boost::mutex::scoped_lock lm (_mutex);
@@ -269,19 +269,19 @@ Butler::audio (shared_ptr<AudioBuffers> audio)
 	}
 
 	boost::mutex::scoped_lock lm2 (_video_audio_mutex);
-	_audio.put (remap (audio, _audio_channels, _audio_mapping));
+	_audio.put (remap (audio, _audio_channels, _audio_mapping), time);
 }
 
 /** Try to get `frames' frames of audio and copy it into `out'.  Silence
  *  will be filled if no audio is available.
- *  @return true if there was a buffer underrun, otherwise false.
+ *  @return time of this audio, or unset if there was a buffer underrun.
  */
-bool
+optional<DCPTime>
 Butler::get_audio (float* out, Frame frames)
 {
-	bool const underrun = _audio.get (out, _audio_channels, frames);
+	optional<DCPTime> t = _audio.get (out, _audio_channels, frames);
 	_summon.notify_all ();
-	return underrun;
+	return t;
 }
 
 void
diff --git a/src/lib/butler.h b/src/lib/butler.h
index a8b38ef2e..e6553cf8c 100644
--- a/src/lib/butler.h
+++ b/src/lib/butler.h
@@ -41,7 +41,7 @@ public:
 
 	void seek (DCPTime position, bool accurate);
 	std::pair<boost::shared_ptr<PlayerVideo>, DCPTime> get_video ();
-	bool get_audio (float* out, Frame frames);
+	boost::optional<DCPTime> get_audio (float* out, Frame frames);
 
 	void disable_audio ();
 
@@ -50,7 +50,7 @@ public:
 private:
 	void thread ();
 	void video (boost::shared_ptr<PlayerVideo> video, DCPTime time);
-	void audio (boost::shared_ptr<AudioBuffers> audio);
+	void audio (boost::shared_ptr<AudioBuffers> audio, DCPTime time);
 	bool should_run () const;
 	void prepare (boost::weak_ptr<PlayerVideo> video) const;
 	void player_changed (int);
diff --git a/src/wx/film_viewer.cc b/src/wx/film_viewer.cc
index ef28018e9..ce34b06b7 100644
--- a/src/wx/film_viewer.cc
+++ b/src/wx/film_viewer.cc
@@ -882,6 +882,16 @@ FilmViewer::config_changed (Config::Property p)
 }
 
 DCPTime
+FilmViewer::uncorrected_time () const
+{
+	if (_audio.isStreamRunning ()) {
+		return DCPTime::from_seconds (const_cast<RtAudio*>(&_audio)->getStreamTime());
+	}
+
+	return _video_position;
+}
+
+DCPTime
 FilmViewer::time () const
 {
 	if (_audio.isStreamRunning ()) {
@@ -895,7 +905,14 @@ FilmViewer::time () const
 int
 FilmViewer::audio_callback (void* out_p, unsigned int frames)
 {
-	_butler->get_audio (reinterpret_cast<float*> (out_p), frames);
+	while (true) {
+		optional<DCPTime> t = _butler->get_audio (reinterpret_cast<float*> (out_p), frames);
+		if (!t || DCPTime(uncorrected_time() - *t) < one_video_frame()) {
+			/* There was an underrun or this audio is on time; carry on */
+			break;
+		}
+		/* The audio we just got was (very) late; drop it and get some more. */
+	}
 
         boost::mutex::scoped_lock lm (_latency_history_mutex, boost::try_to_lock);
         if (lm) {
diff --git a/src/wx/film_viewer.h b/src/wx/film_viewer.h
index e4449fa2f..a41500ace 100644
--- a/src/wx/film_viewer.h
+++ b/src/wx/film_viewer.h
@@ -114,6 +114,7 @@ private:
 	void recreate_butler ();
 	void config_changed (Config::Property);
 	DCPTime time () const;
+	DCPTime uncorrected_time () const;
 	Frame average_latency () const;
 	DCPTime one_video_frame () const;
 
diff --git a/test/audio_ring_buffers_test.cc b/test/audio_ring_buffers_test.cc
index 23491f6b3..506a6350e 100644
--- a/test/audio_ring_buffers_test.cc
+++ b/test/audio_ring_buffers_test.cc
@@ -1,5 +1,5 @@
 /*
-    Copyright (C) 2016-2017 Carl Hetherington <cth@carlh.net>
+    Copyright (C) 2016-2018 Carl Hetherington <cth@carlh.net>
 
     This file is part of DCP-o-matic.
 
@@ -27,6 +27,8 @@ using boost::shared_ptr;
 
 #define CANARY 9999
 
+/* XXX: these tests don't check the timestamping in AudioRingBuffers */
+
 /** Basic tests fetching the same number of channels as went in */
 BOOST_AUTO_TEST_CASE (audio_ring_buffers_test1)
 {
@@ -38,7 +40,7 @@ BOOST_AUTO_TEST_CASE (audio_ring_buffers_test1)
 	/* Getting some data should give an underrun and write zeros */
 	float buffer[256 * 6];
 	buffer[240 * 6] = CANARY;
-	BOOST_CHECK_EQUAL (rb.get (buffer, 6, 240), true);
+	BOOST_CHECK (!rb.get(buffer, 6, 240));
 	for (int i = 0; i < 240 * 6; ++i) {
 		BOOST_REQUIRE_EQUAL (buffer[i], 0);
 	}
@@ -48,7 +50,7 @@ BOOST_AUTO_TEST_CASE (audio_ring_buffers_test1)
 	rb.clear ();
 	BOOST_CHECK_EQUAL (rb.size(), 0);
 	buffer[240 * 6] = CANARY;
-	BOOST_CHECK_EQUAL (rb.get (buffer, 6, 240), true);
+	BOOST_CHECK (rb.get(buffer, 6, 240) == boost::optional<DCPTime>());
 	for (int i = 0; i < 240 * 6; ++i) {
 		BOOST_REQUIRE_EQUAL (buffer[i], 0);
 	}
@@ -62,12 +64,12 @@ BOOST_AUTO_TEST_CASE (audio_ring_buffers_test1)
 			data->data(j)[i] = value++;
 		}
 	}
-	rb.put (data);
+	rb.put (data, DCPTime());
 	BOOST_CHECK_EQUAL (rb.size(), 91);
 
 	/* Get part of it out */
 	buffer[40 * 6] = CANARY;
-	BOOST_CHECK_EQUAL (rb.get (buffer, 6, 40), false);
+	BOOST_CHECK (*rb.get(buffer, 6, 40) == DCPTime());
 	int check = 0;
 	for (int i = 0; i < 40 * 6; ++i) {
 		BOOST_REQUIRE_EQUAL (buffer[i], check++);
@@ -77,7 +79,7 @@ BOOST_AUTO_TEST_CASE (audio_ring_buffers_test1)
 
 	/* Get the rest */
 	buffer[51 * 6] = CANARY;
-	BOOST_CHECK_EQUAL (rb.get (buffer, 6, 51), false);
+	BOOST_CHECK (*rb.get(buffer, 6, 51) == DCPTime());
 	for (int i = 0; i < 51 * 6; ++i) {
 		BOOST_REQUIRE_EQUAL (buffer[i], check++);
 	}
@@ -86,7 +88,7 @@ BOOST_AUTO_TEST_CASE (audio_ring_buffers_test1)
 
 	/* Now there should be an underrun */
 	buffer[240 * 6] = CANARY;
-	BOOST_CHECK_EQUAL (rb.get (buffer, 6, 240), true);
+	BOOST_CHECK (!rb.get(buffer, 6, 240));
 	BOOST_CHECK_EQUAL (buffer[240 * 6], CANARY);
 }
 
@@ -103,13 +105,13 @@ BOOST_AUTO_TEST_CASE (audio_ring_buffers_test2)
 			data->data(j)[i] = value++;
 		}
 	}
-	rb.put (data);
+	rb.put (data, DCPTime());
 	BOOST_CHECK_EQUAL (rb.size(), 91);
 
 	/* Get part of it out */
 	float buffer[256 * 6];
 	buffer[40 * 6] = CANARY;
-	BOOST_CHECK_EQUAL (rb.get (buffer, 6, 40), false);
+	BOOST_CHECK (*rb.get(buffer, 6, 40) == DCPTime());
 	int check = 0;
 	for (int i = 0; i < 40; ++i) {
 		for (int j = 0; j < 2; ++j) {
@@ -124,7 +126,7 @@ BOOST_AUTO_TEST_CASE (audio_ring_buffers_test2)
 
 	/* Get the rest */
 	buffer[51 * 6] = CANARY;
-	BOOST_CHECK_EQUAL (rb.get (buffer, 6, 51), false);
+	BOOST_CHECK (*rb.get(buffer, 6, 51) == DCPTime());
 	for (int i = 0; i < 51; ++i) {
 		for (int j = 0; j < 2; ++j) {
 			BOOST_REQUIRE_EQUAL (buffer[i * 6 + j], check++);
@@ -138,7 +140,7 @@ BOOST_AUTO_TEST_CASE (audio_ring_buffers_test2)
 
 	/* Now there should be an underrun */
 	buffer[240 * 6] = CANARY;
-	BOOST_CHECK_EQUAL (rb.get (buffer, 6, 240), true);
+	BOOST_CHECK (!rb.get(buffer, 6, 240));
 	BOOST_CHECK_EQUAL (buffer[240 * 6], CANARY);
 }
 
@@ -155,13 +157,13 @@ BOOST_AUTO_TEST_CASE (audio_ring_buffers_test3)
 			data->data(j)[i] = value++;
 		}
 	}
-	rb.put (data);
+	rb.put (data, DCPTime ());
 	BOOST_CHECK_EQUAL (rb.size(), 91);
 
 	/* Get part of it out */
 	float buffer[256 * 6];
 	buffer[40 * 2] = CANARY;
-	BOOST_CHECK_EQUAL (rb.get (buffer, 2, 40), false);
+	BOOST_CHECK (*rb.get(buffer, 2, 40) == DCPTime());
 	int check = 0;
 	for (int i = 0; i < 40; ++i) {
 		for (int j = 0; j < 2; ++j) {
@@ -174,7 +176,7 @@ BOOST_AUTO_TEST_CASE (audio_ring_buffers_test3)
 
 	/* Get the rest */
 	buffer[51 * 2] = CANARY;
-	BOOST_CHECK_EQUAL (rb.get (buffer, 2, 51), false);
+	BOOST_CHECK (*rb.get(buffer, 2, 51) == DCPTime());
 	for (int i = 0; i < 51; ++i) {
 		for (int j = 0; j < 2; ++j)  {
 			BOOST_REQUIRE_EQUAL (buffer[i * 2 + j], check++);
@@ -186,6 +188,6 @@ BOOST_AUTO_TEST_CASE (audio_ring_buffers_test3)
 
 	/* Now there should be an underrun */
 	buffer[240 * 2] = CANARY;
-	BOOST_CHECK_EQUAL (rb.get (buffer, 2, 240), true);
+	BOOST_CHECK (!rb.get(buffer, 2, 240));
 	BOOST_CHECK_EQUAL (buffer[240 * 2], CANARY);
 }