Merge.

27 files changed, 650 insertions, 228 deletions

diff --git a/src/lib/ab_transcode_job.cc b/src/lib/ab_transcode_job.cc
index 1a6104251..d94f56d0a 100644
--- a/src/lib/ab_transcode_job.cc
+++ b/src/lib/ab_transcode_job.cc
@@ -46,9 +46,7 @@ ABTranscodeJob::ABTranscodeJob (shared_ptr<const FilmState> s, shared_ptr<const
 string
 ABTranscodeJob::name () const
 {
-	stringstream s;
-	s << "A/B transcode " << _fs->name;
-	return s.str ();
+	return String::compose ("A/B transcode %1", _fs->name);
 }
 
 void
diff --git a/src/lib/ab_transcoder.cc b/src/lib/ab_transcoder.cc
index aabaf2d03..95492a9d8 100644
--- a/src/lib/ab_transcoder.cc
+++ b/src/lib/ab_transcoder.cc
@@ -103,7 +103,7 @@ ABTranscoder::process_video (shared_ptr<Image> yuv, int frame, int index)
 void
 ABTranscoder::go ()
 {
-	_encoder->process_begin ();
+	_encoder->process_begin (_da->audio_channel_layout(), _da->audio_sample_format());
 	_da->process_begin ();
 	_db->process_begin ();
 	
diff --git a/src/lib/check_hashes_job.cc b/src/lib/check_hashes_job.cc
index 5a927f752..cf269564a 100644
--- a/src/lib/check_hashes_job.cc
+++ b/src/lib/check_hashes_job.cc
@@ -41,9 +41,7 @@ CheckHashesJob::CheckHashesJob (shared_ptr<const FilmState> s, shared_ptr<const
 string
 CheckHashesJob::name () const
 {
-	stringstream s;
-	s << "Check hashes of " << _fs->name;
-	return s.str ();
+	return String::compose ("Check hashes of %1", _fs->name);
 }
 
 void
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 <olau@hardworking.dk>.
+ *
+ * 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 <sstream>
+#include <string>
+#include <list>
+#include <map>			// 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 <typename T>
+    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<std::string> 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<int, output_list::iterator> 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 <typename T>
+  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 <typename T1>
+  inline std::string compose(const std::string &fmt, const T1 &o1)
+  {
+    StringPrivate::Composition c(fmt);
+    c.arg(o1);
+    return c.str();
+  }
+
+  template <typename T1, typename T2>
+  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 <typename T1, typename T2, typename T3>
+  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 <typename T1, typename T2, typename T3, typename T4>
+  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 <typename T1, typename T2, typename T3, typename T4, typename T5>
+  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 <typename T1, typename T2, typename T3, typename T4, typename T5,
+	    typename T6>
+  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 <typename T1, typename T2, typename T3, typename T4, typename T5,
+	    typename T6, typename T7>
+  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 <typename T1, typename T2, typename T3, typename T4, typename T5,
+	    typename T6, typename T7, typename T8>
+  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 <typename T1, typename T2, typename T3, typename T4, typename T5,
+	    typename T6, typename T7, typename T8, typename T9>
+  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 <typename T1, typename T2, typename T3, typename T4, typename T5,
+	    typename T6, typename T7, typename T8, typename T9, typename T10>
+  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 <typename T1, typename T2, typename T3, typename T4, typename T5,
+	    typename T6, typename T7, typename T8, typename T9, typename T10,
+	    typename T11>
+  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 <typename T1, typename T2, typename T3, typename T4, typename T5,
+	    typename T6, typename T7, typename T8, typename T9, typename T10,
+	    typename T11, typename T12>
+  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 <typename T1, typename T2, typename T3, typename T4, typename T5,
+	    typename T6, typename T7, typename T8, typename T9, typename T10,
+	    typename T11, typename T12, typename T13>
+  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 <typename T1, typename T2, typename T3, typename T4, typename T5,
+	    typename T6, typename T7, typename T8, typename T9, typename T10,
+	    typename T11, typename T12, typename T13, typename T14>
+  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 <typename T1, typename T2, typename T3, typename T4, typename T5,
+	    typename T6, typename T7, typename T8, typename T9, typename T10,
+	    typename T11, typename T12, typename T13, typename T14,
+	    typename T15>
+  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/dcp_video_frame.cc b/src/lib/dcp_video_frame.cc
index da7133c4b..90826a99f 100644
--- a/src/lib/dcp_video_frame.cc
+++ b/src/lib/dcp_video_frame.cc
@@ -262,11 +262,7 @@ DCPVideoFrame::encode_locally ()
 		throw EncodeError ("jpeg2000 encoding failed");
 	}
 
-	{
-		stringstream s;
-		s << "Finished locally-encoded frame " << _frame;
-		_log->log (s.str ());
-	}
+	_log->log (String::compose ("Finished locally-encoded frame %1", _frame));
 	
 	return shared_ptr<EncodedData> (new LocallyEncodedData (_cio->buffer, cio_tell (_cio)));
 }
@@ -318,11 +314,7 @@ DCPVideoFrame::encode_remotely (ServerDescription const * serv)
 	/* now read the rest */
 	socket.read_definite_and_consume (e->data(), e->size(), 30);
 
-	{
-		stringstream s;
-		s << "Finished remotely-encoded frame " << _frame;
-		_log->log (s.str ());
-	}
+	_log->log (String::compose ("Finished remotely-encoded frame %1", _frame));
 	
 	return e;
 }
diff --git a/src/lib/decoder.cc b/src/lib/decoder.cc
index 973582ca4..8aa5f77c6 100644
--- a/src/lib/decoder.cc
+++ b/src/lib/decoder.cc
@@ -23,6 +23,7 @@
 
 #include <iostream>
 #include <stdint.h>
+#include <boost/lexical_cast.hpp>
 extern "C" {
 #include <libavfilter/avfiltergraph.h>
 #include <libavfilter/buffersrc.h>
@@ -69,9 +70,6 @@ Decoder::Decoder (boost::shared_ptr<const FilmState> s, boost::shared_ptr<const
 	, _video_frame (0)
 	, _buffer_src_context (0)
 	, _buffer_sink_context (0)
-#if HAVE_SWRESAMPLE	  
-	, _swr_context (0)
-#endif	  
 	, _have_setup_video_filters (false)
 	, _delay_line (0)
 	, _delay_in_bytes (0)
@@ -91,29 +89,6 @@ Decoder::~Decoder ()
 void
 Decoder::process_begin ()
 {
-	if (_fs->audio_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 +100,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,18 +112,23 @@ 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->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;
 		}
@@ -240,16 +191,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 +226,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.
@@ -409,6 +314,7 @@ Decoder::process_video (AVFrame* frame)
 				image->make_black ();
 			}
 
+			TIMING ("Decoder emits %1", _video_frame);
 			Video (image, _video_frame);
 			++_video_frame;
 		}
diff --git a/src/lib/decoder.h b/src/lib/decoder.h
index 14b25c7b0..19ef25ede 100644
--- a/src/lib/decoder.h
+++ b/src/lib/decoder.h
@@ -29,11 +29,6 @@
 #include <stdint.h>
 #include <boost/shared_ptr.hpp>
 #include <sigc++/sigc++.h>
-#ifdef HAVE_SWRESAMPLE
-extern "C" {
-#include <libswresample/swresample.h>
-}
-#endif
 #include "util.h"
 
 class Job;
@@ -134,10 +129,6 @@ private:
 	AVFilterContext* _buffer_src_context;
 	AVFilterContext* _buffer_sink_context;
 
-#if HAVE_SWRESAMPLE	
-	SwrContext* _swr_context;
-#endif	
-
 	bool _have_setup_video_filters;
 	DelayLine* _delay_line;
 	int _delay_in_bytes;
diff --git a/src/lib/encoder.h b/src/lib/encoder.h
index 539b2912c..ea356cec4 100644
--- a/src/lib/encoder.h
+++ b/src/lib/encoder.h
@@ -28,6 +28,9 @@
 #include <boost/thread/mutex.hpp>
 #include <list>
 #include <stdint.h>
+extern "C" {
+#include <libavutil/samplefmt.h>
+}
 
 class FilmState;
 class Options;
@@ -50,7 +53,7 @@ public:
 	Encoder (boost::shared_ptr<const FilmState> s, boost::shared_ptr<const Options> o, Log* l);
 
 	/** Called to indicate that a processing run is about to begin */
-	virtual void process_begin () = 0;
+	virtual void process_begin (int64_t audio_channel_layout, AVSampleFormat audio_sample_format) = 0;
 
 	/** Called with a frame of video.
 	 *  @param i Video frame image.
diff --git a/src/lib/examine_content_job.cc b/src/lib/examine_content_job.cc
index 6927715bd..d77ede2f9 100644
--- a/src/lib/examine_content_job.cc
+++ b/src/lib/examine_content_job.cc
@@ -43,9 +43,7 @@ ExamineContentJob::~ExamineContentJob ()
 string
 ExamineContentJob::name () const
 {
-	stringstream s;
-	s << "Examine content of " << _fs->name;
-	return s.str ();
+	return String::compose ("Examine content of %1", _fs->name);
 }
 
 void
diff --git a/src/lib/film.cc b/src/lib/film.cc
index 583a15e19..2db03f6a6 100644
--- a/src/lib/film.cc
+++ b/src/lib/film.cc
@@ -49,6 +49,7 @@
 #include "decoder_factory.h"
 #include "config.h"
 #include "check_hashes_job.h"
+#include "version.h"
 
 using namespace std;
 using namespace boost;
@@ -483,18 +484,12 @@ Film::make_dcp (bool transcode, int freq)
 		throw BadSettingError ("name", "cannot contain slashes");
 	}
 	
-	{
-		stringstream s;
-		s << "DVD-o-matic " << DVDOMATIC_VERSION << " using " << dependency_version_summary ();
-		log()->log (s.str ());
-	}
+	log()->log (String::compose ("DVD-o-matic %1 git %2 using %3", dvdomatic_version, dvdomatic_git_commit, dependency_version_summary()));
 
 	{
 		char buffer[128];
 		gethostname (buffer, sizeof (buffer));
-		stringstream s;
-		s << "Starting to make a DCP on " << buffer;
-		log()->log (s.str ());
+		log()->log (String::compose ("Starting to make DCP on %1", buffer));
 	}
 		
 	if (format() == 0) {
diff --git a/src/lib/film_state.cc b/src/lib/film_state.cc
index e472434ce..d7d9a1462 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 || (fabs (frames_per_second - 29.97) < 1e-6)) {
+			/* 24fps or 30fps drop-frame ie {24,30} * 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_still_encoder.h b/src/lib/j2k_still_encoder.h
index d4d68724e..755c68877 100644
--- a/src/lib/j2k_still_encoder.h
+++ b/src/lib/j2k_still_encoder.h
@@ -36,7 +36,7 @@ class J2KStillEncoder : public Encoder
 public:
 	J2KStillEncoder (boost::shared_ptr<const FilmState>, boost::shared_ptr<const Options>, Log *);
 
-	void process_begin () {}
+	void process_begin (int64_t audio_channel_layout, AVSampleFormat audio_sample_format) {}
 	void process_video (boost::shared_ptr<Image>, int);
 	void process_audio (uint8_t *, int) {}
 	void process_end () {}
diff --git a/src/lib/j2k_wav_encoder.cc b/src/lib/j2k_wav_encoder.cc
index 9ae01c774..2f892948d 100644
--- a/src/lib/j2k_wav_encoder.cc
+++ b/src/lib/j2k_wav_encoder.cc
@@ -46,6 +46,9 @@ using namespace boost;
 
 J2KWAVEncoder::J2KWAVEncoder (shared_ptr<const FilmState> s, shared_ptr<const Options> o, Log* l)
 	: Encoder (s, o, l)
+#ifdef HAVE_SWRESAMPLE	  
+	, _swr_context (0)
+#endif	  
 	, _deinterleave_buffer_size (8192)
 	, _deinterleave_buffer (0)
 	, _process_end (false)
@@ -108,7 +111,9 @@ J2KWAVEncoder::process_video (shared_ptr<Image> yuv, int frame)
 
 	/* Wait until the queue has gone down a bit */
 	while (_queue.size() >= _worker_threads.size() * 2 && !_process_end) {
+		TIMING ("decoder sleeps with queue of %1", _queue.size());
 		_worker_condition.wait (lock);
+		TIMING ("decoder wakes with queue of %1", _queue.size());
 	}
 
 	if (_process_end) {
@@ -118,6 +123,7 @@ J2KWAVEncoder::process_video (shared_ptr<Image> 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<string, string> const s = Filter::ffmpeg_strings (_fs->filters);
+		TIMING ("adding to queue of %1", _queue.size ());
 		_queue.push_back (boost::shared_ptr<DCPVideoFrame> (
 					  new DCPVideoFrame (
 						  yuv, _opt->out_size, _opt->padding, _fs->scaler, frame, _fs->frames_per_second, s.second,
@@ -142,6 +148,8 @@ J2KWAVEncoder::encoder_thread (ServerDescription* server)
 	int remote_backoff = 0;
 	
 	while (1) {
+
+		TIMING ("encoder thread %1 sleeps", pthread_self ());
 		boost::mutex::scoped_lock lock (_worker_mutex);
 		while (_queue.empty () && !_process_end) {
 			_worker_condition.wait (lock);
@@ -151,7 +159,9 @@ J2KWAVEncoder::encoder_thread (ServerDescription* server)
 			return;
 		}
 
+		TIMING ("encoder thread %1 wakes with queue of %2", pthread_self(), _queue.size());
 		boost::shared_ptr<DCPVideoFrame> vf = _queue.front ();
+		_log->log (String::compose ("Encoder thread %1 pops frame %2 from queue", pthread_self(), vf->frame()));
 		_queue.pop_front ();
 		
 		lock.unlock ();
@@ -163,9 +173,7 @@ J2KWAVEncoder::encoder_thread (ServerDescription* server)
 				encoded = vf->encode_remotely (server);
 
 				if (remote_backoff > 0) {
-					stringstream s;
-					s << server->host_name() << " was lost, but now she is found; removing backoff";
-					_log->log (s.str ());
+					_log->log (String::compose ("%1 was lost, but now she is found; removing backoff", server->host_name ()));
 				}
 				
 				/* This job succeeded, so remove any backoff */
@@ -176,18 +184,20 @@ J2KWAVEncoder::encoder_thread (ServerDescription* server)
 					/* back off more */
 					remote_backoff += 10;
 				}
-				stringstream s;
-				s << "Remote encode of " << vf->frame() << " on " << server->host_name() << " failed (" << e.what() << "); thread sleeping for " << remote_backoff << "s.";
-				_log->log (s.str ());
+				_log->log (
+					String::compose (
+						"Remote encode of %1 on %2 failed (%3); thread sleeping for %4s",
+						vf->frame(), server->host_name(), e.what(), remote_backoff)
+					);
 			}
 				
 		} else {
 			try {
+				TIMING ("encoder thread %1 begins local encode of %2", pthread_self(), vf->frame());
 				encoded = vf->encode_locally ();
+				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() << ".";
-				_log->log (s.str ());
+				_log->log (String::compose ("Local encode failed (%1)", e.what ()));
 			}
 		}
 
@@ -196,6 +206,7 @@ J2KWAVEncoder::encoder_thread (ServerDescription* server)
 			frame_done (vf->frame ());
 		} else {
 			lock.lock ();
+			_log->log (String::compose ("Encoder thread %1 pushes frame %2 back onto queue after failure", pthread_self(), vf->frame()));
 			_queue.push_front (vf);
 			lock.unlock ();
 		}
@@ -210,8 +221,36 @@ J2KWAVEncoder::encoder_thread (ServerDescription* server)
 }
 
 void
-J2KWAVEncoder::process_begin ()
+J2KWAVEncoder::process_begin (int64_t audio_channel_layout, AVSampleFormat audio_sample_format)
 {
+	if (_fs->audio_sample_rate != _fs->target_sample_rate ()) {
+#ifdef HAVE_SWRESAMPLE
+
+		stringstream s;
+		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,
+			_fs->target_sample_rate(),
+			audio_channel_layout,
+			audio_sample_format,
+			_fs->audio_sample_rate,
+			0, 0
+			);
+		
+		swr_init (_swr_context);
+#else
+		throw EncodeError ("Cannot resample audio as libswresample is not present");
+#endif
+	} else {
+#ifdef HAVE_SWRESAMPLE
+		_swr_context = 0;
+#endif		
+	}
+	
 	for (int i = 0; i < Config::instance()->num_local_encoding_threads (); ++i) {
 		_worker_threads.push_back (new boost::thread (boost::bind (&J2KWAVEncoder::encoder_thread, this, (ServerDescription *) 0)));
 	}
@@ -255,19 +294,42 @@ J2KWAVEncoder::process_end ()
 	*/
 
 	for (list<shared_ptr<DCPVideoFrame> >::iterator i = _queue.begin(); i != _queue.end(); ++i) {
-		stringstream s;
-		s << "Encode left-over frame " << (*i)->frame();
-		_log->log (s.str ());
+		_log->log (String::compose ("Encode left-over frame %1", (*i)->frame ()));
 		try {
 			shared_ptr<EncodedData> e = (*i)->encode_locally ();
 			e->write (_opt, (*i)->frame ());
 			frame_done ((*i)->frame ());
 		} catch (std::exception& e) {
-			stringstream s;
-			s << "Local encode failed " << e.what() << ".";
-			_log->log (s.str ());
+			_log->log (String::compose ("Local encode failed (%1)", e.what ()));
+		}
+	}
+
+#if HAVE_SWRESAMPLE	
+	if (_swr_context) {
+
+		while (1) {
+			uint8_t buffer[256 * _fs->bytes_per_sample() * _fs->audio_channels];
+			uint8_t* out[2] = {
+				buffer,
+				0
+			};
+
+			int const frames = swr_convert (_swr_context, out, 256, 0, 0);
+
+			if (frames < 0) {
+				throw EncodeError ("could not run sample-rate converter");
+			}
+
+			if (frames == 0) {
+				break;
+			}
+
+			write_audio (buffer, frames * _fs->bytes_per_sample() * _fs->audio_channels);
 		}
+
+		swr_free (&_swr_context);
 	}
+#endif	
 	
 	close_sound_files ();
 
@@ -281,39 +343,92 @@ J2KWAVEncoder::process_end ()
 }
 
 void
-J2KWAVEncoder::process_audio (uint8_t* data, int data_size)
+J2KWAVEncoder::process_audio (uint8_t* data, int size)
 {
-	/* Size of a sample in bytes */
-	int const sample_size = 2;
+	/* This is a buffer we might use if we are sample-rate converting;
+	   it will need freeing if so.
+	*/
+	uint8_t* out_buffer = 0;
 	
-	/* 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.
+	/* Maybe sample-rate convert */
+#if HAVE_SWRESAMPLE	
+	if (_swr_context) {
+
+		uint8_t const * in[2] = {
+			data,
+			0
+		};
+
+		/* Here's samples per channel */
+		int const samples = size / _fs->bytes_per_sample();
+		
+		/* 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;
+
+		/* Compute the resampled frame count and add 32 for luck */
+		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];
+
+		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 EncodeError ("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
+
+	write_audio (data, size);
+
+	/* Delete the sample-rate conversion buffer, if it exists */
+	delete[] out_buffer;
+}
+
+void
+J2KWAVEncoder::write_audio (uint8_t* data, int 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 ... */
 	
 	/* Number of bytes left to read this time */
-	int remaining = data_size;
+	int remaining = size;
 	/* Our position in the output buffers, in bytes */
 	int position = 0;
 	while (remaining > 0) {
 		/* 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 DecodeError ("unknown audio sample format");
+				throw EncodeError ("unknown audio sample format");
 			}
 		}
 		
@@ -321,3 +436,4 @@ J2KWAVEncoder::process_audio (uint8_t* data, int data_size)
 		remaining -= this_time * _fs->audio_channels;
 	}
 }
+
diff --git a/src/lib/j2k_wav_encoder.h b/src/lib/j2k_wav_encoder.h
index 1c2f50065..e11358c2c 100644
--- a/src/lib/j2k_wav_encoder.h
+++ b/src/lib/j2k_wav_encoder.h
@@ -26,6 +26,11 @@
 #include <boost/thread/condition.hpp>
 #include <boost/thread/mutex.hpp>
 #include <boost/thread.hpp>
+#ifdef HAVE_SWRESAMPLE
+extern "C" {
+#include <libswresample/swresample.h>
+}
+#endif
 #include <sndfile.h>
 #include "encoder.h"
 
@@ -43,17 +48,22 @@ public:
 	J2KWAVEncoder (boost::shared_ptr<const FilmState>, boost::shared_ptr<const Options>, Log *);
 	~J2KWAVEncoder ();
 
-	void process_begin ();
+	void process_begin (int64_t audio_channel_layout, AVSampleFormat audio_sample_format);
 	void process_video (boost::shared_ptr<Image>, int);
 	void process_audio (uint8_t *, int);
 	void process_end ();
 
-private:	
+private:
 
+	void write_audio (uint8_t* data, int size);
 	void encoder_thread (ServerDescription *);
 	void close_sound_files ();
 	void terminate_worker_threads ();
 
+#if HAVE_SWRESAMPLE	
+	SwrContext* _swr_context;
+#endif	
+
 	std::vector<SNDFILE*> _sound_files;
 	int _deinterleave_buffer_size;
 	uint8_t* _deinterleave_buffer;
diff --git a/src/lib/job.cc b/src/lib/job.cc
index 22754eb90..39ce4173a 100644
--- a/src/lib/job.cc
+++ b/src/lib/job.cc
@@ -41,6 +41,7 @@ Job::Job (shared_ptr<const FilmState> s, shared_ptr<const Options> o, Log* l)
 	, _state (NEW)
 	, _start_time (0)
 	, _progress_unknown (false)
+	, _ran_for (0)
 {
 	assert (_log);
 	
@@ -68,9 +69,7 @@ Job::run_wrapper ()
 		
 		set_progress (1);
 		set_state (FINISHED_ERROR);
-		stringstream s;
-		s << e.what() << "(" << filesystem::path (e.filename()).leaf() << ")";
-		set_error (s.str ());
+		set_error (String::compose ("%1 (%2)", e.what(), filesystem::path (e.filename()).leaf()));
 		
 	} catch (std::exception& e) {
 
@@ -121,6 +120,10 @@ Job::set_state (State s)
 {
 	boost::mutex::scoped_lock lm (_state_mutex);
 	_state = s;
+
+	if (_state == FINISHED_OK || _state == FINISHED_ERROR) {
+		_ran_for = elapsed_time ();
+	}
 }
 
 /** A hack to work around our lack of cross-thread
@@ -245,7 +248,7 @@ Job::status () const
 	} else if (!finished () && (t <= 10 || r == 0)) {
 		s << rint (p * 100) << "%";
 	} else if (finished_ok ()) {
-		s << "OK (ran for " << seconds_to_hms (t) << ")";
+		s << "OK (ran for " << seconds_to_hms (_ran_for) << ")";
 	} else if (finished_in_error ()) {
 		s << "Error (" << error() << ")";
 	}
diff --git a/src/lib/job.h b/src/lib/job.h
index b39130479..802bf468d 100644
--- a/src/lib/job.h
+++ b/src/lib/job.h
@@ -119,6 +119,8 @@ private:
 
 	/** true if this job's progress will always be unknown */
 	bool _progress_unknown;
+
+	int _ran_for;
 };
 
 #endif
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);
@@ -53,6 +53,23 @@ Log::log (string m, Level l)
 }
 
 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)
 {
 	boost::mutex::scoped_lock lm (_mutex);
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/lib/make_dcp_job.cc b/src/lib/make_dcp_job.cc
index 8d3547cae..ae4bb4fbe 100644
--- a/src/lib/make_dcp_job.cc
+++ b/src/lib/make_dcp_job.cc
@@ -52,9 +52,7 @@ MakeDCPJob::MakeDCPJob (shared_ptr<const FilmState> s, shared_ptr<const Options>
 string
 MakeDCPJob::name () const
 {
-	stringstream s;
-	s << "Make DCP for " << _fs->name;
-	return s.str ();
+	return String::compose ("Make DCP for %1", _fs->name);
 }
 
 string
diff --git a/src/lib/scp_dcp_job.cc b/src/lib/scp_dcp_job.cc
index f62d2db8d..dac4a602c 100644
--- a/src/lib/scp_dcp_job.cc
+++ b/src/lib/scp_dcp_job.cc
@@ -78,9 +78,7 @@ public:
 	{
 		scp = ssh_scp_new (s, SSH_SCP_WRITE | SSH_SCP_RECURSIVE, Config::instance()->tms_path().c_str ());
 		if (!scp) {
-			stringstream s;
-			s << "Could not start SCP session (" << ssh_get_error (s) << ")";
-			throw NetworkError (s.str ());
+			throw NetworkError (String::compose ("Could not start SCP session (%1)", ssh_get_error (s)));
 		}
 	}
 
@@ -103,9 +101,7 @@ SCPDCPJob::SCPDCPJob (shared_ptr<const FilmState> s, Log* l)
 string
 SCPDCPJob::name () const
 {
-	stringstream s;
-	s << "Copy DCP to TMS";
-	return s.str ();
+	return "Copy DCP to TMS";
 }
 
 void
@@ -124,39 +120,29 @@ SCPDCPJob::run ()
 	
 	int r = ss.connect ();
 	if (r != SSH_OK) {
-		stringstream s;
-		s << "Could not connect to server " << Config::instance()->tms_ip() << " (" << ssh_get_error (ss.session) << ")";
-		throw NetworkError (s.str ());
+		throw NetworkError (String::compose ("Could not connect to server %1 (%2)", Config::instance()->tms_ip(), ssh_get_error (ss.session)));
 	}
 	
 	int const state = ssh_is_server_known (ss.session);
 	if (state == SSH_SERVER_ERROR) {
-		stringstream s;
-		s << "SSH error (" << ssh_get_error (ss.session) << ")";
-		throw NetworkError (s.str ());
+		throw NetworkError (String::compose ("SSH error (%1)", ssh_get_error (ss.session)));
 	}
 	
 	r = ssh_userauth_password (ss.session, 0, Config::instance()->tms_password().c_str ());
 	if (r != SSH_AUTH_SUCCESS) {
-		stringstream s;
-		s << "Failed to authenticate with server (" << ssh_get_error (ss.session) << ")";
-		throw NetworkError (s.str ());
+		throw NetworkError (String::compose ("Failed to authenticate with server (%1)", ssh_get_error (ss.session)));
 	}
 	
 	SSHSCP sc (ss.session);
 	
 	r = ssh_scp_init (sc.scp);
 	if (r != SSH_OK) {
-		stringstream s;
-		s << "Could not start SCP session (" << ssh_get_error (ss.session) << ")";
-		throw NetworkError (s.str ());
+		throw NetworkError (String::compose ("Could not start SCP session (%1)", ssh_get_error (ss.session)));
 	}
 	
 	r = ssh_scp_push_directory (sc.scp, _fs->name.c_str(), S_IRWXU);
 	if (r != SSH_OK) {
-		stringstream s;
-		s << "Could not create remote directory " << _fs->name << "(" << ssh_get_error (ss.session) << ")";
-		throw NetworkError (s.str ());
+		throw NetworkError (String::compose ("Could not create remote directory %1 (%2)", _fs->name, ssh_get_error (ss.session)));
 	}
 	
 	string const dcp_dir = _fs->dir (_fs->name);
@@ -186,9 +172,7 @@ SCPDCPJob::run ()
 
 		FILE* f = fopen (filesystem::path (*i).string().c_str(), "rb");
 		if (f == 0) {
-			stringstream s;
-			s << "Could not open " << *i << " to send";
-			throw NetworkError (s.str ());
+			throw NetworkError (String::compose ("Could not open %1 to send", *i));
 		}
 
 		while (to_do > 0) {
@@ -200,9 +184,7 @@ SCPDCPJob::run ()
 			
 			r = ssh_scp_write (sc.scp, buffer, t);
 			if (r != SSH_OK) {
-				stringstream s;
-				s << "Could not write to remote file (" << ssh_get_error (ss.session) << ")";
-				throw NetworkError (s.str ());
+				throw NetworkError (String::compose ("Could not write to remote file (%1)", ssh_get_error (ss.session)));
 			}
 			to_do -= t;
 			bytes_transferred += t;
diff --git a/src/lib/server.cc b/src/lib/server.cc
index f8c4425d9..28236e3e0 100644
--- a/src/lib/server.cc
+++ b/src/lib/server.cc
@@ -163,9 +163,7 @@ Server::worker_thread ()
 		if (frame >= 0) {
 			struct timeval end;
 			gettimeofday (&end, 0);
-			stringstream s;
-			s << "Encoded frame " << frame << " in " << (seconds (end) - seconds (start));
-			_log->log (s.str ());
+			_log->log (String::compose ("Encoded frame %1 in %2", frame, seconds (end) - seconds (start)));
 		}
 		
 		_worker_condition.notify_all ();
@@ -175,9 +173,7 @@ Server::worker_thread ()
 void
 Server::run (int num_threads)
 {
-	stringstream s;
-	s << "Server starting with " << num_threads << " threads.";
-	_log->log (s.str ());
+	_log->log (String::compose ("Server starting with %1 threads", num_threads));
 	
 	for (int i = 0; i < num_threads; ++i) {
 		_worker_threads.push_back (new thread (bind (&Server::worker_thread, this)));
diff --git a/src/lib/thumbs_job.cc b/src/lib/thumbs_job.cc
index 0eb116fd1..f6ed75ff7 100644
--- a/src/lib/thumbs_job.cc
+++ b/src/lib/thumbs_job.cc
@@ -44,9 +44,7 @@ ThumbsJob::ThumbsJob (shared_ptr<const FilmState> s, shared_ptr<const Options> o
 string
 ThumbsJob::name () const
 {
-	stringstream s;
-	s << "Update thumbs for " << _fs->name;
-	return s.str ();
+	return String::compose ("Update thumbs for %1", _fs->name);
 }
 
 void
diff --git a/src/lib/tiff_encoder.h b/src/lib/tiff_encoder.h
index ec8e38011..ef1ce25d2 100644
--- a/src/lib/tiff_encoder.h
+++ b/src/lib/tiff_encoder.h
@@ -36,7 +36,7 @@ class TIFFEncoder : public Encoder
 public:
 	TIFFEncoder (boost::shared_ptr<const FilmState> s, boost::shared_ptr<const Options> o, Log* l);
 
-	void process_begin () {}
+	void process_begin (int64_t audio_channel_layout, AVSampleFormat audio_sample_format) {}
 	void process_video (boost::shared_ptr<Image>, int);
 	void process_audio (uint8_t *, int) {}
 	void process_end () {}
diff --git a/src/lib/transcode_job.cc b/src/lib/transcode_job.cc
index 9113593f0..e79be09fe 100644
--- a/src/lib/transcode_job.cc
+++ b/src/lib/transcode_job.cc
@@ -48,9 +48,7 @@ TranscodeJob::TranscodeJob (shared_ptr<const FilmState> s, shared_ptr<const Opti
 string
 TranscodeJob::name () const
 {
-	stringstream s;
-	s << "Transcode " << _fs->name;
-	return s.str ();
+	return String::compose ("Transcode %1", _fs->name);
 }
 
 void
@@ -70,12 +68,9 @@ TranscodeJob::run ()
 
 	} catch (std::exception& e) {
 
-		stringstream s;
 		set_progress (1);
 		set_state (FINISHED_ERROR);
-
-		s << "Transcode job failed (" << e.what() << ")";
-		_log->log (s.str ());
+		_log->log (String::compose ("Transcode job failed (%1)", e.what()));
 
 		throw;
 	}
diff --git a/src/lib/transcoder.cc b/src/lib/transcoder.cc
index 3d71b68f5..b74d09174 100644
--- a/src/lib/transcoder.cc
+++ b/src/lib/transcoder.cc
@@ -57,7 +57,7 @@ Transcoder::Transcoder (shared_ptr<const FilmState> s, shared_ptr<const Options>
 void
 Transcoder::go ()
 {
-	_encoder->process_begin ();
+	_encoder->process_begin (_decoder->audio_channel_layout(), _decoder->audio_sample_format());
 	try {
 		_decoder->go ();
 	} catch (...) {
diff --git a/src/lib/util.h b/src/lib/util.h
index bc5a00fc4..3eac06e97 100644
--- a/src/lib/util.h
+++ b/src/lib/util.h
@@ -33,6 +33,13 @@ extern "C" {
 #include <libavcodec/avcodec.h>
 #include <libavfilter/avfilter.h>
 }
+#include "compose.hpp"
+
+#ifdef DVDOMATIC_DEBUG
+#define TIMING(...) _log->microsecond_log (String::compose (__VA_ARGS__), Log::TIMING);
+#else
+#define TIMING(...)
+#endif
 
 class Scaler;