Hand craft an A/B test of SDCH compression...

net/base/sdch_filter.cc

 // Copyright (c) 2006-2008 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include <limits.h>
 #include <ctype.h>
 #include <algorithm>
 
 #include "base/file_util.h"
 #include "base/histogram.h"
 #include "base/logging.h"
 #include "net/base/sdch_filter.h"
 #include "net/base/sdch_manager.h"
 
 #include "sdch/open-vcdiff/src/google/vcdecoder.h"
 
 SdchFilter::SdchFilter(const FilterContext& filter_context)
     : Filter(filter_context),
       decoding_status_(DECODING_UNINITIALIZED),
       vcdiff_streaming_decoder_(NULL),
       dictionary_hash_(),
       dictionary_hash_is_plausible_(false),
       dictionary_(NULL),
       dest_buffer_excess_(),
       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);
   success = filter_context.GetURL(&url_);
   DCHECK(success);
 }
 
 SdchFilter::~SdchFilter() {
   // All code here is for gathering stats, and can be removed when SDCH is
   // considered stable.
@@ skipping 30 matching lines @@
     UMA_HISTOGRAM_COUNTS("Sdch.UnflushedVcdiffOut", output_bytes_);
   }
 
   if (was_cached_) {
     // 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::CACHE_DECODED);
     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: {
       SdchManager::SdchErrorRecovery(SdchManager::UNINITIALIZED);
       return;
     }
     case WAITING_FOR_DICTIONARY_SELECTION: {
       SdchManager::SdchErrorRecovery(SdchManager::PRIOR_TO_DICTIONARY);
       return;
     }
     case DECODING_ERROR: {
       SdchManager::SdchErrorRecovery(SdchManager::DECODE_ERROR);
       return;
     }
     case META_REFRESH_RECOVERY: {
       // Already accounted for when set.
       return;
     }
   }  // 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;
 
   // Handle case  where sdch filter is guessed, but not required.
   if (FILTER_TYPE_SDCH_POSSIBLE == filter_type)
     possible_pass_through_ = true;
 
   // Initialize decoder only after we have a dictionary in hand.
   decoding_status_ = WAITING_FOR_DICTIONARY_SELECTION;
@@ skipping 11 matching lines @@
 
 
 Filter::FilterStatus SdchFilter::ReadFilteredData(char* dest_buffer,
                                                   int* dest_len) {
   int available_space = *dest_len;
   *dest_len = 0;  // Nothing output yet.
 
   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.
       // If we decide that things are looking very bad (too hard to recover),
       // we may even issue a "meta-refresh" to reload the page without an SDCH
       // advertisement (so that we are sure we're not hurting anything).  First
       // we try for some light weight recovery, and teh final else clause below
       // supports the last ditch meta-refresh approach.
       //
       // Watch out for an error page inserted by the proxy as part of a 40x
@@ skipping 59 matching lines @@
       }
     } else {
       DCHECK(DECODING_IN_PROGRESS == decoding_status_);
     }
   }
 
   int amount = OutputBufferExcess(dest_buffer, available_space);
   *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_) {
       // Absorb all input data.  We've already output page reload HTML.
       next_stream_data_ = NULL;
       stream_data_len_ = 0;
       return FILTER_NEED_MORE_DATA;
     }
     if (PASS_THROUGH == decoding_status_) {
       // We must pass in available_space, but it will be changed to bytes_used.
@@ skipping 29 matching lines @@
   dest_buffer += amount;
   available_space -= amount;
   if (0 == available_space && !dest_buffer_excess_.empty())
       return FILTER_OK;
   return FILTER_NEED_MORE_DATA;
 }
 
 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) {
     dictionary_hash_.append(next_stream_data_, stream_data_len_);
     next_stream_data_ = NULL;
     stream_data_len_ = 0;
     return FILTER_NEED_MORE_DATA;
   }
   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
     next_stream_data_ = NULL;
 
   DCHECK(!dictionary_.get());
   dictionary_hash_is_plausible_ = true;  // Assume plausible, but check.
 
   SdchManager::Dictionary* dictionary = NULL;
   if ('\0' == dictionary_hash_[kServerIdLength - 1])
@@ skipping 39 matching lines @@
   memcpy(dest_buffer, dest_buffer_excess_.data() + dest_buffer_excess_index_,
          amount);
   dest_buffer_excess_index_ += amount;
   if (dest_buffer_excess_.size() <= dest_buffer_excess_index_) {
     DCHECK(dest_buffer_excess_.size() == dest_buffer_excess_index_);
     dest_buffer_excess_.clear();
     dest_buffer_excess_index_ = 0;
   }
   return amount;
 }