Insert histograms to support latency experiments with SDCH

Gather data to show the duration of time between the first
byte sent, to last byte read.  Use a second histogram to 
look at latency when the content-encoding is not really 
sdch (due to server side experiment, or proxy interference).

r=huanr,wtc
Review URL: http://codereview.chromium.org/9448

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

5 files changed, 42 insertions, 1 deletions

diff --git a/net/base/filter.cc b/net/base/filter.cc
index d8717db..433fdcd 100644
--- a/net/base/filter.cc
+++ b/net/base/filter.cc
@@ -201,6 +201,7 @@ Filter::Filter()
       next_stream_data_(NULL),
       stream_data_len_(0),
       url_(),
+      connect_time_(),
       mime_type_(),
       next_filter_(NULL),
       last_status_(FILTER_NEED_MORE_DATA) {
@@ -307,3 +308,8 @@ void Filter::SetMimeType(const std::string& mime_type) {
     next_filter_->SetMimeType(mime_type);
 }
 
+void Filter::SetConnectTime(const base::Time& time) {
+  connect_time_ = time;
+  if (next_filter_.get())
+    next_filter_->SetConnectTime(time);
+}
diff --git a/net/base/filter.h b/net/base/filter.h
index 98a531c..36a631e 100644
--- a/net/base/filter.h
+++ b/net/base/filter.h
@@ -34,6 +34,7 @@
 
 #include "base/basictypes.h"
 #include "base/scoped_ptr.h"
+#include "base/time.h"
 #include "googleurl/src/gurl.h"
 #include "testing/gtest/include/gtest/gtest_prod.h"
 
@@ -120,6 +121,8 @@ class Filter {
   void SetMimeType(const std::string& mime_type);
   const std::string& mime_type() const { return mime_type_; }
 
+  void SetConnectTime(const base::Time& time);
+
   // Translate the text of a filter name (from Content-Encoding header) into a
   // FilterType.
   static FilterType ConvertEncodingToType(const std::string& filter_type);
@@ -168,6 +171,8 @@ class Filter {
 
   FilterStatus last_status() const { return last_status_; }
 
+  base::Time connect_time() const { return connect_time_; }
+
   // Buffer to hold the data to be filtered.
   scoped_array<char> stream_buffer_;
 
@@ -185,6 +190,10 @@ class Filter {
   // a specific URL or path.
   GURL url_;
 
+  // To facilitate histogramming by individual filters, we store the connect
+  // time for the corresponding HTTP transaction.
+  base::Time connect_time_;
+
   // To facilitate error recovery in SDCH filters, allow filter to know if
   // content is text/html by checking within this mime type (SDCH filter may
   // do a meta-refresh via html).
diff --git a/net/base/sdch_filter.cc b/net/base/sdch_filter.cc
index 6de5c6a..9678ae4 100644
--- a/net/base/sdch_filter.cc
+++ b/net/base/sdch_filter.cc
@@ -22,7 +22,8 @@ SdchFilter::SdchFilter()
       dest_buffer_excess_(),
       dest_buffer_excess_index_(0),
       source_bytes_(0),
-      output_bytes_(0) {
+      output_bytes_(0),
+      time_of_last_read_() {
 }
 
 SdchFilter::~SdchFilter() {
@@ -37,6 +38,24 @@ SdchFilter::~SdchFilter() {
       decoding_status_ = DECODING_ERROR;
   }
 
+  if (base::Time() != connect_time() && base::Time() != time_of_last_read_) {
+    base::TimeDelta duration = time_of_last_read_ - connect_time();
+    // Note: connect_time may be somewhat incorrect if this is cached data, as
+    // it will reflect the time the connect was done for the original read :-(.
+    // To avoid any chances of overflow (and since SDCH is meant to primarilly
+    // handle short downloads, we'll restrict what results we log to effectively
+    // discard bogus large numbers.  Note that IF the number is large enough, it
+    // would DCHECK in histogram as the square of the value is summed.  The
+    // relatively precise histogram only properly covers the range 1ms to 10
+    // seconds, so the discarded data would not be that readable anyway.
+    if (30 >= duration.InSeconds()) {
+      if (DECODING_IN_PROGRESS == decoding_status_)
+        UMA_HISTOGRAM_TIMES(L"Sdch.Transit_Latency", duration);
+      if (PASS_THROUGH == decoding_status_)
+        UMA_HISTOGRAM_TIMES(L"Sdch.Transit_Pass-through_Latency", duration);
+    }
+  }
+
   UMA_HISTOGRAM_COUNTS(L"Sdch.Bytes read", source_bytes_);
   UMA_HISTOGRAM_COUNTS(L"Sdch.Bytes output", output_bytes_);
 
@@ -71,6 +90,7 @@ Filter::FilterStatus SdchFilter::ReadFilteredData(char* dest_buffer,
   if (!dest_buffer || available_space <= 0)
     return FILTER_ERROR;
 
+  time_of_last_read_ = base::Time::Now();
 
   if (WAITING_FOR_DICTIONARY_SELECTION == decoding_status_) {
     FilterStatus status = InitializeDictionary();
diff --git a/net/base/sdch_filter.h b/net/base/sdch_filter.h
index 6bd0ed9..566d4d5 100644
--- a/net/base/sdch_filter.h
+++ b/net/base/sdch_filter.h
@@ -99,6 +99,8 @@ class SdchFilter : public Filter {
   size_t source_bytes_;
   size_t output_bytes_;
 
+  base::Time time_of_last_read_;
+
   DISALLOW_COPY_AND_ASSIGN(SdchFilter);
 };
 
diff --git a/net/url_request/url_request_job.cc b/net/url_request/url_request_job.cc
index dc372ba..ea5ccb9 100644
--- a/net/url_request/url_request_job.cc
+++ b/net/url_request/url_request_job.cc
@@ -58,6 +58,10 @@ void URLRequestJob::SetupFilter() {
       GetMimeType(&mime_type);
       filter_->SetURL(request_->url());
       filter_->SetMimeType(mime_type);
+      // Approximate connect time with request_time. If it is not cached, then
+      // this is a good approximation for when the first bytes went on the
+      // wire.
+      filter_->SetConnectTime(request_->response_info_.request_time);
     }
   }
 }