Some work on rationalising and tidying up timing logging.

4 files changed, 83 insertions, 48 deletions

diff --git a/hacks/analog.py b/hacks/analog.py
index c74cf1bef..4fc1dda84 100644
--- a/hacks/analog.py
+++ b/hacks/analog.py
@@ -1,4 +1,7 @@
 #!/usr/bin/python
+#
+# Analyse a DCP-o-matic log file to extract various information.
+#
 
 import sys
 import time
@@ -11,6 +14,7 @@ parser.add_argument('-q', '--queue', help='plot queue size', action='store_true'
 parser.add_argument('-e', '--encoder-threads', help='plot encoder thread activity', action='store_true')
 parser.add_argument('-f', '--plot-first-encoder', help='plot more detailed activity of the first encoder thread', action='store_true')
 parser.add_argument('-s', '--fps-stats', help='frames-per-second stats', action='store_true')
+parser.add_argument('--encoder-stats', help='encoder thread activity stats', action='store_true')
 parser.add_argument('--dump-first-encoder', help='dump activity of the first encoder thread', action='store_true')
 parser.add_argument('--from', help='time in seconds to start at', type=int, dest='from_time')
 parser.add_argument('--to', help='time in seconds to stop at', type=int, dest='to_time')
@@ -23,8 +27,9 @@ def find_nth(haystack, needle, n):
         n -= 1
     return start
 
+# Representation of time in seconds and microseconds
 class Time:
-    def __init__(self, s, m = 0):
+    def __init__(self, s = 0, m = 0):
         self.seconds = s
         self.microseconds = m
 
@@ -34,6 +39,14 @@ class Time:
     def float_seconds(self):
         return self.seconds + self.microseconds / 1000000.0
 
+    def __iadd__(self, x):
+        self.microseconds += x.microseconds
+        self.seconds += x.seconds
+        if self.microseconds >= 1000000:
+            self.microseconds -= 1000000
+            self.seconds += 1
+        return self
+
     def __sub__(self, x):
         m = self.microseconds - x.microseconds
         if m < 0:
@@ -43,14 +56,17 @@ class Time:
 
 queue_size = []
 general_events = []
+encoder_threads = []
 encoder_thread_events = dict()
 
 def add_encoder_thread_event(thread, time, event):
+    global encoder_threads
     global encoder_thread_events
-    if thread in encoder_thread_events:
-        encoder_thread_events[thread].append((time, event))
-    else:
+    if not thread in encoder_threads:
+        encoder_threads.append(thread)
         encoder_thread_events[thread] = [(time, event)]
+    else:
+        encoder_thread_events[thread].append((time, event))
 
 def add_general_event(time, event):
     global general_events
@@ -63,49 +79,39 @@ while True:
     if l == '':
         break
 
-    l = l.strip()
-    p = l.split()
+    p = l.strip().split()
 
     if len(p) == 0:
         continue
 
     if len(p[0].split(':')) == 2:
-        # s:us timestamp
-        x = p[0].split(':')
-        T = Time(int(x[0]), int(x[1]))
-        message = l[l.find(' ')+1:]
+        # s:us timestamp: LOG_TIMING
+        t = p[0].split(':')
+        T = Time(int(t[0]), int(t[1]))
+        p = l.split()
+        message = p[1]
+        values = {}
+        for i in range(2, len(p)):
+            x = p[i].split('=')
+            values[x[0]] = x[1]
     else:
-        # Date/time timestamp
+        # Date/time timestamp: other LOG_*
         s = find_nth(l, ':', 3)
         T = Time(time.mktime(time.strptime(l[:s])))
         message = l[s+2:]
 
+    # T is elapsed time since the first log message
     if start is None:
         start = T
     else:
         T = T - start
 
-    thread = None
-    if message.startswith('['):
-        thread = message.split()[0][1:-1]
-        message = message[message.find(' ')+1:]
-
-    if message.startswith('adding to queue of '):
-        queue_size.append((T, int(message.split()[4])))
-    elif message.startswith('encoder thread sleeps'):
-        add_encoder_thread_event(thread, T, 'sleep')
-    elif message.startswith('encoder thread wakes'):
-        add_encoder_thread_event(thread, T, 'wake')
-    elif message.startswith('encoder thread begins local encode'):
-        add_encoder_thread_event(thread, T, 'begin_encode')
-    elif message.startswith('MagickImageProxy begins decode and convert') or message.startswith('MagickImageProxy begins read and decode'):
-        add_encoder_thread_event(thread, T, 'magick_begin_decode')
-    elif message.startswith('MagickImageProxy decode finished'):
-        add_encoder_thread_event(thread, T, 'magick_end_decode')
-    elif message.startswith('MagickImageProxy completes decode and convert'):
-        add_encoder_thread_event(thread, T, 'magick_end_unpack')
-    elif message.startswith('encoder thread finishes local encode'):
-        add_encoder_thread_event(thread, T, 'end_encode')
+    # Not-so-human-readable log messages (LOG_TIMING)
+    if message == 'add-frame-to-queue':
+        queue_size.append((T, values['queue']))
+    elif message in ['encoder-sleep', 'encoder-wake', 'start-local-encode', 'finish-local-encode', 'start-remote-send', 'finish-remote-send', 'start-remote-encode-and-receive', 'finish-remote-encode-and-receive']:
+        add_encoder_thread_event(values['thread'], T, message)
+    # Human-readable log message (other LOG_*)
     elif message.startswith('Finished locally-encoded'):
         add_general_event(T, 'end_local_encode')
     elif message.startswith('Finished remotely-encoded'):
@@ -116,6 +122,7 @@ while True:
         add_general_event(T, 'end_transcode')
 
 if args.queue:
+    # Plot queue size against time; queue_size contains times and queue sizes
     plt.figure()
     x = []
     y = []
@@ -127,6 +134,10 @@ if args.queue:
     plt.show()
 
 elif args.encoder_threads:
+    # Plot the things that are happening in each encoder thread with time
+    # y=0 thread is sleeping
+    # y=1 thread is awake
+    # y=2 thread is encoding
     plt.figure()
     N = len(encoder_thread_events)
     n = 1
@@ -151,10 +162,6 @@ elif args.encoder_threads:
                 y.append(2)
             elif e[1] == 'end_encode':
                 y.append(1)
-            elif e[1] == 'magick_begin_decode':
-                y.append(3)
-            elif e[1] == 'magick_end_decode':
-                y.append(2)
 
             previous = y[-1]
 
@@ -171,7 +178,7 @@ elif args.plot_first_encoder:
 
     N = 6
     n = 1
-    for t in ['sleep', 'wake', 'begin_encode', 'magick_begin_decode', 'magick_end_decode', 'end_encode']:
+    for t in ['sleep', 'wake', 'begin_encode', 'end_encode']:
         plt.subplot(N, 1, n)
         x = []
         y = []
@@ -187,7 +194,7 @@ elif args.plot_first_encoder:
                 y.append(0)
                 y.append(1)
                 y.append(0)
-                
+
         plt.plot(x, y)
         plt.title(t)
         n += 1
@@ -225,3 +232,26 @@ elif args.fps_stats:
     print 'Job ran for %fs' % duration.float_seconds()
     print '%d local and %d remote' % (local, remote)
     print '%.2f fps local and %.2f fps remote' % (local / duration.float_seconds(), remote / duration.float_seconds())
+
+elif args.encoder_stats:
+
+    for t in encoder_threads:
+        last = None
+        asleep = Time()
+        encoding = Time()
+        wakes = 0
+        for e in encoder_thread_events[t]:
+            if e[1] == 'encoder-sleep':
+                if last is not None:
+                    encoding += e[0] - last
+                last = e[0]
+            elif e[1] == 'encoder-wake':
+                wakes += 1
+                asleep += e[0] - last
+                last = e[0]
+
+        print '-- Encoder thread %s' % t
+        print 'Awoken %d times' % wakes
+        total = asleep.float_seconds() + encoding.float_seconds()
+        print 'Asleep: %s (%s%%)' % (asleep, asleep.float_seconds() * 100 / total)
+        print 'Encoding: %s (%s%%)' % (encoding, encoding.float_seconds() * 100 / total)
diff --git a/src/lib/dcp_video.cc b/src/lib/dcp_video.cc
index 5b5edba95..7d060b30d 100644
--- a/src/lib/dcp_video.cc
+++ b/src/lib/dcp_video.cc
@@ -51,6 +51,7 @@
 
 #define LOG_GENERAL(...) _log->log (String::compose (__VA_ARGS__), Log::TYPE_GENERAL);
 #define LOG_DEBUG_ENCODE(...) _log->log (String::compose (__VA_ARGS__), Log::TYPE_DEBUG_ENCODE);
+#define LOG_TIMING(...) _log->microsecond_log (String::compose (__VA_ARGS__), Log::TYPE_TIMING);
 
 #include "i18n.h"
 
@@ -265,13 +266,17 @@ DCPVideo::encode_remotely (ServerDescription serv)
 	socket->write ((uint8_t *) xml.c_str(), xml.length() + 1);
 
 	/* Send binary data */
+	LOG_TIMING("start-remote-send thread=%1", boost::this_thread::get_id());
 	_frame->send_binary (socket);
+	LOG_TIMING("finish-remote-send thread=%1", boost::this_thread::get_id());
 
 	/* Read the response (JPEG2000-encoded data); this blocks until the data
 	   is ready and sent back.
 	*/
+	LOG_TIMING("start-remote-encode-and-receive thread=%1", boost::this_thread::get_id ());
 	Data e (socket->read_uint32 ());
 	socket->read (e.data().get(), e.size());
+	LOG_TIMING("finish-remote-encode-and-receive thread=%1", boost::this_thread::get_id ());
 
 	LOG_DEBUG_ENCODE (N_("Finished remotely-encoded frame %1"), _index);
 
diff --git a/src/lib/encoder.cc b/src/lib/encoder.cc
index 917f313a2..08f4e66d4 100644
--- a/src/lib/encoder.cc
+++ b/src/lib/encoder.cc
@@ -200,9 +200,9 @@ Encoder::enqueue (shared_ptr<PlayerVideo> pv)
 
 	/* Wait until the queue has gone down a bit */
 	while (_queue.size() >= _threads.size() * 2 && !_terminate) {
-		LOG_TIMING ("decoder sleeps with queue of %1", _queue.size());
+		LOG_TIMING ("decoder-sleep queue=%1", _queue.size());
 		_full_condition.wait (lock);
-		LOG_TIMING ("decoder wakes with queue of %1", _queue.size());
+		LOG_TIMING ("decoder-wake queue=%1", _queue.size());
 	}
 
 	if (_terminate) {
@@ -227,7 +227,7 @@ Encoder::enqueue (shared_ptr<PlayerVideo> pv)
 		_writer->repeat (_video_frames_enqueued, pv->eyes ());
 	} else {
 		/* Queue this new frame for encoding */
-		LOG_TIMING ("adding to queue of %1", _queue.size ());
+		LOG_TIMING ("add-frame-to-queue queue=%1", _queue.size ());
 		_queue.push_back (shared_ptr<DCPVideo> (
 					  new DCPVideo (
 						  pv,
@@ -300,7 +300,7 @@ try
 
 	while (true) {
 
-		LOG_TIMING ("[%1] encoder thread sleeps", boost::this_thread::get_id());
+		LOG_TIMING ("encoder-sleep thread=%1", boost::this_thread::get_id());
 		boost::mutex::scoped_lock lock (_mutex);
 		while (_queue.empty () && !_terminate) {
 			_empty_condition.wait (lock);
@@ -310,9 +310,9 @@ try
 			return;
 		}
 
-		LOG_TIMING ("[%1] encoder thread wakes with queue of %2", boost::this_thread::get_id(), _queue.size());
+		LOG_TIMING ("encoder-wake thread=%1 queue=%2", boost::this_thread::get_id(), _queue.size());
 		shared_ptr<DCPVideo> vf = _queue.front ();
-		LOG_TIMING ("[%1] encoder thread pops frame %2 (%3) from queue", boost::this_thread::get_id(), vf->index(), vf->eyes ());
+		LOG_TIMING ("encoder-pop thread=%1 frame=%2 eyes=%3", boost::this_thread::get_id(), vf->index(), vf->eyes ());
 		_queue.pop_front ();
 
 		lock.unlock ();
@@ -344,9 +344,9 @@ try
 
 		} else {
 			try {
-				LOG_TIMING ("[%1] encoder thread begins local encode of %2", boost::this_thread::get_id(), vf->index());
+				LOG_TIMING ("start-local-encode thread=%1 frame=%2", boost::this_thread::get_id(), vf->index());
 				encoded = vf->encode_locally (boost::bind (&Log::dcp_log, _film->log().get(), _1, _2));
-				LOG_TIMING ("[%1] encoder thread finishes local encode of %2", boost::this_thread::get_id(), vf->index());
+				LOG_TIMING ("finish-local-encode thread=%1 frame=%2", boost::this_thread::get_id(), vf->index());
 			} catch (std::exception& e) {
 				LOG_ERROR (N_("Local encode failed (%1)"), e.what ());
 			}
diff --git a/src/lib/writer.cc b/src/lib/writer.cc
index 2ff93d74a..91263fe25 100644
--- a/src/lib/writer.cc
+++ b/src/lib/writer.cc
@@ -321,9 +321,9 @@ try
 			}
 
 			/* Nothing to do: wait until something happens which may indicate that we do */
-			LOG_TIMING (N_("writer sleeps with a queue of %1"), _queue.size());
+			LOG_TIMING (N_("writer-sleep queue=%1"), _queue.size());
 			_empty_condition.wait (lock);
-			LOG_TIMING (N_("writer wakes with a queue of %1"), _queue.size());
+			LOG_TIMING (N_("writer-wake queue=%1"), _queue.size());
 		}
 
 		if (_finish && _queue.empty()) {