From: Carl Hetherington Date: Sun, 5 Jul 2020 19:38:35 +0000 (+0200) Subject: Add more logging and some missing prefs checkboxes for existing logging. X-Git-Tag: v2.15.87 X-Git-Url: https://git.carlh.net/gitweb/?a=commitdiff_plain;h=f20ec58b5fa6b5ffd49f0af6865290a775077e73;p=dcpomatic.git 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 e77f83bde..acd730a68 100644 --- 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 film, shared_ptraudio_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 (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 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 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 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 52a77f2f1..d5d230414 100644 --- a/src/lib/dcpomatic_log.h +++ b/src/lib/dcpomatic_log.h @@ -40,3 +40,6 @@ extern boost::shared_ptr 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 f890d488a..2af2c0f25 100644 --- 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 4bace41a4..50b8bc1a6 100644 --- 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 b45401fa9..57fc7a67c 100644 --- 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 dcp = dynamic_pointer_cast(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, DCPTime> > audio = _audio_merger.pull (pull_to); for (list, 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 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 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 5a3c05b9b..922758469 100644 --- 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