#!/usr/bin/python
+#
+# Analyse a DCP-o-matic log file to extract various information.
+#
import sys
import time
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')
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
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:
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
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'):
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 = []
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
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]
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 = []
y.append(0)
y.append(1)
y.append(0)
-
+
plt.plot(x, y)
plt.title(t)
n += 1
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)
/* 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) {
_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,
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);
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 ();
} 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 ());
}