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