Tidy up timing code a bit.

[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 ef1e8edc1b1728285276163c0f4f2c129769387c..73aa1bff2023833ea9afcc519f2f3d95ef66b948 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) {
+               TIMING ("decoder sleeps with queue of %1", _queue.size());
                _worker_condition.wait (lock);
+               TIMING ("decoder wakes with queue of %1", _queue.size());
        }
 
        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);
+               TIMING ("adding to queue of %1", _queue.size ());
                _queue.push_back (boost::shared_ptr<DCPVideoFrame> (
                                          new DCPVideoFrame (
                                                  yuv, _opt->out_size, _opt->padding, _fs->scaler, frame, _fs->frames_per_second, s.second,
@@ -141,6 +145,8 @@ J2KWAVEncoder::encoder_thread (ServerDescription* server)
        int remote_backoff = 0;
        
        while (1) {
+
+               TIMING ("encoder thread %1 sleeps", pthread_self ());
                boost::mutex::scoped_lock lock (_worker_mutex);
                while (_queue.empty () && !_process_end) {
                        _worker_condition.wait (lock);
@@ -150,6 +156,7 @@ J2KWAVEncoder::encoder_thread (ServerDescription* server)
                        return;
                }
 
+               TIMING ("encoder thread %1 wakes with queue of %2", pthread_self(), _queue.size());
                boost::shared_ptr<DCPVideoFrame> vf = _queue.front ();
                _queue.pop_front ();
                
@@ -182,7 +189,9 @@ J2KWAVEncoder::encoder_thread (ServerDescription* server)
                                
                } else {
                        try {
+                               TIMING ("encoder thread %1 begins local encode of %2", pthread_self(), vf->frame());
                                encoded = vf->encode_locally ();
+                               TIMING ("encoder thread %1 finishes local encode of %2", pthread_self(), vf->frame());
                        } catch (std::exception& e) {
                                stringstream s;
                                s << "Local encode failed " << e.what() << ".";
@@ -229,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);
        }
@@ -239,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