[net/dns] Measure performance of adaptive UDP timeout.

Continuation of Szymon's work here: https://chromiumcodereview.appspot.com/12690019/.

patch from issue 12690019

BUG=110197

Review URL: https://chromiumcodereview.appspot.com/15293009

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@201747 0039d316-1c4b-4281-b951-d872f2087c98

3 files changed, 235 insertions, 27 deletions

diff --git a/net/dns/dns_session.cc b/net/dns/dns_session.cc
index 56e0b2e..688697b 100644
--- a/net/dns/dns_session.cc
+++ b/net/dns/dns_session.cc
@@ -6,6 +6,8 @@
 
 #include "base/basictypes.h"
 #include "base/bind.h"
+#include "base/metrics/histogram.h"
+#include "base/metrics/sample_vector.h"
 #include "base/rand_util.h"
 #include "base/stl_util.h"
 #include "base/time.h"
@@ -18,6 +20,19 @@
 
 namespace net {
 
+namespace {
+// Never exceed max timeout.
+const base::TimeDelta kMaxTimeout = base::TimeDelta::FromSeconds(5);
+
+// Set min timeout, in case we are talking to a local DNS proxy.
+const base::TimeDelta kMinTimeout = base::TimeDelta::FromMilliseconds(10);
+
+// Number of buckets in the histogram of observed RTTs.
+const size_t kRTTBucketCount = 100;
+// Target percentile in the RTT histogram used for retransmission timeout.
+const unsigned kRTOPercentile = 99;
+}  // namespace
+
 DnsSession::SocketLease::SocketLease(scoped_refptr<DnsSession> session,
                                      unsigned server_index,
                                      scoped_ptr<DatagramClientSocket> socket)
@@ -35,8 +50,19 @@ DnsSession::DnsSession(const DnsConfig& config,
       socket_pool_(socket_pool.Pass()),
       rand_callback_(base::Bind(rand_int_callback, 0, kuint16max)),
       net_log_(net_log),
-      server_index_(0) {
+      server_index_(0),
+      rtt_estimates_(config_.nameservers.size(), config_.timeout),
+      rtt_deviations_(config_.nameservers.size()),
+      rtt_buckets_(new base::BucketRanges(kRTTBucketCount + 1)) {
   socket_pool_->Initialize(&config_.nameservers, net_log);
+
+  // TODO(mef): This could be done once per process lifetime.
+  base::Histogram::InitializeBucketRanges(1, 5000, kRTTBucketCount,
+                                          rtt_buckets_.get());
+  for (size_t i = 0; i < config_.nameservers.size(); ++i) {
+    rtt_histograms_.push_back(
+        new base::SampleVector(rtt_buckets_.get()));
+  }
 }
 
 DnsSession::~DnsSession() {
@@ -53,12 +79,53 @@ int DnsSession::NextFirstServerIndex() {
   return index;
 }
 
-base::TimeDelta DnsSession::NextTimeout(int attempt) {
+void DnsSession::RecordRTT(unsigned server_index, base::TimeDelta rtt) {
+  DCHECK_LT(server_index, rtt_histograms_.size());
+
+  // For measurement, assume it is the first attempt (no backoff).
+  base::TimeDelta timeout_jacobson = NextTimeoutFromJacobson(server_index, 0);
+  base::TimeDelta timeout_histogram = NextTimeoutFromHistogram(server_index, 0);
+  UMA_HISTOGRAM_TIMES("AsyncDNS.TimeoutErrorJacobson",
+                      rtt - timeout_jacobson);
+  UMA_HISTOGRAM_TIMES("AsyncDNS.TimeoutErrorHistogram",
+                      rtt - timeout_histogram);
+  UMA_HISTOGRAM_TIMES("AsyncDNS.TimeoutErrorJacobsonUnder",
+                      timeout_jacobson - rtt);
+  UMA_HISTOGRAM_TIMES("AsyncDNS.TimeoutErrorHistogramUnder",
+                      timeout_histogram - rtt);
+
+  // Jacobson/Karels algorithm for TCP.
+  // Using parameters: alpha = 1/8, delta = 1/4, beta = 4
+  base::TimeDelta& estimate = rtt_estimates_[server_index];
+  base::TimeDelta& deviation = rtt_deviations_[server_index];
+  base::TimeDelta current_error = rtt - estimate;
+  estimate += current_error / 8;  // * alpha
+  base::TimeDelta abs_error = base::TimeDelta::FromInternalValue(
+      std::abs(current_error.ToInternalValue()));
+  deviation += (abs_error - deviation) / 4;  // * delta
+
+  // Histogram-based method.
+  rtt_histograms_[server_index]->Accumulate(rtt.InMilliseconds(), 1);
+}
+
+void DnsSession::RecordLostPacket(unsigned server_index, int attempt) {
+  base::TimeDelta timeout_jacobson = NextTimeoutFromJacobson(server_index,
+                                                             attempt);
+  base::TimeDelta timeout_histogram = NextTimeoutFromHistogram(server_index,
+                                                               attempt);
+  UMA_HISTOGRAM_TIMES("AsyncDNS.TimeoutSpentJacobson", timeout_jacobson);
+  UMA_HISTOGRAM_TIMES("AsyncDNS.TimeoutSpentHistogram", timeout_histogram);
+}
+
+base::TimeDelta DnsSession::NextTimeout(unsigned server_index, int attempt) {
+  DCHECK_LT(server_index, rtt_histograms_.size());
+
+  base::TimeDelta timeout = config_.timeout;
+
   // The timeout doubles every full round (each nameserver once).
-  // TODO(szym): Adapt timeout to observed RTT. http://crbug.com/110197
-  const base::TimeDelta kMaxTimeout = base::TimeDelta::FromSeconds(5);
   unsigned num_backoffs = attempt / config_.nameservers.size();
-  return std::min(config_.timeout * (1 << num_backoffs), kMaxTimeout);
+
+  return std::min(timeout * (1 << num_backoffs), kMaxTimeout);
 }
 
 // Allocate a socket, already connected to the server address.
@@ -96,4 +163,47 @@ void DnsSession::FreeSocket(
   socket_pool_->FreeSocket(server_index, socket.Pass());
 }
 
+base::TimeDelta DnsSession::NextTimeoutFromJacobson(
+    unsigned server_index, int attempt) {
+  DCHECK_LT(server_index, rtt_estimates_.size());
+
+  base::TimeDelta timeout = rtt_estimates_[server_index] +
+                            4 * rtt_deviations_[server_index];
+
+  timeout = std::max(timeout, kMinTimeout);
+
+  // The timeout doubles every full round.
+  unsigned num_backoffs = attempt / config_.nameservers.size();
+
+  return std::min(timeout * (1 << num_backoffs), kMaxTimeout);
+}
+
+base::TimeDelta DnsSession::NextTimeoutFromHistogram(
+    unsigned server_index, int attempt) {
+  DCHECK_LT(server_index, rtt_histograms_.size());
+
+  COMPILE_ASSERT(std::numeric_limits<base::HistogramBase::Count>::is_signed,
+                 histogram_base_count_assumed_to_be_signed);
+
+  // Use fixed percentile of observed samples.
+  const base::SampleVector& samples = *rtt_histograms_[server_index];
+  base::HistogramBase::Count total = samples.TotalCount();
+  base::HistogramBase::Count remaining_count = kRTOPercentile * total / 100;
+  size_t index = 0;
+  while (remaining_count > 0 && index < rtt_buckets_->size()) {
+    remaining_count -= samples.GetCountAtIndex(index);
+    ++index;
+  }
+
+  base::TimeDelta timeout = base::TimeDelta::FromMilliseconds(
+      rtt_buckets_->range(index));
+
+  timeout = std::max(timeout, kMinTimeout);
+
+  // The timeout still doubles every full round.
+  unsigned num_backoffs = attempt / config_.nameservers.size();
+
+  return std::min(timeout * (1 << num_backoffs), kMaxTimeout);
+}
+
 }  // namespace net
diff --git a/net/dns/dns_session.h b/net/dns/dns_session.h
index dc37d34..e35ddb0 100644
--- a/net/dns/dns_session.h
+++ b/net/dns/dns_session.h
@@ -9,12 +9,18 @@
 
 #include "base/memory/ref_counted.h"
 #include "base/memory/scoped_ptr.h"
+#include "base/memory/scoped_vector.h"
 #include "base/time.h"
 #include "net/base/net_export.h"
 #include "net/base/rand_callback.h"
 #include "net/dns/dns_config_service.h"
 #include "net/dns/dns_socket_pool.h"
 
+namespace base {
+class BucketRanges;
+class SampleVector;
+}
+
 namespace net {
 
 class ClientSocketFactory;
@@ -63,8 +69,15 @@ class NET_EXPORT_PRIVATE DnsSession
   // Return the index of the first configured server to use on first attempt.
   int NextFirstServerIndex();
 
-  // Return the timeout for the next query.
-  base::TimeDelta NextTimeout(int attempt);
+  // Record how long it took to receive a response from the server.
+  void RecordRTT(unsigned server_index, base::TimeDelta rtt);
+
+  // Record suspected loss of a packet for a specific server.
+  void RecordLostPacket(unsigned server_index, int attempt);
+
+  // Return the timeout for the next query. |attempt| counts from 0 and is used
+  // for exponential backoff.
+  base::TimeDelta NextTimeout(unsigned server_index, int attempt);
 
   // Allocate a socket, already connected to the server address.
   // When the SocketLease is destroyed, the socket will be freed.
@@ -84,6 +97,12 @@ class NET_EXPORT_PRIVATE DnsSession
   void FreeSocket(unsigned server_index,
                   scoped_ptr<DatagramClientSocket> socket);
 
+  // Return the timeout using the TCP timeout method.
+  base::TimeDelta NextTimeoutFromJacobson(unsigned server_index, int attempt);
+
+  // Compute the timeout using the histogram method.
+  base::TimeDelta NextTimeoutFromHistogram(unsigned server_index, int attempt);
+
   const DnsConfig config_;
   scoped_ptr<DnsSocketPool> socket_pool_;
   RandCallback rand_callback_;
@@ -92,8 +111,15 @@ class NET_EXPORT_PRIVATE DnsSession
   // Current index into |config_.nameservers| to begin resolution with.
   int server_index_;
 
-  // TODO(szym): Add current RTT estimate.
-  // TODO(szym): Add TCP connection pool to support DNS over TCP.
+  // Estimated RTT for each name server using moving average.
+  std::vector<base::TimeDelta> rtt_estimates_;
+  // Estimated error in the above for each name server.
+  std::vector<base::TimeDelta> rtt_deviations_;
+
+  // Buckets shared for all |rtt_histograms_|.
+  scoped_ptr<base::BucketRanges> rtt_buckets_;
+  // A histogram of observed RTT for each name server.
+  ScopedVector<base::SampleVector> rtt_histograms_;
 
   DISALLOW_COPY_AND_ASSIGN(DnsSession);
 };
diff --git a/net/dns/dns_transaction.cc b/net/dns/dns_transaction.cc
index fdd2eb2..ea03502 100644
--- a/net/dns/dns_transaction.cc
+++ b/net/dns/dns_transaction.cc
@@ -73,6 +73,8 @@ Value* NetLogStartCallback(const std::string* hostname,
 // matches. Logging is done in the socket and in the outer DnsTransaction.
 class DnsAttempt {
  public:
+  DnsAttempt() : result_(ERR_FAILED) {}
+
   virtual ~DnsAttempt() {}
   // Starts the attempt. Returns ERR_IO_PENDING if cannot complete synchronously
   // and calls |callback| upon completion.
@@ -103,6 +105,25 @@ class DnsAttempt {
     GetSocketNetLog().source().AddToEventParameters(dict);
     return dict;
   }
+
+  void set_result(int result) {
+    result_ = result;
+  }
+
+  // True if current attempt is pending (waiting for server response).
+  bool is_pending() const {
+    return result_ == ERR_IO_PENDING;
+  }
+
+  // True if attempt is completed (received server response).
+  bool is_completed() const {
+    return (result_ == OK) || (result_ == ERR_NAME_NOT_RESOLVED) ||
+        (result_ == ERR_DNS_SERVER_REQUIRES_TCP);
+  }
+
+ private:
+  // Result of last operation.
+  int result_;
 };
 
 class DnsUDPAttempt : public DnsAttempt {
@@ -178,6 +199,8 @@ class DnsUDPAttempt : public DnsAttempt {
           break;
       }
     } while (rv != ERR_IO_PENDING && next_state_ != STATE_NONE);
+
+    set_result(rv);
     // If we received a malformed response, and are now waiting for another one,
     // indicate to the transaction that the server might be misbehaving.
     if (rv == ERR_IO_PENDING && received_malformed_response_)
@@ -196,9 +219,9 @@ class DnsUDPAttempt : public DnsAttempt {
   int DoSendQuery() {
     next_state_ = STATE_SEND_QUERY_COMPLETE;
     return socket()->Write(query_->io_buffer(),
-                              query_->io_buffer()->size(),
-                              base::Bind(&DnsUDPAttempt::OnIOComplete,
-                                         base::Unretained(this)));
+                           query_->io_buffer()->size(),
+                           base::Bind(&DnsUDPAttempt::OnIOComplete,
+                                      base::Unretained(this)));
   }
 
   int DoSendQueryComplete(int rv) {
@@ -218,9 +241,9 @@ class DnsUDPAttempt : public DnsAttempt {
     next_state_ = STATE_READ_RESPONSE_COMPLETE;
     response_.reset(new DnsResponse());
     return socket()->Read(response_->io_buffer(),
-                             response_->io_buffer()->size(),
-                             base::Bind(&DnsUDPAttempt::OnIOComplete,
-                                        base::Unretained(this)));
+                          response_->io_buffer()->size(),
+                          base::Bind(&DnsUDPAttempt::OnIOComplete,
+                                     base::Unretained(this)));
   }
 
   int DoReadResponseComplete(int rv) {
@@ -272,9 +295,11 @@ class DnsUDPAttempt : public DnsAttempt {
 
 class DnsTCPAttempt : public DnsAttempt {
  public:
-  DnsTCPAttempt(scoped_ptr<StreamSocket> socket,
+  DnsTCPAttempt(unsigned server_index,
+                scoped_ptr<StreamSocket> socket,
                 scoped_ptr<DnsQuery> query)
       : next_state_(STATE_NONE),
+        server_index_(server_index),
         socket_(socket.Pass()),
         query_(query.Pass()),
         length_buffer_(new IOBufferWithSize(sizeof(uint16))),
@@ -289,8 +314,10 @@ class DnsTCPAttempt : public DnsAttempt {
     next_state_ = STATE_CONNECT_COMPLETE;
     int rv = socket_->Connect(base::Bind(&DnsTCPAttempt::OnIOComplete,
                                          base::Unretained(this)));
-    if (rv == ERR_IO_PENDING)
+    if (rv == ERR_IO_PENDING) {
+      set_result(rv);
       return rv;
+    }
     return DoLoop(rv);
   }
 
@@ -308,8 +335,7 @@ class DnsTCPAttempt : public DnsAttempt {
   }
 
   virtual unsigned GetServerIndex() const OVERRIDE {
-    NOTREACHED();
-    return 0;
+    return server_index_;
   }
 
  private:
@@ -349,6 +375,8 @@ class DnsTCPAttempt : public DnsAttempt {
           break;
       }
     } while (rv != ERR_IO_PENDING && next_state_ != STATE_NONE);
+
+    set_result(rv);
     if (rv == OK) {
       DCHECK_EQ(STATE_NONE, next_state_);
       DNS_HISTOGRAM("AsyncDNS.TCPAttemptSuccess",
@@ -467,6 +495,7 @@ class DnsTCPAttempt : public DnsAttempt {
   State next_state_;
   base::TimeTicks start_time_;
 
+  unsigned server_index_;
   scoped_ptr<StreamSocket> socket_;
   scoped_ptr<DnsQuery> query_;
   scoped_refptr<IOBufferWithSize> length_buffer_;
@@ -622,6 +651,7 @@ class DnsTransactionImpl : public DnsTransaction,
     CHECK(result.rv != OK || response != NULL);
 
     timer_.Stop();
+    RecordLostPacketsIfAny();
 
     if (response && qtype_ == dns_protocol::kTypeA) {
       UMA_HISTOGRAM_COUNTS("AsyncDNS.SuffixSearchRemain", qnames_.size());
@@ -670,11 +700,13 @@ class DnsTransactionImpl : public DnsTransaction,
         NetLog::TYPE_DNS_TRANSACTION_ATTEMPT,
         attempt->GetSocketNetLog().source().ToEventParametersCallback());
 
-    int rv = attempt->Start(base::Bind(&DnsTransactionImpl::OnAttemptComplete,
-                                       base::Unretained(this),
-                                       attempt_number));
+    int rv = attempt->Start(
+        base::Bind(&DnsTransactionImpl::OnUdpAttemptComplete,
+                   base::Unretained(this), attempt_number,
+                   base::TimeTicks::Now()));
     if (rv == ERR_IO_PENDING) {
-      base::TimeDelta timeout = session_->NextTimeout(attempt_number);
+      base::TimeDelta timeout = session_->NextTimeout(server_index,
+                                                      attempt_number);
       timer_.Start(FROM_HERE, timeout, this, &DnsTransactionImpl::OnTimeout);
     }
     return AttemptResult(rv, attempt);
@@ -684,21 +716,24 @@ class DnsTransactionImpl : public DnsTransaction,
     DCHECK(previous_attempt);
     DCHECK(!had_tcp_attempt_);
 
+    unsigned server_index = previous_attempt->GetServerIndex();
+
     scoped_ptr<StreamSocket> socket(
-        session_->CreateTCPSocket(previous_attempt->GetServerIndex(),
-                                  net_log_.source()));
+        session_->CreateTCPSocket(server_index, net_log_.source()));
 
     // TODO(szym): Reuse the same id to help the server?
     uint16 id = session_->NextQueryId();
     scoped_ptr<DnsQuery> query(
         previous_attempt->GetQuery()->CloneWithNewId(id));
 
+    RecordLostPacketsIfAny();
     // Cancel all other attempts, no point waiting on them.
     attempts_.clear();
 
     unsigned attempt_number = attempts_.size();
 
-    DnsTCPAttempt* attempt = new DnsTCPAttempt(socket.Pass(), query.Pass());
+    DnsTCPAttempt* attempt = new DnsTCPAttempt(server_index, socket.Pass(),
+                                               query.Pass());
 
     attempts_.push_back(attempt);
     had_tcp_attempt_ = true;
@@ -725,12 +760,24 @@ class DnsTransactionImpl : public DnsTransaction,
                         NetLog::StringCallback("qname", &dotted_qname));
 
     first_server_index_ = session_->NextFirstServerIndex();
-
+    RecordLostPacketsIfAny();
     attempts_.clear();
     had_tcp_attempt_ = false;
     return MakeAttempt();
   }
 
+  void OnUdpAttemptComplete(unsigned attempt_number,
+                            base::TimeTicks start,
+                            int rv) {
+    DCHECK_LT(attempt_number, attempts_.size());
+    const DnsAttempt* attempt = attempts_[attempt_number];
+    if (attempt->GetResponse()) {
+      session_->RecordRTT(attempt->GetServerIndex(),
+                          base::TimeTicks::Now() - start);
+    }
+    OnAttemptComplete(attempt_number, rv);
+  }
+
   void OnAttemptComplete(unsigned attempt_number, int rv) {
     if (callback_.is_null())
       return;
@@ -741,6 +788,31 @@ class DnsTransactionImpl : public DnsTransaction,
       DoCallback(result);
   }
 
+  // Record packet loss for any incomplete attempts.
+  void RecordLostPacketsIfAny() {
+    // Loop through attempts until we find first that is completed
+    size_t first_completed = 0;
+    for (first_completed = 0; first_completed < attempts_.size();
+        ++first_completed) {
+      if (attempts_[first_completed]->is_completed())
+        break;
+    }
+    // If there were no completed attempts, then we must be offline, so don't
+    // record any attempts as lost packets.
+    if (first_completed == attempts_.size())
+      return;
+
+    std::vector<int> num_rounds(session_->config().nameservers.size());
+    for (size_t i = 0; i < first_completed; ++i) {
+      unsigned server_index = attempts_[i]->GetServerIndex();
+      int server_round = num_rounds[server_index]++;
+      // Don't record lost packet unless attempt is in pending state.
+      if (!attempts_[i]->is_pending())
+        continue;
+      session_->RecordLostPacket(server_index, server_round);
+    }
+  }
+
   void LogResponse(const DnsAttempt* attempt) {
     if (attempt && attempt->GetResponse()) {
       net_log_.AddEvent(