Tidy up logging a bit. Make it configurable from the GUI.
[dcpomatic.git] / src / lib / encoder.cc
index 6df7c85a1bde49750ef78f0238cd7cfa6af13ecd..05da6bbdf53db33e0ec62847bd2e0a6e02c4b9c8 100644 (file)
@@ -1,5 +1,5 @@
 /*
-    Copyright (C) 2012 Carl Hetherington <cth@carlh.net>
+    Copyright (C) 2012-2014 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
  */
 
 #include <iostream>
-#include <boost/filesystem.hpp>
-#include <boost/lexical_cast.hpp>
+#include <boost/lambda/lambda.hpp>
+#include <libcxml/cxml.h>
 #include "encoder.h"
 #include "util.h"
-#include "options.h"
 #include "film.h"
 #include "log.h"
-#include "exceptions.h"
-#include "filter.h"
 #include "config.h"
 #include "dcp_video_frame.h"
 #include "server.h"
-#include "format.h"
 #include "cross.h"
+#include "writer.h"
+#include "server_finder.h"
+#include "player.h"
+#include "player_video_frame.h"
+
+#include "i18n.h"
+
+#define LOG_GENERAL(...) _film->log()->log (String::compose (__VA_ARGS__), Log::GENERAL);
+#define LOG_ERROR(...) _film->log()->log (String::compose (__VA_ARGS__), Log::ERROR);
+#define LOG_TIMING(...) _film->log()->log (String::compose (__VA_ARGS__), Log::TIMING);
 
 using std::pair;
 using std::string;
@@ -43,187 +49,105 @@ using std::stringstream;
 using std::vector;
 using std::list;
 using std::cout;
+using std::min;
 using std::make_pair;
-using namespace boost;
+using boost::shared_ptr;
+using boost::weak_ptr;
+using boost::optional;
+using boost::scoped_array;
 
 int const Encoder::_history_size = 25;
 
-/** @param f Film that we are encoding.
- *  @param o Options.
- */
-Encoder::Encoder (shared_ptr<const Film> f)
+/** @param f Film that we are encoding */
+Encoder::Encoder (shared_ptr<const Film> f, weak_ptr<Job> j)
        : _film (f)
-       , _just_skipped (false)
-       , _video_frames_in (0)
-       , _audio_frames_in (0)
+       , _job (j)
        , _video_frames_out (0)
-       , _audio_frames_out (0)
-#ifdef HAVE_SWRESAMPLE   
-       , _swr_context (0)
-#endif   
-       , _process_end (false)
+       , _terminate (false)
 {
-       if (_film->audio_stream()) {
-               /* Create sound output files with .tmp suffixes; we will rename
-                  them if and when we complete.
-               */
-               for (int i = 0; i < dcp_audio_channels (_film->audio_channels()); ++i) {
-                       SF_INFO sf_info;
-                       sf_info.samplerate = dcp_audio_sample_rate (_film->audio_stream()->sample_rate());
-                       /* We write mono files */
-                       sf_info.channels = 1;
-                       sf_info.format = SF_FORMAT_WAV | SF_FORMAT_PCM_24;
-                       SNDFILE* f = sf_open (_film->multichannel_audio_out_path (i, true).c_str (), SFM_WRITE, &sf_info);
-                       if (f == 0) {
-                               throw CreateFileError (_film->multichannel_audio_out_path (i, true));
-                       }
-                       _sound_files.push_back (f);
-               }
-       }
+       _have_a_real_frame[EYES_BOTH] = false;
+       _have_a_real_frame[EYES_LEFT] = false;
+       _have_a_real_frame[EYES_RIGHT] = false;
 }
 
 Encoder::~Encoder ()
 {
-       close_sound_files ();
-       terminate_worker_threads ();
+       terminate_threads ();
 }
 
+/** Add a worker thread for a each thread on a remote server.  Caller must hold
+ *  a lock on _mutex, or know that one is not currently required to
+ *  safely modify _threads.
+ */
 void
-Encoder::process_begin ()
+Encoder::add_worker_threads (ServerDescription d)
 {
-       if (_film->audio_stream() && _film->audio_stream()->sample_rate() != _film->target_audio_sample_rate()) {
-#ifdef HAVE_SWRESAMPLE
-
-               stringstream s;
-               s << "Will resample audio from " << _film->audio_stream()->sample_rate() << " to " << _film->target_audio_sample_rate();
-               _film->log()->log (s.str ());
-
-               /* We will be using planar float data when we call the resampler */
-               _swr_context = swr_alloc_set_opts (
-                       0,
-                       _film->audio_stream()->channel_layout(),
-                       AV_SAMPLE_FMT_FLTP,
-                       _film->target_audio_sample_rate(),
-                       _film->audio_stream()->channel_layout(),
-                       AV_SAMPLE_FMT_FLTP,
-                       _film->audio_stream()->sample_rate(),
-                       0, 0
-                       );
-               
-               swr_init (_swr_context);
-#else
-               throw EncodeError ("Cannot resample audio as libswresample is not present");
-#endif
-       } else {
-#ifdef HAVE_SWRESAMPLE
-               _swr_context = 0;
-#endif         
+       LOG_GENERAL (N_("Adding %1 worker threads for remote %2"), d.host_name ());
+       for (int i = 0; i < d.threads(); ++i) {
+               _threads.push_back (new boost::thread (boost::bind (&Encoder::encoder_thread, this, d)));
        }
+}
 
+void
+Encoder::process_begin ()
+{
        for (int i = 0; i < Config::instance()->num_local_encoding_threads (); ++i) {
-               _worker_threads.push_back (new boost::thread (boost::bind (&Encoder::encoder_thread, this, (ServerDescription *) 0)));
+               _threads.push_back (new boost::thread (boost::bind (&Encoder::encoder_thread, this, optional<ServerDescription> ())));
        }
 
-       vector<ServerDescription*> servers = Config::instance()->servers ();
-
-       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 (&Encoder::encoder_thread, this, *i)));
-               }
-       }
+       _writer.reset (new Writer (_film, _job));
+       ServerFinder::instance()->connect (boost::bind (&Encoder::server_found, this, _1));
 }
 
-
 void
 Encoder::process_end ()
 {
-#if HAVE_SWRESAMPLE    
-       if (_film->audio_stream() && _film->audio_stream()->channels() && _swr_context) {
-
-               shared_ptr<AudioBuffers> out (new AudioBuffers (_film->audio_stream()->channels(), 256));
-                       
-               while (1) {
-                       int const frames = swr_convert (_swr_context, (uint8_t **) out->data(), 256, 0, 0);
-
-                       if (frames < 0) {
-                               throw EncodeError ("could not run sample-rate converter");
-                       }
-
-                       if (frames == 0) {
-                               break;
-                       }
-
-                       out->set_frames (frames);
-                       write_audio (out);
-               }
-
-               swr_free (&_swr_context);
-       }
-#endif
-
-       if (_film->audio_stream()) {
-               close_sound_files ();
-               
-               /* Rename .wav.tmp files to .wav */
-               for (int i = 0; i < dcp_audio_channels (_film->audio_channels()); ++i) {
-                       if (boost::filesystem::exists (_film->multichannel_audio_out_path (i, false))) {
-                               boost::filesystem::remove (_film->multichannel_audio_out_path (i, false));
-                       }
-                       boost::filesystem::rename (_film->multichannel_audio_out_path (i, true), _film->multichannel_audio_out_path (i, false));
-               }
-       }
-
-       boost::mutex::scoped_lock lock (_worker_mutex);
+       boost::mutex::scoped_lock lock (_mutex);
 
-       _film->log()->log ("Clearing queue of " + lexical_cast<string> (_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 ("Waking with " + lexical_cast<string> (_queue.size ()), Log::VERBOSE);
-               _worker_condition.notify_all ();
-               _worker_condition.wait (lock);
+               _condition.notify_all ();
+               _condition.wait (lock);
        }
 
        lock.unlock ();
        
-       terminate_worker_threads ();
+       terminate_threads ();
 
-       _film->log()->log ("Mopping up " + lexical_cast<string> (_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
             2. the loop above terminates
             3. the remote worker fails to encode the image and puts it back on the queue
-            4. the remote worker is then terminated by terminate_worker_threads
+            4. the remote worker is then terminated by terminate_threads
 
             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 ("Encode left-over frame %1", (*i)->frame ()));
+               LOG_GENERAL (N_("Encode left-over frame %1"), (*i)->index ());
                try {
-                       shared_ptr<EncodedData> e = (*i)->encode_locally ();
-                       e->write (_film, (*i)->frame ());
+                       _writer->write ((*i)->encode_locally(), (*i)->index (), (*i)->eyes ());
                        frame_done ();
                } catch (std::exception& e) {
-                       _film->log()->log (String::compose ("Local encode failed (%1)", e.what ()));
+                       LOG_ERROR (N_("Local encode failed (%1)"), e.what ());
                }
        }
-
-       /* Now do links (or copies on windows) to duplicate frames */
-       for (list<pair<int, int> >::iterator i = _links_required.begin(); i != _links_required.end(); ++i) {
-               link (_film->frame_out_path (i->first, false), _film->frame_out_path (i->second, false));
-               link (_film->hash_out_path (i->first, false), _film->hash_out_path (i->second, false));
-       }
+               
+       _writer->finish ();
+       _writer.reset ();
 }      
 
 /** @return an estimate of the current number of frames we are encoding per second,
  *  or 0 if not known.
  */
 float
-Encoder::current_frames_per_second () const
+Encoder::current_encoding_rate () const
 {
-       boost::mutex::scoped_lock lock (_history_mutex);
+       boost::mutex::scoped_lock lock (_state_mutex);
        if (int (_time_history.size()) < _history_size) {
                return 0;
        }
@@ -234,19 +158,11 @@ Encoder::current_frames_per_second () const
        return _history_size / (seconds (now) - seconds (_time_history.back ()));
 }
 
-/** @return true if the last frame to be processed was skipped as it already existed */
-bool
-Encoder::skipping () const
-{
-       boost::mutex::scoped_lock (_history_mutex);
-       return _just_skipped;
-}
-
 /** @return Number of video frames that have been sent out */
 int
 Encoder::video_frames_out () const
 {
-       boost::mutex::scoped_lock (_history_mutex);
+       boost::mutex::scoped_lock (_state_mutex);
        return _video_frames_out;
 }
 
@@ -256,8 +172,7 @@ Encoder::video_frames_out () const
 void
 Encoder::frame_done ()
 {
-       boost::mutex::scoped_lock lock (_history_mutex);
-       _just_skipped = false;
+       boost::mutex::scoped_lock lock (_state_mutex);
        
        struct timeval tv;
        gettimeofday (&tv, 0);
@@ -267,163 +182,88 @@ Encoder::frame_done ()
        }
 }
 
-/** Called by a subclass when it has just skipped the processing
-    of a frame because it has already been done.
-*/
-void
-Encoder::frame_skipped ()
-{
-       boost::mutex::scoped_lock lock (_history_mutex);
-       _just_skipped = true;
-}
-
 void
-Encoder::process_video (shared_ptr<Image> image, bool same, boost::shared_ptr<Subtitle> sub)
+Encoder::process_video (shared_ptr<PlayerVideoFrame> pvf, bool same)
 {
-       DCPFrameRate dfr (_film->frames_per_second ());
+       _waker.nudge ();
        
-       if (dfr.skip && (_video_frames_in % 2)) {
-               ++_video_frames_in;
-               return;
-       }
+       boost::mutex::scoped_lock lock (_mutex);
 
-       boost::mutex::scoped_lock lock (_worker_mutex);
+       /* XXX: discard 3D here if required */
 
        /* 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());
+       while (_queue.size() >= _threads.size() * 2 && !_terminate) {
+               LOG_TIMING ("decoder sleeps with queue of %1", _queue.size());
+               _condition.wait (lock);
+               LOG_TIMING ("decoder wakes with queue of %1", _queue.size());
        }
 
-       if (_process_end) {
+       if (_terminate) {
                return;
        }
 
-       /* Only do the processing if we don't already have a file for this frame */
-       if (boost::filesystem::exists (_film->frame_out_path (_video_frames_out, false))) {
-               frame_skipped ();
-               return;
-       }
-
-       if (same && _last_real_frame) {
-               /* Use the last frame that we encoded.  We need to postpone doing the actual link,
-                  as on windows the link is really a copy and the reference frame might not have
-                  finished encoding yet.
-               */
-               _links_required.push_back (make_pair (_last_real_frame.get(), _video_frames_out));
+       _writer->rethrow ();
+       /* Re-throw any exception raised by one of our threads.  If more
+          than one has thrown an exception, only one will be rethrown, I think;
+          but then, if that happens something has gone badly wrong.
+       */
+       rethrow ();
+
+       if (_writer->can_fake_write (_video_frames_out)) {
+               _writer->fake_write (_video_frames_out, pvf->eyes ());
+               _have_a_real_frame[pvf->eyes()] = false;
+               frame_done ();
+       } else if (same && _have_a_real_frame[pvf->eyes()]) {
+               /* Use the last frame that we encoded. */
+               _writer->repeat (_video_frames_out, pvf->eyes());
+               frame_done ();
        } else {
                /* Queue this new frame for encoding */
-               pair<string, string> const s = Filter::ffmpeg_strings (_film->filters());
-               TIMING ("adding to queue of %1", _queue.size ());
-               _queue.push_back (boost::shared_ptr<DCPVideoFrame> (
+               LOG_TIMING ("adding to queue of %1", _queue.size ());
+               _queue.push_back (shared_ptr<DCPVideoFrame> (
                                          new DCPVideoFrame (
-                                                 image, sub, _film->format()->dcp_size(), _film->format()->dcp_padding (_film),
-                                                 _film->subtitle_offset(), _film->subtitle_scale(),
-                                                 _film->scaler(), _video_frames_out, _film->frames_per_second(), s.second,
-                                                 _film->colour_lut(), _film->j2k_bandwidth(),
-                                                 _film->log()
+                                                 pvf, _video_frames_out, _film->video_frame_rate(),
+                                                 _film->j2k_bandwidth(), _film->resolution(), _film->log()
                                                  )
                                          ));
                
-               _worker_condition.notify_all ();
-               _last_real_frame = _video_frames_out;
+               _condition.notify_all ();
+               _have_a_real_frame[pvf->eyes()] = true;
        }
 
-       ++_video_frames_in;
-       ++_video_frames_out;
-
-       if (dfr.repeat) {
-               _links_required.push_back (make_pair (_video_frames_out, _video_frames_out - 1));
+       if (pvf->eyes() != EYES_LEFT) {
                ++_video_frames_out;
        }
 }
 
 void
-Encoder::process_audio (shared_ptr<AudioBuffers> data)
-{
-#if HAVE_SWRESAMPLE
-       /* Maybe sample-rate convert */
-       if (_swr_context) {
-
-               /* Compute the resampled frames count and add 32 for luck */
-               int const max_resampled_frames = ceil ((int64_t) data->frames() * _film->target_audio_sample_rate() / _film->audio_stream()->sample_rate()) + 32;
-
-               shared_ptr<AudioBuffers> resampled (new AudioBuffers (_film->audio_stream()->channels(), max_resampled_frames));
-
-               /* Resample audio */
-               int const resampled_frames = swr_convert (
-                       _swr_context, (uint8_t **) resampled->data(), max_resampled_frames, (uint8_t const **) data->data(), data->frames()
-                       );
-               
-               if (resampled_frames < 0) {
-                       throw EncodeError ("could not run sample-rate converter");
-               }
-
-               resampled->set_frames (resampled_frames);
-               
-               /* And point our variables at the resampled audio */
-               data = resampled;
-       }
-#endif
-
-       if (_film->audio_channels() == 1) {
-               /* We need to switch things around so that the mono channel is on
-                  the centre channel of a 5.1 set (with other channels silent).
-               */
-
-               shared_ptr<AudioBuffers> b (new AudioBuffers (6, data->frames ()));
-               b->make_silent (libdcp::LEFT);
-               b->make_silent (libdcp::RIGHT);
-               memcpy (b->data()[libdcp::CENTRE], data->data()[0], data->frames() * sizeof(float));
-               b->make_silent (libdcp::LFE);
-               b->make_silent (libdcp::LS);
-               b->make_silent (libdcp::RS);
-
-               data = b;
-       }
-
-       write_audio (data);
-       
-       _audio_frames_in += data->frames ();
-}
-
-void
-Encoder::write_audio (shared_ptr<const AudioBuffers> audio)
+Encoder::process_audio (shared_ptr<const AudioBuffers> data)
 {
-       for (int i = 0; i < audio->channels(); ++i) {
-               sf_write_float (_sound_files[i], audio->data(i), audio->frames());
-       }
-
-       _audio_frames_out += audio->frames ();
+       _writer->write (data);
 }
 
 void
-Encoder::close_sound_files ()
+Encoder::terminate_threads ()
 {
-       for (vector<SNDFILE*>::iterator i = _sound_files.begin(); i != _sound_files.end(); ++i) {
-               sf_close (*i);
+       {
+               boost::mutex::scoped_lock lock (_mutex);
+               _terminate = true;
+               _condition.notify_all ();
        }
 
-       _sound_files.clear ();
-}      
-
-void
-Encoder::terminate_worker_threads ()
-{
-       boost::mutex::scoped_lock lock (_worker_mutex);
-       _process_end = true;
-       _worker_condition.notify_all ();
-       lock.unlock ();
-
-       for (list<boost::thread *>::iterator i = _worker_threads.begin(); i != _worker_threads.end(); ++i) {
-               (*i)->join ();
+       for (list<boost::thread *>::iterator i = _threads.begin(); i != _threads.end(); ++i) {
+               if ((*i)->joinable ()) {
+                       (*i)->join ();
+               }
                delete *i;
        }
+
+       _threads.clear ();
 }
 
 void
-Encoder::encoder_thread (ServerDescription* server)
+Encoder::encoder_thread (optional<ServerDescription> server)
+try
 {
        /* Number of seconds that we currently wait between attempts
           to connect to the server; not relevant for localhost
@@ -433,19 +273,19 @@ Encoder::encoder_thread (ServerDescription* server)
        
        while (1) {
 
-               TIMING ("encoder thread %1 sleeps", boost::this_thread::get_id());
-               boost::mutex::scoped_lock lock (_worker_mutex);
-               while (_queue.empty () && !_process_end) {
-                       _worker_condition.wait (lock);
+               LOG_TIMING ("encoder thread %1 sleeps", boost::this_thread::get_id());
+               boost::mutex::scoped_lock lock (_mutex);
+               while (_queue.empty () && !_terminate) {
+                       _condition.wait (lock);
                }
 
-               if (_process_end) {
+               if (_terminate) {
                        return;
                }
 
-               TIMING ("encoder thread %1 wakes with queue of %2", boost::this_thread::get_id(), _queue.size());
-               boost::shared_ptr<DCPVideoFrame> vf = _queue.front ();
-               _film->log()->log (String::compose ("Encoder thread %1 pops frame %2 from queue", boost::this_thread::get_id(), vf->frame()), Log::VERBOSE);
+               LOG_TIMING ("encoder thread %1 wakes with queue of %2", boost::this_thread::get_id(), _queue.size());
+               shared_ptr<DCPVideoFrame> vf = _queue.front ();
+               LOG_TIMING ("encoder thread %1 pops frame %2 (%3) from queue", boost::this_thread::get_id(), vf->index(), vf->eyes ());
                _queue.pop_front ();
                
                lock.unlock ();
@@ -454,10 +294,10 @@ Encoder::encoder_thread (ServerDescription* server)
 
                if (server) {
                        try {
-                               encoded = vf->encode_remotely (server);
+                               encoded = vf->encode_remotely (server.get ());
 
                                if (remote_backoff > 0) {
-                                       _film->log()->log (String::compose ("%1 was lost, but now she is found; removing backoff", server->host_name ()));
+                                       LOG_GENERAL ("%1 was lost, but now she is found; removing backoff", server->host_name ());
                                }
                                
                                /* This job succeeded, so remove any backoff */
@@ -468,55 +308,47 @@ Encoder::encoder_thread (ServerDescription* server)
                                        /* back off more */
                                        remote_backoff += 10;
                                }
-                               _film->log()->log (
-                                       String::compose (
-                                               "Remote encode of %1 on %2 failed (%3); thread sleeping for %4s",
-                                               vf->frame(), server->host_name(), e.what(), remote_backoff)
+                               LOG_ERROR (
+                                       N_("Remote encode of %1 on %2 failed (%3); thread sleeping for %4s"),
+                                       vf->index(), 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());
+                               LOG_TIMING ("encoder thread %1 begins local encode of %2", boost::this_thread::get_id(), vf->index());
                                encoded = vf->encode_locally ();
-                               TIMING ("encoder thread %1 finishes local encode of %2", boost::this_thread::get_id(), vf->frame());
+                               LOG_TIMING ("encoder thread %1 finishes local encode of %2", boost::this_thread::get_id(), vf->index());
                        } catch (std::exception& e) {
-                               _film->log()->log (String::compose ("Local encode failed (%1)", e.what ()));
+                               LOG_ERROR (N_("Local encode failed (%1)"), e.what ());
                        }
                }
 
                if (encoded) {
-                       encoded->write (_film, vf->frame ());
+                       _writer->write (encoded, vf->index (), vf->eyes ());
                        frame_done ();
                } else {
                        lock.lock ();
-                       _film->log()->log (
-                               String::compose ("Encoder thread %1 pushes frame %2 back onto queue after failure", boost::this_thread::get_id(), vf->frame())
-                               );
+                       LOG_GENERAL (N_("Encoder thread %1 pushes frame %2 back onto queue after failure"), boost::this_thread::get_id(), vf->index());
                        _queue.push_front (vf);
                        lock.unlock ();
                }
 
                if (remote_backoff > 0) {
-                       dvdomatic_sleep (remote_backoff);
+                       dcpomatic_sleep (remote_backoff);
                }
 
                lock.lock ();
-               _worker_condition.notify_all ();
+               _condition.notify_all ();
        }
 }
+catch (...)
+{
+       store_current ();
+}
 
 void
-Encoder::link (string a, string b) const
+Encoder::server_found (ServerDescription s)
 {
-#ifdef DVDOMATIC_POSIX                 
-       int const r = symlink (a.c_str(), b.c_str());
-       if (r) {
-               throw EncodeError (String::compose ("could not create symlink from %1 to %2", a, b));
-       }
-#endif
-       
-#ifdef DVDOMATIC_WINDOWS
-       boost::filesystem::copy_file (a, b);
-#endif                 
+       add_worker_threads (s);
 }