Add DEBUG_DECODE and some basic debugging of the decoding process.

6 files changed, 27 insertions, 8 deletions

diff --git a/src/lib/audio_decoder_stream.cc b/src/lib/audio_decoder_stream.cc
index 8c521f94d..fdcebbc9f 100644
--- a/src/lib/audio_decoder_stream.cc
+++ b/src/lib/audio_decoder_stream.cc
@@ -23,6 +23,8 @@
 #include "audio_decoder.h"
 #include "resampler.h"
 #include "util.h"
+#include "film.h"
+#include "log.h"
 #include <iostream>
 
 #include "i18n.h"
@@ -58,6 +60,8 @@ AudioDecoderStream::get (Frame frame, Frame length, bool accurate)
 {
 	shared_ptr<ContentAudio> dec;
 
+	_content->film()->log()->log (String::compose ("ADS has request for %1 %2", frame, length), Log::TYPE_DEBUG_DECODE);
+
 	Frame const end = frame + length - 1;
 
 	if (frame < _decoded.frame || end > (_decoded.frame + length * 4)) {
@@ -130,6 +134,8 @@ AudioDecoderStream::get (Frame frame, Frame length, bool accurate)
 void
 AudioDecoderStream::audio (shared_ptr<const AudioBuffers> data, ContentTime time)
 {
+	_content->film()->log()->log (String::compose ("ADS receives %1 %2", time, data->frames ()), Log::TYPE_DEBUG_DECODE);
+
 	if (_resampler) {
 		data = _resampler->run (data);
 	}
diff --git a/src/lib/config.cc b/src/lib/config.cc
index e6f363729..ee38e9866 100644
--- a/src/lib/config.cc
+++ b/src/lib/config.cc
@@ -78,7 +78,7 @@ Config::set_defaults ()
 	_check_for_updates = false;
 	_check_for_test_updates = false;
 	_maximum_j2k_bandwidth = 250000000;
-	_log_types = Log::TYPE_GENERAL | Log::TYPE_WARNING | Log::TYPE_ERROR | Log::TYPE_DEBUG;
+	_log_types = Log::TYPE_GENERAL | Log::TYPE_WARNING | Log::TYPE_ERROR;
 #ifdef DCPOMATIC_WINDOWS
 	_win32_console = false;
 #endif
diff --git a/src/lib/log.cc b/src/lib/log.cc
index 42184ec45..d9696f3cc 100644
--- a/src/lib/log.cc
+++ b/src/lib/log.cc
@@ -32,11 +32,11 @@
 
 using namespace std;
 
-int const Log::TYPE_GENERAL = 0x1;
-int const Log::TYPE_WARNING = 0x2;
-int const Log::TYPE_ERROR   = 0x4;
-int const Log::TYPE_DEBUG   = 0x8;
-int const Log::TYPE_TIMING  = 0x10;
+int const Log::TYPE_GENERAL      = 0x1;
+int const Log::TYPE_WARNING      = 0x2;
+int const Log::TYPE_ERROR        = 0x4;
+int const Log::TYPE_DEBUG_DECODE = 0x8;
+int const Log::TYPE_TIMING       = 0x10;
 
 Log::Log ()
 	: _types (0)
diff --git a/src/lib/log.h b/src/lib/log.h
index 1b7cef038..6803f8d59 100644
--- a/src/lib/log.h
+++ b/src/lib/log.h
@@ -42,7 +42,7 @@ public:
 	static const int TYPE_GENERAL;
 	static const int TYPE_WARNING;
 	static const int TYPE_ERROR;
-	static const int TYPE_DEBUG;
+	static const int TYPE_DEBUG_DECODE;
 	static const int TYPE_TIMING;
 
 	void log (std::string message, int type);
diff --git a/src/lib/video_decoder.cc b/src/lib/video_decoder.cc
index fcc262163..cdf8bc12a 100644
--- a/src/lib/video_decoder.cc
+++ b/src/lib/video_decoder.cc
@@ -1,5 +1,5 @@
 /*
-    Copyright (C) 2012-2014 Carl Hetherington <cth@carlh.net>
+    Copyright (C) 2012-2015 Carl Hetherington <cth@carlh.net>
 
     This program is free software; you can redistribute it and/or modify
     it under the terms of the GNU General Public License as published by
@@ -75,6 +75,8 @@ VideoDecoder::get_video (Frame frame, bool accurate)
 	   one after the end of _decoded_video we need to seek.
 	*/
 
+	_video_content->film()->log()->log (String::compose ("VD has request for %1", frame), Log::TYPE_DEBUG_DECODE);
+
 	if (_decoded_video.empty() || frame < _decoded_video.front().frame || frame > (_decoded_video.back().frame + 1)) {
 		seek (ContentTime::from_frames (frame, _video_content->video_frame_rate()), accurate);
 	}
@@ -233,6 +235,8 @@ VideoDecoder::video (shared_ptr<const ImageProxy> image, Frame frame)
 		return;
 	}
 
+	_video_content->film()->log()->log (String::compose ("VD receives %1", frame), Log::TYPE_DEBUG_DECODE);
+
 	/* We may receive the same frame index twice for 3D, and we need to know
 	   when that happens.
 	*/
diff --git a/src/wx/config_dialog.cc b/src/wx/config_dialog.cc
index 036172bb7..0c1ea29e5 100644
--- a/src/wx/config_dialog.cc
+++ b/src/wx/config_dialog.cc
@@ -1118,6 +1118,7 @@ public:
 		, _log_warning (0)
 		, _log_error (0)
 		, _log_timing (0)
+		, _log_debug_decode (0)
 	{}
 
 private:
@@ -1158,6 +1159,8 @@ private:
 			t->Add (_log_error, 1, wxEXPAND | wxALL);
 			_log_timing = new wxCheckBox (_panel, wxID_ANY, S_("Config|Timing"));
 			t->Add (_log_timing, 1, wxEXPAND | wxALL);
+			_log_debug_decode = new wxCheckBox (_panel, wxID_ANY, _("Debug: decode"));
+			t->Add (_log_debug_decode, 1, wxEXPAND | wxALL);
 			table->Add (t, 0, wxALL, 6);
 		}
 
@@ -1174,6 +1177,7 @@ private:
 		_log_warning->Bind (wxEVT_COMMAND_CHECKBOX_CLICKED, boost::bind (&AdvancedPage::log_changed, this));
 		_log_error->Bind (wxEVT_COMMAND_CHECKBOX_CLICKED, boost::bind (&AdvancedPage::log_changed, this));
 		_log_timing->Bind (wxEVT_COMMAND_CHECKBOX_CLICKED, boost::bind (&AdvancedPage::log_changed, this));
+		_log_debug_decode->Bind (wxEVT_COMMAND_CHECKBOX_CLICKED, boost::bind (&AdvancedPage::log_changed, this));
 #ifdef DCPOMATIC_WINDOWS
 		_win32_console->Bind (wxEVT_COMMAND_CHECKBOX_CLICKED, boost::bind (&AdvancedPage::win32_console_changed, this));
 #endif
@@ -1189,6 +1193,7 @@ private:
 		checked_set (_log_warning, config->log_types() & Log::TYPE_WARNING);
 		checked_set (_log_error, config->log_types() & Log::TYPE_ERROR);
 		checked_set (_log_timing, config->log_types() & Log::TYPE_TIMING);
+		checked_set (_log_debug_decode, config->log_types() & Log::TYPE_DEBUG_DECODE);
 #ifdef DCPOMATIC_WINDOWS
 		checked_set (_win32_console, config->win32_console());
 #endif
@@ -1219,6 +1224,9 @@ private:
 		if (_log_timing->GetValue ()) {
 			types |= Log::TYPE_TIMING;
 		}
+		if (_log_debug_decode->GetValue ()) {
+			types |= Log::TYPE_DEBUG_DECODE;
+		}
 		Config::instance()->set_log_types (types);
 	}
 
@@ -1235,6 +1243,7 @@ private:
 	wxCheckBox* _log_warning;
 	wxCheckBox* _log_error;
 	wxCheckBox* _log_timing;
+	wxCheckBox* _log_debug_decode;
 #ifdef DCPOMATIC_WINDOWS
 	wxCheckBox* _win32_console;
 #endif