diff --git a/include/libtorrent/aux_/session_impl.hpp b/include/libtorrent/aux_/session_impl.hpp index c53354f8e..600c666e7 100644 --- a/include/libtorrent/aux_/session_impl.hpp +++ b/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 diff --git a/include/libtorrent/aux_/session_interface.hpp b/include/libtorrent/aux_/session_interface.hpp index 9f5574a70..4bee69249 100644 --- a/include/libtorrent/aux_/session_interface.hpp +++ b/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 diff --git a/include/libtorrent/peer_connection.hpp b/include/libtorrent/peer_connection.hpp index 104869548..163ef6518 100644 --- a/include/libtorrent/peer_connection.hpp +++ b/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 t); void on_seed_mode_hashed(disk_io_job const* j); diff --git a/include/libtorrent/performance_counters.hpp b/include/libtorrent/performance_counters.hpp index a03ba9c5e..2ed6748df 100644 --- a/include/libtorrent/performance_counters.hpp +++ b/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, diff --git a/src/peer_connection.cpp b/src/peer_connection.cpp index 8595070cc..89fd4e443 100644 --- a/src/peer_connection.cpp +++ b/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 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 diff --git a/src/session_impl.cpp b/src/session_impl.cpp index 3a0e49f3c..28b1c7bc4 100644 --- a/src/session_impl.cpp +++ b/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 diff --git a/src/session_stats.cpp b/src/session_stats.cpp index 6e7f74bd4..3db1d6528 100644 --- a/src/session_stats.cpp +++ b/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) diff --git a/tools/parse_session_stats.py b/tools/parse_session_stats.py index e6b4c7052..390fd3903 100755 --- a/tools/parse_session_stats.py +++ b/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', \