src/lib/writer.cc

   1 /*
   2     Copyright (C) 2012-2016 Carl Hetherington <cth@carlh.net>
   3
   4     This file is part of DCP-o-matic.
   5
   6     DCP-o-matic is free software; you can redistribute it and/or modify
   7     it under the terms of the GNU General Public License as published by
   8     the Free Software Foundation; either version 2 of the License, or
   9     (at your option) any later version.
  10
  11     DCP-o-matic is distributed in the hope that it will be useful,
  12     but WITHOUT ANY WARRANTY; without even the implied warranty of
  13     MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
  14     GNU General Public License for more details.
  15
  16     You should have received a copy of the GNU General Public License
  17     along with DCP-o-matic.  If not, see <http://www.gnu.org/licenses/>.
  18
  19 */
  20
  21 #include "writer.h"
  22 #include "compose.hpp"
  23 #include "film.h"
  24 #include "ratio.h"
  25 #include "log.h"
  26 #include "dcp_video.h"
  27 #include "dcp_content_type.h"
  28 #include "audio_mapping.h"
  29 #include "config.h"
  30 #include "job.h"
  31 #include "cross.h"
  32 #include "audio_buffers.h"
  33 #include "version.h"
  34 #include "font.h"
  35 #include "util.h"
  36 #include "reel_writer.h"
  37 #include <dcp/cpl.h>
  38 #include <boost/foreach.hpp>
  39 #include <fstream>
  40 #include <cerrno>
  41 #include <iostream>
  42
  43 #include "i18n.h"
  44
  45 #define LOG_GENERAL(...) _film->log()->log (String::compose (__VA_ARGS__), LogEntry::TYPE_GENERAL);
  46 #define LOG_GENERAL_NC(...) _film->log()->log (__VA_ARGS__, LogEntry::TYPE_GENERAL);
  47 #define LOG_DEBUG_ENCODE(...) _film->log()->log (String::compose (__VA_ARGS__), LogEntry::TYPE_DEBUG_ENCODE);
  48 #define LOG_TIMING(...) _film->log()->log (String::compose (__VA_ARGS__), LogEntry::TYPE_TIMING);
  49 #define LOG_WARNING_NC(...) _film->log()->log (__VA_ARGS__, LogEntry::TYPE_WARNING);
  50 #define LOG_WARNING(...) _film->log()->log (String::compose (__VA_ARGS__), LogEntry::TYPE_WARNING);
  51 #define LOG_ERROR(...) _film->log()->log (String::compose (__VA_ARGS__), LogEntry::TYPE_ERROR);
  52
  53 /* OS X strikes again */
  54 #undef set_key
  55
  56 using std::make_pair;
  57 using std::pair;
  58 using std::string;
  59 using std::list;
  60 using std::cout;
  61 using std::map;
  62 using std::min;
  63 using std::max;
  64 using boost::shared_ptr;
  65 using boost::weak_ptr;
  66 using boost::dynamic_pointer_cast;
  67 using dcp::Data;
  68
  69 Writer::Writer (shared_ptr<const Film> film, weak_ptr<Job> j)
  70         : _film (film)
  71         , _job (j)
  72         , _thread (0)
  73         , _finish (false)
  74         , _queued_full_in_memory (0)
  75         , _maximum_frames_in_memory (0)
  76         , _full_written (0)
  77         , _fake_written (0)
  78         , _repeat_written (0)
  79         , _pushed_to_disk (0)
  80 {
  81         /* Remove any old DCP */
  82         boost::filesystem::remove_all (_film->dir (_film->dcp_name ()));
  83
  84         shared_ptr<Job> job = _job.lock ();
  85         DCPOMATIC_ASSERT (job);
  86
  87         int reel_index = 0;
  88         list<DCPTimePeriod> const reels = _film->reels ();
  89         BOOST_FOREACH (DCPTimePeriod p, reels) {
  90                 _reels.push_back (ReelWriter (film, p, job, reel_index++, reels.size(), _film->content_summary(p)));
  91         }
  92
  93         /* We can keep track of the current audio and subtitle reels easily because audio
  94            and subs arrive to the Writer in sequence.  This is not so for video.
  95         */
  96         _audio_reel = _reels.begin ();
  97         _subtitle_reel = _reels.begin ();
  98
  99         /* Check that the signer is OK if we need one */
 100         if (_film->is_signed() && !Config::instance()->signer_chain()->valid ()) {
 101                 throw InvalidSignerError ();
 102         }
 103 }
 104
 105 void
 106 Writer::start ()
 107 {
 108         _thread = new boost::thread (boost::bind (&Writer::thread, this));
 109 }
 110
 111 Writer::~Writer ()
 112 {
 113         terminate_thread (false);
 114 }
 115
 116 /** Pass a video frame to the writer for writing to disk at some point.
 117  *  This method can be called with frames out of order.
 118  *  @param encoded JPEG2000-encoded data.
 119  *  @param frame Frame index within the DCP.
 120  *  @param eyes Eyes that this frame image is for.
 121  */
 122 void
 123 Writer::write (Data encoded, Frame frame, Eyes eyes)
 124 {
 125         boost::mutex::scoped_lock lock (_state_mutex);
 126
 127         while (_queued_full_in_memory > _maximum_frames_in_memory) {
 128                 /* The queue is too big; wait until that is sorted out */
 129                 _full_condition.wait (lock);
 130         }
 131
 132         QueueItem qi;
 133         qi.type = QueueItem::FULL;
 134         qi.encoded = encoded;
 135         qi.reel = video_reel (frame);
 136         qi.frame = frame - _reels[qi.reel].start ();
 137
 138         if (_film->three_d() && eyes == EYES_BOTH) {
 139                 /* 2D material in a 3D DCP; fake the 3D */
 140                 qi.eyes = EYES_LEFT;
 141                 _queue.push_back (qi);
 142                 ++_queued_full_in_memory;
 143                 qi.eyes = EYES_RIGHT;
 144                 _queue.push_back (qi);
 145                 ++_queued_full_in_memory;
 146         } else {
 147                 qi.eyes = eyes;
 148                 _queue.push_back (qi);
 149                 ++_queued_full_in_memory;
 150         }
 151
 152         /* Now there's something to do: wake anything wait()ing on _empty_condition */
 153         _empty_condition.notify_all ();
 154 }
 155
 156 bool
 157 Writer::can_repeat (Frame frame) const
 158 {
 159         return frame > _reels[video_reel(frame)].start();
 160 }
 161
 162 /** Repeat the last frame that was written to a reel as a new frame.
 163  *  @param frame Frame index within the DCP of the new (repeated) frame.
 164  *  @param eyes Eyes that this repeated frame image is for.
 165  */
 166 void
 167 Writer::repeat (Frame frame, Eyes eyes)
 168 {
 169         boost::mutex::scoped_lock lock (_state_mutex);
 170
 171         while (_queued_full_in_memory > _maximum_frames_in_memory) {
 172                 /* The queue is too big; wait until that is sorted out */
 173                 _full_condition.wait (lock);
 174         }
 175
 176         QueueItem qi;
 177         qi.type = QueueItem::REPEAT;
 178         qi.reel = video_reel (frame);
 179         qi.frame = frame - _reels[qi.reel].start ();
 180         if (_film->three_d() && eyes == EYES_BOTH) {
 181                 qi.eyes = EYES_LEFT;
 182                 _queue.push_back (qi);
 183                 qi.eyes = EYES_RIGHT;
 184                 _queue.push_back (qi);
 185         } else {
 186                 qi.eyes = eyes;
 187                 _queue.push_back (qi);
 188         }
 189
 190         /* Now there's something to do: wake anything wait()ing on _empty_condition */
 191         _empty_condition.notify_all ();
 192 }
 193
 194 void
 195 Writer::fake_write (Frame frame, Eyes eyes)
 196 {
 197         boost::mutex::scoped_lock lock (_state_mutex);
 198
 199         while (_queued_full_in_memory > _maximum_frames_in_memory) {
 200                 /* The queue is too big; wait until that is sorted out */
 201                 _full_condition.wait (lock);
 202         }
 203
 204         size_t const reel = video_reel (frame);
 205         Frame const reel_frame = frame - _reels[reel].start ();
 206
 207         FILE* file = fopen_boost (_film->info_file(_reels[reel].period()), "rb");
 208         if (!file) {
 209                 throw ReadFileError (_film->info_file(_reels[reel].period()));
 210         }
 211         dcp::FrameInfo info = _reels[reel].read_frame_info (file, reel_frame, eyes);
 212         fclose (file);
 213
 214         QueueItem qi;
 215         qi.type = QueueItem::FAKE;
 216         qi.size = info.size;
 217         qi.reel = reel;
 218         qi.frame = reel_frame;
 219         if (_film->three_d() && eyes == EYES_BOTH) {
 220                 qi.eyes = EYES_LEFT;
 221                 _queue.push_back (qi);
 222                 qi.eyes = EYES_RIGHT;
 223                 _queue.push_back (qi);
 224         } else {
 225                 qi.eyes = eyes;
 226                 _queue.push_back (qi);
 227         }
 228
 229         /* Now there's something to do: wake anything wait()ing on _empty_condition */
 230         _empty_condition.notify_all ();
 231 }
 232
 233 /** Write one video frame's worth of audio frames to the DCP.
 234  *  @param audio Audio data or 0 if there is no audio to be written here (i.e. it is referenced).
 235  *  This method is not thread safe.
 236  */
 237 void
 238 Writer::write (shared_ptr<const AudioBuffers> audio)
 239 {
 240         if (_audio_reel == _reels.end ()) {
 241                 /* This audio is off the end of the last reel; ignore it */
 242                 return;
 243         }
 244
 245         _audio_reel->write (audio);
 246
 247         /* written is in video frames, not audio frames */
 248         if (_audio_reel->total_written_audio_frames() >= _audio_reel->period().duration().frames_floor (_film->video_frame_rate())) {
 249                 ++_audio_reel;
 250         }
 251 }
 252
 253 /** This must be called from Writer::thread() with an appropriate lock held */
 254 bool
 255 Writer::have_sequenced_image_at_queue_head ()
 256 {
 257         if (_queue.empty ()) {
 258                 return false;
 259         }
 260
 261         _queue.sort ();
 262
 263         QueueItem const & f = _queue.front();
 264         ReelWriter const & reel = _reels[f.reel];
 265
 266         /* The queue should contain only EYES_LEFT/EYES_RIGHT pairs or EYES_BOTH */
 267
 268         if (f.eyes == EYES_BOTH) {
 269                 /* 2D */
 270                 return f.frame == (reel.last_written_video_frame() + 1);
 271         }
 272
 273         /* 3D */
 274
 275         if (reel.last_written_eyes() == EYES_LEFT && f.frame == reel.last_written_video_frame() && f.eyes == EYES_RIGHT) {
 276                 return true;
 277         }
 278
 279         if (reel.last_written_eyes() == EYES_RIGHT && f.frame == (reel.last_written_video_frame() + 1) && f.eyes == EYES_LEFT) {
 280                 return true;
 281         }
 282
 283         return false;
 284 }
 285
 286 void
 287 Writer::thread ()
 288 try
 289 {
 290         while (true)
 291         {
 292                 boost::mutex::scoped_lock lock (_state_mutex);
 293
 294                 while (true) {
 295
 296                         if (_finish || _queued_full_in_memory > _maximum_frames_in_memory || have_sequenced_image_at_queue_head ()) {
 297                                 /* We've got something to do: go and do it */
 298                                 break;
 299                         }
 300
 301                         /* Nothing to do: wait until something happens which may indicate that we do */
 302                         LOG_TIMING (N_("writer-sleep queue=%1"), _queue.size());
 303                         _empty_condition.wait (lock);
 304                         LOG_TIMING (N_("writer-wake queue=%1"), _queue.size());
 305                 }
 306
 307                 if (_finish && _queue.empty()) {
 308                         return;
 309                 }
 310
 311                 /* We stop here if we have been asked to finish, and if either the queue
 312                    is empty or we do not have a sequenced image at its head (if this is the
 313                    case we will never terminate as no new frames will be sent once
 314                    _finish is true).
 315                 */
 316                 if (_finish && (!have_sequenced_image_at_queue_head() || _queue.empty())) {
 317                         /* (Hopefully temporarily) log anything that was not written */
 318                         if (!_queue.empty() && !have_sequenced_image_at_queue_head()) {
 319                                 LOG_WARNING (N_("Finishing writer with a left-over queue of %1:"), _queue.size());
 320                                 for (list<QueueItem>::const_iterator i = _queue.begin(); i != _queue.end(); ++i) {
 321                                         if (i->type == QueueItem::FULL) {
 322                                                 LOG_WARNING (N_("- type FULL, frame %1, eyes %2"), i->frame, (int) i->eyes);
 323                                         } else {
 324                                                 LOG_WARNING (N_("- type FAKE, size %1, frame %2, eyes %3"), i->size, i->frame, (int) i->eyes);
 325                                         }
 326                                 }
 327                         }
 328                         return;
 329                 }
 330
 331                 /* Write any frames that we can write; i.e. those that are in sequence. */
 332                 while (have_sequenced_image_at_queue_head ()) {
 333                         QueueItem qi = _queue.front ();
 334                         _queue.pop_front ();
 335                         if (qi.type == QueueItem::FULL && qi.encoded) {
 336                                 --_queued_full_in_memory;
 337                         }
 338
 339                         lock.unlock ();
 340
 341                         ReelWriter& reel = _reels[qi.reel];
 342
 343                         switch (qi.type) {
 344                         case QueueItem::FULL:
 345                                 LOG_DEBUG_ENCODE (N_("Writer FULL-writes %1 (%2)"), qi.frame, (int) qi.eyes);
 346                                 if (!qi.encoded) {
 347                                         qi.encoded = Data (_film->j2c_path (qi.reel, qi.frame, qi.eyes, false));
 348                                 }
 349                                 reel.write (qi.encoded, qi.frame, qi.eyes);
 350                                 ++_full_written;
 351                                 break;
 352                         case QueueItem::FAKE:
 353                                 LOG_DEBUG_ENCODE (N_("Writer FAKE-writes %1"), qi.frame);
 354                                 reel.fake_write (qi.frame, qi.eyes, qi.size);
 355                                 ++_fake_written;
 356                                 break;
 357                         case QueueItem::REPEAT:
 358                                 LOG_DEBUG_ENCODE (N_("Writer REPEAT-writes %1"), qi.frame);
 359                                 reel.repeat_write (qi.frame, qi.eyes);
 360                                 ++_repeat_written;
 361                                 break;
 362                         }
 363
 364                         lock.lock ();
 365                 }
 366
 367                 while (_queued_full_in_memory > _maximum_frames_in_memory) {
 368                         /* Too many frames in memory which can't yet be written to the stream.
 369                            Write some FULL frames to disk.
 370                         */
 371
 372                         /* Find one from the back of the queue */
 373                         _queue.sort ();
 374                         list<QueueItem>::reverse_iterator i = _queue.rbegin ();
 375                         while (i != _queue.rend() && (i->type != QueueItem::FULL || !i->encoded)) {
 376                                 ++i;
 377                         }
 378
 379                         DCPOMATIC_ASSERT (i != _queue.rend());
 380                         ++_pushed_to_disk;
 381                         lock.unlock ();
 382
 383                         /* i is valid here, even though we don't hold a lock on the mutex,
 384                            since list iterators are unaffected by insertion and only this
 385                            thread could erase the last item in the list.
 386                         */
 387
 388                         LOG_GENERAL ("Writer full; pushes %1 to disk", i->frame);
 389
 390                         i->encoded->write_via_temp (
 391                                 _film->j2c_path (i->reel, i->frame, i->eyes, true),
 392                                 _film->j2c_path (i->reel, i->frame, i->eyes, false)
 393                                 );
 394
 395                         lock.lock ();
 396                         i->encoded.reset ();
 397                         --_queued_full_in_memory;
 398                 }
 399
 400                 /* The queue has probably just gone down a bit; notify anything wait()ing on _full_condition */
 401                 _full_condition.notify_all ();
 402         }
 403 }
 404 catch (...)
 405 {
 406         store_current ();
 407 }
 408
 409 void
 410 Writer::terminate_thread (bool can_throw)
 411 {
 412         boost::mutex::scoped_lock lock (_state_mutex);
 413         if (_thread == 0) {
 414                 return;
 415         }
 416
 417         _finish = true;
 418         _empty_condition.notify_all ();
 419         _full_condition.notify_all ();
 420         lock.unlock ();
 421
 422         if (_thread->joinable ()) {
 423                 _thread->join ();
 424         }
 425
 426         if (can_throw) {
 427                 rethrow ();
 428         }
 429
 430         delete _thread;
 431         _thread = 0;
 432 }
 433
 434 void
 435 Writer::finish ()
 436 {
 437         if (!_thread) {
 438                 return;
 439         }
 440
 441         LOG_GENERAL_NC ("Terminating writer thread");
 442
 443         terminate_thread (true);
 444
 445         LOG_GENERAL_NC ("Finishing ReelWriters");
 446
 447         BOOST_FOREACH (ReelWriter& i, _reels) {
 448                 i.finish ();
 449         }
 450
 451         LOG_GENERAL_NC ("Writing XML");
 452
 453         dcp::DCP dcp (_film->dir (_film->dcp_name()));
 454
 455         shared_ptr<dcp::CPL> cpl (
 456                 new dcp::CPL (
 457                         _film->dcp_name(),
 458                         _film->dcp_content_type()->libdcp_kind ()
 459                         )
 460                 );
 461
 462         dcp.add (cpl);
 463
 464         /* Calculate digests for each reel in parallel */
 465
 466         shared_ptr<Job> job = _job.lock ();
 467         job->sub (_("Computing digests"));
 468
 469         boost::asio::io_service service;
 470         boost::thread_group pool;
 471
 472         shared_ptr<boost::asio::io_service::work> work (new boost::asio::io_service::work (service));
 473
 474         int const threads = max (1, Config::instance()->num_local_encoding_threads ());
 475
 476         for (int i = 0; i < threads; ++i) {
 477                 pool.create_thread (boost::bind (&boost::asio::io_service::run, &service));
 478         }
 479
 480         BOOST_FOREACH (ReelWriter& i, _reels) {
 481                 boost::function<void (float)> set_progress = boost::bind (&Writer::set_digest_progress, this, job.get(), _1);
 482                 service.post (boost::bind (&ReelWriter::calculate_digests, &i, set_progress));
 483         }
 484
 485         work.reset ();
 486         pool.join_all ();
 487         service.stop ();
 488
 489         /* Add reels to CPL */
 490
 491         BOOST_FOREACH (ReelWriter& i, _reels) {
 492                 cpl->add (i.create_reel (_reel_assets, _fonts));
 493         }
 494
 495         dcp::XMLMetadata meta;
 496         meta.creator = Config::instance()->dcp_creator ();
 497         if (meta.creator.empty ()) {
 498                 meta.creator = String::compose ("DCP-o-matic %1 %2", dcpomatic_version, dcpomatic_git_commit);
 499         }
 500         meta.issuer = Config::instance()->dcp_issuer ();
 501         if (meta.issuer.empty ()) {
 502                 meta.issuer = String::compose ("DCP-o-matic %1 %2", dcpomatic_version, dcpomatic_git_commit);
 503         }
 504         meta.set_issue_date_now ();
 505
 506         cpl->set_metadata (meta);
 507
 508         shared_ptr<const dcp::CertificateChain> signer;
 509         if (_film->is_signed ()) {
 510                 signer = Config::instance()->signer_chain ();
 511                 /* We did check earlier, but check again here to be on the safe side */
 512                 if (!signer->valid ()) {
 513                         throw InvalidSignerError ();
 514                 }
 515         }
 516
 517         dcp.write_xml (_film->interop () ? dcp::INTEROP : dcp::SMPTE, meta, signer, Config::instance()->dcp_metadata_filename_format());
 518
 519         LOG_GENERAL (
 520                 N_("Wrote %1 FULL, %2 FAKE, %3 REPEAT, %4 pushed to disk"), _full_written, _fake_written, _repeat_written, _pushed_to_disk
 521                 );
 522 }
 523
 524 /** @param frame Frame index within the whole DCP.
 525  *  @return true if we can fake-write this frame.
 526  */
 527 bool
 528 Writer::can_fake_write (Frame frame) const
 529 {
 530         /* We have to do a proper write of the first frame so that we can set up the JPEG2000
 531            parameters in the asset writer.
 532         */
 533
 534         ReelWriter const & reel = _reels[video_reel(frame)];
 535
 536         /* Make frame relative to the start of the reel */
 537         frame -= reel.start ();
 538         return (frame != 0 && frame < reel.first_nonexistant_frame());
 539 }
 540
 541 void
 542 Writer::write (PlayerSubtitles subs)
 543 {
 544         if (subs.text.empty ()) {
 545                 return;
 546         }
 547
 548         if (_subtitle_reel->period().to <= subs.from) {
 549                 ++_subtitle_reel;
 550         }
 551
 552         _subtitle_reel->write (subs);
 553 }
 554
 555 void
 556 Writer::write (list<shared_ptr<Font> > fonts)
 557 {
 558         /* Just keep a list of unique fonts and we'll deal with them in ::finish */
 559
 560         BOOST_FOREACH (shared_ptr<Font> i, fonts) {
 561                 bool got = false;
 562                 BOOST_FOREACH (shared_ptr<Font> j, _fonts) {
 563                         if (*i == *j) {
 564                                 got = true;
 565                         }
 566                 }
 567
 568                 if (!got) {
 569                         _fonts.push_back (i);
 570                 }
 571         }
 572 }
 573
 574 bool
 575 operator< (QueueItem const & a, QueueItem const & b)
 576 {
 577         if (a.reel != b.reel) {
 578                 return a.reel < b.reel;
 579         }
 580
 581         if (a.frame != b.frame) {
 582                 return a.frame < b.frame;
 583         }
 584
 585         return static_cast<int> (a.eyes) < static_cast<int> (b.eyes);
 586 }
 587
 588 bool
 589 operator== (QueueItem const & a, QueueItem const & b)
 590 {
 591         return a.reel == b.reel && a.frame == b.frame && a.eyes == b.eyes;
 592 }
 593
 594 void
 595 Writer::set_encoder_threads (int threads)
 596 {
 597         /* I think the scaling factor here should be the ratio of the longest frame
 598            encode time to the shortest; if the thread count is T, longest time is L
 599            and the shortest time S we could encode L/S frames per thread whilst waiting
 600            for the L frame to encode so we might have to store LT/S frames.
 601
 602            However we don't want to use too much memory, so keep it a bit lower than we'd
 603            perhaps like.  A J2K frame is typically about 1Mb so 3 here will mean we could
 604            use about 240Mb with 72 encoding threads.
 605         */
 606         _maximum_frames_in_memory = lrint (threads * 3);
 607 }
 608
 609 void
 610 Writer::write (ReferencedReelAsset asset)
 611 {
 612         _reel_assets.push_back (asset);
 613 }
 614
 615 size_t
 616 Writer::video_reel (int frame) const
 617 {
 618         DCPTime t = DCPTime::from_frames (frame, _film->video_frame_rate ());
 619         size_t i = 0;
 620         while (i < _reels.size() && !_reels[i].period().contains (t)) {
 621                 ++i;
 622         }
 623
 624         DCPOMATIC_ASSERT (i < _reels.size ());
 625         return i;
 626 }
 627
 628 void
 629 Writer::set_digest_progress (Job* job, float progress)
 630 {
 631         /* I believe this is thread-safe */
 632         _digest_progresses[boost::this_thread::get_id()] = progress;
 633
 634         boost::mutex::scoped_lock lm (_digest_progresses_mutex);
 635         float min_progress = 0;
 636         for (map<boost::thread::id, float>::const_iterator i = _digest_progresses.begin(); i != _digest_progresses.end(); ++i) {
 637                 min_progress = min (min_progress, i->second);
 638         }
 639
 640         job->set_progress (min_progress);
 641 }