log latency of bittorrent requests

include/libtorrent/aux_/session_impl.hpp

@@ -409,6 +409,11 @@ namespace libtorrent
 			void set_port_filter(port_filter const& f);
 			port_filter const& get_port_filter() const;
 
+			void request_latency_sample(int us)
+			{
+				m_request_latency.add_sample(us);
+				m_stats_counters.set_value(counters::request_latency, m_request_latency.mean());
+			}
 
 			// TODO: move the login info into the tracker_request object
 			void queue_tracker_request(tracker_request& req
@@ -592,6 +597,9 @@ namespace libtorrent
 			void add_redundant_bytes(size_type b, int reason)
 			{
 				TORRENT_ASSERT(b > 0);
+				// TODO: 3 the m_redundant_bytes array should be made part of
+				// the stats counters. That way another session_impl dependency
+				// from the peer connections would be removed
 				m_redundant_bytes[reason] += b;
 				m_stats_counters.inc_stats_counter(counters::recv_redundant_bytes, b);
 			}
@@ -1192,7 +1200,7 @@ namespace libtorrent
 			vm_statistics_data_t m_last_vm_stat;
 			thread_cpu_usage m_network_thread_cpu_usage;
 			sliding_average<20> m_read_ops;
-			sliding_average<20> m_write_ops;;
+			sliding_average<20> m_write_ops;
 #endif
 
 			// each second tick the timer takes a little
@@ -1232,6 +1240,10 @@ namespace libtorrent
 
 			counters m_stats_counters;
 
+			// the sliding average of the latency (in microseconds) from an
+			// incoming request to sending the data back over the socket
+			sliding_average<50> m_request_latency;
+
 #ifdef TORRENT_UPNP_LOGGING
 			std::ofstream m_upnp_log;
 #endif

include/libtorrent/aux_/session_interface.hpp

@@ -244,6 +244,8 @@ namespace libtorrent { namespace aux
 
 		virtual int peak_up_rate() const = 0;
 
+		virtual void request_latency_sample(int us) = 0;
+
 		enum torrent_list_index
 		{
 			// this is the set of (subscribed) torrents that have changed

include/libtorrent/peer_connection.hpp

@@ -883,7 +883,8 @@ namespace libtorrent
 		void do_update_interest();
 		int preferred_caching() const;
 		void fill_send_buffer();
-		void on_disk_read_complete(disk_io_job const* j, peer_request r);
+		void on_disk_read_complete(disk_io_job const* j, peer_request r
+			, ptime issue_time);
 		void on_disk_write_complete(disk_io_job const* j
 			, peer_request r, boost::shared_ptr<torrent> t);
 		void on_seed_mode_hashed(disk_io_job const* j);

include/libtorrent/performance_counters.hpp

@@ -335,6 +335,7 @@ namespace libtorrent
 
 			write_cache_blocks,
 			read_cache_blocks,
+			request_latency,
 			pinned_blocks,
 			disk_blocks_in_use,
 			queued_disk_jobs,

src/peer_connection.cpp

@@ -2487,7 +2487,7 @@ namespace libtorrent
 				int rtt = int(total_milliseconds(time_now_hires() - i->request_time));
 				m_rtt.add_sample(rtt);
 #if defined TORRENT_VERBOSE_LOGGING || defined TORRENT_ERROR_LOGGING
-				peer_log("*** RTT: %d ms [%s +/- %s ms]", rtt, m_rtt.mean()
+				peer_log("*** RTT: %d ms [%d +/- %d ms]", rtt, m_rtt.mean()
 					, m_rtt.avg_deviation());
 #endif
 			}
@@ -5041,7 +5041,7 @@ namespace libtorrent
 				t->inc_refcount("async_read");
 				m_disk_thread.async_read(&t->storage(), r
 					, boost::bind(&peer_connection::on_disk_read_complete
-					, self(), _1, r), this);
+					, self(), _1, r, time_now_hires()), this);
 			}
 			m_requests.erase(m_requests.begin() + i);
 
@@ -5109,19 +5109,23 @@ namespace libtorrent
 		fill_send_buffer();
 	}
 
-	void peer_connection::on_disk_read_complete(disk_io_job const* j, peer_request r)
+	void peer_connection::on_disk_read_complete(disk_io_job const* j
+		, peer_request r, ptime issue_time)
 	{
 		// return value:
 		// 0: success, piece passed hash check
 		// -1: disk failure
 
+		int disk_rtt = int(total_microseconds(time_now_hires() - issue_time));
+
 #ifdef TORRENT_VERBOSE_LOGGING
 		peer_log("*** FILE ASYNC READ COMPLETE [ ret: %d | piece: %d | s: %x | l: %x"
-			" | b: %p | c: %s | e: %s ]"
+			" | b: %p | c: %s | e: %s | rtt: %d us ]"
 			, j->ret, r.piece, r.start, r.length, j->buffer
 			, (j->flags & disk_io_job::cache_hit ? "cache hit" : "cache miss")
-			, j->error.ec.message().c_str());
+			, j->error.ec.message().c_str(), disk_rtt);
 #endif
+
 		m_reading_bytes -= r.length;
 
 		boost::shared_ptr<torrent> t = m_torrent.lock();
@@ -5185,6 +5189,11 @@ namespace libtorrent
 			, r.piece, r.start, r.length);
 #endif
 
+		// TODO: 3 it would be nice if the sliding_average state required
+		// for this would be baked into the counters object, in which case this
+		// would not be a session_impl dependency.
+		m_ses.request_latency_sample(disk_rtt);
+
 		// we probably just pulled this piece into the cache.
 		// if it's rare enough to make it into the suggested piece
 		// push another piece out

src/session_impl.cpp

@@ -1107,6 +1107,8 @@ namespace aux {
 
 			":connection attempt loops"
 
+			":request latency"
+
 			"\n\n", m_stats_logger);
 	}
 #endif
@@ -4412,6 +4414,8 @@ retry:
 
 			STAT_COUNTER(connection_attempt_loops);
 
+			STAT_COUNTER(request_latency);
+
 			fprintf(m_stats_logger, "\n");
 
 #undef STAT_LOG

src/session_stats.cpp

@@ -288,6 +288,11 @@ namespace libtorrent
 
 		METRIC(disk, write_cache_blocks, type_gauge)
 		METRIC(disk, read_cache_blocks, type_gauge)
+
+		// the number of microseconds it takes from receiving a request from a
+		// peer until we're sending the response back on the socket.
+		METRIC(disk, request_latency, type_gauge)
+
 		METRIC(disk, pinned_blocks, type_gauge)
 		METRIC(disk, disk_blocks_in_use, type_gauge)
 		METRIC(disk, queued_disk_jobs, type_gauge)

tools/parse_session_stats.py

@@ -321,6 +321,7 @@ reports = [
 	('pinned torrents', 'num torrents', '', '', ['pinned torrents']),
 	('loaded torrents', 'num torrents', '', '', ['loaded torrents', 'pinned torrents']),
 	('requests', '', '', '', ['outstanding requests']),
+	('request latency', 'us', '', 'latency from receiving requests to sending response', ['request latency']),
 	('incoming messages', 'num', '', 'number of received bittorrent messages, by type', [ \
 		'num_incoming_choke', 'num_incoming_unchoke', 'num_incoming_interested', \
 		'num_incoming_not_interested', 'num_incoming_have', 'num_incoming_bitfield', \