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