X-Git-Url: https://git.carlh.net/gitweb/?a=blobdiff_plain;f=src%2Flib%2Fencoder.cc;h=f8a2ee3bde878c117f9948015d23951082d82fa5;hb=a78b741c43830c84bcb4d18e3147746f13a668e5;hp=451a5a31adc84549ad61d5416c14f39713a83384;hpb=b30d41f0dd8d7e1efb8f5557cf503c35a7d309b2;p=dcpomatic.git diff --git a/src/lib/encoder.cc b/src/lib/encoder.cc index 451a5a31a..f8a2ee3bd 100644 --- a/src/lib/encoder.cc +++ b/src/lib/encoder.cc @@ -1,19 +1,20 @@ /* Copyright (C) 2012-2015 Carl Hetherington - This program is free software; you can redistribute it and/or modify + This file is part of DCP-o-matic. + + DCP-o-matic is free software; you can redistribute it and/or modify it under the terms of the GNU General Public License as published by the Free Software Foundation; either version 2 of the License, or (at your option) any later version. - This program is distributed in the hope that it will be useful, + DCP-o-matic is distributed in the hope that it will be useful, but WITHOUT ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for more details. You should have received a copy of the GNU General Public License - along with this program; if not, write to the Free Software - Foundation, Inc., 675 Mass Ave, Cambridge, MA 02139, USA. + along with DCP-o-matic. If not, see . */ @@ -27,13 +28,12 @@ #include "log.h" #include "config.h" #include "dcp_video.h" -#include "server.h" #include "cross.h" #include "writer.h" -#include "server_finder.h" +#include "encode_server_finder.h" #include "player.h" #include "player_video.h" -#include "server_description.h" +#include "encode_server_description.h" #include "compose.hpp" #include #include @@ -45,6 +45,7 @@ #define LOG_GENERAL_NC(...) _film->log()->log (__VA_ARGS__, LogEntry::TYPE_GENERAL); #define LOG_ERROR(...) _film->log()->log (String::compose (__VA_ARGS__), LogEntry::TYPE_ERROR); #define LOG_TIMING(...) _film->log()->log (String::compose (__VA_ARGS__), LogEntry::TYPE_TIMING); +#define LOG_DEBUG_ENCODE(...) _film->log()->log (String::compose (__VA_ARGS__), LogEntry::TYPE_DEBUG_ENCODE); using std::list; using std::cout; @@ -53,15 +54,11 @@ using boost::weak_ptr; using boost::optional; using dcp::Data; -int const Encoder::_history_size = 25; +int const Encoder::_history_size = 200; /** @param f Film that we are encoding */ -Encoder::Encoder (shared_ptr film, weak_ptr j, shared_ptr writer) +Encoder::Encoder (shared_ptr film, shared_ptr writer) : _film (film) - , _job (j) - , _position (0) - , _terminate_enqueue (false) - , _terminate_encoding (false) , _writer (writer) { servers_list_changed (); @@ -69,19 +66,35 @@ Encoder::Encoder (shared_ptr film, weak_ptr j, shared_ptrdisabled ()) { - _server_found_connection = ServerFinder::instance()->ServersListChanged.connect (boost::bind (&Encoder::servers_list_changed, this)); + weak_ptr wp = shared_from_this (); + _server_found_connection = EncodeServerFinder::instance()->ServersListChanged.connect ( + boost::bind (&Encoder::call_servers_list_changed, wp) + ); +} + +/* We don't want the servers-list-changed callback trying to do things + during destruction of Encoder, and I think this is the neatest way + to achieve that. +*/ +void +Encoder::call_servers_list_changed (weak_ptr encoder) +{ + shared_ptr e = encoder.lock (); + if (e) { + e->servers_list_changed (); } } @@ -148,12 +161,15 @@ Encoder::current_encoding_rate () const return _history_size / (seconds (now) - seconds (_time_history.back ())); } -/** @return Number of video frames that have been sent out */ +/** @return Number of video frames that have been queued for encoding */ int -Encoder::video_frames_out () const +Encoder::video_frames_enqueued () const { - boost::mutex::scoped_lock (_state_mutex); - return _position; + if (!_last_player_video_time) { + return 0; + } + + return _last_player_video_time->frames_floor (_film->video_frame_rate ()); } /** Should be called when a frame has been encoded successfully. @@ -172,22 +188,13 @@ Encoder::frame_done () } } -/** Called to start encoding of the next video frame in the DCP. This is called in order, +/** Called to request encoding of the next video frame in the DCP. This is called in order, * so each time the supplied frame is the one after the previous one. * pv represents one video frame, and could be empty if there is nothing to encode * for this DCP frame. */ void -Encoder::encode (list > pv) -{ - BOOST_FOREACH (shared_ptr i, pv) { - enqueue (i); - } - ++_position; -} - -void -Encoder::enqueue (shared_ptr pv) +Encoder::encode (shared_ptr pv, DCPTime time) { _waker.nudge (); @@ -199,17 +206,13 @@ Encoder::enqueue (shared_ptr pv) boost::mutex::scoped_lock queue_lock (_queue_mutex); - /* XXX: discard 3D here if required */ - - /* Wait until the queue has gone down a bit */ - while (_queue.size() >= threads * 2 && !_terminate_enqueue) { - LOG_TIMING ("decoder-sleep queue=%1", _queue.size()); + /* Wait until the queue has gone down a bit. Allow one thing in the queue even + when there are no threads. + */ + while (_queue.size() >= (threads * 2) + 1) { + LOG_TIMING ("decoder-sleep queue=%1 threads=%2", _queue.size(), threads); _full_condition.wait (queue_lock); - LOG_TIMING ("decoder-wake queue=%1", _queue.size()); - } - - if (_terminate_enqueue) { - return; + LOG_TIMING ("decoder-wake queue=%1 threads=%2", _queue.size(), threads); } _writer->rethrow (); @@ -219,22 +222,28 @@ Encoder::enqueue (shared_ptr pv) */ rethrow (); - if (_writer->can_fake_write (_position)) { + Frame const position = time.frames_floor(_film->video_frame_rate()); + + if (_writer->can_fake_write (position)) { /* We can fake-write this frame */ - _writer->fake_write (_position, pv->eyes ()); + LOG_DEBUG_ENCODE("Frame @ %1 FAKE", to_string(pv->time())); + _writer->fake_write (position, pv->eyes ()); frame_done (); } else if (pv->has_j2k ()) { + LOG_DEBUG_ENCODE("Frame @ %1 J2K", to_string(pv->time())); /* This frame already has JPEG2000 data, so just write it */ - _writer->write (pv->j2k(), _position, pv->eyes ()); - } else if (_last_player_video && _writer->can_repeat(_position) && pv->same (_last_player_video)) { - _writer->repeat (_position, pv->eyes ()); + _writer->write (pv->j2k(), position, pv->eyes ()); + } else if (_last_player_video && _writer->can_repeat(position) && pv->same (_last_player_video)) { + LOG_DEBUG_ENCODE("Frame @ %1 REPEAT", to_string(pv->time())); + _writer->repeat (position, pv->eyes ()); } else { + LOG_DEBUG_ENCODE("Frame @ %1 ENCODE", to_string(pv->time())); /* Queue this new frame for encoding */ LOG_TIMING ("add-frame-to-queue queue=%1", _queue.size ()); _queue.push_back (shared_ptr ( new DCPVideo ( pv, - _position, + position, _film->video_frame_rate(), _film->j2k_bandwidth(), _film->resolution(), @@ -249,38 +258,40 @@ Encoder::enqueue (shared_ptr pv) } _last_player_video = pv; + _last_player_video_time = time; } void Encoder::terminate_threads () { - { - boost::mutex::scoped_lock queue_lock (_queue_mutex); - _terminate_encoding = true; - } - boost::mutex::scoped_lock threads_lock (_threads_mutex); + int n = 0; for (list::iterator i = _threads.begin(); i != _threads.end(); ++i) { + LOG_GENERAL ("Terminating thread %1 of %2", n + 1, _threads.size ()); (*i)->interrupt (); - if ((*i)->joinable ()) { + DCPOMATIC_ASSERT ((*i)->joinable ()); + try { (*i)->join (); + } catch (boost::thread_interrupted& e) { + /* This is to be expected */ } delete *i; + LOG_GENERAL_NC ("Thread terminated"); + ++n; } _threads.clear (); - _terminate_encoding = false; } void -Encoder::encoder_thread (optional server) +Encoder::encoder_thread (optional server) try { if (server) { - LOG_TIMING ("start-encoder-thread thread=%1 server=%2", boost::this_thread::get_id (), server->host_name ()); + LOG_TIMING ("start-encoder-thread thread=%1 server=%2", thread_id (), server->host_name ()); } else { - LOG_TIMING ("start-encoder-thread thread=%1 server=localhost", boost::this_thread::get_id ()); + LOG_TIMING ("start-encoder-thread thread=%1 server=localhost", thread_id ()); } /* Number of seconds that we currently wait between attempts @@ -291,71 +302,77 @@ try while (true) { - LOG_TIMING ("encoder-sleep thread=%1", boost::this_thread::get_id()); + LOG_TIMING ("encoder-sleep thread=%1", thread_id ()); boost::mutex::scoped_lock lock (_queue_mutex); - while (_queue.empty () && !_terminate_encoding) { + while (_queue.empty ()) { _empty_condition.wait (lock); } - if (_terminate_encoding) { - return; - } - - LOG_TIMING ("encoder-wake thread=%1 queue=%2", boost::this_thread::get_id(), _queue.size()); + LOG_TIMING ("encoder-wake thread=%1 queue=%2", thread_id(), _queue.size()); shared_ptr vf = _queue.front (); - LOG_TIMING ("encoder-pop thread=%1 frame=%2 eyes=%3", boost::this_thread::get_id(), vf->index(), vf->eyes ()); - _queue.pop_front (); - lock.unlock (); + /* We're about to commit to either encoding this frame or putting it back onto the queue, + so we must not be interrupted until one or other of these things have happened. This + block has thread interruption disabled. + */ + { + boost::this_thread::disable_interruption dis; - optional encoded; + LOG_TIMING ("encoder-pop thread=%1 frame=%2 eyes=%3", thread_id(), vf->index(), (int) vf->eyes ()); + _queue.pop_front (); - /* We need to encode this input */ - if (server) { - try { - encoded = vf->encode_remotely (server.get ()); + lock.unlock (); - if (remote_backoff > 0) { - LOG_GENERAL ("%1 was lost, but now she is found; removing backoff", server->host_name ()); + optional encoded; + + /* 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 ("start-local-encode thread=%1 frame=%2", thread_id(), vf->index()); + encoded = vf->encode_locally (boost::bind (&Log::dcp_log, _film->log().get(), _1, _2)); + LOG_TIMING ("finish-local-encode thread=%1 frame=%2", thread_id(), vf->index()); + } catch (std::exception& e) { + /* This is very bad, so don't cope with it, just pass it on */ + LOG_ERROR (N_("Local encode failed (%1)"), e.what ()); + throw; } - 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 { - LOG_TIMING ("start-local-encode thread=%1 frame=%2", boost::this_thread::get_id(), vf->index()); - encoded = vf->encode_locally (boost::bind (&Log::dcp_log, _film->log().get(), _1, _2)); - LOG_TIMING ("finish-local-encode thread=%1 frame=%2", boost::this_thread::get_id(), vf->index()); - } catch (std::exception& e) { - LOG_ERROR (N_("Local encode failed (%1)"), e.what ()); - throw; + if (encoded) { + _writer->write (encoded.get(), vf->index (), vf->eyes ()); + frame_done (); + } else { + lock.lock (); + LOG_GENERAL (N_("[%1] Encoder thread pushes frame %2 back onto queue after failure"), thread_id(), vf->index()); + _queue.push_front (vf); + lock.unlock (); } } - if (encoded) { - _writer->write (encoded.get(), vf->index (), vf->eyes ()); - frame_done (); - } else { - lock.lock (); - 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 (); - } - if (remote_backoff > 0) { - boost::this_thread::sleep_for (boost::chrono::seconds (remote_backoff)); + boost::this_thread::sleep (boost::posix_time::seconds (remote_backoff)); } /* The queue might not be full any more, so notify anything that is waiting on that */ @@ -363,6 +380,10 @@ try _full_condition.notify_all (); } } +catch (boost::thread_interrupted& e) { + /* Ignore these and just stop the thread */ + _full_condition.notify_all (); +} catch (...) { store_current (); @@ -379,13 +400,29 @@ Encoder::servers_list_changed () boost::mutex::scoped_lock lm (_threads_mutex); +#ifdef BOOST_THREAD_PLATFORM_WIN32 + OSVERSIONINFO info; + info.dwOSVersionInfoSize = sizeof (OSVERSIONINFO); + GetVersionEx (&info); + bool const windows_xp = (info.dwMajorVersion == 5 && info.dwMinorVersion == 1); + if (windows_xp) { + LOG_GENERAL_NC (N_("Setting thread affinity for Windows XP")); + } +#endif + if (!Config::instance()->only_servers_encode ()) { 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 ()))); + boost::thread* t = new boost::thread (boost::bind (&Encoder::encoder_thread, this, optional ())); + _threads.push_back (t); +#ifdef BOOST_THREAD_PLATFORM_WIN32 + if (windows_xp) { + SetThreadAffinityMask (t->native_handle(), 1 << i); + } +#endif } } - BOOST_FOREACH (ServerDescription i, ServerFinder::instance()->servers ()) { + BOOST_FOREACH (EncodeServerDescription i, EncodeServerFinder::instance()->servers ()) { LOG_GENERAL (N_("Adding %1 worker threads for remote %2"), i.threads(), i.host_name ()); for (int j = 0; j < i.threads(); ++j) { _threads.push_back (new boost::thread (boost::bind (&Encoder::encoder_thread, this, i)));