X-Git-Url: https://main.carlh.net/gitweb/?a=blobdiff_plain;f=hacks%2Fanalog.py;h=51d8a96390577638a36e36c447d997041b4247bb;hb=eb78e6e2c04ceee1d7cff25cd0b5f3486b38a7a5;hp=c74cf1befa10ea40d013973bed22c36c5a237a8c;hpb=4e411ea97b4dab8a5fa282d1d4cf7971ef1e24ad;p=dcpomatic.git diff --git a/hacks/analog.py b/hacks/analog.py index c74cf1bef..51d8a9639 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: @@ -41,16 +54,31 @@ class Time: else: return Time(self.seconds - x.seconds, m) +class EncoderThread: + def __init__(self, id): + self.id = id + self.events = [] + self.server = None + + def add_event(self, time, message, values): + self.events.append((time, message, values)) + queue_size = [] general_events = [] -encoder_thread_events = dict() +encoder_threads = [] -def add_encoder_thread_event(thread, time, event): - global encoder_thread_events - if thread in encoder_thread_events: - encoder_thread_events[thread].append((time, event)) - else: - encoder_thread_events[thread] = [(time, event)] +def find_encoder_thread(id): + global encoder_threads + thread = None + for t in encoder_threads: + if t.id == id: + thread = t + + if thread is None: + thread = EncoderThread(id) + encoder_threads.append(thread) + + return thread def add_general_event(time, event): global general_events @@ -63,49 +91,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', 'start-remote-encode', 'start-remote-receive', 'finish-remote-receive', 'start-encoder-thread']: + find_encoder_thread(values['thread']).add_event(T, message, values) + # 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 +134,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,15 +146,19 @@ 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 - for thread, events in encoder_thread_events.iteritems(): + for thread in encoder_threads: plt.subplot(N, 1, n) x = [] y = [] previous = 0 - for e in events: + for e in thread.events: if args.from_time is not None and e[0].float_seconds() <= args.from_time: continue if args.to_time is not None and e[0].float_seconds() >= args.to_time: @@ -151,10 +174,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] @@ -165,13 +184,13 @@ elif args.encoder_threads: elif args.plot_first_encoder: plt.figure() - N = len(encoder_thread_events) + N = len(encoder_threads) n = 1 - events = encoder_thread_events.itervalues().next() + events = encoder_threads[0].events 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 +206,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 +244,53 @@ 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: + # Broad stats on what encoder threads spent their time doing + for t in encoder_threads: + last = None + asleep = Time() + local_encoding = Time() + sending = Time() + remote_encoding = Time() + receiving = Time() + wakes = 0 + for e in t.events: + if last is not None: + if last[1] == 'encoder-sleep': + asleep += e[0] - last[0] + elif last[1] == 'encoder-wake': + wakes += 1 + elif last[1] == 'start-local-encode': + local_encoding += e[0] - last[0] + elif last[1] == 'start-remote-send': + sending += e[0] - last[0] + elif last[1] == 'start-remote-encode': + remote_encoding += e[0] - last[0] + elif last[1] == 'start-remote-receive': + receiving += e[0] - last[0] + elif last[1] == 'start-encoder-thread': + find_encoder_thread(last[2]['thread']).server = last[2]['server'] + + last = e + + print '-- Encoder thread %s (%s)' % (t.server, t.id) + print '\tAwoken %d times' % wakes + + total = asleep.float_seconds() + local_encoding.float_seconds() + sending.float_seconds() + remote_encoding.float_seconds() + receiving.float_seconds() + if total == 0: + continue + + print '\t%s: %2.f%%' % ('Asleep'.ljust(16), asleep.float_seconds() * 100 / total) + + def print_with_fps(v, name, total, frames): + if v.float_seconds() > 1: + print '\t%s: %2.f%% %.2ffps' % (name.ljust(16), v.float_seconds() * 100 / total, frames / v.float_seconds()) + + print_with_fps(local_encoding, 'Local encoding', total, wakes) + if sending.float_seconds() > 0: + print '\t%s: %2.f%%' % ('Sending'.ljust(16), sending.float_seconds() * 100 / total) + print_with_fps(remote_encoding, 'Remote encoding', total, wakes) + if receiving.float_seconds() > 0: + print '\t%s: %2.f%%' % ('Receiving'.ljust(16), receiving.float_seconds() * 100 / total) + print ''