|
| 1 | +import os, sys, time |
| 2 | + |
| 3 | +# usage: parse_log.py log-file [socket-index to focus on] |
| 4 | + |
| 5 | + |
| 6 | +socket_filter = None |
| 7 | +if len(sys.argv) >= 3: |
| 8 | + socket_filter = sys.argv[2].strip() |
| 9 | + |
| 10 | +if socket_filter == None: |
| 11 | + print "scanning for socket with the most packets" |
| 12 | + file = open(sys.argv[1], 'rb') |
| 13 | + |
| 14 | + sockets = {} |
| 15 | + |
| 16 | + for l in file: |
| 17 | + if not 'our_delay' in l: continue |
| 18 | + |
| 19 | + try: |
| 20 | + a = l.strip().split(" ") |
| 21 | + socket_index = a[1][:-1] |
| 22 | + except: |
| 23 | + continue |
| 24 | + |
| 25 | + # msvc's runtime library doesn't prefix pointers |
| 26 | + # with '0x' |
| 27 | +# if socket_index[:2] != '0x': |
| 28 | +# continue |
| 29 | + |
| 30 | + if socket_index in sockets: |
| 31 | + sockets[socket_index] += 1 |
| 32 | + else: |
| 33 | + sockets[socket_index] = 1 |
| 34 | + |
| 35 | + items = sockets.items() |
| 36 | + items.sort(lambda x, y: y[1] - x[1]) |
| 37 | + |
| 38 | + count = 0 |
| 39 | + for i in items: |
| 40 | + print '%s: %d' % (i[0], i[1]) |
| 41 | + count += 1 |
| 42 | + if count > 5: break |
| 43 | + |
| 44 | + file.close() |
| 45 | + socket_filter = items[0][0] |
| 46 | + print '\nfocusing on socket %s' % socket_filter |
| 47 | + |
| 48 | +file = open(sys.argv[1], 'rb') |
| 49 | +out_file = 'utp.out%s' % socket_filter; |
| 50 | +out = open(out_file, 'wb') |
| 51 | + |
| 52 | +delay_samples = 'dots lc rgb "blue"' |
| 53 | +delay_base = 'steps lw 2 lc rgb "purple"' |
| 54 | +target_delay = 'steps lw 2 lc rgb "red"' |
| 55 | +off_target = 'dots lc rgb "blue"' |
| 56 | +cwnd = 'steps lc rgb "green"' |
| 57 | +window_size = 'steps lc rgb "sea-green"' |
| 58 | +rtt = 'lines lc rgb "light-blue"' |
| 59 | + |
| 60 | +metrics = { |
| 61 | + 'our_delay':['our delay (ms)', 'x1y2', delay_samples], |
| 62 | + 'upload_rate':['send rate (B/s)', 'x1y1', 'lines'], |
| 63 | + 'max_window':['cwnd (B)', 'x1y1', cwnd], |
| 64 | + 'target_delay':['target delay (ms)', 'x1y2', target_delay], |
| 65 | + 'cur_window':['bytes in-flight (B)', 'x1y1', window_size], |
| 66 | + 'cur_window_packets':['number of packets in-flight', 'x1y2', 'steps'], |
| 67 | + 'packet_size':['current packet size (B)', 'x1y2', 'steps'], |
| 68 | + 'rtt':['rtt (ms)', 'x1y2', rtt], |
| 69 | + 'off_target':['off-target (ms)', 'x1y2', off_target], |
| 70 | + 'delay_sum':['delay sum (ms)', 'x1y2', 'steps'], |
| 71 | + 'their_delay':['their delay (ms)', 'x1y2', delay_samples], |
| 72 | + 'get_microseconds':['clock (us)', 'x1y1', 'steps'], |
| 73 | + 'wnduser':['advertised window size (B)', 'x1y1', 'steps'], |
| 74 | + |
| 75 | + 'delay_base':['delay base (us)', 'x1y1', delay_base], |
| 76 | + 'their_delay_base':['their delay base (us)', 'x1y1', delay_base], |
| 77 | + 'their_actual_delay':['their actual delay (us)', 'x1y1', delay_samples], |
| 78 | + 'actual_delay':['actual_delay (us)', 'x1y1', delay_samples] |
| 79 | +} |
| 80 | + |
| 81 | +histogram_quantization = 1 |
| 82 | +socket_index = None |
| 83 | + |
| 84 | +columns = [] |
| 85 | + |
| 86 | +begin = None |
| 87 | + |
| 88 | +title = "-" |
| 89 | +packet_loss = 0 |
| 90 | +packet_timeout = 0 |
| 91 | + |
| 92 | +delay_histogram = {} |
| 93 | +window_size = {'0': 0, '1': 0} |
| 94 | + |
| 95 | +# [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 |
| 96 | + |
| 97 | +counter = 0 |
| 98 | + |
| 99 | +print "reading log file" |
| 100 | + |
| 101 | +for l in file: |
| 102 | + if "UTP_Connect" in l: |
| 103 | + title = l[:-2] |
| 104 | + if socket_filter != None: |
| 105 | + title += ' socket: %s' % socket_filter |
| 106 | + else: |
| 107 | + title += ' sum of all sockets' |
| 108 | + continue |
| 109 | + |
| 110 | + try: |
| 111 | + a = l.strip().split(" ") |
| 112 | + t = a[0][1:-1] |
| 113 | + socket_index = a[1][:-1] |
| 114 | + except: |
| 115 | + continue |
| 116 | +# if socket_index[:2] != '0x': |
| 117 | +# continue |
| 118 | + |
| 119 | + if socket_filter != None and socket_index != socket_filter: |
| 120 | + continue |
| 121 | + |
| 122 | + counter += 1 |
| 123 | + if (counter % 300 == 0): |
| 124 | + print "\r%d " % counter, |
| 125 | + |
| 126 | + if "lost." in l: |
| 127 | + packet_loss = packet_loss + 1 |
| 128 | + continue |
| 129 | + if "Packet timeout" in l: |
| 130 | + packet_timeout = packet_timeout + 1 |
| 131 | + continue |
| 132 | + if "our_delay:" not in l: |
| 133 | + continue |
| 134 | + |
| 135 | +# used for Logf timestamps |
| 136 | +# t, m = t.split(".") |
| 137 | +# t = time.strptime(t, "%H:%M:%S") |
| 138 | +# t = list(t) |
| 139 | +# t[0] += 107 |
| 140 | +# t = tuple(t) |
| 141 | +# m = float(m) |
| 142 | +# m /= 1000.0 |
| 143 | +# t = time.mktime(t) + m |
| 144 | + |
| 145 | +# used for tick count timestamps |
| 146 | + t = int(t) |
| 147 | + |
| 148 | + if begin is None: |
| 149 | + begin = t |
| 150 | + t = t - begin |
| 151 | + # print time. Convert from milliseconds to seconds |
| 152 | + print >>out, '%f\t' % (float(t)/1000.), |
| 153 | + |
| 154 | + #if t > 200000: |
| 155 | + # break |
| 156 | + |
| 157 | + fill_columns = not columns |
| 158 | + for i in a[2:]: |
| 159 | + try: |
| 160 | + n, v = i.split(':') |
| 161 | + except: |
| 162 | + continue |
| 163 | + v = float(v) |
| 164 | + if n == "our_delay": |
| 165 | + bucket = v / histogram_quantization |
| 166 | + delay_histogram[bucket] = 1 + delay_histogram.get(bucket, 0) |
| 167 | + if not n in metrics: continue |
| 168 | + if fill_columns: |
| 169 | + columns.append(n) |
| 170 | + if n == "max_window": |
| 171 | + window_size[socket_index] = v |
| 172 | + print >>out, '%f\t' % int(reduce(lambda a,b: a+b, window_size.values())), |
| 173 | + else: |
| 174 | + print >>out, '%f\t' % v, |
| 175 | + print >>out, float(packet_loss * 8000), float(packet_timeout * 8000) |
| 176 | + packet_loss = 0 |
| 177 | + packet_timeout = 0 |
| 178 | + |
| 179 | +out.close() |
| 180 | + |
| 181 | +out = open('%s.histogram' % out_file, 'wb') |
| 182 | +for d,f in delay_histogram.iteritems(): |
| 183 | + print >>out, float(d*histogram_quantization) + histogram_quantization / 2, f |
| 184 | +out.close() |
| 185 | + |
| 186 | + |
| 187 | +plot = [ |
| 188 | + { |
| 189 | + 'data': ['upload_rate', 'max_window', 'cur_window', 'wnduser', 'cur_window_packets', 'packet_size', 'rtt'], |
| 190 | + 'title': 'send-packet-size', |
| 191 | + 'y1': 'Bytes', |
| 192 | + 'y2': 'Time (ms)' |
| 193 | + }, |
| 194 | + { |
| 195 | + 'data': ['our_delay', 'max_window', 'target_delay', 'cur_window', 'wnduser', 'cur_window_packets'], |
| 196 | + 'title': 'uploading', |
| 197 | + 'y1': 'Bytes', |
| 198 | + 'y2': 'Time (ms)' |
| 199 | + }, |
| 200 | + { |
| 201 | + 'data': ['our_delay', 'max_window', 'target_delay', 'cur_window', 'cur_window_packets'], |
| 202 | + 'title': 'uploading_packets', |
| 203 | + 'y1': 'Bytes', |
| 204 | + 'y2': 'Time (ms)' |
| 205 | + }, |
| 206 | + { |
| 207 | + 'data': ['get_microseconds'], |
| 208 | + 'title': 'timer', |
| 209 | + 'y1': 'Time microseconds', |
| 210 | + 'y2': 'Time (ms)' |
| 211 | + }, |
| 212 | + { |
| 213 | + 'data': ['their_delay', 'target_delay', 'rtt'], |
| 214 | + 'title': 'their_delay', |
| 215 | + 'y1': '', |
| 216 | + 'y2': 'Time (ms)' |
| 217 | + }, |
| 218 | + { |
| 219 | + 'data': ['their_actual_delay','their_delay_base'], |
| 220 | + 'title': 'their_delay_base', |
| 221 | + 'y1': 'Time (us)', |
| 222 | + 'y2': '' |
| 223 | + }, |
| 224 | + { |
| 225 | + 'data': ['our_delay', 'target_delay', 'rtt'], |
| 226 | + 'title': 'our-delay', |
| 227 | + 'y1': '', |
| 228 | + 'y2': 'Time (ms)' |
| 229 | + }, |
| 230 | + { |
| 231 | + 'data': ['actual_delay', 'delay_base'], |
| 232 | + 'title': 'our_delay_base', |
| 233 | + 'y1': 'Time (us)', |
| 234 | + 'y2': '' |
| 235 | + } |
| 236 | +] |
| 237 | + |
| 238 | +out = open('utp.gnuplot', 'w+') |
| 239 | + |
| 240 | +files = '' |
| 241 | + |
| 242 | +#print >>out, 'set xtics 0, 20' |
| 243 | +print >>out, "set term png size 1280,800" |
| 244 | +print >>out, 'set output "%s.delays.png"' % out_file |
| 245 | +print >>out, 'set xrange [0:250]' |
| 246 | +print >>out, 'set xlabel "delay (ms)"' |
| 247 | +print >>out, 'set boxwidth 1' |
| 248 | +print >>out, 'set style fill solid' |
| 249 | +print >>out, 'set ylabel "number of packets"' |
| 250 | +print >>out, 'plot "%s.histogram" using 1:2 with boxes' % out_file |
| 251 | + |
| 252 | +print >>out, "set style data steps" |
| 253 | +#print >>out, "set yrange [0:*]" |
| 254 | +print >>out, "set y2range [*:*]" |
| 255 | +files += out_file + '.delays.png ' |
| 256 | +#set hidden3d |
| 257 | +#set title "Peer bandwidth distribution" |
| 258 | +#set xlabel "Ratio" |
| 259 | + |
| 260 | +for p in plot: |
| 261 | + print >>out, 'set title "%s %s"' % (p['title'], title) |
| 262 | + print >>out, 'set xlabel "time (s)"' |
| 263 | + print >>out, 'set ylabel "%s"' % p['y1'] |
| 264 | + print >>out, "set tics nomirror" |
| 265 | + print >>out, 'set y2tics' |
| 266 | + print >>out, 'set y2label "%s"' % p['y2'] |
| 267 | + print >>out, 'set xrange [0:*]' |
| 268 | + print >>out, "set key box" |
| 269 | + print >>out, "set term png size 1280,800" |
| 270 | + print >>out, 'set output "%s-%s.png"' % (out_file, p['title']) |
| 271 | + files += '%s-%s.png ' % (out_file, p['title']) |
| 272 | + |
| 273 | + comma = '' |
| 274 | + print >>out, "plot", |
| 275 | + |
| 276 | + for c in p['data']: |
| 277 | + if not c in metrics: continue |
| 278 | + i = columns.index(c) |
| 279 | + print >>out, '%s"%s" using 1:%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]), |
| 280 | + comma = ', ' |
| 281 | + print >>out, '' |
| 282 | + |
| 283 | +out.close() |
| 284 | + |
| 285 | +os.system("gnuplot utp.gnuplot") |
| 286 | + |
| 287 | +os.system("open %s" % files) |
| 288 | + |
0 commit comments