improve utp verbose logging a bit and make the parser pull out more metrics
This commit is contained in:
arvidn
Arvid Norberg
parent
a44ddddede
commit
48a7ab13d5
|
|
@ -739,7 +739,7 @@ void utp_init_mtu(utp_socket_impl* s, int link_mtu, int utp_mtu)
|
|||
}
|
||||
|
||||
bool utp_incoming_packet(utp_socket_impl* s, char const* p
|
||||
, int size, udp::endpoint const& ep, time_point receive_time)
|
||||
, int size, udp::endpoint const& ep, time_point const receive_time)
|
||||
{
|
||||
return s->incoming_packet(reinterpret_cast<boost::uint8_t const*>(p), size
|
||||
, ep, receive_time);
|
||||
|
|
@ -1120,8 +1120,8 @@ size_t utp_stream::read_some(bool clear_buffers)
|
|||
|
||||
if (m_impl->m_receive_buffer_size == 0)
|
||||
{
|
||||
UTP_LOGV(" Didn't fill entire target: %d bytes left in buffer\n"
|
||||
, m_impl->m_receive_buffer_size);
|
||||
UTP_LOGV("%8p: Didn't fill entire target: %d bytes left in buffer\n"
|
||||
, static_cast<void*>(m_impl), m_impl->m_receive_buffer_size);
|
||||
break;
|
||||
}
|
||||
}
|
||||
|
|
@ -1509,8 +1509,8 @@ void utp_socket_impl::parse_close_reason(boost::uint8_t const* ptr, int size)
|
|||
utp_stream::on_close_reason(m_userdata, incoming_close_reason);
|
||||
}
|
||||
|
||||
void utp_socket_impl::parse_sack(boost::uint16_t packet_ack, boost::uint8_t const* ptr
|
||||
, int size, int* acked_bytes, time_point const now, boost::uint32_t& min_rtt)
|
||||
void utp_socket_impl::parse_sack(boost::uint16_t const packet_ack, boost::uint8_t const* ptr
|
||||
, int const size, int* acked_bytes, time_point const now, boost::uint32_t& min_rtt)
|
||||
{
|
||||
INVARIANT_CHECK;
|
||||
|
||||
|
|
@ -1917,7 +1917,6 @@ bool utp_socket_impl::send_pkt(int const flags)
|
|||
p = reinterpret_cast<packet*>(TORRENT_ALLOCA(char, sizeof(packet) + packet_size
|
||||
+ sizeof(packet*) - 1));
|
||||
p = reinterpret_cast<packet*>(align_pointer(p));
|
||||
UTP_LOGV("%8p: allocating %d bytes on the stack\n", static_cast<void*>(this), packet_size);
|
||||
p->allocated = packet_size;
|
||||
}
|
||||
|
||||
|
|
@ -1976,8 +1975,11 @@ bool utp_socket_impl::send_pkt(int const flags)
|
|||
write_payload(p->buf + p->size, size_left);
|
||||
p->size += size_left;
|
||||
|
||||
UTP_LOGV("%8p: NAGLE appending %d bytes to nagle packet. new size: %d allocated: %d\n"
|
||||
, static_cast<void*>(this), size_left, p->size, p->allocated);
|
||||
if (size_left > 0)
|
||||
{
|
||||
UTP_LOGV("%8p: NAGLE appending %d bytes to nagle packet. new size: %d allocated: %d\n"
|
||||
, static_cast<void*>(this), size_left, p->size, p->allocated);
|
||||
}
|
||||
|
||||
// did we fill up the whole mtu?
|
||||
// if we didn't, we may still send it if there's
|
||||
|
|
@ -2352,7 +2354,8 @@ void utp_socket_impl::experienced_loss(int const seq_nr)
|
|||
{
|
||||
m_ssthres = m_cwnd >> 16;
|
||||
m_slow_start = false;
|
||||
UTP_LOGV("%8p: experienced loss, slow_start -> 0\n", static_cast<void*>(this));
|
||||
UTP_LOGV("%8p: experienced loss, slow_start -> 0 ssthres:%d\n"
|
||||
, static_cast<void*>(this), m_ssthres);
|
||||
}
|
||||
}
|
||||
|
||||
|
|
@ -2533,7 +2536,7 @@ bool utp_socket_impl::cancel_handlers(error_code const& ec, bool kill)
|
|||
|
||||
bool utp_socket_impl::consume_incoming_data(
|
||||
utp_header const* ph, boost::uint8_t const* ptr, int payload_size
|
||||
, time_point now)
|
||||
, time_point const now)
|
||||
{
|
||||
INVARIANT_CHECK;
|
||||
|
||||
|
|
@ -3566,7 +3569,7 @@ int utp_socket_impl::packet_timeout() const
|
|||
return timeout;
|
||||
}
|
||||
|
||||
void utp_socket_impl::tick(time_point now)
|
||||
void utp_socket_impl::tick(time_point const now)
|
||||
{
|
||||
INVARIANT_CHECK;
|
||||
|
||||
|
|
|
|||
|
|
@ -69,19 +69,30 @@ metrics = {
|
|||
'cur_window_packets':['number of packets in-flight', 'x1y2', 'steps'],
|
||||
'packet_size':['current packet size (B)', 'x1y2', 'steps'],
|
||||
'rtt':['rtt (ms)', 'x1y2', rtt],
|
||||
'min_rtt':['smallest rtt (ms)', 'x1y2', 'lines'],
|
||||
'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'],
|
||||
'timeout':['until next timeout (ms)', 'x1y2', 'steps'],
|
||||
'rto':['current timeout (ms)', 'x1y2', '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']
|
||||
'recv_buffer':['receive buffer size (B)', 'x1y1', 'lines'],
|
||||
'packet_loss':['packet lost', 'x1y2', 'steps'],
|
||||
'packet_timeout':['packet timed out', 'x1y2', 'steps'],
|
||||
'acked_bytes':['Bytes ACKed by packet', 'x1y2', 'steps'],
|
||||
'bytes_sent':['cumulative bytes sent', 'x1y2', 'steps'],
|
||||
'bytes_resent':['cumulative bytes resent', 'x1y2', 'steps'],
|
||||
'written':['reported written bytes', 'x1y2', 'steps'],
|
||||
'ack_nr':['acked sequence number', 'x1y2', 'steps'],
|
||||
'seq_nr':['sent sequence number', 'x1y2', 'steps'],
|
||||
}
|
||||
|
||||
histogram_quantization = 1
|
||||
|
|
@ -94,10 +105,14 @@ begin = None
|
|||
title = "-"
|
||||
packet_loss = 0
|
||||
packet_timeout = 0
|
||||
num_acked = 0
|
||||
|
||||
delay_histogram = {}
|
||||
packet_size_histogram = {}
|
||||
window_size = {'0': 0, '1': 0}
|
||||
bytes_sent = 0
|
||||
bytes_resent = 0
|
||||
written = 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
|
||||
|
||||
|
|
@ -131,15 +146,34 @@ for l in file:
|
|||
print "\r%d " % counter,
|
||||
|
||||
if "lost." in l:
|
||||
packet_loss = packet_loss + 1
|
||||
packet_loss += 1
|
||||
continue
|
||||
if "Packet timeout" in l:
|
||||
packet_timeout = packet_timeout + 1
|
||||
if "lost (timeout)" in l:
|
||||
packet_timeout += 1
|
||||
continue
|
||||
if "acked packet " in l:
|
||||
num_acked += 1
|
||||
|
||||
if "sending packet" in l:
|
||||
v = l.split('size:')[1].split(' ')[0]
|
||||
packet_size_histogram[v] = 1 + packet_size_histogram.get(v, 0)
|
||||
bytes_sent += int(v)
|
||||
|
||||
if "re-sending packet" in l:
|
||||
v = l.split('size:')[1].split(' ')[0]
|
||||
bytes_resent += int(v)
|
||||
|
||||
if 'calling write handler' in l:
|
||||
v = l.split('written:')[1].split(' ')[0]
|
||||
written += int(v)
|
||||
|
||||
if "incoming packet" in l \
|
||||
and not "ERROR" in l \
|
||||
and "seq_nr:" in l \
|
||||
and "type:ST_SYN" not in l:
|
||||
if "ack_nr:" not in l: print l
|
||||
ack_nr = int(l.split('ack_nr:')[1].split(' ')[0])
|
||||
seq_nr = int(l.split('seq_nr:')[1].split(' ')[0])
|
||||
|
||||
if "our_delay:" not in l:
|
||||
continue
|
||||
|
|
@ -184,9 +218,14 @@ for l in file:
|
|||
print >>out, '%f\t' % int(reduce(lambda a,b: a+b, window_size.values())),
|
||||
else:
|
||||
print >>out, '%f\t' % v,
|
||||
print >>out, float(packet_loss * 8000), float(packet_timeout * 8000)
|
||||
|
||||
if fill_columns:
|
||||
columns += ['packet_loss', 'packet_timeout', 'bytes_sent', 'ack_nr', 'seq_nr', 'bytes_resent', 'written']
|
||||
print >>out, float(packet_loss), float(packet_timeout), float(bytes_sent), ack_nr, seq_nr, float(bytes_resent), written
|
||||
packet_loss = 0
|
||||
packet_timeout = 0
|
||||
num_acked = 0;
|
||||
written = 0
|
||||
|
||||
out.close()
|
||||
|
||||
|
|
@ -207,6 +246,12 @@ plot = [
|
|||
'y1': 'Bytes',
|
||||
'y2': 'Time (ms)'
|
||||
},
|
||||
{
|
||||
'data': ['max_window', 'send_buffer', 'cur_window', 'written'],
|
||||
'title': 'bytes-written',
|
||||
'y1': 'Bytes',
|
||||
'y2': 'Time (ms)'
|
||||
},
|
||||
{
|
||||
'data': ['upload_rate', 'max_window', 'cur_window', 'wnduser', 'cur_window_packets', 'packet_size', 'rtt'],
|
||||
'title': 'slow-start',
|
||||
|
|
@ -219,6 +264,30 @@ plot = [
|
|||
'y1': 'Bytes',
|
||||
'y2': 'Time (ms)'
|
||||
},
|
||||
{
|
||||
'data': ['max_window', 'cur_window', 'packet_loss'],
|
||||
'title': 'packet-loss',
|
||||
'y1': 'Bytes',
|
||||
'y2': 'count'
|
||||
},
|
||||
{
|
||||
'data': ['max_window', 'cur_window', 'packet_timeout'],
|
||||
'title': 'packet-timeout',
|
||||
'y1': 'Bytes',
|
||||
'y2': 'count'
|
||||
},
|
||||
{
|
||||
'data': ['max_window', 'cur_window', 'bytes_sent', 'bytes_resent'],
|
||||
'title': 'cumulative-bytes-sent',
|
||||
'y1': 'Bytes',
|
||||
'y2': 'Cumulative Bytes'
|
||||
},
|
||||
{
|
||||
'data': ['max_window', 'cur_window', 'rto', 'timeout'],
|
||||
'title': 'connection-timeout',
|
||||
'y1': 'Bytes',
|
||||
'y2': 'Time (ms)'
|
||||
},
|
||||
{
|
||||
'data': ['our_delay', 'max_window', 'target_delay', 'cur_window', 'wnduser', 'cur_window_packets'],
|
||||
'title': 'uploading',
|
||||
|
|
@ -227,33 +296,45 @@ plot = [
|
|||
},
|
||||
{
|
||||
'data': ['our_delay', 'max_window', 'target_delay', 'cur_window', 'send_buffer'],
|
||||
'title': 'uploading_packets',
|
||||
'title': 'uploading-packets',
|
||||
'y1': 'Bytes',
|
||||
'y2': 'Time (ms)'
|
||||
},
|
||||
{
|
||||
'data': ['their_delay', 'target_delay', 'rtt'],
|
||||
'title': 'their_delay',
|
||||
'title': 'their-delay',
|
||||
'y1': '',
|
||||
'y2': 'Time (ms)'
|
||||
},
|
||||
{
|
||||
'data': ['their_actual_delay','their_delay_base'],
|
||||
'title': 'their_delay_base',
|
||||
'title': 'their-delay-base',
|
||||
'y1': 'Time (us)',
|
||||
'y2': ''
|
||||
},
|
||||
{
|
||||
'data': ['our_delay', 'target_delay', 'rtt'],
|
||||
'data': ['our_delay', 'target_delay', 'rtt', 'min_rtt'],
|
||||
'title': 'our-delay',
|
||||
'y1': '',
|
||||
'y2': 'Time (ms)'
|
||||
},
|
||||
{
|
||||
'data': ['actual_delay', 'delay_base'],
|
||||
'title': 'our_delay_base',
|
||||
'title': 'our-delay-base',
|
||||
'y1': 'Time (us)',
|
||||
'y2': ''
|
||||
},
|
||||
{
|
||||
'data': ['ack_nr', 'seq_nr'],
|
||||
'title': 'sequence-numbers',
|
||||
'y1': 'Bytes',
|
||||
'y2': 'seqnr'
|
||||
},
|
||||
{
|
||||
'data': ['max_window', 'cur_window', 'acked_bytes'],
|
||||
'title': 'ack-rate',
|
||||
'y1': 'Bytes',
|
||||
'y2': 'Bytes'
|
||||
}
|
||||
]
|
||||
|
||||
|
|
|
|||
Loading…
Reference in New Issue