331 lines
9.4 KiB
Python
Executable File
331 lines
9.4 KiB
Python
Executable File
#!/usr/bin/env python
|
|
# vim: tabstop=8 expandtab shiftwidth=4 softtabstop=4
|
|
|
|
from __future__ import print_function
|
|
|
|
import os
|
|
import sys
|
|
from functools import reduce
|
|
|
|
# usage: parse_log.py log-file [socket-index to focus on]
|
|
|
|
|
|
socket_filter = None
|
|
if len(sys.argv) >= 3:
|
|
socket_filter = sys.argv[2].strip()
|
|
|
|
if socket_filter is None:
|
|
print("scanning for socket with the most packets")
|
|
file = open(sys.argv[1], 'rb')
|
|
|
|
sockets = {}
|
|
|
|
for l in file:
|
|
if 'our_delay' not in l:
|
|
continue
|
|
|
|
try:
|
|
a = l.strip().split(" ")
|
|
socket_index = a[1][:-1]
|
|
except Exception:
|
|
continue
|
|
|
|
# msvc's runtime library doesn't prefix pointers
|
|
# with '0x'
|
|
# if socket_index[:2] != '0x':
|
|
# continue
|
|
|
|
if socket_index in sockets:
|
|
sockets[socket_index] += 1
|
|
else:
|
|
sockets[socket_index] = 1
|
|
|
|
items = list(sockets.items())
|
|
items.sort(lambda x, y: y[1] - x[1])
|
|
|
|
count = 0
|
|
for i in items:
|
|
print('%s: %d' % (i[0], i[1]))
|
|
count += 1
|
|
if count > 5:
|
|
break
|
|
|
|
file.close()
|
|
socket_filter = items[0][0]
|
|
print('\nfocusing on socket %s' % socket_filter)
|
|
|
|
file = open(sys.argv[1], 'rb')
|
|
out_file = 'utp.out%s' % socket_filter
|
|
out = open(out_file, 'wb')
|
|
|
|
delay_samples = 'points lc rgb "blue"'
|
|
delay_base = 'steps lw 2 lc rgb "purple"'
|
|
target_delay = 'steps lw 2 lc rgb "red"'
|
|
off_target = 'dots lc rgb "blue"'
|
|
cwnd = 'steps lc rgb "green" lw 2'
|
|
window_size = 'steps lc rgb "sea-green"'
|
|
rtt = 'lines lc rgb "light-blue"'
|
|
send_buffer = 'lines lc rgb "light-red"'
|
|
|
|
metrics = {
|
|
'our_delay': ['our delay (ms)', 'x1y2', delay_samples],
|
|
'upload_rate': ['send rate (B/s)', 'x1y1', 'lines'],
|
|
'max_window': ['cwnd (B)', 'x1y1', cwnd],
|
|
'target_delay': ['target delay (ms)', 'x1y2', target_delay],
|
|
'cur_window': ['bytes in-flight (B)', 'x1y1', window_size],
|
|
'cur_window_packets': ['number of packets in-flight', 'x1y2', 'steps'],
|
|
'packet_size': ['current packet size (B)', 'x1y2', 'steps'],
|
|
'rtt': ['rtt (ms)', 'x1y2', rtt],
|
|
'off_target': ['off-target (ms)', 'x1y2', off_target],
|
|
'delay_sum': ['delay sum (ms)', 'x1y2', 'steps'],
|
|
'their_delay': ['their delay (ms)', 'x1y2', delay_samples],
|
|
'get_microseconds': ['clock (us)', 'x1y1', 'steps'],
|
|
'wnduser': ['advertised window size (B)', 'x1y1', 'steps'],
|
|
'ssthres': ['slow-start threshold (B)', 'x1y1', 'steps'],
|
|
|
|
'delay_base': ['delay base (us)', 'x1y1', delay_base],
|
|
'their_delay_base': ['their delay base (us)', 'x1y1', delay_base],
|
|
'their_actual_delay': ['their actual delay (us)', 'x1y1', delay_samples],
|
|
'actual_delay': ['actual_delay (us)', 'x1y1', delay_samples],
|
|
'send_buffer': ['send buffer size (B)', 'x1y1', send_buffer],
|
|
'recv_buffer': ['receive buffer size (B)', 'x1y1', 'lines']
|
|
}
|
|
|
|
histogram_quantization = 1
|
|
socket_index = None
|
|
|
|
columns = []
|
|
|
|
begin = None
|
|
|
|
title = "-"
|
|
packet_loss = 0
|
|
packet_timeout = 0
|
|
|
|
delay_histogram = {}
|
|
packet_size_histogram = {}
|
|
window_size = {'0': 0, '1': 0}
|
|
|
|
# [35301484] 0x00ec1190: actual_delay:1021583 our_delay:102 their_delay:-1021345 off_target:297 max_window:2687
|
|
# upload_rate:18942 delay_base:1021481154 delay_sum:-1021242 target_delay:400 acked_bytes:1441 cur_window:2882
|
|
# scaled_gain:2.432
|
|
|
|
counter = 0
|
|
|
|
print("reading log file")
|
|
|
|
for line in file:
|
|
if "UTP_Connect" in line:
|
|
title = line[:-2]
|
|
if socket_filter is not None:
|
|
title += ' socket: %s' % socket_filter
|
|
else:
|
|
title += ' sum of all sockets'
|
|
continue
|
|
|
|
try:
|
|
a = line.strip().split(" ")
|
|
t = a[0][1:-1]
|
|
socket_index = a[1][:-1]
|
|
except Exception:
|
|
continue
|
|
# if socket_index[:2] != '0x':
|
|
# continue
|
|
|
|
if socket_filter is not None and socket_index != socket_filter:
|
|
continue
|
|
|
|
counter += 1
|
|
if (counter % 300 == 0):
|
|
print("\r%d " % counter, end=' ')
|
|
|
|
if "lost." in line:
|
|
packet_loss = packet_loss + 1
|
|
continue
|
|
if "Packet timeout" in line:
|
|
packet_timeout = packet_timeout + 1
|
|
continue
|
|
|
|
if "sending packet" in line:
|
|
v = line.split('size:')[1].split(' ')[0]
|
|
packet_size_histogram[v] = 1 + packet_size_histogram.get(v, 0)
|
|
|
|
if "our_delay:" not in line:
|
|
continue
|
|
|
|
# used for Logf timestamps
|
|
# t, m = t.split(".")
|
|
# t = time.strptime(t, "%H:%M:%S")
|
|
# t = list(t)
|
|
# t[0] += 107
|
|
# t = tuple(t)
|
|
# m = float(m)
|
|
# m /= 1000.0
|
|
# t = time.mktime(t) + m
|
|
|
|
# used for tick count timestamps
|
|
t = int(t)
|
|
|
|
if begin is None:
|
|
begin = t
|
|
t = t - begin
|
|
# print time. Convert from milliseconds to seconds
|
|
print('%f\t' % (float(t) / 1000.), end=' ', file=out)
|
|
|
|
# if t > 200000:
|
|
# break
|
|
|
|
fill_columns = not columns
|
|
for i in a[2:]:
|
|
try:
|
|
n, v = i.split(':')
|
|
except Exception:
|
|
continue
|
|
v = float(v)
|
|
if n == "our_delay":
|
|
bucket = int(v / histogram_quantization)
|
|
delay_histogram[bucket] = 1 + delay_histogram.get(bucket, 0)
|
|
if n not in metrics:
|
|
continue
|
|
if fill_columns:
|
|
columns.append(n)
|
|
if n == "max_window":
|
|
window_size[socket_index] = v
|
|
print('%f\t' % int(reduce(lambda a, b: a + b, list(window_size.values()))), end=' ', file=out)
|
|
else:
|
|
print('%f\t' % v, end=' ', file=out)
|
|
print(float(packet_loss * 8000), float(packet_timeout * 8000), file=out)
|
|
packet_loss = 0
|
|
packet_timeout = 0
|
|
|
|
out.close()
|
|
|
|
out = open('%s.histogram' % out_file, 'wb')
|
|
for d, f in delay_histogram.items():
|
|
print(float(d * histogram_quantization) + histogram_quantization / 2, f, file=out)
|
|
out.close()
|
|
|
|
out = open('%s_packet_size.histogram' % out_file, 'wb')
|
|
for d, f in packet_size_histogram.items():
|
|
print(d, f, file=out)
|
|
out.close()
|
|
|
|
plot = [
|
|
{
|
|
'data': ['max_window', 'send_buffer', 'cur_window', 'rtt'],
|
|
'title': 'send-packet-size',
|
|
'y1': 'Bytes',
|
|
'y2': 'Time (ms)'
|
|
},
|
|
{
|
|
'data': ['upload_rate', 'max_window', 'cur_window', 'wnduser', 'cur_window_packets', 'packet_size', 'rtt'],
|
|
'title': 'slow-start',
|
|
'y1': 'Bytes',
|
|
'y2': 'Time (ms)'
|
|
},
|
|
{
|
|
'data': ['max_window', 'cur_window', 'our_delay', 'target_delay', 'ssthres'],
|
|
'title': 'cwnd',
|
|
'y1': 'Bytes',
|
|
'y2': 'Time (ms)'
|
|
},
|
|
{
|
|
'data': ['our_delay', 'max_window', 'target_delay', 'cur_window', 'wnduser', 'cur_window_packets'],
|
|
'title': 'uploading',
|
|
'y1': 'Bytes',
|
|
'y2': 'Time (ms)'
|
|
},
|
|
{
|
|
'data': ['our_delay', 'max_window', 'target_delay', 'cur_window', 'send_buffer'],
|
|
'title': 'uploading_packets',
|
|
'y1': 'Bytes',
|
|
'y2': 'Time (ms)'
|
|
},
|
|
{
|
|
'data': ['their_delay', 'target_delay', 'rtt'],
|
|
'title': 'their_delay',
|
|
'y1': '',
|
|
'y2': 'Time (ms)'
|
|
},
|
|
{
|
|
'data': ['their_actual_delay', 'their_delay_base'],
|
|
'title': 'their_delay_base',
|
|
'y1': 'Time (us)',
|
|
'y2': ''
|
|
},
|
|
{
|
|
'data': ['our_delay', 'target_delay', 'rtt'],
|
|
'title': 'our-delay',
|
|
'y1': '',
|
|
'y2': 'Time (ms)'
|
|
},
|
|
{
|
|
'data': ['actual_delay', 'delay_base'],
|
|
'title': 'our_delay_base',
|
|
'y1': 'Time (us)',
|
|
'y2': ''
|
|
}
|
|
]
|
|
|
|
out = open('utp.gnuplot', 'w+')
|
|
|
|
files = ''
|
|
|
|
# print('set xtics 0, 20', file=out)
|
|
print("set term png size 1280,800", file=out)
|
|
print('set output "%s.delays.png"' % out_file, file=out)
|
|
print('set xrange [0:200]', file=out)
|
|
print('set xlabel "delay (ms)"', file=out)
|
|
print('set boxwidth 1', file=out)
|
|
print('set ylabel "number of packets"', file=out)
|
|
print('plot "%s.histogram" using 1:2 with boxes fs solid 0.3' % out_file, file=out)
|
|
files += out_file + '.delays.png '
|
|
|
|
print('set output "%s.packet_sizes.png"' % out_file, file=out)
|
|
print('set xrange [0:*]', file=out)
|
|
print('set xlabel "packet size (B)"', file=out)
|
|
print('set boxwidth 1', file=out)
|
|
print('set ylabel "number of packets sent"', file=out)
|
|
print('set logscale y', file=out)
|
|
print('plot "%s_packet_size.histogram" using 1:2 with boxes fs solid 0.3' % out_file, file=out)
|
|
print('set nologscale y', file=out)
|
|
files += out_file + '.packet_sizes.png '
|
|
|
|
print("set style data steps", file=out)
|
|
# print("set yrange [0:*]", file=out)
|
|
print("set y2range [*:*]", file=out)
|
|
# set hidden3d
|
|
# set title "Peer bandwidth distribution"
|
|
# set xlabel "Ratio"
|
|
|
|
for p in plot:
|
|
print('set title "%s %s"' % (p['title'], title), file=out)
|
|
print('set xlabel "time (s)"', file=out)
|
|
print('set ylabel "%s"' % p['y1'], file=out)
|
|
print("set tics nomirror", file=out)
|
|
print('set y2tics', file=out)
|
|
print('set y2label "%s"' % p['y2'], file=out)
|
|
print('set xrange [0:*]', file=out)
|
|
print("set key box", file=out)
|
|
print("set term png size 1280,800", file=out)
|
|
print('set output "%s-%s.png"' % (out_file, p['title']), file=out)
|
|
files += '%s-%s.png ' % (out_file, p['title'])
|
|
|
|
comma = ''
|
|
print("plot", end=' ', file=out)
|
|
|
|
for c in p['data']:
|
|
if c not in metrics:
|
|
continue
|
|
i = columns.index(c)
|
|
print('%s"%s" using ($1/1000):%d title "%s-%s" axes %s with %s' %
|
|
(comma, out_file, i + 2, metrics[c][0], metrics[c][1], metrics[c][1], metrics[c][2]), end=' ', file=out)
|
|
comma = ', '
|
|
print('', file=out)
|
|
|
|
out.close()
|
|
|
|
os.system("gnuplot utp.gnuplot")
|
|
|
|
os.system("open %s" % files)
|