Some more debug logging.

5 files changed, 40 insertions, 3 deletions

diff --git a/src/lib/decoder.cc b/src/lib/decoder.cc
index 973582ca4..19fd4f45c 100644
--- a/src/lib/decoder.cc
+++ b/src/lib/decoder.cc
@@ -23,6 +23,7 @@
 
 #include <iostream>
 #include <stdint.h>
+#include <boost/lexical_cast.hpp>
 extern "C" {
 #include <libavfilter/avfiltergraph.h>
 #include <libavfilter/buffersrc.h>
@@ -409,6 +410,7 @@ Decoder::process_video (AVFrame* frame)
 				image->make_black ();
 			}
 
+			_log->microsecond_log ("Decoder emits " + lexical_cast<string> (_video_frame), Log::TIMING);
 			Video (image, _video_frame);
 			++_video_frame;
 		}
diff --git a/src/lib/j2k_wav_encoder.cc b/src/lib/j2k_wav_encoder.cc
index 9ae01c774..4deedc388 100644
--- a/src/lib/j2k_wav_encoder.cc
+++ b/src/lib/j2k_wav_encoder.cc
@@ -108,7 +108,9 @@ J2KWAVEncoder::process_video (shared_ptr<Image> yuv, int frame)
 
 	/* Wait until the queue has gone down a bit */
 	while (_queue.size() >= _worker_threads.size() * 2 && !_process_end) {
+		_log->microsecond_log ("Decoder sleeps", Log::TIMING);
 		_worker_condition.wait (lock);
+		_log->microsecond_log ("Decoder wakes", Log::TIMING);
 	}
 
 	if (_process_end) {
@@ -118,6 +120,7 @@ J2KWAVEncoder::process_video (shared_ptr<Image> yuv, int frame)
 	/* Only do the processing if we don't already have a file for this frame */
 	if (!boost::filesystem::exists (_opt->frame_out_path (frame, false))) {
 		pair<string, string> const s = Filter::ffmpeg_strings (_fs->filters);
+		_log->microsecond_log ("Adding to queue of " + boost::lexical_cast<string> (_queue.size ()), Log::TIMING);
 		_queue.push_back (boost::shared_ptr<DCPVideoFrame> (
 					  new DCPVideoFrame (
 						  yuv, _opt->out_size, _opt->padding, _fs->scaler, frame, _fs->frames_per_second, s.second,
@@ -144,7 +147,9 @@ J2KWAVEncoder::encoder_thread (ServerDescription* server)
 	while (1) {
 		boost::mutex::scoped_lock lock (_worker_mutex);
 		while (_queue.empty () && !_process_end) {
+			_log->microsecond_log ("Encoder thread sleeps", Log::TIMING);
 			_worker_condition.wait (lock);
+			_log->microsecond_log ("Encoder thread wakes", Log::TIMING);
 		}
 
 		if (_process_end) {
@@ -152,6 +157,7 @@ J2KWAVEncoder::encoder_thread (ServerDescription* server)
 		}
 
 		boost::shared_ptr<DCPVideoFrame> vf = _queue.front ();
+		_log->microsecond_log ("Encoder thread wakes with queue of " + boost::lexical_cast<string> (_queue.size ()), Log::TIMING);
 		_queue.pop_front ();
 		
 		lock.unlock ();
@@ -183,7 +189,9 @@ J2KWAVEncoder::encoder_thread (ServerDescription* server)
 				
 		} else {
 			try {
+				_log->microsecond_log ("Encoder thread begins local encode of " + lexical_cast<string> (vf->frame ()), Log::TIMING);
 				encoded = vf->encode_locally ();
+				_log->microsecond_log ("Encoder thread finishes local encode of " + lexical_cast<string> (vf->frame ()), Log::TIMING);
 			} catch (std::exception& e) {
 				stringstream s;
 				s << "Local encode failed " << e.what() << ".";
diff --git a/src/lib/log.cc b/src/lib/log.cc
index 7f1eea206..650384bc7 100644
--- a/src/lib/log.cc
+++ b/src/lib/log.cc
@@ -42,7 +42,7 @@ Log::log (string m, Level l)
 	if (l > _level) {
 		return;
 	}
-	
+
 	time_t t;
 	time (&t);
 	string a = ctime (&t);
@@ -53,6 +53,23 @@ Log::log (string m, Level l)
 }
 
 void
+Log::microsecond_log (string m, Level l)
+{
+	boost::mutex::scoped_lock lm (_mutex);
+
+	if (l > _level) {
+		return;
+	}
+
+	struct timeval tv;
+	gettimeofday (&tv, 0);
+
+	stringstream s;
+	s << tv.tv_sec << ":" << tv.tv_usec << " " << m;
+	do_log (s.str ());
+}	
+
+void
 Log::set_level (Level l)
 {
 	boost::mutex::scoped_lock lm (_mutex);
diff --git a/src/lib/log.h b/src/lib/log.h
index 2a242e24c..2e5d69a08 100644
--- a/src/lib/log.h
+++ b/src/lib/log.h
@@ -37,10 +37,12 @@ public:
 
 	enum Level {
 		STANDARD = 0,
-		VERBOSE = 1
+		VERBOSE = 1,
+		TIMING = 2
 	};
 
 	void log (std::string m, Level l = STANDARD);
+	void microsecond_log (std::string m, Level l = STANDARD);
 
 	void set_level (Level l);
 
diff --git a/src/tools/makedcp.cc b/src/tools/makedcp.cc
index c6cb1ba14..d3608059c 100644
--- a/src/tools/makedcp.cc
+++ b/src/tools/makedcp.cc
@@ -34,6 +34,7 @@
 #include "version.h"
 #include "cross.h"
 #include "config.h"
+#include "log.h"
 
 using namespace std;
 using namespace boost;
@@ -58,6 +59,7 @@ main (int argc, char* argv[])
 	string film_dir;
 	bool test_mode = false;
 	bool progress = true;
+	int log_level = 1;
 
 	int option_index = 0;
 	while (1) {
@@ -68,10 +70,11 @@ main (int argc, char* argv[])
 			{ "config", no_argument, 0, 'c'},
 			{ "test", no_argument, 0, 't'},
 			{ "no-progress", no_argument, 0, 'n'},
+			{ "log-level", required_argument, 0, 'l' },
 			{ 0, 0, 0, 0 }
 		};
 
-		int c = getopt_long (argc, argv, "vhdctn", long_options, &option_index);
+		int c = getopt_long (argc, argv, "vhdctnl:", long_options, &option_index);
 
 		if (c == -1) {
 			break;
@@ -102,6 +105,9 @@ main (int argc, char* argv[])
 			cout << "built in optimised mode\n";
 #endif			
 			exit (EXIT_SUCCESS);
+		case 'l':
+			log_level = atoi (optarg);
+			break;
 		}
 	}
 
@@ -134,6 +140,8 @@ main (int argc, char* argv[])
 		exit (EXIT_FAILURE);
 	}
 
+	film->log()->set_level ((Log::Level) log_level);
+
 	cout << "\nMaking ";
 	if (film->dcp_ab ()) {
 		cout << "A/B ";