hacks/analog.py

   1 #!/usr/bin/python
   2 #
   3 # Analyse a DCP-o-matic log file to extract various information.
   4 #
   5
   6 import sys
   7 import time
   8 import argparse
   9 import matplotlib.pyplot as plt
  10
  11 parser = argparse.ArgumentParser()
  12 parser.add_argument('log_file')
  13 parser.add_argument('-q', '--queue', help='plot queue size', action='store_true')
  14 parser.add_argument('-e', '--encoder-threads', help='plot encoder thread activity', action='store_true')
  15 parser.add_argument('-f', '--plot-first-encoder', help='plot more detailed activity of the first encoder thread', action='store_true')
  16 parser.add_argument('-s', '--fps-stats', help='frames-per-second stats', action='store_true')
  17 parser.add_argument('--encoder-stats', help='encoder thread activity stats', action='store_true')
  18 parser.add_argument('--dump-first-encoder', help='dump activity of the first encoder thread', action='store_true')
  19 parser.add_argument('--from', help='time in seconds to start at', type=int, dest='from_time')
  20 parser.add_argument('--to', help='time in seconds to stop at', type=int, dest='to_time')
  21 args = parser.parse_args()
  22
  23 def find_nth(haystack, needle, n):
  24     start = haystack.find(needle)
  25     while start >= 0 and n > 1:
  26         start = haystack.find(needle, start+len(needle))
  27         n -= 1
  28     return start
  29
  30 # Representation of time in seconds and microseconds
  31 class Time:
  32     def __init__(self, s = 0, m = 0):
  33         self.seconds = s
  34         self.microseconds = m
  35
  36     def __str__(self):
  37         return '%d:%d' % (self.seconds, self.microseconds)
  38
  39     def float_seconds(self):
  40         return self.seconds + self.microseconds / 1000000.0
  41
  42     def __iadd__(self, x):
  43         self.microseconds += x.microseconds
  44         self.seconds += x.seconds
  45         if self.microseconds >= 1000000:
  46             self.microseconds -= 1000000
  47             self.seconds += 1
  48         return self
  49
  50     def __sub__(self, x):
  51         m = self.microseconds - x.microseconds
  52         if m < 0:
  53             return Time(self.seconds - x.seconds - 1, m + 1000000)
  54         else:
  55             return Time(self.seconds - x.seconds, m)
  56
  57 queue_size = []
  58 general_events = []
  59 encoder_threads = []
  60 encoder_thread_events = dict()
  61
  62 def add_encoder_thread_event(thread, time, event):
  63     global encoder_threads
  64     global encoder_thread_events
  65     if not thread in encoder_threads:
  66         encoder_threads.append(thread)
  67         encoder_thread_events[thread] = [(time, event)]
  68     else:
  69         encoder_thread_events[thread].append((time, event))
  70
  71 def add_general_event(time, event):
  72     global general_events
  73     general_events.append((time, event))
  74
  75 f = open(args.log_file)
  76 start = None
  77 while True:
  78     l = f.readline()
  79     if l == '':
  80         break
  81
  82     p = l.strip().split()
  83
  84     if len(p) == 0:
  85         continue
  86
  87     if len(p[0].split(':')) == 2:
  88         # s:us timestamp: LOG_TIMING
  89         t = p[0].split(':')
  90         T = Time(int(t[0]), int(t[1]))
  91         p = l.split()
  92         message = p[1]
  93         values = {}
  94         for i in range(2, len(p)):
  95             x = p[i].split('=')
  96             values[x[0]] = x[1]
  97     else:
  98         # Date/time timestamp: other LOG_*
  99         s = find_nth(l, ':', 3)
 100         T = Time(time.mktime(time.strptime(l[:s])))
 101         message = l[s+2:]
 102
 103     # T is elapsed time since the first log message
 104     if start is None:
 105         start = T
 106     else:
 107         T = T - start
 108
 109     # Not-so-human-readable log messages (LOG_TIMING)
 110     if message == 'add-frame-to-queue':
 111         queue_size.append((T, values['queue']))
 112     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']:
 113         add_encoder_thread_event(values['thread'], T, message)
 114     # Human-readable log message (other LOG_*)
 115     elif message.startswith('Finished locally-encoded'):
 116         add_general_event(T, 'end_local_encode')
 117     elif message.startswith('Finished remotely-encoded'):
 118         add_general_event(T, 'end_remote_encode')
 119     elif message.startswith('Transcode job starting'):
 120         add_general_event(T, 'begin_transcode')
 121     elif message.startswith('Transcode job completed successfully'):
 122         add_general_event(T, 'end_transcode')
 123
 124 if args.queue:
 125     # Plot queue size against time; queue_size contains times and queue sizes
 126     plt.figure()
 127     x = []
 128     y = []
 129     for q in queue_size:
 130         x.append(q[0].seconds)
 131         y.append(q[1])
 132
 133     plt.plot(x, y)
 134     plt.show()
 135
 136 elif args.encoder_threads:
 137     # Plot the things that are happening in each encoder thread with time
 138     # y=0 thread is sleeping
 139     # y=1 thread is awake
 140     # y=2 thread is encoding
 141     plt.figure()
 142     N = len(encoder_thread_events)
 143     n = 1
 144     for thread, events in encoder_thread_events.iteritems():
 145         plt.subplot(N, 1, n)
 146         x = []
 147         y = []
 148         previous = 0
 149         for e in events:
 150             if args.from_time is not None and e[0].float_seconds() <= args.from_time:
 151                 continue
 152             if args.to_time is not None and e[0].float_seconds() >= args.to_time:
 153                 continue
 154             x.append(e[0].float_seconds())
 155             x.append(e[0].float_seconds())
 156             y.append(previous)
 157             if e[1] == 'sleep':
 158                 y.append(0)
 159             elif e[1] == 'wake':
 160                 y.append(1)
 161             elif e[1] == 'begin_encode':
 162                 y.append(2)
 163             elif e[1] == 'end_encode':
 164                 y.append(1)
 165
 166             previous = y[-1]
 167
 168         plt.plot(x, y)
 169         n += 1
 170
 171     plt.show()
 172
 173 elif args.plot_first_encoder:
 174     plt.figure()
 175     N = len(encoder_thread_events)
 176     n = 1
 177     events = encoder_thread_events.itervalues().next()
 178
 179     N = 6
 180     n = 1
 181     for t in ['sleep', 'wake', 'begin_encode', 'end_encode']:
 182         plt.subplot(N, 1, n)
 183         x = []
 184         y = []
 185         for e in events:
 186             if args.from_time is not None and e[0].float_seconds() <= args.from_time:
 187                 continue
 188             if args.to_time is not None and e[0].float_seconds() >= args.to_time:
 189                 continue
 190             if e[1] == t:
 191                 x.append(e[0].float_seconds())
 192                 x.append(e[0].float_seconds())
 193                 x.append(e[0].float_seconds())
 194                 y.append(0)
 195                 y.append(1)
 196                 y.append(0)
 197
 198         plt.plot(x, y)
 199         plt.title(t)
 200         n += 1
 201
 202     plt.show()
 203
 204 elif args.dump_first_encoder:
 205     events = encoder_thread_events.itervalues().next()
 206     last = 0
 207     for e in events:
 208         print e[0].float_seconds(), (e[0].float_seconds() - last), e[1]
 209         last = e[0].float_seconds()
 210
 211 elif args.fps_stats:
 212     local = 0
 213     remote = 0
 214     start = None
 215     end = None
 216     for e in general_events:
 217         if e[1] == 'begin_transcode':
 218             start = e[0]
 219         elif e[1] == 'end_transcode':
 220             end = e[0]
 221         elif e[1] == 'end_local_encode':
 222             local += 1
 223         elif e[1] == 'end_remote_encode':
 224             remote += 1
 225
 226     if end == None:
 227         print 'Job did not appear to end'
 228         sys.exit(1)
 229
 230     duration = end - start
 231
 232     print 'Job ran for %fs' % duration.float_seconds()
 233     print '%d local and %d remote' % (local, remote)
 234     print '%.2f fps local and %.2f fps remote' % (local / duration.float_seconds(), remote / duration.float_seconds())
 235
 236 elif args.encoder_stats:
 237
 238     for t in encoder_threads:
 239         last = None
 240         asleep = Time()
 241         encoding = Time()
 242         wakes = 0
 243         for e in encoder_thread_events[t]:
 244             if e[1] == 'encoder-sleep':
 245                 if last is not None:
 246                     encoding += e[0] - last
 247                 last = e[0]
 248             elif e[1] == 'encoder-wake':
 249                 wakes += 1
 250                 asleep += e[0] - last
 251                 last = e[0]
 252
 253         print '-- Encoder thread %s' % t
 254         print 'Awoken %d times' % wakes
 255         total = asleep.float_seconds() + encoding.float_seconds()
 256         print 'Asleep: %s (%s%%)' % (asleep, asleep.float_seconds() * 100 / total)
 257         print 'Encoding: %s (%s%%)' % (encoding, encoding.float_seconds() * 100 / total)