Some more debug logging.

diff --git a/src/lib/decoder.cc b/src/lib/decoder.cc
index 973582ca49237e3bd88739edce39389fe0fc88af..19fd4f45ccda48707c90b555e9c2f6ae3a9ddbae 100644 (file)
--- 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 9ae01c774287256e667f3d490eeb3a8914b29bad..4deedc388994ab953c306c8e1e1d21a75cceece8 100644 (file)
--- 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 7f1eea20634f8cba480d8d6884765f7e1be14268..650384bc7726986ff97800613f0ef09f2a41346f 100644 (file)
--- 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);
@@ -52,6 +52,23 @@ Log::log (string m, Level l)
        do_log (s.str ());
 }
 
+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)
 {

diff --git a/src/lib/log.h b/src/lib/log.h
index 2a242e24c96e8f49bfb171d81bac463085ad9f02..2e5d69a0828a77d508b3cc1d4c122898204eb027 100644 (file)
--- 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 c6cb1ba141e791a659974ec7a262a8544e11d126..d3608059c3c0e47fde5c4a46d9f8d35fad1ca60c 100644 (file)
--- 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 ";