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 class EncoderThread:
  58     def __init__(self, id):
  59         self.id = id
  60         self.events = []
  61         self.server = None
  62
  63     def add_event(self, time, message, values):
  64         self.events.append((time, message, values))
  65
  66 queue_size = []
  67 general_events = []
  68 encoder_threads = []
  69
  70 def find_encoder_thread(id):
  71     global encoder_threads
  72     thread = None
  73     for t in encoder_threads:
  74         if t.id == id:
  75             thread = t
  76
  77     if thread is None:
  78         thread = EncoderThread(id)
  79         encoder_threads.append(thread)
  80
  81     return thread
  82
  83 def add_general_event(time, event):
  84     global general_events
  85     general_events.append((time, event))
  86
  87 f = open(args.log_file)
  88 start = None
  89 while True:
  90     l = f.readline()
  91     if l == '':
  92         break
  93
  94     p = l.strip().split()
  95
  96     if len(p) == 0:
  97         continue
  98
  99     if len(p[0].split(':')) == 2:
 100         # s:us timestamp: LOG_TIMING
 101         t = p[0].split(':')
 102         T = Time(int(t[0]), int(t[1]))
 103         p = l.split()
 104         message = p[1]
 105         values = {}
 106         for i in range(2, len(p)):
 107             x = p[i].split('=')
 108             values[x[0]] = x[1]
 109     else:
 110         # Date/time timestamp: other LOG_*
 111         s = find_nth(l, ':', 3)
 112         try:
 113             T = Time(time.mktime(time.strptime(l[:s])))
 114         except:
 115             T = Time(time.mktime(time.strptime(l[:s], "%d.%m.%Y %H:%M:%S")))
 116         message = l[s+2:]
 117
 118     # T is elapsed time since the first log message
 119     if start is None:
 120         start = T
 121     else:
 122         T = T - start
 123
 124     # Not-so-human-readable log messages (LOG_TIMING)
 125     if message == 'add-frame-to-queue':
 126         queue_size.append((T, values['queue']))
 127     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']:
 128         find_encoder_thread(values['thread']).add_event(T, message, values)
 129     # Human-readable log message (other LOG_*)
 130     elif message.startswith('Finished locally-encoded'):
 131         add_general_event(T, 'end_local_encode')
 132     elif message.startswith('Finished remotely-encoded'):
 133         add_general_event(T, 'end_remote_encode')
 134     elif message.startswith('Transcode job starting'):
 135         add_general_event(T, 'begin_transcode')
 136     elif message.startswith('Transcode job completed successfully'):
 137         add_general_event(T, 'end_transcode')
 138
 139 if args.queue:
 140     # Plot queue size against time; queue_size contains times and queue sizes
 141     plt.figure()
 142     x = []
 143     y = []
 144     for q in queue_size:
 145         x.append(q[0].seconds)
 146         y.append(q[1])
 147
 148     plt.plot(x, y)
 149     plt.show()
 150
 151 elif args.encoder_threads:
 152     # Plot the things that are happening in each encoder thread with time
 153     # y=0 thread is sleeping
 154     # y=1 thread is awake
 155     # y=2 thread is encoding
 156     plt.figure()
 157     N = len(encoder_threads)
 158     n = 1
 159     for thread in encoder_threads:
 160         plt.subplot(N, 1, n)
 161         plt.ylim([-0.5, 2.5])
 162         x = []
 163         y = []
 164         previous = 0
 165         for e in thread.events:
 166             if args.from_time is not None and e[0].float_seconds() <= args.from_time:
 167                 continue
 168             if args.to_time is not None and e[0].float_seconds() >= args.to_time:
 169                 continue
 170             x.append(e[0].float_seconds())
 171             x.append(e[0].float_seconds())
 172             y.append(previous)
 173             if e[1] == 'encoder-sleep':
 174                 y.append(0)
 175             elif e[1] == 'encoder-wake':
 176                 y.append(1)
 177             elif e[1] == 'start-local-encode':
 178                 y.append(2)
 179             elif e[1] == 'finish-local-encode':
 180                 y.append(1)
 181             else:
 182                 print>>sys.stderr,'unknown event %s' % e[1]
 183                 sys.exit(1)
 184
 185             previous = y[-1]
 186
 187         plt.plot(x, y)
 188         n += 1
 189
 190     plt.show()
 191
 192 elif args.plot_first_encoder:
 193     plt.figure()
 194     N = len(encoder_threads)
 195     n = 1
 196     events = encoder_threads[0].events
 197
 198     N = 6
 199     n = 1
 200     for t in ['sleep', 'wake', 'begin_encode', 'end_encode']:
 201         plt.subplot(N, 1, n)
 202         x = []
 203         y = []
 204         for e in events:
 205             if args.from_time is not None and e[0].float_seconds() <= args.from_time:
 206                 continue
 207             if args.to_time is not None and e[0].float_seconds() >= args.to_time:
 208                 continue
 209             if e[1] == t:
 210                 x.append(e[0].float_seconds())
 211                 x.append(e[0].float_seconds())
 212                 x.append(e[0].float_seconds())
 213                 y.append(0)
 214                 y.append(1)
 215                 y.append(0)
 216
 217         plt.plot(x, y)
 218         plt.title(t)
 219         n += 1
 220
 221     plt.show()
 222
 223 elif args.dump_first_encoder:
 224     events = encoder_thread_events.itervalues().next()
 225     last = 0
 226     for e in events:
 227         print e[0].float_seconds(), (e[0].float_seconds() - last), e[1]
 228         last = e[0].float_seconds()
 229
 230 elif args.fps_stats:
 231     local = 0
 232     remote = 0
 233     start = None
 234     end = None
 235     for e in general_events:
 236         if e[1] == 'begin_transcode':
 237             start = e[0]
 238         elif e[1] == 'end_transcode':
 239             end = e[0]
 240         elif e[1] == 'end_local_encode':
 241             local += 1
 242         elif e[1] == 'end_remote_encode':
 243             remote += 1
 244
 245     if end == None:
 246         print 'Job did not appear to end'
 247         sys.exit(1)
 248
 249     duration = end - start
 250
 251     print 'Job ran for %fs' % duration.float_seconds()
 252     print '%d local and %d remote' % (local, remote)
 253     print '%.2f fps local and %.2f fps remote' % (local / duration.float_seconds(), remote / duration.float_seconds())
 254
 255 elif args.encoder_stats:
 256     # Broad stats on what encoder threads spent their time doing
 257     for t in encoder_threads:
 258         last = None
 259         asleep = Time()
 260         local_encoding = Time()
 261         sending = Time()
 262         remote_encoding = Time()
 263         receiving = Time()
 264         wakes = 0
 265         for e in t.events:
 266             if last is not None:
 267                 if last[1] == 'encoder-sleep':
 268                     asleep += e[0] - last[0]
 269                 elif last[1] == 'encoder-wake':
 270                     wakes += 1
 271                 elif last[1] == 'start-local-encode':
 272                     local_encoding += e[0] - last[0]
 273                 elif last[1] == 'start-remote-send':
 274                     sending += e[0] - last[0]
 275                 elif last[1] == 'start-remote-encode':
 276                     remote_encoding += e[0] - last[0]
 277                 elif last[1] == 'start-remote-receive':
 278                     receiving += e[0] - last[0]
 279                 elif last[1] == 'start-encoder-thread':
 280                     find_encoder_thread(last[2]['thread']).server = last[2]['server']
 281
 282             last = e
 283
 284         print '-- Encoder thread %s (%s)' % (t.server, t.id)
 285         print '\tAwoken %d times' % wakes
 286
 287         total = asleep.float_seconds() + local_encoding.float_seconds() + sending.float_seconds() + remote_encoding.float_seconds() + receiving.float_seconds()
 288         if total == 0:
 289             continue
 290
 291         print '\t%s: %2.f%%' % ('Asleep'.ljust(16), asleep.float_seconds() * 100 / total)
 292
 293         def print_with_fps(v, name, total, frames):
 294             if v.float_seconds() > 1:
 295                 print '\t%s: %2.f%% %.2ffps' % (name.ljust(16), v.float_seconds() * 100 / total, frames / v.float_seconds())
 296
 297         print_with_fps(local_encoding, 'Local encoding', total, wakes)
 298         if sending.float_seconds() > 0:
 299             print '\t%s: %2.f%%' % ('Sending'.ljust(16), sending.float_seconds() * 100 / total)
 300         print_with_fps(remote_encoding, 'Remote encoding', total, wakes)
 301         if receiving.float_seconds() > 0:
 302             print '\t%s: %2.f%%' % ('Receiving'.ljust(16), receiving.float_seconds() * 100 / total)
 303         print ''