hacks/analog.py

   1 #!/usr/bin/python
   2
   3 import sys
   4 import time
   5 import argparse
   6 import matplotlib.pyplot as plt
   7
   8 parser = argparse.ArgumentParser()
   9 parser.add_argument('log_file')
  10 parser.add_argument('-q', '--queue', help='plot queue size', action='store_true')
  11 parser.add_argument('-e', '--encoder-threads', help='plot encoder thread activity', action='store_true')
  12 parser.add_argument('-f', '--plot-first-encoder', help='plot more detailed activity of the first encoder thread', action='store_true')
  13 parser.add_argument('-s', '--fps-stats', help='frames-per-second stats', action='store_true')
  14 parser.add_argument('--dump-first-encoder', help='dump activity of the first encoder thread', action='store_true')
  15 parser.add_argument('--from', help='time in seconds to start at', type=int, dest='from_time')
  16 parser.add_argument('--to', help='time in seconds to stop at', type=int, dest='to_time')
  17 args = parser.parse_args()
  18
  19 def find_nth(haystack, needle, n):
  20     start = haystack.find(needle)
  21     while start >= 0 and n > 1:
  22         start = haystack.find(needle, start+len(needle))
  23         n -= 1
  24     return start
  25
  26 class Time:
  27     def __init__(self, s, m = 0):
  28         self.seconds = s
  29         self.microseconds = m
  30
  31     def __str__(self):
  32         return '%d:%d' % (self.seconds, self.microseconds)
  33
  34     def float_seconds(self):
  35         return self.seconds + self.microseconds / 1000000.0
  36
  37     def __sub__(self, x):
  38         m = self.microseconds - x.microseconds
  39         if m < 0:
  40             return Time(self.seconds - x.seconds - 1, m + 1000000)
  41         else:
  42             return Time(self.seconds - x.seconds, m)
  43
  44 queue_size = []
  45 general_events = []
  46 encoder_thread_events = dict()
  47
  48 def add_encoder_thread_event(thread, time, event):
  49     global encoder_thread_events
  50     if thread in encoder_thread_events:
  51         encoder_thread_events[thread].append((time, event))
  52     else:
  53         encoder_thread_events[thread] = [(time, event)]
  54
  55 def add_general_event(time, event):
  56     global general_events
  57     general_events.append((time, event))
  58
  59 f = open(args.log_file)
  60 start = None
  61 while True:
  62     l = f.readline()
  63     if l == '':
  64         break
  65
  66     l = l.strip()
  67     p = l.split()
  68
  69     if len(p) == 0:
  70         continue
  71
  72     if len(p[0].split(':')) == 2:
  73         # s:us timestamp
  74         x = p[0].split(':')
  75         T = Time(int(x[0]), int(x[1]))
  76         message = l[l.find(' ')+1:]
  77     else:
  78         # Date/time timestamp
  79         s = find_nth(l, ':', 3)
  80         T = Time(time.mktime(time.strptime(l[:s])))
  81         message = l[s+2:]
  82
  83     if start is None:
  84         start = T
  85     else:
  86         T = T - start
  87
  88     thread = None
  89     if message.startswith('['):
  90         thread = message.split()[0][1:-1]
  91         message = message[message.find(' ')+1:]
  92
  93     if message.startswith('adding to queue of '):
  94         queue_size.append((T, int(message.split()[4])))
  95     elif message.startswith('encoder thread sleeps'):
  96         add_encoder_thread_event(thread, T, 'sleep')
  97     elif message.startswith('encoder thread wakes'):
  98         add_encoder_thread_event(thread, T, 'wake')
  99     elif message.startswith('encoder thread begins local encode'):
 100         add_encoder_thread_event(thread, T, 'begin_encode')
 101     elif message.startswith('MagickImageProxy begins decode and convert') or message.startswith('MagickImageProxy begins read and decode'):
 102         add_encoder_thread_event(thread, T, 'magick_begin_decode')
 103     elif message.startswith('MagickImageProxy decode finished'):
 104         add_encoder_thread_event(thread, T, 'magick_end_decode')
 105     elif message.startswith('MagickImageProxy completes decode and convert'):
 106         add_encoder_thread_event(thread, T, 'magick_end_unpack')
 107     elif message.startswith('encoder thread finishes local encode'):
 108         add_encoder_thread_event(thread, T, 'end_encode')
 109     elif message.startswith('Finished locally-encoded'):
 110         add_general_event(T, 'end_local_encode')
 111     elif message.startswith('Finished remotely-encoded'):
 112         add_general_event(T, 'end_remote_encode')
 113     elif message.startswith('Transcode job starting'):
 114         add_general_event(T, 'begin_transcode')
 115     elif message.startswith('Transcode job completed successfully'):
 116         add_general_event(T, 'end_transcode')
 117
 118 if args.queue:
 119     plt.figure()
 120     x = []
 121     y = []
 122     for q in queue_size:
 123         x.append(q[0].seconds)
 124         y.append(q[1])
 125
 126     plt.plot(x, y)
 127     plt.show()
 128
 129 elif args.encoder_threads:
 130     plt.figure()
 131     N = len(encoder_thread_events)
 132     n = 1
 133     for thread, events in encoder_thread_events.iteritems():
 134         plt.subplot(N, 1, n)
 135         x = []
 136         y = []
 137         previous = 0
 138         for e in events:
 139             if args.from_time is not None and e[0].float_seconds() <= args.from_time:
 140                 continue
 141             if args.to_time is not None and e[0].float_seconds() >= args.to_time:
 142                 continue
 143             x.append(e[0].float_seconds())
 144             x.append(e[0].float_seconds())
 145             y.append(previous)
 146             if e[1] == 'sleep':
 147                 y.append(0)
 148             elif e[1] == 'wake':
 149                 y.append(1)
 150             elif e[1] == 'begin_encode':
 151                 y.append(2)
 152             elif e[1] == 'end_encode':
 153                 y.append(1)
 154             elif e[1] == 'magick_begin_decode':
 155                 y.append(3)
 156             elif e[1] == 'magick_end_decode':
 157                 y.append(2)
 158
 159             previous = y[-1]
 160
 161         plt.plot(x, y)
 162         n += 1
 163
 164     plt.show()
 165
 166 elif args.plot_first_encoder:
 167     plt.figure()
 168     N = len(encoder_thread_events)
 169     n = 1
 170     events = encoder_thread_events.itervalues().next()
 171
 172     N = 6
 173     n = 1
 174     for t in ['sleep', 'wake', 'begin_encode', 'magick_begin_decode', 'magick_end_decode', 'end_encode']:
 175         plt.subplot(N, 1, n)
 176         x = []
 177         y = []
 178         for e in events:
 179             if args.from_time is not None and e[0].float_seconds() <= args.from_time:
 180                 continue
 181             if args.to_time is not None and e[0].float_seconds() >= args.to_time:
 182                 continue
 183             if e[1] == t:
 184                 x.append(e[0].float_seconds())
 185                 x.append(e[0].float_seconds())
 186                 x.append(e[0].float_seconds())
 187                 y.append(0)
 188                 y.append(1)
 189                 y.append(0)
 190
 191         plt.plot(x, y)
 192         plt.title(t)
 193         n += 1
 194
 195     plt.show()
 196
 197 elif args.dump_first_encoder:
 198     events = encoder_thread_events.itervalues().next()
 199     last = 0
 200     for e in events:
 201         print e[0].float_seconds(), (e[0].float_seconds() - last), e[1]
 202         last = e[0].float_seconds()
 203
 204 elif args.fps_stats:
 205     local = 0
 206     remote = 0
 207     start = None
 208     end = None
 209     for e in general_events:
 210         if e[1] == 'begin_transcode':
 211             start = e[0]
 212         elif e[1] == 'end_transcode':
 213             end = e[0]
 214         elif e[1] == 'end_local_encode':
 215             local += 1
 216         elif e[1] == 'end_remote_encode':
 217             remote += 1
 218
 219     if end == None:
 220         print 'Job did not appear to end'
 221         sys.exit(1)
 222
 223     duration = end - start
 224
 225     print 'Job ran for %fs' % duration.float_seconds()
 226     print '%d local and %d remote' % (local, remote)
 227     print '%.2f fps local and %.2f fps remote' % (local / duration.float_seconds(), remote / duration.float_seconds())