From f3fdae3f8f4ae54b17f925f81a5e9d4b3589269b Mon Sep 17 00:00:00 2001 From: Carl Hetherington Date: Sat, 29 Sep 2012 23:41:25 +0100 Subject: Entirely untested resampling to fix 24fps drop-frame. --- src/lib/decoder.cc | 105 +---------------------------------------------------- 1 file changed, 2 insertions(+), 103 deletions(-) (limited to 'src/lib/decoder.cc') diff --git a/src/lib/decoder.cc b/src/lib/decoder.cc index 973582ca4..b7aca764d 100644 --- a/src/lib/decoder.cc +++ b/src/lib/decoder.cc @@ -69,9 +69,6 @@ Decoder::Decoder (boost::shared_ptr s, boost::shared_ptraudio_sample_rate != dcp_audio_sample_rate (_fs->audio_sample_rate)) { -#if HAVE_SWRESAMPLE - _swr_context = swr_alloc_set_opts ( - 0, - audio_channel_layout(), - audio_sample_format(), - dcp_audio_sample_rate (_fs->audio_sample_rate), - audio_channel_layout(), - audio_sample_format(), - _fs->audio_sample_rate, - 0, 0 - ); - - swr_init (_swr_context); -#else - throw DecodeError ("Cannot resample audio as libswresample is not present"); -#endif - } else { -#if HAVE_SWRESAMPLE - _swr_context = 0; -#endif - } - _delay_in_bytes = _fs->audio_delay * _fs->audio_sample_rate * _fs->audio_channels * _fs->bytes_per_sample() / 1000; delete _delay_line; _delay_line = new DelayLine (_delay_in_bytes); @@ -125,35 +99,6 @@ Decoder::process_begin () void Decoder::process_end () { -#if HAVE_SWRESAMPLE - if (_swr_context) { - - int mop = 0; - while (1) { - uint8_t buffer[256 * _fs->bytes_per_sample() * _fs->audio_channels]; - uint8_t* out[1] = { - buffer - }; - - int const frames = swr_convert (_swr_context, out, 256, 0, 0); - - if (frames < 0) { - throw DecodeError ("could not run sample-rate converter"); - } - - if (frames == 0) { - break; - } - - mop += frames; - int available = _delay_line->feed (buffer, frames * _fs->audio_channels * _fs->bytes_per_sample()); - Audio (buffer, available); - } - - swr_free (&_swr_context); - } -#endif - if (_delay_in_bytes < 0) { uint8_t remainder[-_delay_in_bytes]; _delay_line->get_remaining (remainder); @@ -166,7 +111,7 @@ Decoder::process_end () */ int64_t const audio_short_by_frames = - ((int64_t) decoding_frames() * dcp_audio_sample_rate (_fs->audio_sample_rate) / _fs->frames_per_second) + ((int64_t) decoding_frames() * _fs->audio_sample_rate / _fs->frames_per_second) - _audio_frames_processed; if (audio_short_by_frames >= 0) { @@ -240,16 +185,9 @@ Decoder::pass () void Decoder::process_audio (uint8_t* data, int size) { - /* Here's samples per channel */ + /* Samples per channel */ int const samples = size / _fs->bytes_per_sample(); -#if HAVE_SWRESAMPLE - /* And here's frames (where 1 frame is a collection of samples, 1 for each channel, - so for 5.1 a frame would be 6 samples) - */ - int const frames = samples / _fs->audio_channels; -#endif - /* Maybe apply gain */ if (_fs->audio_gain != 0) { float const linear_gain = pow (10, _fs->audio_gain / 20); @@ -282,51 +220,12 @@ Decoder::process_audio (uint8_t* data, int size) } } - /* This is a buffer we might use if we are sample-rate converting; - it will need freeing if so. - */ - uint8_t* out_buffer = 0; - - /* Maybe sample-rate convert */ -#if HAVE_SWRESAMPLE - if (_swr_context) { - - uint8_t const * in[2] = { - data, - 0 - }; - - /* Compute the resampled frame count and add 32 for luck */ - int const out_buffer_size_frames = ceil (frames * float (dcp_audio_sample_rate (_fs->audio_sample_rate)) / _fs->audio_sample_rate) + 32; - int const out_buffer_size_bytes = out_buffer_size_frames * _fs->audio_channels * _fs->bytes_per_sample(); - out_buffer = new uint8_t[out_buffer_size_bytes]; - - uint8_t* out[2] = { - out_buffer, - 0 - }; - - /* Resample audio */ - int out_frames = swr_convert (_swr_context, out, out_buffer_size_frames, in, frames); - if (out_frames < 0) { - throw DecodeError ("could not run sample-rate converter"); - } - - /* And point our variables at the resampled audio */ - data = out_buffer; - size = out_frames * _fs->audio_channels * _fs->bytes_per_sample(); - } -#endif - /* Update the number of audio frames we've pushed to the encoder */ _audio_frames_processed += size / (_fs->audio_channels * _fs->bytes_per_sample ()); /* Push into the delay line and then tell the world what we've got */ int available = _delay_line->feed (data, size); Audio (data, available); - - /* Delete the sample-rate conversion buffer, if it exists */ - delete[] out_buffer; } /** Called by subclasses to tell the world that some video data is ready. -- cgit v1.2.3 From 0f154f43bd0c88d1615e455bd8a169826a08c086 Mon Sep 17 00:00:00 2001 From: Carl Hetherington Date: Mon, 1 Oct 2012 19:51:36 +0100 Subject: Various fixes to resampling. --- src/lib/decoder.cc | 13 +++++++---- src/lib/film_state.cc | 21 ++++++++++++++++++ src/lib/film_state.h | 1 + src/lib/j2k_wav_encoder.cc | 54 +++++++++++++++------------------------------- src/lib/j2k_wav_encoder.h | 2 -- 5 files changed, 48 insertions(+), 43 deletions(-) (limited to 'src/lib/decoder.cc') diff --git a/src/lib/decoder.cc b/src/lib/decoder.cc index b7aca764d..213ff9dd4 100644 --- a/src/lib/decoder.cc +++ b/src/lib/decoder.cc @@ -111,18 +111,23 @@ Decoder::process_end () */ int64_t const audio_short_by_frames = - ((int64_t) decoding_frames() * _fs->audio_sample_rate / _fs->frames_per_second) + ((int64_t) decoding_frames() * _fs->target_sample_rate() / _fs->frames_per_second) - _audio_frames_processed; if (audio_short_by_frames >= 0) { - int bytes = audio_short_by_frames * _fs->audio_channels * _fs->bytes_per_sample(); + + stringstream s; + s << "Adding " << audio_short_by_frames << " frames of silence to the end."; + _log->log (s.str ()); + + int64_t bytes = audio_short_by_frames * _fs->audio_channels * _fs->bytes_per_sample(); - int const silence_size = 64 * 1024; + int64_t const silence_size = 64 * 1024; uint8_t silence[silence_size]; memset (silence, 0, silence_size); while (bytes) { - int const t = min (bytes, silence_size); + int64_t const t = min (bytes, silence_size); Audio (silence, t); bytes -= t; } diff --git a/src/lib/film_state.cc b/src/lib/film_state.cc index e472434ce..0c1ac87dc 100644 --- a/src/lib/film_state.cc +++ b/src/lib/film_state.cc @@ -35,6 +35,7 @@ #include "format.h" #include "dcp_content_type.h" #include "util.h" +#include "exceptions.h" using namespace std; using namespace boost; @@ -278,3 +279,23 @@ FilmState::bytes_per_sample () const return 0; } + +int +FilmState::target_sample_rate () const +{ + double t = dcp_audio_sample_rate (audio_sample_rate); + if (rint (frames_per_second) != frames_per_second) { + if (fabs (frames_per_second - 23.976) < 1e-6) { + /* 24fps drop-frame ie 24 * 1000 / 1001 frames per second; + hence we need to resample the audio to dcp_audio_sample_rate * 1000 / 1001 + so that when we play it back at dcp_audio_sample_rate it is sped up + by the same amount that the video is + */ + t *= double(1000) / 1001; + } else { + throw EncodeError ("unknown fractional frame rate"); + } + } + + return rint (t); +} diff --git a/src/lib/film_state.h b/src/lib/film_state.h index 12d44cdce..8dc0ce11b 100644 --- a/src/lib/film_state.h +++ b/src/lib/film_state.h @@ -80,6 +80,7 @@ public: int thumb_frame (int) const; int bytes_per_sample () const; + int target_sample_rate () const; void write_metadata (std::ofstream &) const; void read_metadata (std::string, std::string); diff --git a/src/lib/j2k_wav_encoder.cc b/src/lib/j2k_wav_encoder.cc index 241639400..9b25717ef 100644 --- a/src/lib/j2k_wav_encoder.cc +++ b/src/lib/j2k_wav_encoder.cc @@ -219,14 +219,14 @@ J2KWAVEncoder::process_begin (int64_t audio_channel_layout, AVSampleFormat audio #ifdef HAVE_SWRESAMPLE stringstream s; - s << "Will resample audio from " << _fs->audio_sample_rate << " to " << target_sample_rate(); + s << "Will resample audio from " << _fs->audio_sample_rate << " to " << _fs->target_sample_rate(); _log->log (s.str ()); _swr_context = swr_alloc_set_opts ( 0, audio_channel_layout, audio_sample_format, - target_sample_rate(), + _fs->target_sample_rate(), audio_channel_layout, audio_sample_format, _fs->audio_sample_rate, @@ -303,11 +303,11 @@ J2KWAVEncoder::process_end () #if HAVE_SWRESAMPLE if (_swr_context) { - int mop = 0; while (1) { uint8_t buffer[256 * _fs->bytes_per_sample() * _fs->audio_channels]; - uint8_t* out[1] = { - buffer + uint8_t* out[2] = { + buffer, + 0 }; int const frames = swr_convert (_swr_context, out, 256, 0, 0); @@ -320,8 +320,7 @@ J2KWAVEncoder::process_end () break; } - mop += frames; - write_audio (buffer, frames); + write_audio (buffer, frames * _fs->bytes_per_sample() * _fs->audio_channels); } swr_free (&_swr_context); @@ -365,7 +364,7 @@ J2KWAVEncoder::process_audio (uint8_t* data, int size) int const frames = samples / _fs->audio_channels; /* Compute the resampled frame count and add 32 for luck */ - int const out_buffer_size_frames = ceil (frames * target_sample_rate() / _fs->audio_sample_rate) + 32; + int const out_buffer_size_frames = ceil (frames * _fs->target_sample_rate() / _fs->audio_sample_rate) + 32; int const out_buffer_size_bytes = out_buffer_size_frames * _fs->audio_channels * _fs->bytes_per_sample(); out_buffer = new uint8_t[out_buffer_size_bytes]; @@ -375,7 +374,7 @@ J2KWAVEncoder::process_audio (uint8_t* data, int size) }; /* Resample audio */ - int out_frames = swr_convert (_swr_context, out, out_buffer_size_frames, in, size); + int out_frames = swr_convert (_swr_context, out, out_buffer_size_frames, in, frames); if (out_frames < 0) { throw EncodeError ("could not run sample-rate converter"); } @@ -395,12 +394,12 @@ J2KWAVEncoder::process_audio (uint8_t* data, int size) void J2KWAVEncoder::write_audio (uint8_t* data, int size) { - /* Size of a sample in bytes */ - int const sample_size = 2; - - /* XXX: we are assuming that sample_size is right, the _deinterleave_buffer_size is a multiple - of the sample size and that data_size is a multiple of _fs->audio_channels * sample_size. + /* XXX: we are assuming that the _deinterleave_buffer_size is a multiple + of the sample size and that size is a multiple of _fs->audio_channels * sample_size. */ + + assert ((size % (_fs->audio_channels * _fs->bytes_per_sample())) == 0); + assert ((_deinterleave_buffer_size % _fs->bytes_per_sample()) == 0); /* XXX: this code is very tricksy and it must be possible to make it simpler ... */ @@ -412,17 +411,17 @@ J2KWAVEncoder::write_audio (uint8_t* data, int size) /* How many bytes of the deinterleaved data to do this time */ int this_time = min (remaining / _fs->audio_channels, _deinterleave_buffer_size); for (int i = 0; i < _fs->audio_channels; ++i) { - for (int j = 0; j < this_time; j += sample_size) { - for (int k = 0; k < sample_size; ++k) { + for (int j = 0; j < this_time; j += _fs->bytes_per_sample()) { + for (int k = 0; k < _fs->bytes_per_sample(); ++k) { int const to = j + k; - int const from = position + (i * sample_size) + (j * _fs->audio_channels) + k; + int const from = position + (i * _fs->bytes_per_sample()) + (j * _fs->audio_channels) + k; _deinterleave_buffer[to] = data[from]; } } switch (_fs->audio_sample_format) { case AV_SAMPLE_FMT_S16: - sf_write_short (_sound_files[i], (const short *) _deinterleave_buffer, this_time / sample_size); + sf_write_short (_sound_files[i], (const short *) _deinterleave_buffer, this_time / _fs->bytes_per_sample()); break; default: throw EncodeError ("unknown audio sample format"); @@ -434,22 +433,3 @@ J2KWAVEncoder::write_audio (uint8_t* data, int size) } } -int -J2KWAVEncoder::target_sample_rate () const -{ - double t = dcp_audio_sample_rate (_fs->audio_sample_rate); - if (rint (_fs->frames_per_second) != _fs->frames_per_second) { - if (_fs->frames_per_second == 23.976) { - /* 24fps drop-frame ie 24 * 1000 / 1001 frames per second; - hence we need to resample the audio to dcp_audio_sample_rate * 1000 / 1001 - so that when we play it back at dcp_audio_sample_rate it is sped up - by the same amount that the video is - */ - t *= double(1000) / 1001; - } else { - throw EncodeError ("unknown fractional frame rate"); - } - } - - return rint (t); -} diff --git a/src/lib/j2k_wav_encoder.h b/src/lib/j2k_wav_encoder.h index 3f01ac480..e11358c2c 100644 --- a/src/lib/j2k_wav_encoder.h +++ b/src/lib/j2k_wav_encoder.h @@ -55,8 +55,6 @@ public: private: - int target_sample_rate () const; - void write_audio (uint8_t* data, int size); void encoder_thread (ServerDescription *); void close_sound_files (); -- cgit v1.2.3 From e1e7827d75df6ea11b6bfd2aabd3eb3fb1f2e701 Mon Sep 17 00:00:00 2001 From: Carl Hetherington Date: Mon, 1 Oct 2012 22:40:09 +0100 Subject: Some more debug logging. --- src/lib/decoder.cc | 2 ++ src/lib/j2k_wav_encoder.cc | 8 ++++++++ src/lib/log.cc | 19 ++++++++++++++++++- src/lib/log.h | 4 +++- src/tools/makedcp.cc | 10 +++++++++- 5 files changed, 40 insertions(+), 3 deletions(-) (limited to 'src/lib/decoder.cc') diff --git a/src/lib/decoder.cc b/src/lib/decoder.cc index 973582ca4..19fd4f45c 100644 --- a/src/lib/decoder.cc +++ b/src/lib/decoder.cc @@ -23,6 +23,7 @@ #include #include +#include extern "C" { #include #include @@ -409,6 +410,7 @@ Decoder::process_video (AVFrame* frame) image->make_black (); } + _log->microsecond_log ("Decoder emits " + lexical_cast (_video_frame), Log::TIMING); Video (image, _video_frame); ++_video_frame; } diff --git a/src/lib/j2k_wav_encoder.cc b/src/lib/j2k_wav_encoder.cc index 9ae01c774..4deedc388 100644 --- a/src/lib/j2k_wav_encoder.cc +++ b/src/lib/j2k_wav_encoder.cc @@ -108,7 +108,9 @@ J2KWAVEncoder::process_video (shared_ptr yuv, int frame) /* Wait until the queue has gone down a bit */ while (_queue.size() >= _worker_threads.size() * 2 && !_process_end) { + _log->microsecond_log ("Decoder sleeps", Log::TIMING); _worker_condition.wait (lock); + _log->microsecond_log ("Decoder wakes", Log::TIMING); } if (_process_end) { @@ -118,6 +120,7 @@ J2KWAVEncoder::process_video (shared_ptr yuv, int frame) /* Only do the processing if we don't already have a file for this frame */ if (!boost::filesystem::exists (_opt->frame_out_path (frame, false))) { pair const s = Filter::ffmpeg_strings (_fs->filters); + _log->microsecond_log ("Adding to queue of " + boost::lexical_cast (_queue.size ()), Log::TIMING); _queue.push_back (boost::shared_ptr ( new DCPVideoFrame ( yuv, _opt->out_size, _opt->padding, _fs->scaler, frame, _fs->frames_per_second, s.second, @@ -144,7 +147,9 @@ J2KWAVEncoder::encoder_thread (ServerDescription* server) while (1) { boost::mutex::scoped_lock lock (_worker_mutex); while (_queue.empty () && !_process_end) { + _log->microsecond_log ("Encoder thread sleeps", Log::TIMING); _worker_condition.wait (lock); + _log->microsecond_log ("Encoder thread wakes", Log::TIMING); } if (_process_end) { @@ -152,6 +157,7 @@ J2KWAVEncoder::encoder_thread (ServerDescription* server) } boost::shared_ptr vf = _queue.front (); + _log->microsecond_log ("Encoder thread wakes with queue of " + boost::lexical_cast (_queue.size ()), Log::TIMING); _queue.pop_front (); lock.unlock (); @@ -183,7 +189,9 @@ J2KWAVEncoder::encoder_thread (ServerDescription* server) } else { try { + _log->microsecond_log ("Encoder thread begins local encode of " + lexical_cast (vf->frame ()), Log::TIMING); encoded = vf->encode_locally (); + _log->microsecond_log ("Encoder thread finishes local encode of " + lexical_cast (vf->frame ()), Log::TIMING); } catch (std::exception& e) { stringstream s; s << "Local encode failed " << e.what() << "."; diff --git a/src/lib/log.cc b/src/lib/log.cc index 7f1eea206..650384bc7 100644 --- a/src/lib/log.cc +++ b/src/lib/log.cc @@ -42,7 +42,7 @@ Log::log (string m, Level l) if (l > _level) { return; } - + time_t t; time (&t); string a = ctime (&t); @@ -52,6 +52,23 @@ Log::log (string m, Level l) do_log (s.str ()); } +void +Log::microsecond_log (string m, Level l) +{ + boost::mutex::scoped_lock lm (_mutex); + + if (l > _level) { + return; + } + + struct timeval tv; + gettimeofday (&tv, 0); + + stringstream s; + s << tv.tv_sec << ":" << tv.tv_usec << " " << m; + do_log (s.str ()); +} + void Log::set_level (Level l) { diff --git a/src/lib/log.h b/src/lib/log.h index 2a242e24c..2e5d69a08 100644 --- a/src/lib/log.h +++ b/src/lib/log.h @@ -37,10 +37,12 @@ public: enum Level { STANDARD = 0, - VERBOSE = 1 + VERBOSE = 1, + TIMING = 2 }; void log (std::string m, Level l = STANDARD); + void microsecond_log (std::string m, Level l = STANDARD); void set_level (Level l); diff --git a/src/tools/makedcp.cc b/src/tools/makedcp.cc index c6cb1ba14..d3608059c 100644 --- a/src/tools/makedcp.cc +++ b/src/tools/makedcp.cc @@ -34,6 +34,7 @@ #include "version.h" #include "cross.h" #include "config.h" +#include "log.h" using namespace std; using namespace boost; @@ -58,6 +59,7 @@ main (int argc, char* argv[]) string film_dir; bool test_mode = false; bool progress = true; + int log_level = 1; int option_index = 0; while (1) { @@ -68,10 +70,11 @@ main (int argc, char* argv[]) { "config", no_argument, 0, 'c'}, { "test", no_argument, 0, 't'}, { "no-progress", no_argument, 0, 'n'}, + { "log-level", required_argument, 0, 'l' }, { 0, 0, 0, 0 } }; - int c = getopt_long (argc, argv, "vhdctn", long_options, &option_index); + int c = getopt_long (argc, argv, "vhdctnl:", long_options, &option_index); if (c == -1) { break; @@ -102,6 +105,9 @@ main (int argc, char* argv[]) cout << "built in optimised mode\n"; #endif exit (EXIT_SUCCESS); + case 'l': + log_level = atoi (optarg); + break; } } @@ -134,6 +140,8 @@ main (int argc, char* argv[]) exit (EXIT_FAILURE); } + film->log()->set_level ((Log::Level) log_level); + cout << "\nMaking "; if (film->dcp_ab ()) { cout << "A/B "; -- cgit v1.2.3 From 9fdcacab9988f4cc5d44a6fab3ab294f5005f468 Mon Sep 17 00:00:00 2001 From: Carl Hetherington Date: Tue, 2 Oct 2012 15:59:39 +0100 Subject: Tidy up timing code a bit. --- analog | 53 ++++++ src/lib/compose.hpp | 393 +++++++++++++++++++++++++++++++++++++++++++++ src/lib/decoder.cc | 2 +- src/lib/j2k_wav_encoder.cc | 35 +--- src/lib/util.h | 7 + src/tools/dvdomatic.cc | 3 +- test.log | 5 + 7 files changed, 468 insertions(+), 30 deletions(-) create mode 100755 analog create mode 100644 src/lib/compose.hpp create mode 100644 test.log (limited to 'src/lib/decoder.cc') diff --git a/analog b/analog new file mode 100755 index 000000000..174300810 --- /dev/null +++ b/analog @@ -0,0 +1,53 @@ +#!/usr/bin/python + +import sys + +class Encoder: + def __init__(self): + self.awake = 0 + self.asleep = 0 + self.last_event = 0 + self.state = None + +encoders = dict() + +f = open(sys.argv[1], 'r') +while 1: + l = f.readline() + if l == '': + break + + s = l.split() + if len(s) == 0: + continue + + t = s[0].split(':') + if len(t) != 2: + continue + + secs = float(t[0]) + float(t[1]) / 1e6 + if s[1] == 'encoder' and s[2] == 'thread' and s[4] == 'finishes': + tid = s[3] + if not tid in encoders: + encoders[tid] = Encoder() + + assert(encoders[tid].state == None or encoders[tid].state == 'awake') + if encoders[tid].state == 'awake': + encoders[tid].awake += (secs - encoders[tid].last_event) + + encoders[tid].state = 'asleep' + encoders[tid].last_event = secs + + elif s[1] == 'encoder' and s[2] == 'thread' and s[4] == 'begins': + tid = s[3] + if not tid in encoders: + encoders[tid] = Encoder() + + if encoders[tid].state is not None: + encoders[tid].asleep += (secs - encoders[tid].last_event) + + encoders[tid].state = 'awake' + encoders[tid].last_event = secs + +for k, v in encoders.iteritems(): + print '%s: awake %f asleep %f' % (k, v.awake, v.asleep) diff --git a/src/lib/compose.hpp b/src/lib/compose.hpp new file mode 100644 index 000000000..b3f410c8e --- /dev/null +++ b/src/lib/compose.hpp @@ -0,0 +1,393 @@ +/* Defines String::compose(fmt, arg...) for easy, i18n-friendly + * composition of strings. + * + * Version 1.0. + * + * Copyright (c) 2002 Ole Laursen . + * + * This library is free software; you can redistribute it and/or + * modify it under the terms of the GNU Lesser General Public License + * as published by the Free Software Foundation; either version 2.1 of + * the License, or (at your option) any later version. + * + * This program 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 + * Lesser General Public License for more details. + * + * You should have received a copy of the GNU Lesser General Public + * License along with this library; if not, write to the Free Software + * Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111-1307 + * USA. + */ + +// +// Basic usage is like +// +// std::cout << String::compose("This is a %1x%2 matrix.", rows, cols); +// +// See http://www.cs.aau.dk/~olau/compose/ or the included README.compose for +// more details. +// + +#ifndef STRING_COMPOSE_H +#define STRING_COMPOSE_H + +#include +#include +#include +#include // for multimap + +namespace StringPrivate +{ + // the actual composition class - using string::compose is cleaner, so we + // hide it here + class Composition + { + public: + // initialize and prepare format string on the form "text %1 text %2 etc." + explicit Composition(std::string fmt); + + // supply an replacement argument starting from %1 + template + Composition &arg(const T &obj); + + // compose and return string + std::string str() const; + + private: + std::ostringstream os; + int arg_no; + + // we store the output as a list - when the output string is requested, the + // list is concatenated to a string; this way we can keep iterators into + // the list instead of into a string where they're possibly invalidated on + // inserting a specification string + typedef std::list output_list; + output_list output; + + // the initial parse of the format string fills in the specification map + // with positions for each of the various %?s + typedef std::multimap specification_map; + specification_map specs; + }; + + // helper for converting spec string numbers + inline int char_to_int(char c) + { + switch (c) { + case '0': return 0; + case '1': return 1; + case '2': return 2; + case '3': return 3; + case '4': return 4; + case '5': return 5; + case '6': return 6; + case '7': return 7; + case '8': return 8; + case '9': return 9; + default: return -1000; + } + } + + inline bool is_number(int n) + { + switch (n) { + case '0': + case '1': + case '2': + case '3': + case '4': + case '5': + case '6': + case '7': + case '8': + case '9': + return true; + + default: + return false; + } + } + + + // implementation of class Composition + template + inline Composition &Composition::arg(const T &obj) + { + os << obj; + + std::string rep = os.str(); + + if (!rep.empty()) { // manipulators don't produce output + for (specification_map::const_iterator i = specs.lower_bound(arg_no), + end = specs.upper_bound(arg_no); i != end; ++i) { + output_list::iterator pos = i->second; + ++pos; + + output.insert(pos, rep); + } + + os.str(std::string()); + //os.clear(); + ++arg_no; + } + + return *this; + } + + inline Composition::Composition(std::string fmt) + : arg_no(1) + { + std::string::size_type b = 0, i = 0; + + // fill in output with the strings between the %1 %2 %3 etc. and + // fill in specs with the positions + while (i < fmt.length()) { + if (fmt[i] == '%' && i + 1 < fmt.length()) { + if (fmt[i + 1] == '%') { // catch %% + fmt.replace(i, 2, "%"); + ++i; + } + else if (is_number(fmt[i + 1])) { // aha! a spec! + // save string + output.push_back(fmt.substr(b, i - b)); + + int n = 1; // number of digits + int spec_no = 0; + + do { + spec_no += char_to_int(fmt[i + n]); + spec_no *= 10; + ++n; + } while (i + n < fmt.length() && is_number(fmt[i + n])); + + spec_no /= 10; + output_list::iterator pos = output.end(); + --pos; // safe since we have just inserted a string> + + specs.insert(specification_map::value_type(spec_no, pos)); + + // jump over spec string + i += n; + b = i; + } + else + ++i; + } + else + ++i; + } + + if (i - b > 0) // add the rest of the string + output.push_back(fmt.substr(b, i - b)); + } + + inline std::string Composition::str() const + { + // assemble string + std::string str; + + for (output_list::const_iterator i = output.begin(), end = output.end(); + i != end; ++i) + str += *i; + + return str; + } +} + +// now for the real thing(s) +namespace String +{ + // a series of functions which accept a format string on the form "text %1 + // more %2 less %3" and a number of templated parameters and spits out the + // composited string + template + inline std::string compose(const std::string &fmt, const T1 &o1) + { + StringPrivate::Composition c(fmt); + c.arg(o1); + return c.str(); + } + + template + inline std::string compose(const std::string &fmt, + const T1 &o1, const T2 &o2) + { + StringPrivate::Composition c(fmt); + c.arg(o1).arg(o2); + return c.str(); + } + + template + inline std::string compose(const std::string &fmt, + const T1 &o1, const T2 &o2, const T3 &o3) + { + StringPrivate::Composition c(fmt); + c.arg(o1).arg(o2).arg(o3); + return c.str(); + } + + template + inline std::string compose(const std::string &fmt, + const T1 &o1, const T2 &o2, const T3 &o3, + const T4 &o4) + { + StringPrivate::Composition c(fmt); + c.arg(o1).arg(o2).arg(o3).arg(o4); + return c.str(); + } + + template + inline std::string compose(const std::string &fmt, + const T1 &o1, const T2 &o2, const T3 &o3, + const T4 &o4, const T5 &o5) + { + StringPrivate::Composition c(fmt); + c.arg(o1).arg(o2).arg(o3).arg(o4).arg(o5); + return c.str(); + } + + template + inline std::string compose(const std::string &fmt, + const T1 &o1, const T2 &o2, const T3 &o3, + const T4 &o4, const T5 &o5, const T6 &o6) + { + StringPrivate::Composition c(fmt); + c.arg(o1).arg(o2).arg(o3).arg(o4).arg(o5).arg(o6); + return c.str(); + } + + template + inline std::string compose(const std::string &fmt, + const T1 &o1, const T2 &o2, const T3 &o3, + const T4 &o4, const T5 &o5, const T6 &o6, + const T7 &o7) + { + StringPrivate::Composition c(fmt); + c.arg(o1).arg(o2).arg(o3).arg(o4).arg(o5).arg(o6).arg(o7); + return c.str(); + } + + template + inline std::string compose(const std::string &fmt, + const T1 &o1, const T2 &o2, const T3 &o3, + const T4 &o4, const T5 &o5, const T6 &o6, + const T7 &o7, const T8 &o8) + { + StringPrivate::Composition c(fmt); + c.arg(o1).arg(o2).arg(o3).arg(o4).arg(o5).arg(o6).arg(o7).arg(o8); + return c.str(); + } + + template + inline std::string compose(const std::string &fmt, + const T1 &o1, const T2 &o2, const T3 &o3, + const T4 &o4, const T5 &o5, const T6 &o6, + const T7 &o7, const T8 &o8, const T9 &o9) + { + StringPrivate::Composition c(fmt); + c.arg(o1).arg(o2).arg(o3).arg(o4).arg(o5).arg(o6).arg(o7).arg(o8).arg(o9); + return c.str(); + } + + template + inline std::string compose(const std::string &fmt, + const T1 &o1, const T2 &o2, const T3 &o3, + const T4 &o4, const T5 &o5, const T6 &o6, + const T7 &o7, const T8 &o8, const T9 &o9, + const T10 &o10) + { + StringPrivate::Composition c(fmt); + c.arg(o1).arg(o2).arg(o3).arg(o4).arg(o5).arg(o6).arg(o7).arg(o8).arg(o9) + .arg(o10); + return c.str(); + } + + template + inline std::string compose(const std::string &fmt, + const T1 &o1, const T2 &o2, const T3 &o3, + const T4 &o4, const T5 &o5, const T6 &o6, + const T7 &o7, const T8 &o8, const T9 &o9, + const T10 &o10, const T11 &o11) + { + StringPrivate::Composition c(fmt); + c.arg(o1).arg(o2).arg(o3).arg(o4).arg(o5).arg(o6).arg(o7).arg(o8).arg(o9) + .arg(o10).arg(o11); + return c.str(); + } + + template + inline std::string compose(const std::string &fmt, + const T1 &o1, const T2 &o2, const T3 &o3, + const T4 &o4, const T5 &o5, const T6 &o6, + const T7 &o7, const T8 &o8, const T9 &o9, + const T10 &o10, const T11 &o11, const T12 &o12) + { + StringPrivate::Composition c(fmt); + c.arg(o1).arg(o2).arg(o3).arg(o4).arg(o5).arg(o6).arg(o7).arg(o8).arg(o9) + .arg(o10).arg(o11).arg(o12); + return c.str(); + } + + template + inline std::string compose(const std::string &fmt, + const T1 &o1, const T2 &o2, const T3 &o3, + const T4 &o4, const T5 &o5, const T6 &o6, + const T7 &o7, const T8 &o8, const T9 &o9, + const T10 &o10, const T11 &o11, const T12 &o12, + const T13 &o13) + { + StringPrivate::Composition c(fmt); + c.arg(o1).arg(o2).arg(o3).arg(o4).arg(o5).arg(o6).arg(o7).arg(o8).arg(o9) + .arg(o10).arg(o11).arg(o12).arg(o13); + return c.str(); + } + + template + inline std::string compose(const std::string &fmt, + const T1 &o1, const T2 &o2, const T3 &o3, + const T4 &o4, const T5 &o5, const T6 &o6, + const T7 &o7, const T8 &o8, const T9 &o9, + const T10 &o10, const T11 &o11, const T12 &o12, + const T13 &o13, const T14 &o14) + { + StringPrivate::Composition c(fmt); + c.arg(o1).arg(o2).arg(o3).arg(o4).arg(o5).arg(o6).arg(o7).arg(o8).arg(o9) + .arg(o10).arg(o11).arg(o12).arg(o13).arg(o14); + return c.str(); + } + + template + inline std::string compose(const std::string &fmt, + const T1 &o1, const T2 &o2, const T3 &o3, + const T4 &o4, const T5 &o5, const T6 &o6, + const T7 &o7, const T8 &o8, const T9 &o9, + const T10 &o10, const T11 &o11, const T12 &o12, + const T13 &o13, const T14 &o14, const T15 &o15) + { + StringPrivate::Composition c(fmt); + c.arg(o1).arg(o2).arg(o3).arg(o4).arg(o5).arg(o6).arg(o7).arg(o8).arg(o9) + .arg(o10).arg(o11).arg(o12).arg(o13).arg(o14).arg(o15); + return c.str(); + } +} + + +#endif // STRING_COMPOSE_H diff --git a/src/lib/decoder.cc b/src/lib/decoder.cc index 19fd4f45c..e35517012 100644 --- a/src/lib/decoder.cc +++ b/src/lib/decoder.cc @@ -410,7 +410,7 @@ Decoder::process_video (AVFrame* frame) image->make_black (); } - _log->microsecond_log ("Decoder emits " + lexical_cast (_video_frame), Log::TIMING); + TIMING ("Decoder emits %1", _video_frame); Video (image, _video_frame); ++_video_frame; } diff --git a/src/lib/j2k_wav_encoder.cc b/src/lib/j2k_wav_encoder.cc index 0d786ab04..73aa1bff2 100644 --- a/src/lib/j2k_wav_encoder.cc +++ b/src/lib/j2k_wav_encoder.cc @@ -108,9 +108,9 @@ J2KWAVEncoder::process_video (shared_ptr yuv, int frame) /* Wait until the queue has gone down a bit */ while (_queue.size() >= _worker_threads.size() * 2 && !_process_end) { - _log->microsecond_log ("Decoder sleeps", Log::TIMING); + TIMING ("decoder sleeps with queue of %1", _queue.size()); _worker_condition.wait (lock); - _log->microsecond_log ("Decoder wakes", Log::TIMING); + TIMING ("decoder wakes with queue of %1", _queue.size()); } if (_process_end) { @@ -120,7 +120,7 @@ J2KWAVEncoder::process_video (shared_ptr yuv, int frame) /* Only do the processing if we don't already have a file for this frame */ if (!boost::filesystem::exists (_opt->frame_out_path (frame, false))) { pair const s = Filter::ffmpeg_strings (_fs->filters); - _log->microsecond_log ("Adding to queue of " + boost::lexical_cast (_queue.size ()), Log::TIMING); + TIMING ("adding to queue of %1", _queue.size ()); _queue.push_back (boost::shared_ptr ( new DCPVideoFrame ( yuv, _opt->out_size, _opt->padding, _fs->scaler, frame, _fs->frames_per_second, s.second, @@ -146,12 +146,7 @@ J2KWAVEncoder::encoder_thread (ServerDescription* server) while (1) { - { - stringstream s; - s << "Encoder thread " << pthread_self() << " sleeps."; - _log->microsecond_log (s.str(), Log::TIMING); - } - + TIMING ("encoder thread %1 sleeps", pthread_self ()); boost::mutex::scoped_lock lock (_worker_mutex); while (_queue.empty () && !_process_end) { _worker_condition.wait (lock); @@ -161,14 +156,8 @@ J2KWAVEncoder::encoder_thread (ServerDescription* server) return; } + TIMING ("encoder thread %1 wakes with queue of %2", pthread_self(), _queue.size()); boost::shared_ptr vf = _queue.front (); - - { - stringstream s; - s << "Encoder thread " << pthread_self() << " wakes with queue of " << _queue.size(); - _log->microsecond_log (s.str(), Log::TIMING); - } - _queue.pop_front (); lock.unlock (); @@ -200,19 +189,9 @@ J2KWAVEncoder::encoder_thread (ServerDescription* server) } else { try { - { - stringstream s; - s << "Encoder thread " << pthread_self() << " begins local encode of " << vf->frame(); - _log->microsecond_log (s.str(), Log::TIMING); - } - + TIMING ("encoder thread %1 begins local encode of %2", pthread_self(), vf->frame()); encoded = vf->encode_locally (); - - { - stringstream s; - s << "Encoder thread " << pthread_self() << " finishes local encode of " << vf->frame(); - _log->microsecond_log (s.str(), Log::TIMING); - } + TIMING ("encoder thread %1 finishes local encode of %2", pthread_self(), vf->frame()); } catch (std::exception& e) { stringstream s; s << "Local encode failed " << e.what() << "."; diff --git a/src/lib/util.h b/src/lib/util.h index bc5a00fc4..8d98437af 100644 --- a/src/lib/util.h +++ b/src/lib/util.h @@ -34,6 +34,13 @@ extern "C" { #include } +#ifdef DVDOMATIC_DEBUG +#include "compose.hpp" +#define TIMING(...) _log->microsecond_log (String::compose (__VA_ARGS__), Log::TIMING); +#else +#define TIMING(...) +#endif + class Scaler; extern std::string seconds_to_hms (int); diff --git a/src/tools/dvdomatic.cc b/src/tools/dvdomatic.cc index c42321300..9ff2c1ddc 100644 --- a/src/tools/dvdomatic.cc +++ b/src/tools/dvdomatic.cc @@ -352,11 +352,12 @@ public: info.SetName (_("DVD-o-matic")); info.SetVersion (wxT (DVDOMATIC_VERSION)); info.SetDescription (_("Free, open-source DCP generation from almost anything.")); - info.SetCopyright (_("(C) Carl Hetherington, Terrence Meiczinger, Paul Davis")); + info.SetCopyright (_("(C) Carl Hetherington, Terrence Meiczinger, Paul Davis, Ole Laursen")); wxArrayString authors; authors.Add (wxT ("Carl Hetherington")); authors.Add (wxT ("Terrence Meiczinger")); authors.Add (wxT ("Paul Davis")); + authors.Add (wxT ("Ole Laursen")); info.SetDevelopers (authors); info.SetWebSite (wxT ("http://carlh.net/software/dvdomatic")); wxAboutBox (info); diff --git a/test.log b/test.log new file mode 100644 index 000000000..31b9699bc --- /dev/null +++ b/test.log @@ -0,0 +1,5 @@ +0:0 Encoder thread 0 sleeps. +0:75 Encoder thread 0 wakes +0:100 Encoder thread 0 sleeps. +0:150 Encoder thread 0 wakes + -- cgit v1.2.3