Add HttpCache histograms focussed on blocking and transaction type.

net/http/http_cache_transaction.cc

Index: net/http/http_cache_transaction.cc
diff --git a/net/http/http_cache_transaction.cc b/net/http/http_cache_transaction.cc
index 652a3b26b6d136d0a7fa3d8926deb9841f940582..80b5a8b3d099c7074576672dd4c7450bd493005d 100644
--- a/net/http/http_cache_transaction.cc
+++ b/net/http/http_cache_transaction.cc
@@ -41,6 +41,19 @@ using base::TimeTicks;
 
 namespace net {
 
+namespace {

[rvargas (doing something else), 2012/07/21 02:24:21]

Move this outside of net

[gavinp, 2012/07/25 01:07:01]

Done. You didn't say why: is it because it doesn't reference anything in net?

[rvargas (doing something else), 2012/07/25 19:41:04]

In part because it's the common pattern everywhere (even when it references
stuff from the file namespace)

In part because I dislike nested namespaces :)

+
+// The cutoff for tagging small transactions in histograms; this size was chosen
+// to cover resources likely to be received in a single TCP window. With an
+// initial CWND of 10, and an MTU of 1500 bytes, with TCP and HTTP framing
+// overhead this is a size relatively likely to take only one RTT.
+const int kSmallResourceMaxBytes = 14 * 1024;
+
+// Requests faster than this do not report as many performance histograms.
+const int kFastRequestCutoffMs = 5;
+
+}
+
 struct HeaderNameAndValue {
   const char* name;
   const char* value;
@@ -126,7 +139,8 @@ HttpCache::Transaction::Transaction(HttpCache* cache)
       ALLOW_THIS_IN_INITIALIZER_LIST(weak_factory_(this)),
       ALLOW_THIS_IN_INITIALIZER_LIST(io_callback_(
           base::Bind(&Transaction::OnIOComplete,
-                     weak_factory_.GetWeakPtr()))) {
+                     weak_factory_.GetWeakPtr()))),
+      disposition_(DISPOSITION_UNDEFINED) {
   COMPILE_ASSERT(HttpCache::Transaction::kNumValidationHeaders ==
                  arraysize(kValidationHeaders),
                  Invalid_number_of_validation_headers);
@@ -670,6 +684,8 @@ int HttpCache::Transaction::DoGetBackendComplete(int result) {
     if (effective_load_flags_ & LOAD_ONLY_FROM_CACHE) {
       mode_ = READ;
     } else if (effective_load_flags_ & LOAD_BYPASS_CACHE) {
+      // Don't record a load that isn't really testing the cache.

[rvargas (doing something else), 2012/07/21 02:24:21]

This goes through the cache.

[gavinp, 2012/07/25 01:07:01]

Good point. Comment fixed. Srsly fixed.

+      MaybeUpdateDisposition(DISPOSITION_DO_NOT_RECORD);
       mode_ = WRITE;
     } else {
       mode_ = READ_WRITE;
@@ -718,6 +734,8 @@ int HttpCache::Transaction::DoSendRequest() {
   DCHECK(mode_ & WRITE || mode_ == NONE);
   DCHECK(!network_trans_.get());
 
+  started_reading_since_ = TimeTicks::Now();

[rvargas (doing something else), 2012/07/21 02:24:21]

The name is weird for what it is measuring.

[gavinp, 2012/07/25 01:07:01]

Yup. Do you like the new name and use?

+
   // Create a network transaction.
   int rv = cache_->network_layer_->CreateTransaction(&network_trans_);
   if (rv != OK)
@@ -737,6 +755,8 @@ int HttpCache::Transaction::DoSendRequestComplete(int result) {
     return OK;
   }
 
+  // Do not record requests that have network errors or restarts.
+  MaybeUpdateDisposition(DISPOSITION_DO_NOT_RECORD);
   if (IsCertificateError(result)) {
     const HttpResponseInfo* response = network_trans_->GetResponseInfo();
     // If we get a certificate error, then there is a certificate in ssl_info,
@@ -767,6 +787,7 @@ int HttpCache::Transaction::DoSuccessfulSendRequest() {
     // If we have an authentication response, we are exposed to weird things
     // hapenning if the user cancels the authentication before we receive
     // the new response.
+    MaybeUpdateDisposition(DISPOSITION_DO_NOT_RECORD);
     response_ = HttpResponseInfo();
     network_trans_.reset();
     new_response_ = NULL;
@@ -797,9 +818,11 @@ int HttpCache::Transaction::DoSuccessfulSendRequest() {
   // Are we expecting a response to a conditional query?
   if (mode_ == READ_WRITE || mode_ == UPDATE) {
     if (new_response->headers->response_code() == 304 || handling_206_) {
+      MaybeUpdateDisposition(DISPOSITION_ENTRY_VALIDATED_304);

[rvargas (doing something else), 2012/07/21 02:24:21]

This is more than just 304. Why not drop the 304 part?

[gavinp, 2012/07/25 01:07:01]

Done, the new more consistant names are good. Thanks for suggesting it.

But since this code doesn't report on partial requests which could return 206,
what's the other case here?

[rvargas (doing something else), 2012/07/25 19:41:04]

No other case, but to know that 206 doesn't matter requires reading something a
thousand lines apart :)

       next_state_ = STATE_UPDATE_CACHED_RESPONSE;
       return OK;
     }
+    MaybeUpdateDisposition(DISPOSITION_ENTRY_VALIDATED_200);

[rvargas (doing something else), 2012/07/21 02:24:21]

What about names that match the histogram? used, validated, updated.

[gavinp, 2012/07/25 01:07:01]

Done.

     mode_ = WRITE;
   }
 
@@ -847,6 +870,7 @@ int HttpCache::Transaction::DoOpenEntry() {
   next_state_ = STATE_OPEN_ENTRY_COMPLETE;
   cache_pending_ = true;
   net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_OPEN_ENTRY);
+  open_entry_since_ = TimeTicks::Now();
   return cache_->OpenEntry(cache_key_, &new_entry_, this);
 }
 
@@ -866,6 +890,7 @@ int HttpCache::Transaction::DoOpenEntryComplete(int result) {
     return OK;
   }
 
+  MaybeUpdateDisposition(DISPOSITION_NO_ENTRY);
   if (request_->method == "PUT" || request_->method == "DELETE") {
     DCHECK(mode_ == READ_WRITE || mode_ == WRITE);
     mode_ = NONE;
@@ -1239,6 +1264,8 @@ int HttpCache::Transaction::DoCacheReadResponseComplete(int result) {
   //
   switch (mode_) {
     case READ:
+      MaybeUpdateDisposition(DISPOSITION_ENTRY_UNCONDITIONALLY_USED);
+      started_reading_since_ = TimeTicks::Now();

[rvargas (doing something else), 2012/07/21 02:24:21]

Now I'm confused about what do you want to measure with
started_reading_since_... there are 3 different values used.

[gavinp, 2012/07/25 01:07:01]

You're right, it was too confusing. I came into the CL with a concern about
conditional GETs, and forced that view on all of the transactions. The new code
talks about send_request_since_, and it's happy with transactions that lack
that.

       result = BeginCacheRead();
       break;
     case READ_WRITE:
@@ -1346,12 +1373,17 @@ int HttpCache::Transaction::DoCacheReadDataComplete(int result) {
   if (!cache_)
     return ERR_UNEXPECTED;
 
-  if (partial_.get())
+  if (partial_.get()) {
+    // Partial requests are confusing to report in histograms because they may
+    // have multiple underlying requests.
+    MaybeUpdateDisposition(DISPOSITION_DO_NOT_RECORD);
     return DoPartialCacheReadCompleted(result);
+  }
 
   if (result > 0) {
     read_offset_ += result;
   } else if (result == 0) {  // End of file.
+    RecordHistograms(read_offset_);
     cache_->DoneReadingFromEntry(entry_, this);
     entry_ = NULL;
   } else {
@@ -1499,6 +1531,7 @@ void HttpCache::Transaction::SetRequest(const BoundNetLog& net_log,
   }
 
   if (range_found && !(effective_load_flags_ & LOAD_DISABLE_CACHE)) {
+    MaybeUpdateDisposition(DISPOSITION_DO_NOT_RECORD);
     partial_.reset(new PartialData);
     if (request_->method == "GET" && partial_->Init(request_->extra_headers)) {
       // We will be modifying the actual range requested to the server, so
@@ -1570,13 +1603,19 @@ int HttpCache::Transaction::BeginCacheValidation() {
   bool skip_validation = effective_load_flags_ & LOAD_PREFERRING_CACHE ||
                          !RequiresValidation();
 
-  if (truncated_)
+  if (truncated_) {
+    // Truncated entries can cause partial gets, so we shouldn't record this
+    // load in histograms.
+    MaybeUpdateDisposition(DISPOSITION_DO_NOT_RECORD);
     skip_validation = !partial_->initial_validation();
+  }
 
   if ((partial_.get() && !partial_->IsCurrentRangeCached()) || invalid_range_)
     skip_validation = false;
 
   if (skip_validation) {
+    MaybeUpdateDisposition(DISPOSITION_ENTRY_UNCONDITIONALLY_USED);
+    started_reading_since_ = TimeTicks::Now();
     if (partial_.get()) {
       // We are going to return the saved response headers to the caller, so
       // we may need to adjust them first.
@@ -1594,6 +1633,7 @@ int HttpCache::Transaction::BeginCacheValidation() {
     // Our mode remains READ_WRITE for a conditional request.  We'll switch to
     // either READ or WRITE mode once we hear back from the server.
     if (!ConditionalizeRequest()) {
+      MaybeUpdateDisposition(DISPOSITION_ENTRY_UNCONDITIONALLY_USED);
       DCHECK(!partial_.get());
       DCHECK_NE(206, response_.headers->response_code());
       mode_ = WRITE;
@@ -1610,6 +1650,8 @@ int HttpCache::Transaction::BeginPartialCacheValidation() {
       !truncated_)
     return BeginCacheValidation();
 
+  // Partial requests should not be recorded in histograms.
+  MaybeUpdateDisposition(DISPOSITION_DO_NOT_RECORD);
   if (range_requested_) {
     next_state_ = STATE_CACHE_QUERY_DATA;
     return OK;
@@ -1670,6 +1712,7 @@ int HttpCache::Transaction::BeginExternallyConditionalizedRequest() {
         validator.empty() || validator != external_validation_.values[i]) {
       // The externally conditionalized request is not a validation request
       // for our existing cache entry. Proceed with caching disabled.
+      MaybeUpdateDisposition(DISPOSITION_DO_NOT_RECORD);
       DoneWritingToEntry(true);
     }
   }
@@ -1893,6 +1936,7 @@ bool HttpCache::Transaction::ValidatePartialResponse() {
 
   if (failure) {
     // We cannot truncate this entry, it has to be deleted.
+    MaybeUpdateDisposition(DISPOSITION_DO_NOT_RECORD);
     DoomPartialEntry(false);
     mode_ = NONE;
     if (!reading_ && !partial_->IsLastRange()) {
@@ -2015,9 +2059,11 @@ void HttpCache::Transaction::DoneWritingToEntry(bool success) {
   if (!entry_)
     return;
 
-  if (cache_->mode() == RECORD)
+  RecordHistograms(entry_->disk_entry->GetDataSize(kResponseContentIndex));
+  if (cache_->mode() == RECORD) {
     DVLOG(1) << "Recorded: " << request_->method << request_->url

[rvargas (doing something else), 2012/07/21 02:24:21]

unrelated: we should just delete this log.

[gavinp, 2012/07/25 01:07:01]

Done.

              << " status: " << response_.headers->response_code();
+  }
 
   cache_->DoneWritingToEntry(entry_, success);
   entry_ = NULL;
@@ -2112,4 +2158,113 @@ void HttpCache::Transaction::OnIOComplete(int result) {
   DoLoop(result);
 }
 
+void HttpCache::Transaction::MaybeUpdateDisposition(

[rvargas (doing something else), 2012/07/21 02:24:21]

Remove the "maybe" part from the name.

[gavinp, 2012/07/25 01:07:01]

Done.

+    const Disposition disposition) {

[rvargas (doing something else), 2012/07/21 02:24:21]

Drop the const

[gavinp, 2012/07/25 01:07:01]

Done.

+  // Once a transaction has been found to have a complicated disposition, it
+  // can't change to any other simpler disposition.
+  if (disposition_ == DISPOSITION_DO_NOT_RECORD)

[rvargas (doing something else), 2012/07/21 02:24:21]

is this really worth the extra work?. We could just have a single value for
don't track and uninitialized, and avoid a bunch of calls.

[gavinp, 2012/07/25 01:07:01]

Done. Having both and the DCHECK was very good for me to go through the unit
tests, and some live runs, to make sure I had at least the beginning of an idea
of the paths through this state machine.

[gavinp, 2012/07/25 14:00:27]

I should have updated this comment before uploading; my apologies. I tried
updating it in the way you asked, but the problem was that some transactions get
identified as one or the other simple patterns, but then later become
DO_NOT_RECORD. Then they might get updated again... I could tighten up all my
logic for assigning patterns, or have the check here for DO_NOT_RECORD. So I
went with this.

+    return;
+  DCHECK(disposition_ == DISPOSITION_UNDEFINED ||
+         disposition == DISPOSITION_DO_NOT_RECORD);

[rvargas (doing something else), 2012/07/21 02:24:21]

cannot reach do_not_record

[gavinp, 2012/07/25 01:07:01]

Hrm, you are wrong. Does this mean I'm naming my parameter badly?

[rvargas (doing something else), 2012/07/25 19:41:04]

Why am I wrong? the previous line returns if p_not_covered.

[gavinp, 2012/07/28 01:36:06]

The previous line compares the member variable |disposition_| to
DISPOSITION_..., the new line compares |disposition|, the function parameter.
Names changed.

+  disposition_ = disposition;
+}
+
+void HttpCache::Transaction::RecordHistograms(const int resource_size) {

[rvargas (doing something else), 2012/07/21 02:24:21]

Drop the const

[gavinp, 2012/07/25 01:07:01]

Done.

+  if (cache_->mode() != NORMAL || request_->method != "GET")
+    return;
+
+  UMA_HISTOGRAM_BOOLEAN(
+      "HttpCache.DoNotRecord", disposition_ == DISPOSITION_DO_NOT_RECORD);
+  if (disposition_ == DISPOSITION_DO_NOT_RECORD)
+    return;
+  DCHECK(!range_requested_);
+  DCHECK_NE(DISPOSITION_UNDEFINED, disposition_);

[gavinp, 2012/07/20 17:19:24]

Should these DCHECKs be changed into early returns? Or should we have both?

[rvargas (doing something else), 2012/07/21 02:24:21]

DCHECKS seem file to me.

[gavinp, 2012/07/25 01:07:01]

What I found very interesting was how many different ways there were through the
state machine when considering all the potential validation paths for resources.
A few browsing sessions and the unit tests hit these DCHECKs many times.

I'm a bit concerned that I missed some corner case, but on the other hand, I
found the HttpCache test suite very complete in this area, it's as if someone
else has spent a long time going over these cases as they came up one by one...

+  DCHECK(!open_entry_since_.is_null());
+  DCHECK(!started_reading_since_.is_null());
+
+  const TimeDelta before_reading_time =

[rvargas (doing something else), 2012/07/21 02:24:21]

I also think we should drop the const on these variables. It's not that useful
and add noise/distraction.

[gavinp, 2012/07/25 01:07:01]

Done.

+      started_reading_since_ - open_entry_since_;
+  const TimeDelta reading_time = TimeTicks::Now() - started_reading_since_;
+  const TimeDelta total_time = before_reading_time + reading_time;
+
+  UMA_HISTOGRAM_TIMES("HttpCache.TimeBlocked", before_reading_time);

[rvargas (doing something else), 2012/07/21 02:24:21]

This puts together all cache types under the same histogram, and the expected
behavior is not the same.

On the other hand, these don't really look that useful to me. We'll end up with
two wide curves with slightly different parameters without a real way to extract
data about them.

I'd argue that what we want is to know the percentage of time that a request
stays on any given "state".

+  UMA_HISTOGRAM_TIMES("HttpCache.TimeReading", reading_time);
+
+  const bool is_small_resource = resource_size < kSmallResourceMaxBytes;

[rvargas (doing something else), 2012/07/21 02:24:21]

This is not what the caller is passing... I mean, to compare against a value of
a single network read you'd have to add the http headers too.

[gavinp, 2012/07/25 01:07:01]

Good point. It's also undefined since I don't really know the initial CWND, the
actual MTU, if there was a drop, etc...., the idea was to BS my way into
something that halfway works. But headers can vary a lot in size, might be good
to include them.

The new upload makes a first pass at just summing the reads from each of the
cache and network. Is this crazy?

+  if (is_small_resource) {
+    UMA_HISTOGRAM_TIMES(
+        "HttpCache.TimeBlocked.SmallResource", before_reading_time);

[rvargas (doing something else), 2012/07/21 02:24:21]

nit: TimeBlocked?

+    UMA_HISTOGRAM_TIMES("HttpCache.TimeReading.SmallResource", reading_time);
+  }
+
+  // The more detailed histograms are only interesting for requests that are not

[rvargas (doing something else), 2012/07/21 02:24:21]

why?

[gavinp, 2012/07/25 01:07:01]

Good point I had no reason whatsoever to actually know this. I'm tracking both
absolute time per request and the percents. If I become suspicious that short
requests have funny behaviour, I can add another test.

+  // fast.
+  if (total_time.InMilliseconds() < kFastRequestCutoffMs)
+    return;
+
+  const int before_reading_percent = before_reading_time * 100 / total_time;
+  DCHECK_LE(0, before_reading_percent);
+  DCHECK_GE(100, before_reading_percent);
+
+  UMA_HISTOGRAM_PERCENTAGE("HttpCache.PercentBlocked", before_reading_percent);

[rvargas (doing something else), 2012/07/21 02:24:21]

nit: Not really blocked

[gavinp, 2012/07/25 01:07:01]

Now named how long before send. The request isn't blocked, however, for many
requests, an unmodified request cannot be sent until the disk performs the
ritual reads.

+  if (is_small_resource)
+    UMA_HISTOGRAM_PERCENTAGE("HttpCache.PercentBlocked.SmallResource",
+                             before_reading_percent);
+
+  // TODO(gavinp): Remove or minimize these histograms, particularly the ones
+  // below this comment after we have received initial data.
+  switch (disposition_) {

[rvargas (doing something else), 2012/07/21 02:24:21]

nit: I'm not really happy with the term "disposition". It covers "do not track"
plus whether the response came from the cache or not (with revalidation or not).

How about a name that conveys a tracking/histogram, type/status?
track_status, cached_status, transaction_type (too vague)... something like
that.

[gavinp, 2012/07/25 01:07:01]

Now that you point it out, I hate the name too.

The new one is "TransactionPattern".  Does that manage the right combination of
specific and general?

+    case DISPOSITION_NO_ENTRY: {
+      UMA_HISTOGRAM_TIMES(
+          "HttpCache.TimeBlocked.NotCached", before_reading_time);
+      UMA_HISTOGRAM_PERCENTAGE(
+          "HttpCache.PercentBlocked.NotCached", before_reading_percent);

[rvargas (doing something else), 2012/07/21 02:24:21]

Id suggest just dropping the absolute times.

[gavinp, 2012/07/25 01:07:01]

You might be right. I'd like to wait for results. I promise I'll aggressively
narrow these if we don't find them useful.

+      if (is_small_resource) {
+        UMA_HISTOGRAM_PERCENTAGE(
+            "HttpCache.PercentBlocked.NotCached.SmallResource",
+            before_reading_percent);
+      }
+      break;
+    }
+    case DISPOSITION_ENTRY_UNCONDITIONALLY_USED: {
+      UMA_HISTOGRAM_TIMES(
+          "HttpCache.TimeBlocked.Used", before_reading_time);
+      UMA_HISTOGRAM_PERCENTAGE(
+          "HttpCache.PercentBlocked.Used", before_reading_percent);
+      if (is_small_resource) {
+        UMA_HISTOGRAM_PERCENTAGE("HttpCache.PercentBlocked.Used.SmallResource",
+                                 before_reading_percent);
+      }
+      break;
+    }
+    case DISPOSITION_ENTRY_VALIDATED_304: {
+      UMA_HISTOGRAM_TIMES(
+          "HttpCache.TimeBlocked.Validated", before_reading_time);
+      UMA_HISTOGRAM_PERCENTAGE(
+          "HttpCache.PercentBlocked.Validated", before_reading_percent);
+      if (is_small_resource) {
+        UMA_HISTOGRAM_PERCENTAGE(
+            "HttpCache.PercentBlocked.Validated.SmallResource",
+            before_reading_percent);
+      }
+      break;
+    }
+    case DISPOSITION_ENTRY_VALIDATED_200: {
+      UMA_HISTOGRAM_TIMES(
+          "HttpCache.TimeBlocked.Updated", before_reading_time);
+      UMA_HISTOGRAM_PERCENTAGE(
+          "HttpCache.PercentBlocked.Updated", before_reading_percent);
+      if (is_small_resource) {
+        UMA_HISTOGRAM_PERCENTAGE(
+            "HttpCache.PercentBlocked.Updated.SmallResource",
+            before_reading_percent);
+      }
+      break;
+    }
+    case DISPOSITION_UNDEFINED:
+    default:
+      NOTREACHED();
+  }
+}
+
 }  // namespace net