measure uTP send delay and log it in stats log. change unit on times to seconds (from milliseconds and microseconds)

include/libtorrent/utp_stream.hpp

@@ -216,6 +216,8 @@ public:
 	void set_write_handler(handler_t h);
 	size_t read_some(bool clear_buffers);
 	
+	int send_delay() const;
+
 	void do_connect(tcp::endpoint const& ep, connect_handler_t h);
 
 	endpoint_type local_endpoint() const

parse_session_stats.py

@@ -46,7 +46,7 @@ def gen_report(name, unit, lines, short_unit, generation, log_file):
 	print >>out, "set tics nomirror"
 	print >>out, "set style data lines"
 	print >>out, "set key box"
-	print >>out, "set format y \"%%.0s%%c%s\";" % short_unit
+	print >>out, "set format y \"%%.1s%%c%s\";" % short_unit
 	print >>out, 'plot',
 	column = 2
 	first = True
@@ -107,23 +107,24 @@ reports = [
 	('peers', 'num', '', 'num connected peers', ['peers', 'connecting peers', 'connection attempts', 'banned peers', 'max connections']),
 	('connect_candidates', 'num', '', 'number of peers we know of that we can connect to', ['connect candidates']),
 	('peers_list_size', 'num', '', 'number of known peers (not necessarily connected)', ['num list peers']),
-	('overall_rates', 'Bytes / second', 'B/s', 'download and upload rates', ['uploaded bytes', 'downloaded bytes', 'upload rate', 'download rate', 'smooth upload rate', 'smooth download rate']),
+	('overall_rates', 'rate', 'B/s', 'download and upload rates', ['uploaded bytes', 'downloaded bytes', 'upload rate', 'download rate', 'smooth upload rate', 'smooth download rate']),
 	('disk_write_queue', 'Bytes', 'B', 'bytes queued up by peers, to be written to disk', ['disk write queued bytes', 'disk queue limit', 'disk queue low watermark']),
 	('peers_upload', 'num', '', 'number of peers by state wrt. uploading', ['peers up interested', 'peers up unchoked', 'peers up requests', 'peers disk-up', 'peers bw-up', 'max unchoked']),
 	('peers_download', 'num', '', 'number of peers by state wrt. downloading', ['peers down interesting', 'peers down unchoked', 'peers down requests', 'peers disk-down', 'peers bw-down','num end-game peers']),
 	('peer_errors', 'num', '', 'number of peers by error that disconnected them', ['error peers', 'peer disconnects', 'peers eof', 'peers connection reset', 'connect timeouts', 'uninteresting peers disconnect', 'banned for hash failure']),
 	('waste', '% of all downloaded bytes', '%%', 'proportion of all downloaded bytes that were wasted', ['% failed payload bytes', '% wasted payload bytes', '% protocol bytes']),
-	('average_disk_time_absolute', 'microseconds', 'us', 'running averages of timings of disk operations', ['disk read time', 'disk write time', 'disk queue time', 'disk hash time', 'disk job time', 'disk sort time']),
+	('average_disk_time_absolute', 'job time', 's', 'running averages of timings of disk operations', ['disk read time', 'disk write time', 'disk queue time', 'disk hash time', 'disk job time', 'disk sort time']),
 	('disk_time', '% of total disk job time', '%%', 'proportion of time spent by the disk thread', ['% read time', '% write time', '% hash time', '% sort time']),
 	('disk_cache_hits', 'blocks (16kiB)', '', '', ['disk block read', 'read cache hits', 'disk block written', 'disk read back']),
 	('disk_cache', 'blocks (16kiB)', '', 'disk cache size and usage', ['read disk cache size', 'disk cache size', 'disk buffer allocations', 'cache size']),
 	('disk_readback', '% of written blocks', '%%', 'portion of written blocks that had to be read back for hash verification', ['% read back']),
 	('disk_queue', 'number of queued disk jobs', '', 'queued disk jobs', ['disk queue size', 'disk read queue size', 'read job queue size limit']),
-	('mixed mode', 'rate', '', 'rates by transport protocol', ['tcp up rate','tcp down rate','utp up rate','utp down rate','tcp up limit','tcp down limit']),
+	('mixed mode', 'rate', 'B/s', 'rates by transport protocol', ['TCP up rate','TCP down rate','uTP up rate','uTP down rate','TCP up limit','TCP down limit']),
+	('uTP delay', 'buffer delay', 's', 'network delays measured by uTP', ['uTP peak send delay','uTP avg send delay']),
 #	('absolute_waste', 'num', '', ['failed bytes', 'redundant bytes', 'download rate']),
 
 #somewhat uninteresting stats
-	('tick_rate', 'milliseconds between ticks', 'ms', '', ['tick interval', 'tick residual']),
+	('tick_rate', 'time between ticks', 's', '', ['tick interval', 'tick residual']),
 	('peer_dl_rates', 'num', '', 'peers split into download rate buckets', ['peers down 0', 'peers down 0-2', 'peers down 2-5', 'peers down 5-10', 'peers down 50-100', 'peers down 100-']),
 	('peer_dl_rates2', 'num', '', 'peers split into download rate buckets (only downloading peers)', ['peers down 0-2', 'peers down 2-5', 'peers down 5-10', 'peers down 50-100', 'peers down 100-']),
 	('peer_ul_rates', 'num', '', 'peers split into upload rate buckets', ['peers up 0', 'peers up 0-2', 'peers up 2-5', 'peers up 5-10', 'peers up 50-100', 'peers up 100-']),

src/session_impl.cpp

@@ -961,10 +961,12 @@ namespace aux {
 			":num end-game peers"
 			":TCP up rate"
 			":TCP down rate"
-			":TCP down limit"
 			":TCP up limit"
+			":TCP down limit"
 			":uTP up rate"
 			":uTP down rate"
+			":uTP peak send delay"
+			":uTP avg send delay"
 			"\n\n", m_stats_logger);
 	}
 #endif
@@ -3153,6 +3155,9 @@ namespace aux {
 		int tcp_down_rate = 0;
 		int utp_up_rate = 0;
 		int utp_down_rate = 0;
+		int utp_peak_send_delay = 0;
+		boost::uint64_t utp_send_delay_sum = 0;
+		int utp_num_delay_sockets = 0;
 		int num_complete_connections = 0;
 		int num_half_open = 0;
 		int peers_down_unchoked = 0;
@@ -3201,10 +3206,18 @@ namespace aux {
 			++peer_dl_rate_buckets[dl_bucket];
 			++peer_ul_rate_buckets[ul_bucket];
 
-			if (p->get_socket()->get<utp_stream>())
+			utp_stream* utp_socket = p->get_socket()->get<utp_stream>();
+			if (utp_socket)
 			{
 				utp_up_rate += ul_rate;
-				utp_down_rate += ul_rate;
+				utp_down_rate += dl_rate;
+				int send_delay = utp_socket->send_delay();
+				utp_peak_send_delay = (std::max)(utp_peak_send_delay, send_delay);
+				if (send_delay > 0)
+				{
+					utp_send_delay_sum += send_delay;
+					++utp_num_delay_sockets;
+				}
 			}
 			else
 			{
@@ -3234,11 +3247,11 @@ namespace aux {
 				  "%d\t%d\t%d\t%d\t%d\t%d\t%d\t%d\t%d\t%d\t"
 				  "%d\t%d\t%d\t%d\t%d\t%d\t%d\t%d\t%d\t%d\t"
 				  "%d\t%d\t%d\t%d\t%d\t%d\t%d\t%d\t%d\t%d\t"
-				  "%f\t%f\t%f\t%d\t%d\t%d\t%d\t%d\t%d\t%d\t"
+				  "%f\t%f\t%f\t%f\t%f\t%f\t%d\t%d\t%d\t%d\t"
-				  "%d\t%d\t%d\t%d\t%d\t%d\t%d\t%d\t%d\t%d\t"
+				  "%d\t%d\t%d\t%d\t%d\t%d\t%d\t%f\t%f\t%f\t"
 				  "%d\t%d\t%d\t%d\t%d\t%d\t%d\t%d\t%f\t%f\t"
-				  "%f\t%f\t%d\t%f\t%d\t%d\t%d\t%d\t%d\t%d\t"
+				  "%f\t%f\t%d\t%f\t%d\t%f\t%f\t%d\t%d\t%d\t"
-				  "%d\t%d\t%d\t%d\t%d\t%d\t%d\t%d\n"
+				  "%d\t%d\t%d\t%d\t%d\t%d\t%d\t%d\t%f\t%f\n"
 				, total_milliseconds(now - m_last_log_rotation) / 1000.f
 				, int(m_stat.total_upload() - m_last_uploaded)
 				, int(m_stat.total_download() - m_last_downloaded)
@@ -3302,9 +3315,9 @@ namespace aux {
 				, (float(m_total_failed_bytes) * 100.f / m_stat.total_payload_download())
 				, (float(m_total_redundant_bytes) * 100.f / m_stat.total_payload_download())
 				, (float(m_stat.total_protocol_download()) * 100.f / m_stat.total_download())
-				, int(cs.average_read_time)
+				, float(cs.average_read_time) / 1000000.f
-				, int(cs.average_write_time)
+				, float(cs.average_write_time) / 1000000.f
-				, int(cs.average_queue_time)
+				, float(cs.average_queue_time) / 1000000.f
 				, int(cs.job_queue_length)
 				, int(cs.queued_bytes)
 				, int(cs.blocks_read_hit - m_last_cache_status.blocks_read_hit)
@@ -3316,9 +3329,9 @@ namespace aux {
 				, cs.read_cache_size
 				, cs.cache_size
 				, cs.total_used_buffers
-				, int(cs.average_hash_time)
+				, float(cs.average_hash_time) / 1000000.f
-				, int(cs.average_job_time)
+				, float(cs.average_job_time) / 1000000.f
-				, int(cs.average_sort_time)
+				, float(cs.average_sort_time) / 1000000.f
 				, m_connection_attempts
 				, m_num_banned_peers
 				, m_banned_for_hash_failure
@@ -3334,8 +3347,8 @@ namespace aux {
 				, int(cs.total_read_back - m_last_cache_status.total_read_back)
 				, float(cs.total_read_back * 100.f / (cs.blocks_written == 0 ? 1: cs.blocks_written))
 				, cs.read_queue_size
-				, tick_interval_ms
+				, float(tick_interval_ms) / 1000.f
-				, m_tick_residual
+				, float(m_tick_residual) / 1000.f
 				, m_allowed_upload_slots
 				, m_settings.unchoke_slots_limit * 2
 				, m_stat.low_pass_upload_rate()
@@ -3347,6 +3360,8 @@ namespace aux {
 				, int(m_tcp_download_channel.throttle())
 				, utp_up_rate
 				, utp_down_rate
+				, float(utp_peak_send_delay) / 1000000.f
+				, float(utp_num_delay_sockets ? float(utp_send_delay_sum) / float(utp_num_delay_sockets) : 0) / 1000000.f
 			);
 			m_last_cache_status = cs;
 			m_last_failed = m_total_failed_bytes;

src/utp_stream.cpp

@@ -236,6 +236,8 @@ struct utp_socket_impl
 		, m_in_buf_size(100 * 1024 * 1024)
 		, m_in_packets(0)
 		, m_out_packets(0)
+		, m_send_delay(0)
+//		, m_recv_delay(0)
 		, m_port(0)
 		, m_send_id(send_id)
 		, m_recv_id(recv_id)
@@ -473,6 +475,11 @@ struct utp_socket_impl
 	boost::uint32_t m_in_packets;
 	boost::uint32_t m_out_packets;
 
+	// the last send delay sample
+	boost::int32_t m_send_delay;
+	// the last receive delay sample
+//	boost::int32_t m_recv_delay;
+
 	// average RTT
 	sliding_average<16> m_rtt;
 
@@ -679,6 +686,11 @@ int utp_socket_state(utp_socket_impl const* s)
 	return s->m_state;
 }
 
+int utp_stream::send_delay() const
+{
+	return m_impl ? m_impl->m_send_delay : 0;
+}
+
 utp_stream::utp_stream(asio::io_service& io_service)
 	: m_io_service(io_service)
 	, m_impl(0)
@@ -2485,7 +2497,10 @@ bool utp_socket_impl::incoming_packet(char const* buf, int size
 			delay = *std::min_element(m_delay_sample_hist, m_delay_sample_hist + num_delay_hist);
 
 			if (sample && acked_bytes && prev_bytes_in_flight)
+			{
 				do_ledbat(acked_bytes, delay, prev_bytes_in_flight, receive_time);
+				m_send_delay = delay;
+			}
 
 			consume_incoming_data(ph, ptr, payload_size, receive_time);