Add more logging and some missing prefs checkboxes for existing logging.

diff --git a/src/lib/analyse_audio_job.cc b/src/lib/analyse_audio_job.cc
index e77f83bdedfd8c8b82dd21f8c28d287f2b8b8ab8..acd730a68bc1e4588546a64cdabed407ba5aac80 100644 (file)
--- a/src/lib/analyse_audio_job.cc
+++ b/src/lib/analyse_audio_job.cc
@@ -23,6 +23,7 @@
 #include "analyse_audio_job.h"
 #include "audio_content.h"
 #include "compose.hpp"
+#include "dcpomatic_log.h"
 #include "film.h"
 #include "player.h"
 #include "playlist.h"
@@ -74,6 +75,8 @@ AnalyseAudioJob::AnalyseAudioJob (shared_ptr<const Film> film, shared_ptr<const
        , _ebur128 (new AudioFilterGraph (film->audio_frame_rate(), film->audio_channels()))
 #endif
 {
+       LOG_DEBUG_AUDIO_ANALYSIS_NC("AnalyseAudioJob::AnalyseAudioJob");
+
 #ifdef DCPOMATIC_HAVE_EBUR128_PATCHED_FFMPEG
        _filters.push_back (new Filter ("ebur128", "ebur128", "audio", "ebur128=peak=true"));
        _ebur128->setup (_filters);
@@ -140,6 +143,8 @@ AnalyseAudioJob::json_name () const
 void
 AnalyseAudioJob::run ()
 {
+       LOG_DEBUG_AUDIO_ANALYSIS_NC("AnalyseAudioJob::run");
+
        shared_ptr<Player> player (new Player(_film, _playlist));
        player->set_ignore_video ();
        player->set_ignore_text ();
@@ -164,11 +169,15 @@ AnalyseAudioJob::run ()
        }
 
        if (has_any_audio) {
+               LOG_DEBUG_AUDIO_ANALYSIS("Seeking to %1", to_string(_start));
                player->seek (_start, true);
                _done = 0;
+               LOG_DEBUG_AUDIO_ANALYSIS("Starting loop for playlist of length %1", to_string(length));
                while (!player->pass ()) {}
        }
 
+       LOG_DEBUG_AUDIO_ANALYSIS_NC("Loop complete");
+
        vector<AudioAnalysis::PeakTime> sample_peak;
        for (int i = 0; i < _film->audio_channels(); ++i) {
                sample_peak.push_back (
@@ -205,6 +214,7 @@ AnalyseAudioJob::run ()
        _analysis->set_leqm (_leqm->leq_m());
        _analysis->write (_path);
 
+       LOG_DEBUG_AUDIO_ANALYSIS_NC("Job finished");
        set_progress (1);
        set_state (FINISHED_OK);
 }
@@ -212,6 +222,7 @@ AnalyseAudioJob::run ()
 void
 AnalyseAudioJob::analyse (shared_ptr<const AudioBuffers> b, DCPTime time)
 {
+       LOG_DEBUG_AUDIO_ANALYSIS("Received %1 frames at %2", b->frames(), to_string(time));
        DCPOMATIC_ASSERT (time >= _start);
 
 #ifdef DCPOMATIC_HAVE_EBUR128_PATCHED_FFMPEG
@@ -259,4 +270,5 @@ AnalyseAudioJob::analyse (shared_ptr<const AudioBuffers> b, DCPTime time)
 
        DCPTime const length = _playlist->length (_film);
        set_progress ((time.seconds() - _start.seconds()) / (length.seconds() - _start.seconds()));
+       LOG_DEBUG_AUDIO_ANALYSIS_NC("Frames processed");
 }

diff --git a/src/lib/dcpomatic_log.h b/src/lib/dcpomatic_log.h
index 52a77f2f1615cbaeac919aeff48bcb7dcdf23319..d5d230414751ad14d2d4057440d9b87ffd94ee8c 100644 (file)
--- a/src/lib/dcpomatic_log.h
+++ b/src/lib/dcpomatic_log.h
@@ -40,3 +40,6 @@ extern boost::shared_ptr<Log> dcpomatic_log;
 #define LOG_DISK_NC(...)      dcpomatic_log->log(__VA_ARGS__, LogEntry::TYPE_DISK);
 #define LOG_DEBUG_PLAYER(...)    dcpomatic_log->log(String::compose(__VA_ARGS__), LogEntry::TYPE_DEBUG_PLAYER);
 #define LOG_DEBUG_PLAYER_NC(...) dcpomatic_log->log(__VA_ARGS__, LogEntry::TYPE_DEBUG_PLAYER);
+#define LOG_DEBUG_AUDIO_ANALYSIS(...)    dcpomatic_log->log(String::compose(__VA_ARGS__), LogEntry::TYPE_DEBUG_AUDIO_ANALYSIS);
+#define LOG_DEBUG_AUDIO_ANALYSIS_NC(...) dcpomatic_log->log(__VA_ARGS__, LogEntry::TYPE_DEBUG_AUDIO_ANALYSIS);
+

diff --git a/src/lib/log_entry.cc b/src/lib/log_entry.cc
index f890d488ab920c256ce417b9fa05d3d7dcf7eb5b..2af2c0f25ef77cf135b2aaed60fbffc8fa54dbd5 100644 (file)
--- a/src/lib/log_entry.cc
+++ b/src/lib/log_entry.cc
@@ -34,6 +34,7 @@ int const LogEntry::TYPE_DEBUG_EMAIL  = 0x040;
 int const LogEntry::TYPE_DEBUG_VIDEO_VIEW = 0x080;
 int const LogEntry::TYPE_DISK         = 0x100;
 int const LogEntry::TYPE_DEBUG_PLAYER = 0x200;
+int const LogEntry::TYPE_DEBUG_AUDIO_ANALYSIS = 0x400;
 
 using std::string;
 

diff --git a/src/lib/log_entry.h b/src/lib/log_entry.h
index 4bace41a43b88a94c978bd066dd3e592ff9fcc75..50b8bc1a671f77484ac15440d2f85d4794effc44 100644 (file)
--- a/src/lib/log_entry.h
+++ b/src/lib/log_entry.h
@@ -38,6 +38,7 @@ public:
        static const int TYPE_DEBUG_VIDEO_VIEW; ///< real-time video viewing (i.e. "playback")
        static const int TYPE_DISK;
        static const int TYPE_DEBUG_PLAYER;     ///< the Player class
+       static const int TYPE_DEBUG_AUDIO_ANALYSIS; ///< audio analysis job
 
        explicit LogEntry (int type);
        virtual ~LogEntry () {}

diff --git a/src/lib/player.cc b/src/lib/player.cc
index b45401fa90cf8ca0b3b831b6f8607cc23ae535ae..57fc7a67c6bdeab59cc591a9c316ce655b3494fc 100644 (file)
--- a/src/lib/player.cc
+++ b/src/lib/player.cc
@@ -595,6 +595,7 @@ Player::pass ()
 
        if (_suspended) {
                /* We can't pass in this state */
+               LOG_DEBUG_PLAYER_NC ("Player is suspended");
                return false;
        }
 
@@ -655,6 +656,7 @@ Player::pass ()
        switch (which) {
        case CONTENT:
        {
+               LOG_DEBUG_PLAYER ("Calling pass() on %1", earliest_content->content->path(0));
                earliest_content->done = earliest_content->decoder->pass ();
                shared_ptr<DCPContent> dcp = dynamic_pointer_cast<DCPContent>(earliest_content->content);
                if (dcp && !_play_referenced && dcp->reference_audio()) {
@@ -673,6 +675,7 @@ Player::pass ()
                break;
        case SILENT:
        {
+               LOG_DEBUG_PLAYER ("Emit silence for gap at %1", to_string(_silent.position()));
                DCPTimePeriod period (_silent.period_at_position());
                if (_last_audio_time) {
                        /* Sometimes the thing that happened last finishes fractionally before
@@ -716,6 +719,7 @@ Player::pass ()
                pull_to = _silent.position();
        }
 
+       LOG_DEBUG_PLAYER("Emitting audio up to %1", to_string(pull_to));
        list<pair<shared_ptr<AudioBuffers>, DCPTime> > audio = _audio_merger.pull (pull_to);
        for (list<pair<shared_ptr<AudioBuffers>, DCPTime> >::iterator i = audio.begin(); i != audio.end(); ++i) {
                if (_last_audio_time && i->second < *_last_audio_time) {
@@ -808,6 +812,7 @@ Player::video (weak_ptr<Piece> wp, ContentVideo video)
 
        /* Time of the first frame we will emit */
        DCPTime const time = content_video_to_dcp (piece, video.frame);
+       LOG_DEBUG_PLAYER("Received video frame %1 at %2", video.frame, to_string(time));
 
        /* Discard if it's before the content's period or the last accurate seek.  We can't discard
           if it's after the content's period here as in that case we still need to fill any gap between
@@ -912,6 +917,8 @@ Player::audio (weak_ptr<Piece> wp, AudioStreamPtr stream, ContentAudio content_a
 
        /* Compute time in the DCP */
        DCPTime time = resampled_audio_to_dcp (piece, content_audio.frame);
+       LOG_DEBUG_PLAYER("Received audio frame %1 at %2", content_audio.frame, to_string(time));
+
        /* And the end of this block in the DCP */
        DCPTime end = time + DCPTime::from_frames(content_audio.audio->frames(), rfr);
 
@@ -1079,6 +1086,7 @@ void
 Player::seek (DCPTime time, bool accurate)
 {
        boost::mutex::scoped_lock lm (_mutex);
+       LOG_DEBUG_PLAYER("Seek to %1 (%2accurate)", to_string(time), accurate ? "" : "in");
 
        if (_suspended) {
                /* We can't seek in this state */

diff --git a/src/wx/full_config_dialog.cc b/src/wx/full_config_dialog.cc
index 5a3c05b9bf3528dd907d80db2433a286891c7beb..92275846977cda0b1260ea4fd45384af7dc8a94c 100644 (file)
--- a/src/wx/full_config_dialog.cc
+++ b/src/wx/full_config_dialog.cc
@@ -1284,6 +1284,9 @@ public:
                , _log_debug_threed (0)
                , _log_debug_encode (0)
                , _log_debug_email (0)
+               , _log_debug_video_view (0)
+               , _log_debug_player (0)
+               , _log_debug_audio_analysis (0)
        {}
 
 private:
@@ -1400,6 +1403,12 @@ private:
                        t->Add (_log_debug_encode, 1, wxEXPAND | wxALL);
                        _log_debug_email = new CheckBox (_panel, _("Debug: email sending"));
                        t->Add (_log_debug_email, 1, wxEXPAND | wxALL);
+                       _log_debug_video_view = new CheckBox (_panel, _("Debug: video view"));
+                       t->Add (_log_debug_video_view, 1, wxEXPAND | wxALL);
+                       _log_debug_player = new CheckBox (_panel, _("Debug: player"));
+                       t->Add (_log_debug_player, 1, wxEXPAND | wxALL);
+                       _log_debug_audio_analysis = new CheckBox (_panel, _("Debug: audio analysis"));
+                       t->Add (_log_debug_audio_analysis, 1, wxEXPAND | wxALL);
                        table->Add (t, 0, wxALL, 6);
                }
 
@@ -1428,6 +1437,9 @@ private:
                _log_debug_threed->Bind (wxEVT_CHECKBOX, boost::bind (&AdvancedPage::log_changed, this));
                _log_debug_encode->Bind (wxEVT_CHECKBOX, boost::bind (&AdvancedPage::log_changed, this));
                _log_debug_email->Bind (wxEVT_CHECKBOX, boost::bind (&AdvancedPage::log_changed, this));
+               _log_debug_video_view->Bind (wxEVT_CHECKBOX, boost::bind (&AdvancedPage::log_changed, this));
+               _log_debug_player->Bind (wxEVT_CHECKBOX, boost::bind (&AdvancedPage::log_changed, this));
+               _log_debug_audio_analysis->Bind (wxEVT_CHECKBOX, boost::bind (&AdvancedPage::log_changed, this));
 #ifdef DCPOMATIC_WINDOWS
                _win32_console->Bind (wxEVT_CHECKBOX, boost::bind (&AdvancedPage::win32_console_changed, this));
 #endif
@@ -1457,6 +1469,9 @@ private:
                checked_set (_log_debug_threed, config->log_types() & LogEntry::TYPE_DEBUG_THREED);
                checked_set (_log_debug_encode, config->log_types() & LogEntry::TYPE_DEBUG_ENCODE);
                checked_set (_log_debug_email, config->log_types() & LogEntry::TYPE_DEBUG_EMAIL);
+               checked_set (_log_debug_video_view, config->log_types() & LogEntry::TYPE_DEBUG_VIDEO_VIEW);
+               checked_set (_log_debug_player, config->log_types() & LogEntry::TYPE_DEBUG_PLAYER);
+               checked_set (_log_debug_audio_analysis, config->log_types() & LogEntry::TYPE_DEBUG_AUDIO_ANALYSIS);
                checked_set (_frames_in_memory_multiplier, config->frames_in_memory_multiplier());
 #ifdef DCPOMATIC_WINDOWS
                checked_set (_win32_console, config->win32_console());
@@ -1536,6 +1551,15 @@ private:
                if (_log_debug_email->GetValue ()) {
                        types |= LogEntry::TYPE_DEBUG_EMAIL;
                }
+               if (_log_debug_video_view->GetValue()) {
+                       types |= LogEntry::TYPE_DEBUG_VIDEO_VIEW;
+               }
+               if (_log_debug_player->GetValue()) {
+                       types |= LogEntry::TYPE_DEBUG_PLAYER;
+               }
+               if (_log_debug_audio_analysis->GetValue()) {
+                       types |= LogEntry::TYPE_DEBUG_AUDIO_ANALYSIS;
+               }
                Config::instance()->set_log_types (types);
        }
 
@@ -1562,6 +1586,9 @@ private:
        wxCheckBox* _log_debug_threed;
        wxCheckBox* _log_debug_encode;
        wxCheckBox* _log_debug_email;
+       wxCheckBox* _log_debug_video_view;
+       wxCheckBox* _log_debug_player;
+       wxCheckBox* _log_debug_audio_analysis;
 #ifdef DCPOMATIC_WINDOWS
        wxCheckBox* _win32_console;
 #endif