Remove unused LOG_DEBUG_DECODE and re-use it to add some 3D shuffler logging.v2.15.46

4 files changed, 19 insertions, 4 deletions

diff --git a/src/lib/dcpomatic_log.h b/src/lib/dcpomatic_log.h
index 2cec0c405..dbc850036 100644
--- a/src/lib/dcpomatic_log.h
+++ b/src/lib/dcpomatic_log.h
@@ -1,5 +1,5 @@
 /*
-    Copyright (C) 2018 Carl Hetherington <cth@carlh.net>
+    Copyright (C) 2018-2020 Carl Hetherington <cth@carlh.net>
 
     This file is part of DCP-o-matic.
 
@@ -34,3 +34,5 @@ extern boost::shared_ptr<Log> dcpomatic_log;
 #define LOG_TIMING(...)       dcpomatic_log->log(String::compose(__VA_ARGS__), LogEntry::TYPE_TIMING);
 #define LOG_DEBUG_ENCODE(...) dcpomatic_log->log(String::compose(__VA_ARGS__), LogEntry::TYPE_DEBUG_ENCODE);
 #define LOG_DEBUG_PLAYER(...) dcpomatic_log->log(String::compose(__VA_ARGS__), LogEntry::TYPE_DEBUG_PLAYER);
+#define LOG_DEBUG_THREED(...) dcpomatic_log->log(String::compose(__VA_ARGS__), LogEntry::TYPE_DEBUG_THREED);
+#define LOG_DEBUG_THREED_NC(...) dcpomatic_log->log(__VA_ARGS__, LogEntry::TYPE_DEBUG_THREED);
diff --git a/src/lib/log_entry.cc b/src/lib/log_entry.cc
index 6a36c3383..54f9bfc53 100644
--- a/src/lib/log_entry.cc
+++ b/src/lib/log_entry.cc
@@ -27,7 +27,7 @@
 int const LogEntry::TYPE_GENERAL      = 0x1;
 int const LogEntry::TYPE_WARNING      = 0x2;
 int const LogEntry::TYPE_ERROR        = 0x4;
-int const LogEntry::TYPE_DEBUG_DECODE = 0x8;
+int const LogEntry::TYPE_DEBUG_THREED = 0x8;
 int const LogEntry::TYPE_DEBUG_ENCODE = 0x10;
 int const LogEntry::TYPE_TIMING       = 0x20;
 int const LogEntry::TYPE_DEBUG_EMAIL  = 0x40;
diff --git a/src/lib/log_entry.h b/src/lib/log_entry.h
index 50bbf63a0..c15a006d1 100644
--- a/src/lib/log_entry.h
+++ b/src/lib/log_entry.h
@@ -31,7 +31,7 @@ public:
 	static const int TYPE_GENERAL;
 	static const int TYPE_WARNING;
 	static const int TYPE_ERROR;
-	static const int TYPE_DEBUG_DECODE;
+	static const int TYPE_DEBUG_THREED;
 	static const int TYPE_DEBUG_ENCODE;
 	static const int TYPE_TIMING;
 	static const int TYPE_DEBUG_EMAIL;
diff --git a/src/lib/shuffler.cc b/src/lib/shuffler.cc
index a46b26da0..f6f05d41d 100644
--- a/src/lib/shuffler.cc
+++ b/src/lib/shuffler.cc
@@ -1,5 +1,5 @@
 /*
-    Copyright (C) 2018-2019 Carl Hetherington <cth@carlh.net>
+    Copyright (C) 2018-2020 Carl Hetherington <cth@carlh.net>
 
     This file is part of DCP-o-matic.
 
@@ -23,9 +23,11 @@
 #include "dcpomatic_assert.h"
 #include "dcpomatic_log.h"
 #include <boost/foreach.hpp>
+#include <string>
 #include <iostream>
 
 using std::make_pair;
+using std::string;
 using boost::weak_ptr;
 using boost::shared_ptr;
 using boost::optional;
@@ -45,6 +47,8 @@ struct Comparator
 void
 Shuffler::video (weak_ptr<Piece> weak_piece, ContentVideo video)
 {
+	LOG_DEBUG_THREED ("Shuffler::video frame=%1 eyes=%2 part=%3", video.frame, static_cast<int>(video.eyes), static_cast<int>(video.part));
+
 	if (video.eyes != EYES_LEFT && video.eyes != EYES_RIGHT) {
 		/* Pass through anything that we don't care about */
 		Video (weak_piece, video);
@@ -55,6 +59,7 @@ Shuffler::video (weak_ptr<Piece> weak_piece, ContentVideo video)
 	DCPOMATIC_ASSERT (piece);
 
 	if (!_last && video.eyes == EYES_LEFT) {
+		LOG_DEBUG_THREED_NC ("Shuffler first after clear");
 		/* We haven't seen anything since the last clear() and we have some eyes-left so assume everything is OK */
 		Video (weak_piece, video);
 		_last = video;
@@ -74,6 +79,12 @@ Shuffler::video (weak_ptr<Piece> weak_piece, ContentVideo video)
 				(_store.front().second.frame >= (_last->frame + 1) && _store.front().second.eyes == EYES_LEFT  && _last->eyes == EYES_RIGHT)
 				);
 
+		if (!store_front_in_sequence) {
+			string const store = _store.empty() ? "store empty" : String::compose("store front frame=%1 eyes=%2", _store.front().second.frame, static_cast<int>(_store.front().second.eyes));
+			string const last = _last ? String::compose("last frame=%1 eyes=%2", _last->frame, static_cast<int>(_last->eyes)) : "no last";
+			LOG_DEBUG_THREED("Shuffler not in sequence: %1 %2", store, last);
+		}
+
 		if (!store_front_in_sequence && _store.size() <= _max_size) {
 			/* store_front_in_sequence means everything is ok; otherwise if the store is getting too big just
 			   start emitting things as best we can.  This can easily happen if, for example, there is only content
@@ -86,6 +97,7 @@ Shuffler::video (weak_ptr<Piece> weak_piece, ContentVideo video)
 			LOG_WARNING ("Shuffler is full after receiving frame %1; 3D sync may be incorrect.", video.frame);
 		}
 
+		LOG_DEBUG_THREED("Shuffler emits frame=%1 eyes=%2 store=%3", _store.front().second.frame, static_cast<int>(_store.front().second.eyes, _store.size()));
 		Video (_store.front().first, _store.front().second);
 		_last = _store.front().second;
 		_store.pop_front ();
@@ -95,6 +107,7 @@ Shuffler::video (weak_ptr<Piece> weak_piece, ContentVideo video)
 void
 Shuffler::clear ()
 {
+	LOG_DEBUG_THREED_NC ("Shuffler::clear");
 	_store.clear ();
 	_last = optional<ContentVideo>();
 }