Some more debug logging.

[dcpomatic.git] / src / lib / j2k_wav_encoder.cc

diff --git a/src/lib/j2k_wav_encoder.cc b/src/lib/j2k_wav_encoder.cc
index 2f29f9021d2ba7561e53bb8406df0f5c35f6ba1a..4deedc388994ab953c306c8e1e1d21a75cceece8 100644 (file)
--- a/src/lib/j2k_wav_encoder.cc
+++ b/src/lib/j2k_wav_encoder.cc
@@ -27,6 +27,7 @@
 #include <iostream>
 #include <boost/thread.hpp>
 #include <boost/filesystem.hpp>
+#include <boost/lexical_cast.hpp>
 #include <sndfile.h>
 #include <openjpeg.h>
 #include "j2k_wav_encoder.h"
@@ -107,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) {
@@ -117,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,
@@ -126,11 +130,13 @@ J2KWAVEncoder::process_video (shared_ptr<Image> yuv, int frame)
                                          ));
                
                _worker_condition.notify_all ();
+       } else {
+               frame_skipped ();
        }
 }
 
 void
-J2KWAVEncoder::encoder_thread (Server* server)
+J2KWAVEncoder::encoder_thread (ServerDescription* server)
 {
        /* Number of seconds that we currently wait between attempts
           to connect to the server; not relevant for localhost
@@ -141,7 +147,9 @@ J2KWAVEncoder::encoder_thread (Server* 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) {
@@ -149,6 +157,7 @@ J2KWAVEncoder::encoder_thread (Server* 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 ();
@@ -180,7 +189,9 @@ J2KWAVEncoder::encoder_thread (Server* 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() << ".";
@@ -190,7 +201,7 @@ J2KWAVEncoder::encoder_thread (Server* server)
 
                if (encoded) {
                        encoded->write (_opt, vf->frame ());
-                       frame_done ();
+                       frame_done (vf->frame ());
                } else {
                        lock.lock ();
                        _queue.push_front (vf);
@@ -210,12 +221,12 @@ void
 J2KWAVEncoder::process_begin ()
 {
        for (int i = 0; i < Config::instance()->num_local_encoding_threads (); ++i) {
-               _worker_threads.push_back (new boost::thread (boost::bind (&J2KWAVEncoder::encoder_thread, this, (Server *) 0)));
+               _worker_threads.push_back (new boost::thread (boost::bind (&J2KWAVEncoder::encoder_thread, this, (ServerDescription *) 0)));
        }
 
-       vector<Server*> servers = Config::instance()->servers ();
+       vector<ServerDescription*> servers = Config::instance()->servers ();
 
-       for (vector<Server*>::iterator i = servers.begin(); i != servers.end(); ++i) {
+       for (vector<ServerDescription*>::iterator i = servers.begin(); i != servers.end(); ++i) {
                for (int j = 0; j < (*i)->threads (); ++j) {
                        _worker_threads.push_back (new boost::thread (boost::bind (&J2KWAVEncoder::encoder_thread, this, *i)));
                }
@@ -227,8 +238,11 @@ J2KWAVEncoder::process_end ()
 {
        boost::mutex::scoped_lock lock (_worker_mutex);
 
+       _log->log ("Clearing queue of " + lexical_cast<string> (_queue.size ()));
+
        /* Keep waking workers until the queue is empty */
        while (!_queue.empty ()) {
+               _log->log ("Waking with " + lexical_cast<string> (_queue.size ()));
                _worker_condition.notify_all ();
                _worker_condition.wait (lock);
        }
@@ -237,6 +251,8 @@ J2KWAVEncoder::process_end ()
        
        terminate_worker_threads ();
 
+       _log->log ("Mopping up " + lexical_cast<string> (_queue.size()));
+
        /* The following sequence of events can occur in the above code:
             1. a remote worker takes the last image off the queue
             2. the loop above terminates
@@ -253,7 +269,7 @@ J2KWAVEncoder::process_end ()
                try {
                        shared_ptr<EncodedData> e = (*i)->encode_locally ();
                        e->write (_opt, (*i)->frame ());
-                       frame_done ();
+                       frame_done ((*i)->frame ());
                } catch (std::exception& e) {
                        stringstream s;
                        s << "Local encode failed " << e.what() << ".";