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