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

5 files changed, 25 insertions, 0 deletions

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<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 52a77f2f1..d5d230414 100644
--- 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 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<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 */