wip: more or less plays BT@ER (Flat) at full resolution with

about 130% CPU on i7-7700 CPU @ 3.60GHz, Quadro K1200.

No XYZ -> RGB colour transform yet.

8 files changed, 47 insertions, 24 deletions

diff --git a/src/lib/cpu_player_video_preparer.cc b/src/lib/cpu_player_video_preparer.cc
index 80cb5bc91..0891189b3 100644
--- a/src/lib/cpu_player_video_preparer.cc
+++ b/src/lib/cpu_player_video_preparer.cc
@@ -2,6 +2,7 @@
 #include "cross.h"
 #include "dcpomatic_log.h"
 #include "player_video.h"
+#include "timer.h"
 #include <boost/thread.hpp>
 
 
@@ -42,6 +43,7 @@ try
 		LOG_TIMING("start-prepare in %1", thread_id());
 		video->prepare (_pixel_format, _aligned, _fast);
 		LOG_TIMING("finish-prepare in %1", thread_id());
+		timestamped_printf("cpu finishes %d\n", video->time.frames_round(24));
 	}
 }
 catch (...)
diff --git a/src/lib/fastvideo_player_video_preparer.cc b/src/lib/fastvideo_player_video_preparer.cc
index 9d694df14..4e0f267ab 100644
--- a/src/lib/fastvideo_player_video_preparer.cc
+++ b/src/lib/fastvideo_player_video_preparer.cc
@@ -5,6 +5,7 @@
 #include "fastvideo_player_video_preparer.h"
 #include "j2k_image_proxy.h"
 #include "player_video.h"
+#include "timer.h"
 #include <fastvideo_decoder_j2k.h>
 #include <fastvideo_sdk.h>
 #include <boost/bind.hpp>
@@ -99,20 +100,22 @@ void
 FastvideoPlayerVideoPreparer::send_to_gpu (shared_ptr<PlayerVideo> pv, shared_ptr<const J2KImageProxy> proxy)
 {
 	if (!_setup_done) {
-		std::cout << "setup.\n";
 		setup (proxy->j2k());
 		_setup_done = true;
 	}
 
-	std::cout << "add to batch.\n";
+	//std::cout << "add to batch.\n";
+	timestamped_printf("fv sends %d to gpu\n", pv->time.frames_round(24));
 	fastDecoderJ2kAddImageToBatch(_decoder, proxy->j2k().data().get(), proxy->j2k().size());
 	_batch.push_back (pv);
 
 	int free_slots = 0;
 	fastDecoderJ2kFreeSlotsInBatch(_decoder, &free_slots);
-	std::cout << free_slots << " left in batch.\n";
+	timestamped_printf("now %d slots left.\n", free_slots);
+	//std::cout << free_slots << " left in batch.\n";
 	if (free_slots == 0) {
 		/* Do some decoding */
+		timestamped_printf("tx & extract\n");
 		transform_and_extract ();
 	}
 
@@ -130,12 +133,12 @@ FastvideoPlayerVideoPreparer::transform_and_extract ()
 	}
 
 	size_t index = 0;
-	int images_left;
-	do {
+	int images_left = 1;
+	while (true) {
 		DCPOMATIC_ASSERT (index <= _batch.size());
 		shared_ptr<PlayerVideo> pv = _batch[index].lock();
 		if (pv) {
-			std::cout << "got a pv for batch number " << index << "\n";
+			//std::cout << "got a pv for batch number " << index << "\n";
 			/* XXX: this should be memlocked or whatever fastMalloc does */
 			shared_ptr<J2KImageProxy> proxy = const_pointer_cast<J2KImageProxy>(dynamic_pointer_cast<const J2KImageProxy>(pv->image_proxy()));
 			DCPOMATIC_ASSERT (proxy);
@@ -148,21 +151,22 @@ FastvideoPlayerVideoPreparer::transform_and_extract ()
 				throw FastvideoError ("ExportToHostCopy", r);
 			}
 
-			std::cout << "setting the proxy's image.\n";
+			timestamped_printf("fv sets image for %d\n", pv->time.frames_round(24));
 			proxy->set_image (image);
 
 			_cpu.request (pv);
 		}
 
+		if (images_left == 0) {
+			break;
+		}
 		fastStatus_t r = fastDecoderJ2kGetNextDecodedImage(_decoder, &report, &images_left);
-		std::cout << images_left << " images left.\n";
 		if (r != FAST_OK) {
 			throw FastvideoError ("DecoderJ2kGetNextDecodedImage", r);
 		}
 
 		++index;
-
-	} while (images_left);
+	};
 
 	_batch.clear ();
 }
diff --git a/src/lib/j2k_image_proxy.cc b/src/lib/j2k_image_proxy.cc
index 18d597e50..b22296b43 100644
--- a/src/lib/j2k_image_proxy.cc
+++ b/src/lib/j2k_image_proxy.cc
@@ -127,20 +127,7 @@ J2KImageProxy::prepare (optional<dcp::Size> target_size) const
 {
 	boost::mutex::scoped_lock lm (_mutex);
 
-	if (target_size) {
-		std::cout << "target_size is " << target_size->width << " " << target_size->height << "\n";
-	} else {
-		std::cout << "no target size.\n";
-	}
-
-	if (_target_size) {
-		std::cout << "_target_size is " << _target_size->width << " " << _target_size->height << "\n";
-	} else {
-		std::cout << "no _target size.\n";
-	}
-
 	if (_image) {// && target_size == _target_size) {
-		std::cout << "hit.\n";
 		return 0;
 		//DCPOMATIC_ASSERT (_reduce);
 		//return *_reduce;
@@ -160,7 +147,6 @@ J2KImageProxy::prepare (optional<dcp::Size> target_size) const
 	}
 
 	try {
-		std::cout << "cpu decompress.\n";
 		shared_ptr<dcp::OpenJPEGImage> decompressed = dcp::decompress_j2k (_data, reduce);
 		_image.reset (new Image (_pixel_format, decompressed->size(), true));
 
diff --git a/src/lib/player.cc b/src/lib/player.cc
index 57fc7a67c..85bf3a180 100644
--- a/src/lib/player.cc
+++ b/src/lib/player.cc
@@ -891,6 +891,10 @@ Player::video (weak_ptr<Piece> wp, ContentVideo video)
 			)
 		);
 
+#ifdef DCPOMATIC_DEBUG
+	_last_video[wp]->time = time;
+#endif
+
 	DCPTime t = time;
 	for (int i = 0; i < frc.repeat; ++i) {
 		if (t < piece->content->end(_film)) {
diff --git a/src/lib/player_video.cc b/src/lib/player_video.cc
index 1a4c9028d..3c2f3f094 100644
--- a/src/lib/player_video.cc
+++ b/src/lib/player_video.cc
@@ -25,6 +25,7 @@
 #include "image_proxy.h"
 #include "j2k_image_proxy.h"
 #include "film.h"
+#include "timer.h"
 #include <dcp/raw_convert.h>
 extern "C" {
 #include <libavutil/pixfmt.h>
@@ -116,6 +117,7 @@ PlayerVideo::image (function<AVPixelFormat (AVPixelFormat)> pixel_format, bool a
 
 	boost::mutex::scoped_lock lm (_mutex);
 	if (!_image || _crop != _image_crop || _inter_size != _image_inter_size || _out_size != _image_out_size || _fade != _image_fade) {
+		timestamped_printf("_________________!!! make_image() for %d [%d]\n", time.frames_round(24), !_image);
 		make_image (pixel_format, aligned, fast);
 	}
 	return _image;
diff --git a/src/lib/player_video.h b/src/lib/player_video.h
index 464bb4894..65d25bfd9 100644
--- a/src/lib/player_video.h
+++ b/src/lib/player_video.h
@@ -121,6 +121,10 @@ public:
 		return _in;
 	}
 
+#ifdef DCPOMATIC_DEBUG
+	dcpomatic::DCPTime time;
+#endif
+
 private:
 	void make_image (boost::function<AVPixelFormat (AVPixelFormat)> pixel_format, bool aligned, bool fast) const;
 
diff --git a/src/lib/timer.cc b/src/lib/timer.cc
index e4e7bdfdc..7518b5ddc 100644
--- a/src/lib/timer.cc
+++ b/src/lib/timer.cc
@@ -25,6 +25,7 @@
 #include "timer.h"
 #include "util.h"
 #include "compose.hpp"
+#include <boost/thread.hpp>
 #include <iostream>
 #include <sys/time.h>
 
@@ -134,3 +135,19 @@ StateTimer::~StateTimer ()
 		cout << N_("\t") << i->second << "\n";
 	}
 }
+
+
+void timestamped_printf (char const* format, ...)
+{
+	static boost::mutex mutex;
+	boost::mutex::scoped_lock lm (mutex);
+
+	va_list arg;
+	va_start (arg, format);
+	struct timeval t;
+	gettimeofday (&t, 0);
+	printf("%.4f ", seconds(t));
+	vfprintf (stdout, format, arg);
+	va_end (arg);
+}
+
diff --git a/src/lib/timer.h b/src/lib/timer.h
index bd4e652f8..2ec350cea 100644
--- a/src/lib/timer.h
+++ b/src/lib/timer.h
@@ -30,6 +30,10 @@
 #include <string>
 #include <map>
 
+
+void timestamped_printf(char const* format, ...);
+
+
 /** @class PeriodTimer
  *  @brief A class to allow timing of a period within the caller.
  *