X-Git-Url: https://main.carlh.net/gitweb/?a=blobdiff_plain;f=hacks%2Fanalog.py;h=c58af76ee53972ba0341dba4e69cd96485fbc798;hb=04c6526adc6f583e513f394419d9193c6ba5f7b0;hp=de5a319c482df6a176cbde64d6ffb68e10285bfd;hpb=a7971193b2fdbac8adb58d3eecf9ba48643cf93f;p=dcpomatic.git diff --git a/hacks/analog.py b/hacks/analog.py index de5a319c4..c58af76ee 100644 --- a/hacks/analog.py +++ b/hacks/analog.py @@ -11,11 +11,12 @@ import matplotlib.pyplot as plt parser = argparse.ArgumentParser() parser.add_argument('log_file') 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('--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('--encoder-dump', help='dump activity of the specified encoder', action='store_true') +parser.add_argument('-e', '--encoder', help='encoder index (from 0)') 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') args = parser.parse_args() @@ -29,7 +30,7 @@ def find_nth(haystack, needle, n): # Representation of time in seconds and microseconds class Time: - def __init__(self, s = 0, m = 0): + def __init__(self, s=0, m=0): self.seconds = s self.microseconds = m @@ -54,19 +55,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_threads = [] -encoder_thread_events = dict() -def add_encoder_thread_event(thread, time, event): +def find_encoder_thread(id): global encoder_threads - global encoder_thread_events - if not thread in 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) - encoder_thread_events[thread] = [(time, event)] - else: - encoder_thread_events[thread].append((time, event)) + + return thread def add_general_event(time, event): global general_events @@ -97,7 +110,16 @@ while True: else: # Date/time timestamp: other LOG_* s = find_nth(l, ':', 3) - T = Time(time.mktime(time.strptime(l[:s]))) + try: + T = Time(time.mktime(time.strptime(l[:s]))) + except: + try: + T = Time(time.mktime(time.strptime(l[:s], "%d.%m.%Y %H:%M:%S"))) + except: + x = l[:s] + if not x.endswith('M'): + x += 'M' + T = Time(time.mktime(time.strptime(x, "%d/%m/%Y %H:%M:%S %p"))) message = l[s+2:] # T is elapsed time since the first log message @@ -110,7 +132,7 @@ while True: 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']: - add_encoder_thread_event(values['thread'], T, message) + 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') @@ -139,14 +161,15 @@ elif args.encoder_threads: # y=1 thread is awake # y=2 thread is encoding plt.figure() - N = len(encoder_thread_events) + N = len(encoder_threads) n = 1 - for thread, events in encoder_thread_events.iteritems(): + for thread in encoder_threads: plt.subplot(N, 1, n) + plt.ylim([-0.5, 2.5]) 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: @@ -154,14 +177,17 @@ elif args.encoder_threads: x.append(e[0].float_seconds()) x.append(e[0].float_seconds()) y.append(previous) - if e[1] == 'sleep': + if e[1] == 'encoder-sleep': y.append(0) - elif e[1] == 'wake': + elif e[1] == 'encoder-wake': y.append(1) - elif e[1] == 'begin_encode': + elif e[1] == 'start-local-encode': y.append(2) - elif e[1] == 'end_encode': + elif e[1] == 'finish-local-encode': y.append(1) + else: + print>>sys.stderr,'unknown event %s' % e[1] + sys.exit(1) previous = y[-1] @@ -172,13 +198,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', 'end_encode']: + for t in ['encoder-sleep', 'encoder-wake', 'start-local-encode', 'finish-local-encode']: plt.subplot(N, 1, n) x = [] y = [] @@ -201,12 +227,12 @@ elif args.plot_first_encoder: plt.show() -elif args.dump_first_encoder: - events = encoder_thread_events.itervalues().next() - last = 0 - for e in events: - print e[0].float_seconds(), (e[0].float_seconds() - last), e[1] - last = e[0].float_seconds() +elif args.encoder_dump: + for t in encoder_threads[int(args.encoder)]: + last = 0 + for e in t.events: + print (e[0].float_seconds() - last), e[1] + last = e[0].float_seconds() elif args.fps_stats: local = 0 @@ -243,15 +269,13 @@ elif args.encoder_stats: remote_encoding = Time() receiving = Time() wakes = 0 - for e in encoder_thread_events[t]: - if e[1] not in ['encoder-sleep', 'encoder-wake', 'start-remote-send', 'start-remote-encode', 'start-remote-receive', 'finish-remote-receive']: - continue - + 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] @@ -259,21 +283,28 @@ elif args.encoder_stats: 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' % t + 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 '\tAsleep: %s (%.2f%%)' % (asleep, asleep.float_seconds() * 100 / total) - if local_encoding.float_seconds() > 0: - print '\tLocal encoding: %s (%.2f%%)' % (local_encoding, local_encoding.float_seconds() * 100 / total) + + print '\t%s: %2.f%% %fs' % ('Asleep'.ljust(16), asleep.float_seconds() * 100 / total, asleep.float_seconds()) + + def print_with_fps(v, name, total, frames): + if v.float_seconds() > 1: + print '\t%s: %2.f%% %f %.2ffps' % (name.ljust(16), v.float_seconds() * 100 / total, v.float_seconds(), frames / v.float_seconds()) + + print_with_fps(local_encoding, 'Local encoding', total, wakes) if sending.float_seconds() > 0: - print '\tSending: %s (%.2f%%)' % (sending, sending.float_seconds() * 100 / total) - if remote_encoding.float_seconds() > 0: - print '\tRemote encoding: %s (%.2f%%)' % (remote_encoding, remote_encoding.float_seconds() * 100 / total) + 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 '\tReceiving: %s (%.2f%%)' % (receiving, receiving.float_seconds() * 100 / total) + print '\t%s: %2.f%%' % ('Receiving'.ljust(16), receiving.float_seconds() * 100 / total) print ''