Tidy up timing code a bit.

diff --git a/analog b/analog
new file mode 100755 (executable)
index 0000000..1743008
--- /dev/null
+++ b/analog
@@ -0,0 +1,53 @@
+#!/usr/bin/python
+
+import sys
+
+class Encoder:
+      def __init__(self):
+            self.awake = 0
+            self.asleep = 0
+            self.last_event = 0
+            self.state = None
+
+encoders = dict()
+
+f = open(sys.argv[1], 'r')
+while 1:
+      l = f.readline()
+      if l == '':
+        break
+
+      s = l.split()
+      if len(s) == 0:
+            continue
+
+      t = s[0].split(':')
+      if len(t) != 2:
+            continue
+
+      secs = float(t[0]) + float(t[1]) / 1e6
+      if s[1] == 'encoder' and s[2] == 'thread' and s[4] == 'finishes':
+            tid = s[3]
+            if not tid in encoders:
+                  encoders[tid] = Encoder()
+
+            assert(encoders[tid].state == None or encoders[tid].state == 'awake')
+            if encoders[tid].state == 'awake':
+                  encoders[tid].awake += (secs - encoders[tid].last_event)
+
+            encoders[tid].state = 'asleep'
+            encoders[tid].last_event = secs
+
+      elif s[1] == 'encoder' and s[2] == 'thread' and s[4] == 'begins':
+            tid = s[3]
+            if not tid in encoders:
+                  encoders[tid] = Encoder()
+
+            if encoders[tid].state is not None:
+                  encoders[tid].asleep += (secs - encoders[tid].last_event)
+
+            encoders[tid].state = 'awake'
+            encoders[tid].last_event = secs
+
+for k, v in encoders.iteritems():
+      print '%s: awake %f asleep %f' % (k, v.awake, v.asleep)

diff --git a/src/lib/compose.hpp b/src/lib/compose.hpp
new file mode 100644 (file)
index 0000000..b3f410c
--- /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/decoder.cc b/src/lib/decoder.cc
index 19fd4f45ccda48707c90b555e9c2f6ae3a9ddbae..e3551701204349eed357cba01fc552690d0c67e7 100644 (file)
--- a/src/lib/decoder.cc
+++ b/src/lib/decoder.cc
@@ -410,7 +410,7 @@ Decoder::process_video (AVFrame* frame)
                                image->make_black ();
                        }
 
-                       _log->microsecond_log ("Decoder emits " + lexical_cast<string> (_video_frame), Log::TIMING);
+                       TIMING ("Decoder emits %1", _video_frame);
                        Video (image, _video_frame);
                        ++_video_frame;
                }

diff --git a/src/lib/j2k_wav_encoder.cc b/src/lib/j2k_wav_encoder.cc
index 0d786ab048f9235323736c762674fa3556770525..73aa1bff2023833ea9afcc519f2f3d95ef66b948 100644 (file)
--- a/src/lib/j2k_wav_encoder.cc
+++ b/src/lib/j2k_wav_encoder.cc
@@ -108,9 +108,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) {
-               _log->microsecond_log ("Decoder sleeps", Log::TIMING);
+               TIMING ("decoder sleeps with queue of %1", _queue.size());
                _worker_condition.wait (lock);
-               _log->microsecond_log ("Decoder wakes", Log::TIMING);
+               TIMING ("decoder wakes with queue of %1", _queue.size());
        }
 
        if (_process_end) {
@@ -120,7 +120,7 @@ J2KWAVEncoder::process_video (shared_ptr<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);
-               _log->microsecond_log ("Adding to queue of " + boost::lexical_cast<string> (_queue.size ()), Log::TIMING);
+               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,
@@ -146,12 +146,7 @@ J2KWAVEncoder::encoder_thread (ServerDescription* server)
        
        while (1) {
 
-               {
-                       stringstream s;
-                       s << "Encoder thread " << pthread_self() << " sleeps.";
-                       _log->microsecond_log (s.str(), Log::TIMING);
-               }
-               
+               TIMING ("encoder thread %1 sleeps", pthread_self ());
                boost::mutex::scoped_lock lock (_worker_mutex);
                while (_queue.empty () && !_process_end) {
                        _worker_condition.wait (lock);
@@ -161,14 +156,8 @@ J2KWAVEncoder::encoder_thread (ServerDescription* server)
                        return;
                }
 
+               TIMING ("encoder thread %1 wakes with queue of %2", pthread_self(), _queue.size());
                boost::shared_ptr<DCPVideoFrame> vf = _queue.front ();
-
-               {
-                       stringstream s;
-                       s << "Encoder thread " << pthread_self() << " wakes with queue of " << _queue.size();
-                       _log->microsecond_log (s.str(), Log::TIMING);
-               }
-               
                _queue.pop_front ();
                
                lock.unlock ();
@@ -200,19 +189,9 @@ J2KWAVEncoder::encoder_thread (ServerDescription* server)
                                
                } else {
                        try {
-                               {
-                                       stringstream s;
-                                       s << "Encoder thread " << pthread_self() << " begins local encode of " << vf->frame();
-                                       _log->microsecond_log (s.str(), Log::TIMING);
-                               }
-
+                               TIMING ("encoder thread %1 begins local encode of %2", pthread_self(), vf->frame());
                                encoded = vf->encode_locally ();
-
-                               {
-                                       stringstream s;
-                                       s << "Encoder thread " << pthread_self() << " finishes local encode of " << vf->frame();
-                                       _log->microsecond_log (s.str(), Log::TIMING);
-                               }
+                               TIMING ("encoder thread %1 finishes local encode of %2", pthread_self(), vf->frame());
                        } catch (std::exception& e) {
                                stringstream s;
                                s << "Local encode failed " << e.what() << ".";

diff --git a/src/lib/util.h b/src/lib/util.h
index bc5a00fc47e2a63b8d8edd3db5f18fd4f52d65c6..8d98437afafd4eace452c4695a1d27d8687657a9 100644 (file)
--- a/src/lib/util.h
+++ b/src/lib/util.h
@@ -34,6 +34,13 @@ extern "C" {
 #include <libavfilter/avfilter.h>
 }
 
+#ifdef DVDOMATIC_DEBUG
+#include "compose.hpp"
+#define TIMING(...) _log->microsecond_log (String::compose (__VA_ARGS__), Log::TIMING);
+#else
+#define TIMING(...)
+#endif
+
 class Scaler;
 
 extern std::string seconds_to_hms (int);

diff --git a/src/tools/dvdomatic.cc b/src/tools/dvdomatic.cc
index c4232130026c3dbe796db5945c15a6cda837a401..9ff2c1ddc4016f6768d1bd1af142188e25ee6bbc 100644 (file)
--- a/src/tools/dvdomatic.cc
+++ b/src/tools/dvdomatic.cc
@@ -352,11 +352,12 @@ public:
                info.SetName (_("DVD-o-matic"));
                info.SetVersion (wxT (DVDOMATIC_VERSION));
                info.SetDescription (_("Free, open-source DCP generation from almost anything."));
-               info.SetCopyright (_("(C) Carl Hetherington, Terrence Meiczinger, Paul Davis"));
+               info.SetCopyright (_("(C) Carl Hetherington, Terrence Meiczinger, Paul Davis, Ole Laursen"));
                wxArrayString authors;
                authors.Add (wxT ("Carl Hetherington"));
                authors.Add (wxT ("Terrence Meiczinger"));
                authors.Add (wxT ("Paul Davis"));
+               authors.Add (wxT ("Ole Laursen"));
                info.SetDevelopers (authors);
                info.SetWebSite (wxT ("http://carlh.net/software/dvdomatic"));
                wxAboutBox (info);

diff --git a/test.log b/test.log
new file mode 100644 (file)
index 0000000..31b9699
--- /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
+