Hand craft an A/B test of SDCH compression

After we're sure we can do SDCH compression to a given URL, toss
a 50-50 coin each time we have a chance to advertise SDCH, and
either completely avoid advertisement, or advertise (including
the dictionary).  Histogram both compression download times, as
well as the download times for the "completely avoid" case.

http://crbug.com/11236
bug=11236
r=wtc,openvcdiff
Review URL: http://codereview.chromium.org/100004

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

8 files changed, 107 insertions, 159 deletions

diff --git a/net/base/filter.h b/net/base/filter.h
index 852faba..295d80f 100644
--- a/net/base/filter.h
+++ b/net/base/filter.h
@@ -48,6 +48,15 @@
 // or later filters in a chain.
 class FilterContext {
  public:
+  // Enum to control what histograms are emitted near end-of-life of this
+  // instance.
+  enum StatisticSelector {
+    SDCH_DECODE,
+    SDCH_PASSTHROUGH,
+    SDCH_EXPERIMENT_DECODE,
+    SDCH_EXPERIMENT_HOLDBACK,
+  };
+
   virtual ~FilterContext() {}
 
   // What mime type was specified in the header for this data?
@@ -85,6 +94,10 @@ class FilterContext {
   // don't change the input buffer sizes for a linked chain of filters, and the
   // buffer size for input to all filters in a chain is this one constant).
   virtual int GetInputStreamBufferSize() const = 0;
+
+  // The following method forces the context to emit a specific set of
+  // statistics as selected by the argument.
+  virtual void RecordPacketStats(StatisticSelector statistic) const = 0;
 };
 
 //------------------------------------------------------------------------------
@@ -179,6 +192,7 @@ class Filter {
   // advertised in the GET), as well as the mime type of the content.
   static void FixupEncodingTypes(const FilterContext& filter_context,
                                  std::vector<FilterType>* encoding_types);
+
  protected:
   explicit Filter(const FilterContext& filter_context);
 
diff --git a/net/base/filter_unittest.h b/net/base/filter_unittest.h
index a15ae59..9de5bb5 100644
--- a/net/base/filter_unittest.h
+++ b/net/base/filter_unittest.h
@@ -67,6 +67,7 @@ class MockFilterContext : public FilterContext {
   // What is the desirable input buffer size for these filters?
   virtual int GetInputStreamBufferSize() const { return buffer_size_; }
 
+  virtual void RecordPacketStats(StatisticSelector statistic) const {}
 
  private:
   int buffer_size_;
diff --git a/net/base/load_flags.h b/net/base/load_flags.h
index c2c0d20..09851ec 100644
--- a/net/base/load_flags.h
+++ b/net/base/load_flags.h
@@ -66,16 +66,12 @@ enum {
   // cookies or updating existing ones.
   LOAD_DO_NOT_SAVE_COOKIES = 1 << 13,
 
-  // An SDCH dictionary was advertised, and an SDCH encoded response is
-  // possible.
-  LOAD_SDCH_DICTIONARY_ADVERTISED = 1 << 14,
-
   // Do not resolve proxies. This override is used when downloading PAC files
   // to avoid having a circular dependency.
-  LOAD_BYPASS_PROXY = 1 << 15,
+  LOAD_BYPASS_PROXY = 1 << 14,
 
   // Indicate this request is for a download, as opposed to viewing.
-  LOAD_IS_DOWNLOAD = 1 << 16,
+  LOAD_IS_DOWNLOAD = 1 << 15,
 };
 
 }  // namespace net
diff --git a/net/base/sdch_filter.cc b/net/base/sdch_filter.cc
index 3ff78b5..0eb98a0 100644
--- a/net/base/sdch_filter.cc
+++ b/net/base/sdch_filter.cc
@@ -25,11 +25,7 @@ SdchFilter::SdchFilter(const FilterContext& filter_context)
       dest_buffer_excess_index_(0),
       source_bytes_(0),
       output_bytes_(0),
-      observed_packet_count_(0),
-      bytes_observed_in_packets_(0),
-      final_packet_time_(),
       possible_pass_through_(false),
-      connect_time_(filter_context.GetRequestTime()),
       was_cached_(filter_context.IsCachedContent()) {
   bool success = filter_context.GetMimeType(&mime_type_);
   DCHECK(success);
@@ -80,92 +76,20 @@ SdchFilter::~SdchFilter() {
     return;  // We don't need timing stats, and we aready got ratios.
   }
 
-  if (base::Time() == connect_time_ || read_times_.empty()) {
-    // Not a real error, but it is useful to have this tally.
-    // TODO(jar): Remove this stat after SDCH stability is validated.
-    SdchManager::SdchErrorRecovery(SdchManager::MISSING_TIME_STATS);
-    UMA_HISTOGRAM_COUNTS("Sdch.MissingTimeBytesIn",
-         static_cast<int>(filter_context().GetByteReadCount()));
-    UMA_HISTOGRAM_COUNTS("Sdch.MissingTimeVcdiffIn", source_bytes_);
-    return;
-  }
-  // Since read_times_ is not empty, we can assert we have some packets times.
-  DCHECK(final_packet_time_ != base::Time());
-
-  base::TimeDelta duration = final_packet_time_ - connect_time_;
-  // We clip our logging at 10 minutes to prevent anamolous data from being
-  // considered (per suggestion from Jake Brutlag).
-  if (10 < duration.InMinutes()) {
-    SdchManager::SdchErrorRecovery(SdchManager::OVER_10_MINUTES);
-    return;
-  }
-
   switch (decoding_status_) {
     case DECODING_IN_PROGRESS: {
       UMA_HISTOGRAM_PERCENTAGE("Sdch.Network_Decode_Ratio_a", static_cast<int>(
           (filter_context().GetByteReadCount() * 100) / output_bytes_));
-      UMA_HISTOGRAM_CLIPPED_TIMES("Sdch.Network_Decode_Latency_F_a", duration,
-                                  base::TimeDelta::FromMilliseconds(20),
-                                  base::TimeDelta::FromMinutes(10), 100);
-      UMA_HISTOGRAM_CLIPPED_TIMES("Sdch.Network_Decode_1st_To_Last_a",
-                                  final_packet_time_ - read_times_[0],
-                                  base::TimeDelta::FromMilliseconds(20),
-                                  base::TimeDelta::FromMinutes(10), 100);
-      if (read_times_.size() > 4) {
-        UMA_HISTOGRAM_CLIPPED_TIMES("Sdch.Network_Decode_1st_To_2nd_b",
-                                    read_times_[1] - read_times_[0],
-                                    base::TimeDelta::FromMilliseconds(10),
-                                    base::TimeDelta::FromSeconds(3), 100);
-        UMA_HISTOGRAM_CLIPPED_TIMES("Sdch.Network_Decode_2nd_To_3rd_b",
-                                    read_times_[2] - read_times_[1],
-                                    base::TimeDelta::FromMilliseconds(10),
-                                    base::TimeDelta::FromSeconds(3), 100);
-        UMA_HISTOGRAM_CLIPPED_TIMES("Sdch.Network_Decode_3rd_To_4th_b",
-                                    read_times_[3] - read_times_[2],
-                                    base::TimeDelta::FromMilliseconds(10),
-                                    base::TimeDelta::FromSeconds(3), 100);
-        UMA_HISTOGRAM_CLIPPED_TIMES("Sdch.Network_Decode_4th_To_5th_b",
-                                    read_times_[4] - read_times_[3],
-                                    base::TimeDelta::FromMilliseconds(10),
-                                    base::TimeDelta::FromSeconds(3), 100);
-      }
-      UMA_HISTOGRAM_COUNTS_100("Sdch.Network_Decode_Packets_b",
-                               observed_packet_count_);
-      UMA_HISTOGRAM_COUNTS("Sdch.Network_Decode_Bytes_Processed_a",
-          static_cast<int>(filter_context().GetByteReadCount()));
       UMA_HISTOGRAM_COUNTS("Sdch.Network_Decode_Bytes_VcdiffOut_a",
                            output_bytes_);
+      filter_context().RecordPacketStats(FilterContext::SDCH_DECODE);
+
+      // Allow latency experiments to proceed.
+      SdchManager::Global()->SetAllowLatencyExperiment(url_, true);
       return;
     }
     case PASS_THROUGH: {
-      UMA_HISTOGRAM_CLIPPED_TIMES("Sdch.Network_Pass-through_Latency_F_a",
-                                  duration,
-                                  base::TimeDelta::FromMilliseconds(20),
-                                  base::TimeDelta::FromMinutes(10), 100);
-      UMA_HISTOGRAM_CLIPPED_TIMES("Sdch.Network_Pass-through_1st_To_Last_a",
-                                  final_packet_time_ - read_times_[0],
-                                  base::TimeDelta::FromMilliseconds(20),
-                                  base::TimeDelta::FromMinutes(10), 100);
-      if (read_times_.size() > 4) {
-        UMA_HISTOGRAM_CLIPPED_TIMES("Sdch.Network_Pass-through_1st_To_2nd_b",
-                                    read_times_[1] - read_times_[0],
-                                    base::TimeDelta::FromMilliseconds(10),
-                                    base::TimeDelta::FromSeconds(3), 100);
-        UMA_HISTOGRAM_CLIPPED_TIMES("Sdch.Network_Pass-through_2nd_To_3rd_b",
-                                    read_times_[2] - read_times_[1],
-                                    base::TimeDelta::FromMilliseconds(10),
-                                    base::TimeDelta::FromSeconds(3), 100);
-        UMA_HISTOGRAM_CLIPPED_TIMES("Sdch.Network_Pass-through_3rd_To_4th_b",
-                                    read_times_[3] - read_times_[2],
-                                    base::TimeDelta::FromMilliseconds(10),
-                                    base::TimeDelta::FromSeconds(3), 100);
-        UMA_HISTOGRAM_CLIPPED_TIMES("Sdch.Network_Pass-through_4th_To_5th_b",
-                                    read_times_[4] - read_times_[3],
-                                    base::TimeDelta::FromMilliseconds(10),
-                                    base::TimeDelta::FromSeconds(3), 100);
-      }
-      UMA_HISTOGRAM_COUNTS_100("Sdch.Network_Pass-through_Packets_b",
-                               observed_packet_count_);
+      filter_context().RecordPacketStats(FilterContext::SDCH_PASSTHROUGH);
       return;
     }
     case DECODING_UNINITIALIZED: {
@@ -187,33 +111,6 @@ SdchFilter::~SdchFilter() {
   }  // end of switch.
 }
 
-void SdchFilter::UpdateReadTimes() {
-  if (!next_stream_data_ || (stream_data_len_ == 0)) {
-    // Don't update when we're called to just flush out our internal buffers.
-    return;
-  }
-  const size_t bytes_read_so_far =
-      static_cast<size_t>(filter_context().GetByteReadCount());
-  if (bytes_read_so_far <= bytes_observed_in_packets_) {
-    DCHECK(bytes_read_so_far == bytes_observed_in_packets_);
-    return;  // No new bytes have arrived.
-  }
-
-  // We only save distinct times for the first 5 packets.
-  const size_t kMaxTimesInArray = 5;
-  const size_t kTypicalPacketSize = 1430;
-  final_packet_time_ = base::Time::Now();
-  while (bytes_read_so_far > bytes_observed_in_packets_) {
-    if (++observed_packet_count_ <= kMaxTimesInArray) {
-      read_times_.push_back(final_packet_time_);
-    }
-    bytes_observed_in_packets_ += kTypicalPacketSize;
-  }
-  // Since packets may not be full, we'll remember the number of bytes we've
-  // accounted for in packets thus far.
-  bytes_observed_in_packets_ = bytes_read_so_far;
-}
-
 bool SdchFilter::InitDecoding(Filter::FilterType filter_type) {
   if (decoding_status_ != DECODING_UNINITIALIZED)
     return false;
@@ -245,15 +142,13 @@ Filter::FilterStatus SdchFilter::ReadFilteredData(char* dest_buffer,
   if (!dest_buffer || available_space <= 0)
     return FILTER_ERROR;
 
-  UpdateReadTimes();
-
   if (WAITING_FOR_DICTIONARY_SELECTION == decoding_status_) {
     FilterStatus status = InitializeDictionary();
     if (FILTER_NEED_MORE_DATA == status)
       return FILTER_NEED_MORE_DATA;
     if (FILTER_ERROR == status) {
       DCHECK(DECODING_ERROR == decoding_status_);
-      DCHECK(0 == dest_buffer_excess_index_);
+      DCHECK_EQ(0u, dest_buffer_excess_index_);
       DCHECK(dest_buffer_excess_.empty());
       // This is where we try very hard to do error recovery, and make this
       // protocol robust in teh face of proxies that do many different things.
@@ -333,12 +228,12 @@ Filter::FilterStatus SdchFilter::ReadFilteredData(char* dest_buffer,
   *dest_len += amount;
   dest_buffer += amount;
   available_space -= amount;
-  DCHECK(available_space >= 0);
+  DCHECK_GE(available_space, 0);
 
   if (available_space <= 0)
     return FILTER_OK;
   DCHECK(dest_buffer_excess_.empty());
-  DCHECK(0 == dest_buffer_excess_index_);
+  DCHECK_EQ(0u, dest_buffer_excess_index_);
 
   if (decoding_status_ != DECODING_IN_PROGRESS) {
     if (META_REFRESH_RECOVERY == decoding_status_) {
@@ -388,7 +283,7 @@ Filter::FilterStatus SdchFilter::ReadFilteredData(char* dest_buffer,
 Filter::FilterStatus SdchFilter::InitializeDictionary() {
   const size_t kServerIdLength = 9;  // Dictionary hash plus null from server.
   size_t bytes_needed = kServerIdLength - dictionary_hash_.size();
-  DCHECK(bytes_needed > 0);
+  DCHECK_GT(bytes_needed, 0u);
   if (!next_stream_data_)
     return FILTER_NEED_MORE_DATA;
   if (static_cast<size_t>(stream_data_len_) < bytes_needed) {
@@ -400,7 +295,7 @@ Filter::FilterStatus SdchFilter::InitializeDictionary() {
   dictionary_hash_.append(next_stream_data_, bytes_needed);
   DCHECK(kServerIdLength == dictionary_hash_.size());
   stream_data_len_ -= bytes_needed;
-  DCHECK(0 <= stream_data_len_);
+  DCHECK_LE(0, stream_data_len_);
   if (stream_data_len_ > 0)
     next_stream_data_ += bytes_needed;
   else
diff --git a/net/base/sdch_filter.h b/net/base/sdch_filter.h
index 85dfef6..7255839 100644
--- a/net/base/sdch_filter.h
+++ b/net/base/sdch_filter.h
@@ -56,10 +56,6 @@ class SdchFilter : public Filter {
     PASS_THROUGH,  // Non-sdch content being passed without alteration.
   };
 
-  // Update the read_times_ array with time estimates for the number of packets
-  // read so far.
-  void UpdateReadTimes();
-
   // Identify the suggested dictionary, and initialize underlying decompressor.
   Filter::FilterStatus InitializeDictionary();
 
@@ -106,25 +102,6 @@ class SdchFilter : public Filter {
   size_t source_bytes_;
   size_t output_bytes_;
 
-  // The number of packets we've observed over the net.
-  size_t observed_packet_count_;
-
-  // We can't really see when a packet arrives, but we can record how much data
-  // was accounted for in previously noted packets. We use this count to (later)
-  // identify new packets .
-  size_t bytes_observed_in_packets_;
-
-  // Since we don't save all packet times in read_times_, we save the last time
-  // for use in histograms.
-  base::Time final_packet_time_;
-
-  // Record of packet processing times for this filter.  Used only for stats
-  // generations in histograms.  There is one time entry each time the byte
-  // count receieved exceeds the next multiple of 1430 bytes (a common
-  // per-TCP/IP-packet payload size). It is currently only valid for the first
-  // 5 packets.
-  std::vector<base::Time> read_times_;
-
   // Error recovery in content type may add an sdch filter type, in which case
   // we should gracefully perform pass through if the format is incorrect, or
   // an applicable dictionary can't be found.
@@ -134,11 +111,9 @@ class SdchFilter : public Filter {
   // This is used to restrict use of a dictionary to a specific URL or path.
   GURL url_;
 
-  // To facilitate histogramming by individual filters, we store the connect
-  // time for the corresponding HTTP transaction, as well as whether this time
-  // was recalled from a cached entry.  The time is approximate, and may be
-  // bogus if the data was gotten from cache (i.e., it may be LOOOONG ago).
-  const base::Time connect_time_;
+  // To facilitate error recovery, we store whether this content came from a
+  // cache, as we then probably don't have the requsite dictionary, and will
+  // need to induce a meta-refresh.
   const bool was_cached_;
 
   // To facilitate error recovery, allow filter to know if content is text/html
diff --git a/net/base/sdch_filter_unittest.cc b/net/base/sdch_filter_unittest.cc
index ca6b266..532bba6 100644
--- a/net/base/sdch_filter_unittest.cc
+++ b/net/base/sdch_filter_unittest.cc
@@ -1184,3 +1184,32 @@ TEST_F(SdchFilterTest, PathMatch) {
   EXPECT_FALSE(PathMatch("/ABC", "/abc"));
   EXPECT_FALSE(PathMatch("/abc", "/ABC"));
 }
+
+// The following are only applicable while we have a latency test in the code,
+// and can be removed when that functionality is stripped.
+TEST_F(SdchFilterTest, LatencyTestControls) {
+  GURL url("http://www.google.com");
+  GURL url2("http://www.google2.com");
+
+  // First make sure we default to false.
+  EXPECT_FALSE(sdch_manager_->AllowLatencyExperiment(url));
+  EXPECT_FALSE(sdch_manager_->AllowLatencyExperiment(url2));
+
+  // That we can set each to true.
+  sdch_manager_->SetAllowLatencyExperiment(url, true);
+  EXPECT_TRUE(sdch_manager_->AllowLatencyExperiment(url));
+  EXPECT_FALSE(sdch_manager_->AllowLatencyExperiment(url2));
+
+  sdch_manager_->SetAllowLatencyExperiment(url2, true);
+  EXPECT_TRUE(sdch_manager_->AllowLatencyExperiment(url));
+  EXPECT_TRUE(sdch_manager_->AllowLatencyExperiment(url2));
+
+  // And can reset them to false.
+  sdch_manager_->SetAllowLatencyExperiment(url, false);
+  EXPECT_FALSE(sdch_manager_->AllowLatencyExperiment(url));
+  EXPECT_TRUE(sdch_manager_->AllowLatencyExperiment(url2));
+
+  sdch_manager_->SetAllowLatencyExperiment(url2, false);
+  EXPECT_FALSE(sdch_manager_->AllowLatencyExperiment(url));
+  EXPECT_FALSE(sdch_manager_->AllowLatencyExperiment(url2));
+}
diff --git a/net/base/sdch_manager.cc b/net/base/sdch_manager.cc
index c6bf950..1ea9e89 100644
--- a/net/base/sdch_manager.cc
+++ b/net/base/sdch_manager.cc
@@ -85,6 +85,7 @@ SdchManager::~SdchManager() {
 void SdchManager::BlacklistDomain(const GURL& url) {
   if (!global_ )
     return;
+  global_->SetAllowLatencyExperiment(url, false);
 
   std::string domain(StringToLowerASCII(url.host()));
   int count = global_->blacklisted_domains_[domain];
@@ -104,6 +105,7 @@ void SdchManager::BlacklistDomain(const GURL& url) {
 void SdchManager::BlacklistDomainForever(const GURL& url) {
   if (!global_ )
     return;
+  global_->SetAllowLatencyExperiment(url, false);
 
   std::string domain(StringToLowerASCII(url.host()));
   global_->exponential_blacklist_count[domain] = INT_MAX;
@@ -331,8 +333,8 @@ void SdchManager::GenerateHash(const std::string& dictionary_text,
   UrlSafeBase64Encode(first_48_bits, client_hash);
   UrlSafeBase64Encode(second_48_bits, server_hash);
 
-  DCHECK(server_hash->length() == 8);
-  DCHECK(client_hash->length() == 8);
+  DCHECK_EQ(server_hash->length(), 8u);
+  DCHECK_EQ(client_hash->length(), 8u);
 }
 
 // static
@@ -507,3 +509,23 @@ bool SdchManager::Dictionary::DomainMatch(const GURL& gurl,
   // TODO(jar): This is not precisely a domain match definition.
   return gurl.DomainIs(restriction.data(), restriction.size());
 }
+
+//------------------------------------------------------------------------------
+// Methods for supporting latency experiments.
+
+bool SdchManager::AllowLatencyExperiment(const GURL& url) const {
+  return allow_latency_experiment_.end() !=
+      allow_latency_experiment_.find(url.host());
+}
+
+void SdchManager::SetAllowLatencyExperiment(const GURL& url, bool enable) {
+  if (enable) {
+    allow_latency_experiment_.insert(url.host());
+    return;
+  }
+  ExperimentSet::iterator it = allow_latency_experiment_.find(url.host());
+  if (allow_latency_experiment_.end() == it)
+    return;  // It was already erased, or never allowed.
+  SdchErrorRecovery(LATENCY_TEST_DISALLOWED);
+  allow_latency_experiment_.erase(it);
+}
diff --git a/net/base/sdch_manager.h b/net/base/sdch_manager.h
index 6524e7a..e8329e1 100644
--- a/net/base/sdch_manager.h
+++ b/net/base/sdch_manager.h
@@ -130,13 +130,16 @@ class SdchManager {
     // (i.e., be able to be sure all dictionary advertisements are accounted
     // for).
 
-    UNFLUSHED_CONTENT = 90,   // Possible error in filter chaining.
-    MISSING_TIME_STATS = 91,  // Should never happen.
-    CACHE_DECODED = 92,       // No timing stats recorded.
-    OVER_10_MINUTES = 93,     // No timing stats will be recorded.
-    UNINITIALIZED = 94,       // Filter never even got initialized.
-    PRIOR_TO_DICTIONARY = 95, // We hadn't even parsed a dictionary selector.
-    DECODE_ERROR = 96,        // Something went wrong during decode.
+    UNFLUSHED_CONTENT = 90,    // Possible error in filter chaining.
+    // defunct = 91,           // MISSING_TIME_STATS (Should never happen.)
+    CACHE_DECODED = 92,        // No timing stats recorded.
+    // defunct = 93,           // OVER_10_MINUTES (No timing stats recorded.)
+    UNINITIALIZED = 94,        // Filter never even got initialized.
+    PRIOR_TO_DICTIONARY = 95,  // We hadn't even parsed a dictionary selector.
+    DECODE_ERROR = 96,         // Something went wrong during decode.
+
+    // Problem during the latency test.
+    LATENCY_TEST_DISALLOWED = 100,  // SDCH now failing, but it worked before!
 
     MAX_PROBLEM_CODE  // Used to bound histogram.
   };
@@ -302,8 +305,17 @@ class SdchManager {
   static void GenerateHash(const std::string& dictionary_text,
                            std::string* client_hash, std::string* server_hash);
 
+  // For Latency testing only, we need to know if we've succeeded in doing a
+  // round trip before starting our comparative tests.  If ever we encounter
+  // problems with SDCH, we opt-out of the test unless/until we perform a
+  // complete SDCH decoding.
+  bool AllowLatencyExperiment(const GURL& url) const;
+
+  void SetAllowLatencyExperiment(const GURL& url, bool enable);
+
  private:
-  typedef std::map<const std::string, int> DomainCounter;
+  typedef std::map<std::string, int> DomainCounter;
+  typedef std::set<std::string> ExperimentSet;
 
   // A map of dictionaries info indexed by the hash that the server provides.
   typedef std::map<std::string, Dictionary*> DictionaryMap;
@@ -334,6 +346,10 @@ class SdchManager {
   // blacklisting expires.
   DomainCounter exponential_blacklist_count;
 
+  // List of hostnames for which a latency experiment is allowed (because a
+  // round trip test has recently passed).
+  ExperimentSet allow_latency_experiment_;
+
   DISALLOW_COPY_AND_ASSIGN(SdchManager);
 };