Merge branch '2.0' of ssh://git.carlh.net/home/carl/git/dcpomatic2 into 2.0
[dcpomatic.git] / src / lib / writer.cc
index 5c711ef9224db8c422198d65361feb002ebc7b71..ff6e4f63cba6b0caf44d81030d64d816b55c2a97 100644 (file)
 #include "i18n.h"
 
 #define LOG_GENERAL(...) _film->log()->log (String::compose (__VA_ARGS__), Log::TYPE_GENERAL);
+#define LOG_DEBUG_ENCODE(...) _film->log()->log (String::compose (__VA_ARGS__), Log::TYPE_DEBUG_ENCODE);
 #define LOG_TIMING(...) _film->log()->microsecond_log (String::compose (__VA_ARGS__), Log::TYPE_TIMING);
 #define LOG_WARNING_NC(...) _film->log()->log (__VA_ARGS__, Log::TYPE_WARNING);
 #define LOG_WARNING(...) _film->log()->log (String::compose (__VA_ARGS__), Log::TYPE_WARNING);
 #define LOG_ERROR(...) _film->log()->log (String::compose (__VA_ARGS__), Log::TYPE_ERROR);
-#define LOG_DEBUG(...) _film->log()->log (String::compose (__VA_ARGS__), Log::TYPE_DEBUG);
-#define LOG_DEBUG_NC(...) _film->log()->log (__VA_ARGS__, Log::TYPE_DEBUG);
 
 /* OS X strikes again */
 #undef set_key
@@ -74,8 +73,8 @@ using boost::shared_ptr;
 using boost::weak_ptr;
 using boost::dynamic_pointer_cast;
 
-Writer::Writer (shared_ptr<const Film> f, weak_ptr<Job> j)
-       : _film (f)
+Writer::Writer (shared_ptr<const Film> film, weak_ptr<Job> j)
+       : _film (film)
        , _job (j)
        , _first_nonexistant_frame (0)
        , _thread (0)
@@ -118,7 +117,7 @@ Writer::Writer (shared_ptr<const Film> f, weak_ptr<Job> j)
 
        job->sub (_("Checking existing image data"));
        check_existing_picture_asset ();
-       
+
        _picture_asset_writer = _picture_asset->start_write (
                _film->internal_video_asset_dir() / _film->internal_video_asset_filename(),
                _film->interop() ? dcp::INTEROP : dcp::SMPTE,
@@ -133,7 +132,7 @@ Writer::Writer (shared_ptr<const Film> f, weak_ptr<Job> j)
                if (_film->encrypted ()) {
                        _sound_asset->set_key (_film->key ());
                }
-       
+
                /* Write the sound asset into the film directory so that we leave the creation
                   of the DCP directory until the last minute.
                */
@@ -227,14 +226,14 @@ Writer::fake_write (int frame, Eyes eyes)
                /* The queue is too big; wait until that is sorted out */
                _full_condition.wait (lock);
        }
-       
+
        FILE* file = fopen_boost (_film->info_file (), "rb");
        if (!file) {
                throw ReadFileError (_film->info_file ());
        }
        dcp::FrameInfo info = read_frame_info (file, frame, eyes);
        fclose (file);
-       
+
        QueueItem qi;
        qi.type = QueueItem::FAKE;
        qi.size = info.size;
@@ -314,11 +313,8 @@ try
        {
                boost::mutex::scoped_lock lock (_mutex);
 
-               /* This is for debugging only */
-               bool done_something = false;
-
                while (true) {
-                       
+
                        if (_finish || _queued_full_in_memory > _maximum_frames_in_memory || have_sequenced_image_at_queue_head ()) {
                                /* We've got something to do: go and do it */
                                break;
@@ -340,7 +336,6 @@ try
                   _finish is true).
                */
                if (_finish && (!have_sequenced_image_at_queue_head() || _queue.empty())) {
-                       done_something = true;
                        /* (Hopefully temporarily) log anything that was not written */
                        if (!_queue.empty() && !have_sequenced_image_at_queue_head()) {
                                LOG_WARNING (N_("Finishing writer with a left-over queue of %1:"), _queue.size());
@@ -349,7 +344,7 @@ try
                                                LOG_WARNING (N_("- type FULL, frame %1, eyes %2"), i->frame, i->eyes);
                                        } else {
                                                LOG_WARNING (N_("- type FAKE, size %1, frame %2, eyes %3"), i->size, i->frame, i->eyes);
-                                       }                                               
+                                       }
                                }
                                LOG_WARNING (N_("Last written frame %1, last written eyes %2"), _last_written_frame, _last_written_eyes);
                        }
@@ -357,7 +352,6 @@ try
                }
                /* Write any frames that we can write; i.e. those that are in sequence. */
                while (have_sequenced_image_at_queue_head ()) {
-                       done_something = true;
                        QueueItem qi = _queue.front ();
                        _queue.pop_front ();
                        if (qi.type == QueueItem::FULL && qi.encoded) {
@@ -368,7 +362,7 @@ try
                        switch (qi.type) {
                        case QueueItem::FULL:
                        {
-                               LOG_GENERAL (N_("Writer FULL-writes %1 (%2)"), qi.frame, qi.eyes);
+                               LOG_DEBUG_ENCODE (N_("Writer FULL-writes %1 (%2)"), qi.frame, qi.eyes);
                                if (!qi.encoded) {
                                        qi.encoded = Data (_film->j2c_path (qi.frame, qi.eyes, false));
                                }
@@ -380,13 +374,13 @@ try
                                break;
                        }
                        case QueueItem::FAKE:
-                               LOG_GENERAL (N_("Writer FAKE-writes %1"), qi.frame);
+                               LOG_DEBUG_ENCODE (N_("Writer FAKE-writes %1"), qi.frame);
                                _picture_asset_writer->fake_write (qi.size);
                                _last_written[qi.eyes].reset ();
                                ++_fake_written;
                                break;
                        case QueueItem::REPEAT:
-                               LOG_GENERAL (N_("Writer REPEAT-writes %1"), qi.frame);
+                               LOG_DEBUG_ENCODE (N_("Writer REPEAT-writes %1"), qi.frame);
                                dcp::FrameInfo fin = _picture_asset_writer->write (
                                        _last_written[qi.eyes]->data().get(),
                                        _last_written[qi.eyes]->size()
@@ -399,7 +393,7 @@ try
 
                        _last_written_frame = qi.frame;
                        _last_written_eyes = qi.eyes;
-                       
+
                        shared_ptr<Job> job = _job.lock ();
                        DCPOMATIC_ASSERT (job);
                        int64_t total = _film->length().frames (_film->video_frame_rate ());
@@ -410,12 +404,11 @@ try
                                total *= 2;
                        }
                        if (total) {
-                               job->set_progress (float (_full_written + _fake_written) / total);
+                               job->set_progress (float (_full_written + _fake_written + _repeat_written) / total);
                        }
                }
 
                while (_queued_full_in_memory > _maximum_frames_in_memory) {
-                       done_something = true;
                        /* Too many frames in memory which can't yet be written to the stream.
                           Write some FULL frames to disk.
                        */
@@ -443,20 +436,12 @@ try
                                );
 
                        i->encoded->write_via_temp (_film->j2c_path (i->frame, i->eyes, true), _film->j2c_path (i->frame, i->eyes, false));
-                       
+
                        lock.lock ();
                        i->encoded.reset ();
                        --_queued_full_in_memory;
                }
 
-               if (!done_something) {
-                       LOG_DEBUG_NC ("Writer loop ran without doing anything");
-                       LOG_DEBUG ("_queued_full_in_memory=%1", _queued_full_in_memory);
-                       LOG_DEBUG ("_queue_size=%1", _queue.size ());
-                       LOG_DEBUG ("_finish=%1", _finish);
-                       LOG_DEBUG ("_last_written_frame=%1", _last_written_frame);
-               }
-
                /* The queue has probably just gone down a bit; notify anything wait()ing on _full_condition */
                _full_condition.notify_all ();
        }
@@ -473,7 +458,7 @@ Writer::terminate_thread (bool can_throw)
        if (_thread == 0) {
                return;
        }
-       
+
        _finish = true;
        _empty_condition.notify_all ();
        _full_condition.notify_all ();
@@ -483,10 +468,10 @@ Writer::terminate_thread (bool can_throw)
        if (can_throw) {
                rethrow ();
        }
-       
+
        delete _thread;
        _thread = 0;
-}      
+}
 
 void
 Writer::finish ()
@@ -494,17 +479,17 @@ Writer::finish ()
        if (!_thread) {
                return;
        }
-       
+
        terminate_thread (true);
 
        _picture_asset_writer->finalize ();
        if (_sound_asset_writer) {
                _sound_asset_writer->finalize ();
        }
-       
+
        /* Hard-link the video asset into the DCP */
        boost::filesystem::path video_from = _picture_asset->file ();
-       
+
        boost::filesystem::path video_to;
        video_to /= _film->dir (_film->dcp_name());
        video_to /= video_asset_filename (_picture_asset);
@@ -528,7 +513,7 @@ Writer::finish ()
                boost::filesystem::path audio_to;
                audio_to /= _film->dir (_film->dcp_name ());
                audio_to /= audio_asset_filename (_sound_asset);
-               
+
                boost::filesystem::rename (_film->file (audio_asset_filename (_sound_asset)), audio_to, ec);
                if (ec) {
                        throw FileError (
@@ -547,7 +532,7 @@ Writer::finish ()
                        _film->dcp_content_type()->libdcp_kind ()
                        )
                );
-       
+
        dcp.add (cpl);
 
        shared_ptr<dcp::Reel> reel (new dcp::Reel ());
@@ -583,7 +568,7 @@ Writer::finish ()
                                _film->dir (_film->dcp_name ()) / ("sub_" + _subtitle_asset->id() + ".mxf")
                                );
                }
-               
+
                reel->add (shared_ptr<dcp::ReelSubtitleAsset> (
                                   new dcp::ReelSubtitleAsset (
                                           _subtitle_asset,
@@ -593,7 +578,7 @@ Writer::finish ()
                                           )
                                   ));
        }
-       
+
        cpl->add (reel);
 
        shared_ptr<Job> job = _job.lock ();
@@ -637,14 +622,14 @@ Writer::check_existing_picture_asset_frame (FILE* asset, int f, Eyes eyes)
                LOG_GENERAL ("Existing frame %1 has no info file", f);
                return false;
        }
-       
+
        dcp::FrameInfo info = read_frame_info (file, f, eyes);
        fclose (file);
        if (info.size == 0) {
                LOG_GENERAL ("Existing frame %1 has no info file", f);
                return false;
        }
-       
+
        /* Read the data from the asset and hash it */
        dcpomatic_fseek (asset, info.offset, SEEK_SET);
        Data data (info.size);
@@ -694,7 +679,7 @@ Writer::check_existing_picture_asset ()
                        }
                }
 
-               LOG_GENERAL ("Have existing frame %1", _first_nonexistant_frame);
+               LOG_DEBUG_ENCODE ("Have existing frame %1", _first_nonexistant_frame);
                ++_first_nonexistant_frame;
        }
 
@@ -738,9 +723,9 @@ Writer::write (PlayerSubtitles subs)
                        s->set_edit_rate (dcp::Fraction (_film->video_frame_rate (), 1));
                        s->set_time_code_rate (_film->video_frame_rate ());
                        _subtitle_asset = s;
-               }                       
+               }
        }
-       
+
        for (list<dcp::SubtitleString>::const_iterator i = subs.text.begin(); i != subs.text.end(); ++i) {
                _subtitle_asset->add (*i);
        }
@@ -779,7 +764,7 @@ long
 Writer::frame_info_position (int frame, Eyes eyes) const
 {
        static int const info_size = 48;
-       
+
        switch (eyes) {
        case EYES_BOTH:
                return frame * info_size;
@@ -790,7 +775,7 @@ Writer::frame_info_position (int frame, Eyes eyes) const
        default:
                DCPOMATIC_ASSERT (false);
        }
-       
+
 
        DCPOMATIC_ASSERT (false);
 }
@@ -802,7 +787,7 @@ Writer::read_frame_info (FILE* file, int frame, Eyes eyes) const
        dcpomatic_fseek (file, frame_info_position (frame, eyes), SEEK_SET);
        fread (&info.offset, sizeof (info.offset), 1, file);
        fread (&info.size, sizeof (info.size), 1, file);
-       
+
        char hash_buffer[33];
        fread (hash_buffer, 1, 32, file);
        hash_buffer[32] = '\0';