log uTP receive delay in stats log

include/libtorrent/utp_stream.hpp

@@ -220,6 +220,7 @@ public:
 	size_t read_some(bool clear_buffers);
 	
 	int send_delay() const;
+	int recv_delay() const;
 
 	void do_connect(tcp::endpoint const& ep, connect_handler_t h);
 

parse_session_stats.py

@@ -144,8 +144,9 @@ reports = [
 	('disk_iops', 'operations/s', '', 'number of disk operations per second', ['read ops/s', 'write ops/s', 'smooth read ops/s', 'smooth write ops/s']),
 	('disk pending reads', 'Bytes', '', 'number of bytes peers are waiting for to be read from the disk', ['pending reading bytes']),
 	('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', 'buffering delay', 's', 'network delays measured by uTP', ['uTP peak send delay','uTP avg send delay']),
+	('uTP delay', 'buffering delay', 's', 'network delays measured by uTP', ['uTP peak send delay','uTP peak recv delay', 'uTP avg send delay', 'uTP avg recv delay']),
-	('uTP delay histogram', 'buffering delay', 's', 'network delays measured by uTP', ['uTP avg send delay'], True),
+	('uTP send delay histogram', 'buffering delay', 's', 'send delays measured by uTP', ['uTP avg send delay'], True),
+	('uTP recv delay histogram', 'buffering delay', 's', 'receive delays measured by uTP', ['uTP avg recv delay'], True),
 	('system memory', '', '', 'virtual memory page count', ['active resident pages', 'inactive resident pages', 'pinned resident pages', 'free pages']),
 	('memory paging', '', '', 'vm disk activity', ['pageins', 'pageouts']),
 	('page faults', '', '', '', ['page faults']),

src/session_impl.cpp

@@ -1031,6 +1031,8 @@ namespace aux {
 			":uTP down rate"
 			":uTP peak send delay"
 			":uTP avg send delay"
+			":uTP peak recv delay"
+			":uTP avg recv delay"
 			":read ops/s"
 			":write ops/s"
 			":active resident pages"
@@ -3271,8 +3273,11 @@ namespace aux {
 		int utp_up_rate = 0;
 		int utp_down_rate = 0;
 		int utp_peak_send_delay = 0;
+		int utp_peak_recv_delay = 0;
 		boost::uint64_t utp_send_delay_sum = 0;
+		boost::uint64_t utp_recv_delay_sum = 0;
 		int utp_num_delay_sockets = 0;
+		int utp_num_recv_delay_sockets = 0;
 		int num_complete_connections = 0;
 		int num_half_open = 0;
 		int peers_down_unchoked = 0;
@@ -3329,12 +3334,19 @@ namespace aux {
 				utp_up_rate += ul_rate;
 				utp_down_rate += dl_rate;
 				int send_delay = utp_socket->send_delay();
+				int recv_delay = utp_socket->recv_delay();
 				utp_peak_send_delay = (std::max)(utp_peak_send_delay, send_delay);
+				utp_peak_recv_delay = (std::max)(utp_peak_recv_delay, recv_delay);
 				if (send_delay > 0)
 				{
 					utp_send_delay_sum += send_delay;
 					++utp_num_delay_sockets;
 				}
+				if (recv_delay > 0)
+				{
+					utp_recv_delay_sum += recv_delay;
+					++utp_num_recv_delay_sockets;
+				}
 			}
 			else
 			{
@@ -3477,6 +3489,8 @@ namespace aux {
 			STAT_LOG(d, utp_down_rate);
 			STAT_LOG(f, float(utp_peak_send_delay) / 1000000.f);
 			STAT_LOG(f, float(utp_num_delay_sockets ? float(utp_send_delay_sum) / float(utp_num_delay_sockets) : 0) / 1000000.f);
+			STAT_LOG(f, float(utp_peak_recv_delay) / 1000000.f);
+			STAT_LOG(f, float(utp_num_recv_delay_sockets ? float(utp_recv_delay_sum) / float(utp_num_recv_delay_sockets) : 0) / 1000000.f);
 			STAT_LOG(f, float(cs.reads - m_last_cache_status.reads) * 1000.0 / float(tick_interval_ms));
 			STAT_LOG(f, float(cs.writes - m_last_cache_status.writes) * 1000.0 / float(tick_interval_ms));
 

src/utp_stream.cpp

@@ -237,7 +237,7 @@ struct utp_socket_impl
 		, m_in_packets(0)
 		, m_out_packets(0)
 		, m_send_delay(0)
-//		, m_recv_delay(0)
+		, m_recv_delay(0)
 		, m_port(0)
 		, m_send_id(send_id)
 		, m_recv_id(recv_id)
@@ -470,7 +470,7 @@ struct utp_socket_impl
 	// the last send delay sample
 	boost::int32_t m_send_delay;
 	// the last receive delay sample
-//	boost::int32_t m_recv_delay;
+	boost::int32_t m_recv_delay;
 
 	// average RTT
 	sliding_average<16> m_rtt;
@@ -683,6 +683,11 @@ int utp_stream::send_delay() const
 	return m_impl ? m_impl->m_send_delay : 0;
 }
 
+int utp_stream::recv_delay() const
+{
+	return m_impl ? m_impl->m_recv_delay : 0;
+}
+
 utp_stream::utp_stream(asio::io_service& io_service)
 	: m_io_service(io_service)
 	, m_impl(0)
@@ -2505,6 +2510,8 @@ bool utp_socket_impl::incoming_packet(char const* buf, int size
 				m_send_delay = delay;
 			}
 
+			m_recv_delay = (std::min)(their_delay, min_rtt);
+
 			consume_incoming_data(ph, ptr, payload_size, receive_time);
 
 			// the parameter to send_pkt tells it if we're acking data