5b5c36d28d07e8cd93af5a3f766fd95f2a506beb from master; increase the number of images...
[dcpomatic.git] / src / lib / encoder.cc
index 7863859deb817d3c66f364afb3613c5175108a65..7a0295e4c52dc9a85e7d20980cd7fa6840eb7eab 100644 (file)
@@ -1,5 +1,5 @@
 /*
-    Copyright (C) 2012 Carl Hetherington <cth@carlh.net>
+    Copyright (C) 2012-2015 Carl Hetherington <cth@carlh.net>
 
     This program is free software; you can redistribute it and/or modify
     it under the terms of the GNU General Public License as published by
  *  @brief Parent class for classes which can encode video and audio frames.
  */
 
-#include <iostream>
-#include <boost/lambda/lambda.hpp>
-#include <libcxml/cxml.h>
 #include "encoder.h"
 #include "util.h"
 #include "film.h"
 #include "log.h"
 #include "config.h"
-#include "dcp_video_frame.h"
+#include "dcp_video.h"
 #include "server.h"
 #include "cross.h"
 #include "writer.h"
 #include "server_finder.h"
 #include "player.h"
+#include "player_video.h"
+#include <libcxml/cxml.h>
+#include <boost/lambda/lambda.hpp>
+#include <iostream>
 
 #include "i18n.h"
 
+#define LOG_GENERAL(...) _film->log()->log (String::compose (__VA_ARGS__), Log::TYPE_GENERAL);
+#define LOG_ERROR(...) _film->log()->log (String::compose (__VA_ARGS__), Log::TYPE_ERROR);
+#define LOG_TIMING(...) _film->log()->microsecond_log (String::compose (__VA_ARGS__), Log::TYPE_TIMING);
+
 using std::pair;
 using std::string;
-using std::stringstream;
 using std::vector;
 using std::list;
 using std::cout;
@@ -54,15 +58,14 @@ using boost::scoped_array;
 int const Encoder::_history_size = 25;
 
 /** @param f Film that we are encoding */
-Encoder::Encoder (shared_ptr<const Film> f, weak_ptr<Job> j)
+Encoder::Encoder (shared_ptr<const Film> f, weak_ptr<Job> j, shared_ptr<Writer> writer)
        : _film (f)
        , _job (j)
        , _video_frames_out (0)
        , _terminate (false)
+       , _writer (writer)
 {
-       _have_a_real_frame[EYES_BOTH] = false;
-       _have_a_real_frame[EYES_LEFT] = false;
-       _have_a_real_frame[EYES_RIGHT] = false;
+
 }
 
 Encoder::~Encoder ()
@@ -77,41 +80,46 @@ Encoder::~Encoder ()
 void
 Encoder::add_worker_threads (ServerDescription d)
 {
+       LOG_GENERAL (N_("Adding %1 worker threads for remote %2"), d.threads(), d.host_name ());
        for (int i = 0; i < d.threads(); ++i) {
                _threads.push_back (new boost::thread (boost::bind (&Encoder::encoder_thread, this, d)));
        }
+
+       _writer->set_encoder_threads (_threads.size ());
 }
 
 void
-Encoder::process_begin ()
+Encoder::begin ()
 {
        for (int i = 0; i < Config::instance()->num_local_encoding_threads (); ++i) {
                _threads.push_back (new boost::thread (boost::bind (&Encoder::encoder_thread, this, optional<ServerDescription> ())));
        }
 
-       _writer.reset (new Writer (_film, _job));
-       ServerFinder::instance()->connect (boost::bind (&Encoder::server_found, this, _1));
+       _writer->set_encoder_threads (_threads.size ());
+
+       if (!ServerFinder::instance()->disabled ()) {
+               _server_found_connection = ServerFinder::instance()->connect (boost::bind (&Encoder::server_found, this, _1));
+       }
 }
 
 void
-Encoder::process_end ()
+Encoder::end ()
 {
        boost::mutex::scoped_lock lock (_mutex);
 
-       _film->log()->log (String::compose (N_("Clearing queue of %1"), _queue.size ()));
+       LOG_GENERAL (N_("Clearing queue of %1"), _queue.size ());
 
        /* Keep waking workers until the queue is empty */
        while (!_queue.empty ()) {
-               _film->log()->log (String::compose (N_("Waking with %1"), _queue.size ()), Log::VERBOSE);
-               _condition.notify_all ();
-               _condition.wait (lock);
+               _empty_condition.notify_all ();
+               _full_condition.wait (lock);
        }
 
        lock.unlock ();
        
        terminate_threads ();
 
-       _film->log()->log (String::compose (N_("Mopping up %1"), _queue.size()));
+       LOG_GENERAL (N_("Mopping up %1"), _queue.size());
 
        /* The following sequence of events can occur in the above code:
             1. a remote worker takes the last image off the queue
@@ -122,18 +130,19 @@ Encoder::process_end ()
             So just mop up anything left in the queue here.
        */
 
-       for (list<shared_ptr<DCPVideoFrame> >::iterator i = _queue.begin(); i != _queue.end(); ++i) {
-               _film->log()->log (String::compose (N_("Encode left-over frame %1"), (*i)->frame ()));
+       for (list<shared_ptr<DCPVideo> >::iterator i = _queue.begin(); i != _queue.end(); ++i) {
+               LOG_GENERAL (N_("Encode left-over frame %1"), (*i)->index ());
                try {
-                       _writer->write ((*i)->encode_locally(), (*i)->frame (), (*i)->eyes ());
+                       _writer->write (
+                               (*i)->encode_locally (boost::bind (&Log::dcp_log, _film->log().get(), _1, _2)),
+                               (*i)->index (),
+                               (*i)->eyes ()
+                               );
                        frame_done ();
                } catch (std::exception& e) {
-                       _film->log()->log (String::compose (N_("Local encode failed (%1)"), e.what ()));
+                       LOG_ERROR (N_("Local encode failed (%1)"), e.what ());
                }
        }
-               
-       _writer->finish ();
-       _writer.reset ();
 }      
 
 /** @return an estimate of the current number of frames we are encoding per second,
@@ -177,8 +186,11 @@ Encoder::frame_done ()
        }
 }
 
+/** Called in order, so each time this is called the supplied frame is the one
+ *  after the previous one.
+ */
 void
-Encoder::process_video (shared_ptr<PlayerImage> image, Eyes eyes, ColourConversion conversion, bool same)
+Encoder::enqueue (shared_ptr<PlayerVideo> pv)
 {
        _waker.nudge ();
        
@@ -188,9 +200,9 @@ Encoder::process_video (shared_ptr<PlayerImage> image, Eyes eyes, ColourConversi
 
        /* Wait until the queue has gone down a bit */
        while (_queue.size() >= _threads.size() * 2 && !_terminate) {
-               TIMING ("decoder sleeps with queue of %1", _queue.size());
-               _condition.wait (lock);
-               TIMING ("decoder wakes with queue of %1", _queue.size());
+               LOG_TIMING ("decoder sleeps with queue of %1", _queue.size());
+               _full_condition.wait (lock);
+               LOG_TIMING ("decoder wakes with queue of %1", _queue.size());
        }
 
        if (_terminate) {
@@ -205,45 +217,46 @@ Encoder::process_video (shared_ptr<PlayerImage> image, Eyes eyes, ColourConversi
        rethrow ();
 
        if (_writer->can_fake_write (_video_frames_out)) {
-               _writer->fake_write (_video_frames_out, eyes);
-               _have_a_real_frame[eyes] = false;
-               frame_done ();
-       } else if (same && _have_a_real_frame[eyes]) {
-               /* Use the last frame that we encoded. */
-               _writer->repeat (_video_frames_out, eyes);
+               /* We can fake-write this frame */
+               _writer->fake_write (_video_frames_out, pv->eyes ());
                frame_done ();
+       } else if (pv->has_j2k ()) {
+               /* This frame already has JPEG2000 data, so just write it */
+               _writer->write (pv->j2k(), _video_frames_out, pv->eyes ());
        } else {
                /* Queue this new frame for encoding */
-               TIMING ("adding to queue of %1", _queue.size ());
-               _queue.push_back (shared_ptr<DCPVideoFrame> (
-                                         new DCPVideoFrame (
-                                                 image->image(PIX_FMT_RGB24, false), _video_frames_out, eyes, conversion, _film->video_frame_rate(),
-                                                 _film->j2k_bandwidth(), _film->resolution(), _film->log()
+               LOG_TIMING ("adding to queue of %1", _queue.size ());
+               _queue.push_back (shared_ptr<DCPVideo> (
+                                         new DCPVideo (
+                                                 pv,
+                                                 _video_frames_out,
+                                                 _film->video_frame_rate(),
+                                                 _film->j2k_bandwidth(),
+                                                 _film->resolution(),
+                                                 _film->burn_subtitles(),
+                                                 _film->log()
                                                  )
                                          ));
-               
-               _condition.notify_all ();
-               _have_a_real_frame[eyes] = true;
+
+               /* The queue might not be empty any more, so notify anything which is
+                  waiting on that.
+               */
+               _empty_condition.notify_all ();
        }
 
-       if (eyes != EYES_LEFT) {
+       if (pv->eyes() != EYES_LEFT) {
                ++_video_frames_out;
        }
 }
 
-void
-Encoder::process_audio (shared_ptr<const AudioBuffers> data)
-{
-       _writer->write (data);
-}
-
 void
 Encoder::terminate_threads ()
 {
        {
                boost::mutex::scoped_lock lock (_mutex);
                _terminate = true;
-               _condition.notify_all ();
+               _full_condition.notify_all ();
+               _empty_condition.notify_all ();
        }
 
        for (list<boost::thread *>::iterator i = _threads.begin(); i != _threads.end(); ++i) {
@@ -265,69 +278,77 @@ try
           encodings.
        */
        int remote_backoff = 0;
+       shared_ptr<DCPVideo> last_dcp_video;
+       shared_ptr<EncodedData> last_encoded;
        
-       while (1) {
+       while (true) {
 
-               TIMING ("encoder thread %1 sleeps", boost::this_thread::get_id());
+               LOG_TIMING ("[%1] encoder thread sleeps", boost::this_thread::get_id());
                boost::mutex::scoped_lock lock (_mutex);
                while (_queue.empty () && !_terminate) {
-                       _condition.wait (lock);
+                       _empty_condition.wait (lock);
                }
 
                if (_terminate) {
                        return;
                }
 
-               TIMING ("encoder thread %1 wakes with queue of %2", boost::this_thread::get_id(), _queue.size());
-               shared_ptr<DCPVideoFrame> vf = _queue.front ();
-               TIMING ("encoder thread %1 pops frame %2 (%3) from queue", boost::this_thread::get_id(), vf->frame(), vf->eyes ());
+               LOG_TIMING ("[%1] encoder thread wakes with queue of %2", boost::this_thread::get_id(), _queue.size());
+               shared_ptr<DCPVideo> vf = _queue.front ();
+               LOG_TIMING ("[%1] encoder thread pops frame %2 (%3) from queue", boost::this_thread::get_id(), vf->index(), vf->eyes ());
                _queue.pop_front ();
                
                lock.unlock ();
 
                shared_ptr<EncodedData> encoded;
 
-               if (server) {
-                       try {
-                               encoded = vf->encode_remotely (server.get ());
-
-                               if (remote_backoff > 0) {
-                                       _film->log()->log (String::compose (N_("%1 was lost, but now she is found; removing backoff"), server->host_name ()));
+               if (last_dcp_video && vf->same (last_dcp_video)) {
+                       /* We already have encoded data for the same input as this one, so take a short-cut */
+                       encoded = last_encoded;
+               } else {
+                       /* We need to encode this input */
+                       if (server) {
+                               try {
+                                       encoded = vf->encode_remotely (server.get ());
+                                       
+                                       if (remote_backoff > 0) {
+                                               LOG_GENERAL ("%1 was lost, but now she is found; removing backoff", server->host_name ());
+                                       }
+                                       
+                                       /* This job succeeded, so remove any backoff */
+                                       remote_backoff = 0;
+                                       
+                               } catch (std::exception& e) {
+                                       if (remote_backoff < 60) {
+                                               /* back off more */
+                                               remote_backoff += 10;
+                                       }
+                                       LOG_ERROR (
+                                               N_("Remote encode of %1 on %2 failed (%3); thread sleeping for %4s"),
+                                               vf->index(), server->host_name(), e.what(), remote_backoff
+                                               );
                                }
                                
-                               /* This job succeeded, so remove any backoff */
-                               remote_backoff = 0;
-                               
-                       } catch (std::exception& e) {
-                               if (remote_backoff < 60) {
-                                       /* back off more */
-                                       remote_backoff += 10;
+                       } else {
+                               try {
+                                       LOG_TIMING ("[%1] encoder thread begins local encode of %2", boost::this_thread::get_id(), vf->index());
+                                       encoded = vf->encode_locally (boost::bind (&Log::dcp_log, _film->log().get(), _1, _2));
+                                       LOG_TIMING ("[%1] encoder thread finishes local encode of %2", boost::this_thread::get_id(), vf->index());
+                               } catch (std::exception& e) {
+                                       LOG_ERROR (N_("Local encode failed (%1)"), e.what ());
                                }
-                               _film->log()->log (
-                                       String::compose (
-                                               N_("Remote encode of %1 on %2 failed (%3); thread sleeping for %4s"),
-                                               vf->frame(), server->host_name(), e.what(), remote_backoff)
-                                       );
-                       }
-                               
-               } else {
-                       try {
-                               TIMING ("encoder thread %1 begins local encode of %2", boost::this_thread::get_id(), vf->frame());
-                               encoded = vf->encode_locally ();
-                               TIMING ("encoder thread %1 finishes local encode of %2", boost::this_thread::get_id(), vf->frame());
-                       } catch (std::exception& e) {
-                               _film->log()->log (String::compose (N_("Local encode failed (%1)"), e.what ()));
                        }
                }
 
+               last_dcp_video = vf;
+               last_encoded = encoded;
+
                if (encoded) {
-                       _writer->write (encoded, vf->frame (), vf->eyes ());
+                       _writer->write (encoded, vf->index (), vf->eyes ());
                        frame_done ();
                } else {
                        lock.lock ();
-                       _film->log()->log (
-                               String::compose (N_("Encoder thread %1 pushes frame %2 back onto queue after failure"), boost::this_thread::get_id(), vf->frame())
-                               );
+                       LOG_GENERAL (N_("[%1] Encoder thread pushes frame %2 back onto queue after failure"), boost::this_thread::get_id(), vf->index());
                        _queue.push_front (vf);
                        lock.unlock ();
                }
@@ -336,8 +357,9 @@ try
                        dcpomatic_sleep (remote_backoff);
                }
 
+               /* The queue might not be full any more, so notify anything that is waiting on that */
                lock.lock ();
-               _condition.notify_all ();
+               _full_condition.notify_all ();
        }
 }
 catch (...)