src/lib/writer.cc

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