Tidy and fix logging.
[dcpomatic.git] / src / lib / writer.cc
index b5123ad74cf2e81511dbc1ad988a593c2fe52cb9..c31ae2a91661f5e42b5403f28220bc0a1e8c4936 100644 (file)
@@ -1,5 +1,5 @@
 /*
-    Copyright (C) 2012-2017 Carl Hetherington <cth@carlh.net>
+    Copyright (C) 2012-2018 Carl Hetherington <cth@carlh.net>
 
     This file is part of DCP-o-matic.
 
@@ -23,6 +23,7 @@
 #include "film.h"
 #include "ratio.h"
 #include "log.h"
+#include "dcpomatic_log.h"
 #include "dcp_video.h"
 #include "dcp_content_type.h"
 #include "audio_mapping.h"
 
 #include "i18n.h"
 
-#define LOG_GENERAL(...) _film->log()->log (String::compose (__VA_ARGS__), LogEntry::TYPE_GENERAL);
-#define LOG_GENERAL_NC(...) _film->log()->log (__VA_ARGS__, LogEntry::TYPE_GENERAL);
-#define LOG_DEBUG_ENCODE(...) _film->log()->log (String::compose (__VA_ARGS__), LogEntry::TYPE_DEBUG_ENCODE);
-#define LOG_TIMING(...) _film->log()->log (String::compose (__VA_ARGS__), LogEntry::TYPE_TIMING);
-#define LOG_WARNING_NC(...) _film->log()->log (__VA_ARGS__, LogEntry::TYPE_WARNING);
-#define LOG_WARNING(...) _film->log()->log (String::compose (__VA_ARGS__), LogEntry::TYPE_WARNING);
-#define LOG_ERROR(...) _film->log()->log (String::compose (__VA_ARGS__), LogEntry::TYPE_ERROR);
-
 /* OS X strikes again */
 #undef set_key
 
@@ -63,9 +56,11 @@ using std::cout;
 using std::map;
 using std::min;
 using std::max;
+using std::vector;
 using boost::shared_ptr;
 using boost::weak_ptr;
 using boost::dynamic_pointer_cast;
+using boost::optional;
 using dcp::Data;
 
 Writer::Writer (shared_ptr<const Film> film, weak_ptr<Job> j)
@@ -74,7 +69,9 @@ Writer::Writer (shared_ptr<const Film> film, weak_ptr<Job> j)
        , _thread (0)
        , _finish (false)
        , _queued_full_in_memory (0)
-       , _maximum_frames_in_memory (0)
+       /* These will be reset to sensible values when J2KEncoder is created */
+       , _maximum_frames_in_memory (8)
+       , _maximum_queue_size (8)
        , _full_written (0)
        , _fake_written (0)
        , _repeat_written (0)
@@ -89,11 +86,14 @@ Writer::Writer (shared_ptr<const Film> film, weak_ptr<Job> j)
                _reels.push_back (ReelWriter (film, p, job, reel_index++, reels.size(), _film->content_summary(p)));
        }
 
-       /* We can keep track of the current audio and subtitle reels easily because audio
-          and subs arrive to the Writer in sequence.  This is not so for video.
+       /* We can keep track of the current audio, subtitle and closed caption reels easily because audio
+          and captions arrive to the Writer in sequence.  This is not so for video.
        */
        _audio_reel = _reels.begin ();
        _subtitle_reel = _reels.begin ();
+       BOOST_FOREACH (DCPTextTrack i, _film->closed_caption_tracks()) {
+               _caption_reels[i] = _reels.begin ();
+       }
 
        /* Check that the signer is OK if we need one */
        string reason;
@@ -106,6 +106,9 @@ void
 Writer::start ()
 {
        _thread = new boost::thread (boost::bind (&Writer::thread, this));
+#ifdef DCPOMATIC_LINUX
+       pthread_setname_np (_thread->native_handle(), "writer");
+#endif
 }
 
 Writer::~Writer ()
@@ -125,7 +128,9 @@ Writer::write (Data encoded, Frame frame, Eyes eyes)
        boost::mutex::scoped_lock lock (_state_mutex);
 
        while (_queued_full_in_memory > _maximum_frames_in_memory) {
-               /* The queue is too big; wait until that is sorted out */
+               /* There are too many full frames in memory; wake the main writer thread and
+                  wait until it sorts everything out */
+               _empty_condition.notify_all ();
                _full_condition.wait (lock);
        }
 
@@ -168,8 +173,11 @@ Writer::repeat (Frame frame, Eyes eyes)
 {
        boost::mutex::scoped_lock lock (_state_mutex);
 
-       while (_queued_full_in_memory > _maximum_frames_in_memory) {
-               /* The queue is too big; wait until that is sorted out */
+       while (_queue.size() > _maximum_queue_size && have_sequenced_image_at_queue_head()) {
+               /* The queue is too big, and the main writer thread can run and fix it, so
+                  wake it and wait until it has done.
+               */
+               _empty_condition.notify_all ();
                _full_condition.wait (lock);
        }
 
@@ -196,8 +204,11 @@ Writer::fake_write (Frame frame, Eyes eyes)
 {
        boost::mutex::scoped_lock lock (_state_mutex);
 
-       while (_queued_full_in_memory > _maximum_frames_in_memory) {
-               /* The queue is too big; wait until that is sorted out */
+       while (_queue.size() > _maximum_queue_size && have_sequenced_image_at_queue_head()) {
+               /* The queue is too big, and the main writer thread can run and fix it, so
+                  wake it and wait until it has done.
+               */
+               _empty_condition.notify_all ();
                _full_condition.wait (lock);
        }
 
@@ -231,36 +242,61 @@ Writer::fake_write (Frame frame, Eyes eyes)
 }
 
 /** Write some audio frames to the DCP.
- *  @param audio Audio data or 0 if there is no audio to be written here (i.e. it is referenced).
+ *  @param audio Audio data.
+ *  @param time Time of this data within the DCP.
  *  This method is not thread safe.
  */
 void
-Writer::write (shared_ptr<const AudioBuffers> audio)
+Writer::write (shared_ptr<const AudioBuffers> audio, DCPTime const time)
 {
+       DCPOMATIC_ASSERT (audio);
+
+       int const afr = _film->audio_frame_rate();
+
+       DCPTime const end = time + DCPTime::from_frames(audio->frames(), afr);
+
        /* The audio we get might span a reel boundary, and if so we have to write it in bits */
 
-       int32_t offset = 0;
-       while (offset < audio->frames ()) {
+       DCPTime t = time;
+       while (t < end) {
 
                if (_audio_reel == _reels.end ()) {
                        /* This audio is off the end of the last reel; ignore it */
                        return;
                }
 
-               int32_t const remaining = audio->frames() - offset;
-               int32_t const reel_space = _audio_reel->period().duration().frames_floor(_film->audio_frame_rate()) - _audio_reel->total_written_audio_frames();
-
-               if (remaining <= reel_space) {
+               if (end <= _audio_reel->period().to) {
                        /* Easy case: we can write all the audio to this reel */
                        _audio_reel->write (audio);
-                       offset += remaining;
+                       t = end;
                } else {
-                       /* Write the part we can */
-                       shared_ptr<AudioBuffers> part (new AudioBuffers (audio->channels(), reel_space));
-                       part->copy_from (audio.get(), reel_space, offset, 0);
-                       _audio_reel->write (part);
+                       /* Split the audio into two and write the first part */
+                       DCPTime part_lengths[2] = {
+                               _audio_reel->period().to - t,
+                               end - _audio_reel->period().to
+                       };
+
+                       Frame part_frames[2] = {
+                               part_lengths[0].frames_ceil(afr),
+                               part_lengths[1].frames_ceil(afr)
+                       };
+
+                       if (part_frames[0]) {
+                               shared_ptr<AudioBuffers> part (new AudioBuffers (audio->channels(), part_frames[0]));
+                               part->copy_from (audio.get(), part_frames[0], 0, 0);
+                               _audio_reel->write (part);
+                       }
+
+                       if (part_frames[1]) {
+                               shared_ptr<AudioBuffers> part (new AudioBuffers (audio->channels(), part_frames[1]));
+                               part->copy_from (audio.get(), part_frames[1], part_frames[0], 0);
+                               audio = part;
+                       } else {
+                               audio.reset ();
+                       }
+
                        ++_audio_reel;
-                       offset += reel_space;
+                       t += part_lengths[0];
                }
        }
 }
@@ -377,6 +413,7 @@ try
                        }
 
                        lock.lock ();
+                       _full_condition.notify_all ();
                }
 
                while (_queued_full_in_memory > _maximum_frames_in_memory) {
@@ -394,7 +431,7 @@ try
                        DCPOMATIC_ASSERT (i != _queue.rend());
                        ++_pushed_to_disk;
                        /* For the log message below */
-                       int const awaiting = _reels[_queue.front().reel].last_written_video_frame();
+                       int const awaiting = _reels[_queue.front().reel].last_written_video_frame() + 1;
                        lock.unlock ();
 
                        /* i is valid here, even though we don't hold a lock on the mutex,
@@ -412,10 +449,8 @@ try
                        lock.lock ();
                        i->encoded.reset ();
                        --_queued_full_in_memory;
+                       _full_condition.notify_all ();
                }
-
-               /* The queue has probably just gone down a bit; notify anything wait()ing on _full_condition */
-               _full_condition.notify_all ();
        }
 }
 catch (...)
@@ -609,6 +644,11 @@ Writer::write_cover_sheet ()
 bool
 Writer::can_fake_write (Frame frame) const
 {
+       if (_film->encrypted()) {
+               /* We need to re-write the frame because the asset ID is embedded in the HMAC... I think... */
+               return false;
+       }
+
        /* We have to do a proper write of the first frame so that we can set up the JPEG2000
           parameters in the asset writer.
        */
@@ -620,18 +660,32 @@ Writer::can_fake_write (Frame frame) const
        return (frame != 0 && frame < reel.first_nonexistant_frame());
 }
 
+/** @param track Closed caption track if type == TEXT_CLOSED_CAPTION */
 void
-Writer::write (PlayerSubtitles subs, DCPTimePeriod period)
+Writer::write (PlayerText text, TextType type, optional<DCPTextTrack> track, DCPTimePeriod period)
 {
-       if (subs.text.empty ()) {
-               return;
+       vector<ReelWriter>::iterator* reel = 0;
+
+       switch (type) {
+       case TEXT_OPEN_SUBTITLE:
+               reel = &_subtitle_reel;
+               break;
+       case TEXT_CLOSED_CAPTION:
+               DCPOMATIC_ASSERT (track);
+               DCPOMATIC_ASSERT (_caption_reels.find(*track) != _caption_reels.end());
+               reel = &_caption_reels[*track];
+               break;
+       default:
+               DCPOMATIC_ASSERT (false);
        }
 
-       if (_subtitle_reel->period().to <= period.from) {
-               ++_subtitle_reel;
+       DCPOMATIC_ASSERT (*reel != _reels.end());
+       while ((*reel)->period().to <= period.from) {
+               ++(*reel);
+               DCPOMATIC_ASSERT (*reel != _reels.end());
        }
 
-       _subtitle_reel->write (subs);
+       (*reel)->write (text, type, track, period);
 }
 
 void
@@ -676,16 +730,9 @@ operator== (QueueItem const & a, QueueItem const & b)
 void
 Writer::set_encoder_threads (int threads)
 {
-       /* I think the scaling factor here should be the ratio of the longest frame
-          encode time to the shortest; if the thread count is T, longest time is L
-          and the shortest time S we could encode L/S frames per thread whilst waiting
-          for the L frame to encode so we might have to store LT/S frames.
-
-          However we don't want to use too much memory, so keep it a bit lower than we'd
-          perhaps like.  A J2K frame is typically about 1Mb so 3 here will mean we could
-          use about 240Mb with 72 encoding threads.
-       */
-       _maximum_frames_in_memory = lrint (threads * 3);
+       boost::mutex::scoped_lock lm (_state_mutex);
+       _maximum_frames_in_memory = lrint (threads * Config::instance()->frames_in_memory_multiplier());
+       _maximum_queue_size = threads * 16;
 }
 
 void