3 # Analyse a DCP-o-matic log file to extract various information.
10 matplotlib.use('GTK3Cairo')
11 import matplotlib.pyplot as plt
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()
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))
34 # Representation of time in seconds and microseconds
36 def __init__(self, s=0, m=0):
41 return '%d:%d' % (self.seconds, self.microseconds)
43 def float_seconds(self):
44 return self.seconds + self.microseconds / 1000000.0
46 def __iadd__(self, x):
47 self.microseconds += x.microseconds
48 self.seconds += x.seconds
49 if self.microseconds >= 1000000:
50 self.microseconds -= 1000000
55 m = self.microseconds - x.microseconds
57 return Time(self.seconds - x.seconds - 1, m + 1000000)
59 return Time(self.seconds - x.seconds, m)
62 def __init__(self, id):
67 def add_event(self, time, message, values):
68 self.events.append((time, message, values))
74 def find_encoder_thread(id):
75 global encoder_threads
77 for t in encoder_threads:
82 thread = EncoderThread(id)
83 encoder_threads.append(thread)
87 def add_general_event(time, event):
89 general_events.append((time, event))
91 f = open(args.log_file)
103 if len(p[0].split(':')) == 2:
104 # s:us timestamp: LOG_TIMING
106 T = Time(int(t[0]), int(t[1]))
110 for i in range(2, len(p)):
115 # Date/time timestamp: other LOG_*
116 s = find_nth(l, ':', 3)
118 T = Time(time.mktime(time.strptime(l[:s])))
121 T = Time(time.mktime(time.strptime(l[:s], "%d.%m.%Y %H:%M:%S")))
124 T = Time(time.mktime(time.strptime(l[:s], "%d/%m/%Y %H:%M:%S")))
127 if not x.endswith('M'):
129 T = Time(time.mktime(time.strptime(x, "%d/%m/%Y %H:%M:%S %p")))
132 # T is elapsed time since the first log message
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')
154 # Plot queue size against time; queue_size contains times and queue sizes
159 x.append(q[0].seconds)
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
172 if args.max_encoder_threads is not None:
173 encoder_threads = encoder_threads[0:min(args.max_encoder_threads, len(encoder_threads))]
176 N = len(encoder_threads)
178 for thread in encoder_threads:
180 plt.ylim([-0.5, 2.5])
184 for e in thread.events:
185 if args.from_time is not None and e[0].float_seconds() <= args.from_time:
187 if args.to_time is not None and e[0].float_seconds() >= args.to_time:
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':
191 x.append(e[0].float_seconds())
192 x.append(e[0].float_seconds())
194 if e[1] == 'encoder-sleep':
196 elif e[1] == 'encoder-wake':
198 elif e[1] == 'start-local-encode':
200 elif e[1] == 'finish-local-encode':
202 elif e[1] == 'start-remote-encode':
204 elif e[1] == 'finish-remote-encode':
207 print('unknown event %s' % e[1], file=sys.stderr)
217 elif args.plot_first_encoder:
219 N = len(encoder_threads)
221 events = encoder_threads[0].events
225 for t in ['encoder-sleep', 'encoder-wake', 'start-local-encode', 'finish-local-encode']:
230 if args.from_time is not None and e[0].float_seconds() <= args.from_time:
232 if args.to_time is not None and e[0].float_seconds() >= args.to_time:
235 x.append(e[0].float_seconds())
236 x.append(e[0].float_seconds())
237 x.append(e[0].float_seconds())
248 elif args.encoder_dump:
249 for t in encoder_threads[int(args.encoder)]:
252 print((e[0].float_seconds() - last), e[1])
253 last = e[0].float_seconds()
260 for e in general_events:
261 if e[1] == 'begin_transcode':
263 elif e[1] == 'end_transcode':
265 elif e[1] == 'end_local_encode':
267 elif e[1] == 'end_remote_encode':
271 print('Job did not appear to end')
274 duration = end - start
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()))
280 elif args.encoder_stats:
281 # Broad stats on what encoder threads spent their time doing
282 for t in encoder_threads:
285 local_encoding = Time()
287 remote_encoding = Time()
292 if last[1] == 'encoder-sleep':
293 asleep += e[0] - last[0]
294 elif last[1] == 'encoder-wake':
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']
309 print('-- Encoder thread %s (%s)' % (t.server, t.id))
310 print('\tAwoken %d times' % wakes)
312 total = asleep.float_seconds() + local_encoding.float_seconds() + sending.float_seconds() + remote_encoding.float_seconds() + receiving.float_seconds()
316 print('\t%s: %2.f%% %fs' % ('Asleep'.ljust(16), asleep.float_seconds() * 100 / total, asleep.float_seconds()))
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()))
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))