Add DEBUG_DECODE and some basic debugging of the decoding process.

diff --git a/ChangeLog b/ChangeLog
index 8759abeb4ced1e9b65aa7173a27c4da7f096cc88..8e182f80cc28b16dbc178243720d23a471b20266 100644 (file)
--- a/ChangeLog
+++ b/ChangeLog
@@ -1,3 +1,7 @@
+2015-06-25  c.hetherington  <cth@carlh.net>
+
+       * Add decode debugging option.
+
 2015-06-24  c.hetherington  <cth@carlh.net>
 
        * Bump libdcp for probable fix to various font ID problems (#620).

diff --git a/src/lib/audio_decoder_stream.cc b/src/lib/audio_decoder_stream.cc
index 8c521f94dfbdee956dbc5085b2764a73e651ee01..fdcebbc9f0648a24a22cc8770a56c1bf52e512b6 100644 (file)
--- 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 e6f3637292939955df627752c7f8118e87504020..ee38e98665994ce4c87380e400032b4dd35adf45 100644 (file)
--- 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 42184ec4582662bf09d21896f4332d9ab6bae24b..d9696f3cce2ca31bacc89692cbedf7bd468b8880 100644 (file)
--- 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 1b7cef03891c107d979bb465ed05ef6e8700b24f..6803f8d59ce707bb87cdb3d8c9a01599e1149751 100644 (file)
--- 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 fcc262163ecab19844fdd992b641d4d3a2d12c31..cdf8bc12afa954205353f98f106960b23ce478fe 100644 (file)
--- 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 036172bb7eaa45f381e4b91b7e4ed7f22d1e4696..0c1ea29e56709fcdb9fc4f4aab4254a3fc8bc8cb 100644 (file)
--- 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