Merge.

40 files changed, 775 insertions, 249 deletions

diff --git a/.be/aff5ca2c-44ee-4ed6-800b-4abe9c3e794c/bugs/666e8ba3-f1a3-4245-9d00-9a3a5e048ed9/values b/.be/aff5ca2c-44ee-4ed6-800b-4abe9c3e794c/bugs/666e8ba3-f1a3-4245-9d00-9a3a5e048ed9/values
index 8861f1d19..26a0240ff 100644
--- a/.be/aff5ca2c-44ee-4ed6-800b-4abe9c3e794c/bugs/666e8ba3-f1a3-4245-9d00-9a3a5e048ed9/values
+++ b/.be/aff5ca2c-44ee-4ed6-800b-4abe9c3e794c/bugs/666e8ba3-f1a3-4245-9d00-9a3a5e048ed9/values
@@ -7,7 +7,7 @@ reporter: Carl Hetherington <cth@carlh.net>
 severity: minor
 
 
-status: open
+status: fixed
 
 
 summary: Re-setting content file runs thumb scan twice?
diff --git a/ChangeLog b/ChangeLog
index b260b8745..d34b781b6 100644
--- a/ChangeLog
+++ b/ChangeLog
@@ -1,3 +1,22 @@
+2012-10-02  Carl Hetherington  <cth@carlh.net>
+
+	* Version 0.54 released.
+
+2012-10-02  Carl Hetherington  <cth@carlh.net>
+
+	* When encoding 24 frames per second drop
+	frame (ie 23.976 frames per second) run the
+	video at 24 FPS and resample the audio so
+	that when it is run correspondingly (slightly) fast
+	it remains in sync.
+
+	* Some code cleanup.
+
+2012-10-01  Carl Hetherington  <cth@carlh.net>
+
+	* Fix aff/666: thumbnail scan is run twice
+	when changing the content file for a film.
+
 2012-09-28  Carl Hetherington  <cth@carlh.net>
 
 	* Fix crash bug which seems to have been
diff --git a/TODO b/TODO
index 221d2c285..0a120fa47 100644
--- a/TODO
+++ b/TODO
@@ -1,4 +1,26 @@
 Look at http://liblqr.wikidot.com/en:manual
+
+EC2
+
+Small instance $0.085 ph
+Sintel Trailer 1080p @ 200000 Mbps
+1247 frames @ 24fps ie 51.96s
+Took 1h20 to encode
+
+High-CPU medium $0.186 ph
+Sintel Trailer 1080p @ 200000 Mbps
+1247 frames @ 24fps ie 51.96s
+Took 23m to encode
+
+High-CPU extra-large $0.744 ph
+Sintel Trailer 1080p @ 200000 Mbps
+1247 frames @ 24fps ie 51.96s
+
+
+Transfer in free
+Transfer out $0.120 per GB
+
+
 Port DVD rip
 
 Write still j2ks straight to a MXF.
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/builds/ubuntu-12.04-64 b/builds/ubuntu-12.04-64
index 5f0185087..e5899ebd7 100755
--- a/builds/ubuntu-12.04-64
+++ b/builds/ubuntu-12.04-64
@@ -3,14 +3,14 @@
 export DEST=dvdomatic-ubuntu-12.04-64
 export ENV=/home/carl/Environments/ubuntu-12.04-64
 
-#./waf clean
+./waf clean
 
 export PATH=$ENV/bin:$PATH
 export PKG_CONFIG_LIBDIR=$ENV/lib/pkgconfig:/usr/lib/pkgconfig:/usr/lib/x86_64-linux-gnu/pkgconfig:/usr/share/pkgconfig
 
 CXXFLAGS="-I$ENV_PREFIX/include" \
   LINKFLAGS="-L$ENV_PREFIX/lib" \
-  ./waf configure --enable-debug
+  ./waf configure
 
 ./waf
 
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;
 
diff --git a/src/tools/dvdomatic.cc b/src/tools/dvdomatic.cc
index c42321300..23cf216ca 100644
--- a/src/tools/dvdomatic.cc
+++ b/src/tools/dvdomatic.cc
@@ -38,6 +38,7 @@
 #include "lib/util.h"
 #include "lib/scaler.h"
 #include "lib/exceptions.h"
+#include "lib/version.h"
 
 using namespace std;
 using namespace boost;
@@ -350,13 +351,14 @@ public:
 	{
 		wxAboutDialogInfo info;
 		info.SetName (_("DVD-o-matic"));
-		info.SetVersion (wxT (DVDOMATIC_VERSION));
+		info.SetVersion (std_to_wx (String::compose ("DVD-o-matic version %1 git %2", dvdomatic_version, dvdomatic_git_commit)));
 		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/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 ";
diff --git a/src/wx/film_editor.cc b/src/wx/film_editor.cc
index 6de3af9e7..9171daa5c 100644
--- a/src/wx/film_editor.cc
+++ b/src/wx/film_editor.cc
@@ -289,9 +289,7 @@ FilmEditor::content_changed (wxCommandEvent &)
 		_film->set_content (wx_to_std (_content->GetPath ()));
 	} catch (std::exception& e) {
 		_content->SetPath (std_to_wx (_film->directory ()));
-		stringstream m;
-		m << "Could not set content: " << e.what() << ".";
-		error_dialog (this, m.str ());
+		error_dialog (this, String::compose ("Could not set content: %1", e.what ()));
 	}
 
 	_ignore_changes = Film::NONE;
diff --git a/src/wx/film_viewer.cc b/src/wx/film_viewer.cc
index 0d17baf83..e647a5886 100644
--- a/src/wx/film_viewer.cc
+++ b/src/wx/film_viewer.cc
@@ -171,7 +171,7 @@ END_EVENT_TABLE ()
 
 FilmViewer::FilmViewer (Film* f, wxWindow* p)
 	: wxPanel (p)
-	, _film (f)
+	, _film (0)
 {
 	_sizer = new wxBoxSizer (wxVERTICAL);
 	SetSizer (_sizer);
@@ -232,6 +232,10 @@ FilmViewer::film_changed (Film::Property p)
 void
 FilmViewer::set_film (Film* f)
 {
+	if (_film == f) {
+		return;
+	}
+	
 	_film = f;
 	_thumb_panel->set_film (_film);
 
diff --git a/src/wx/job_manager_view.cc b/src/wx/job_manager_view.cc
index 1d5c855ea..97da3936f 100644
--- a/src/wx/job_manager_view.cc
+++ b/src/wx/job_manager_view.cc
@@ -111,9 +111,7 @@ JobManagerView::update ()
 			try {
 				(*i)->emit_finished ();
 			} catch (OpenFileError& e) {
-				stringstream s;
-				s << "Error: " << e.what();
-				error_dialog (this, s.str ());
+				error_dialog (this, String::compose ("Error: %1", e.what ()));
 			}
 			
 			_job_records[*i].informed_of_finish = true;
diff --git a/src/wx/job_wrapper.cc b/src/wx/job_wrapper.cc
index ad83aa271..cc7507547 100644
--- a/src/wx/job_wrapper.cc
+++ b/src/wx/job_wrapper.cc
@@ -35,12 +35,8 @@ JobWrapper::make_dcp (wxWindow* parent, Film* film, bool transcode)
 	try {
 		film->make_dcp (transcode);
 	} catch (BadSettingError& e) {
-		stringstream s;
-		s << "Bad setting for " << e.setting() << "(" << e.what() << ")";
-		error_dialog (parent, s.str ());
+		error_dialog (parent, String::compose ("Bad setting for %1 (%2)", e.setting(), e.what ()));
 	} catch (std::exception& e) {
-		stringstream s;
-		s << "Could not make DCP: " << e.what () << ".";
-		error_dialog (parent, s.str ());
+		error_dialog (parent, String::compose ("Could not make DCP: %1", e.what ()));
 	}
 }
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
+
diff --git a/wscript b/wscript
index 7f6c3722f..cb284b126 100644
--- a/wscript
+++ b/wscript
@@ -3,7 +3,7 @@ import os
 import sys
 
 APPNAME = 'dvdomatic'
-VERSION = '0.54pre'
+VERSION = '0.55pre'
 
 def options(opt):
     opt.load('compiler_cxx')
@@ -20,7 +20,6 @@ def configure(conf):
         conf.load('winres')
 
     conf.env.append_value('CXXFLAGS', ['-D__STDC_CONSTANT_MACROS', '-msse', '-mfpmath=sse', '-ffast-math', '-fno-strict-aliasing', '-Wall', '-Wno-attributes'])
-    conf.env.append_value('CXXFLAGS', ['-DDVDOMATIC_VERSION="%s"' % VERSION])
 
     # Turn off player for now
     conf.options.disable_player = True