Add HttpCache histograms focussed on blocking and transaction type.

net/http/http_cache_transaction.cc

 // Copyright (c) 2012 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 "net/http/http_cache_transaction.h"
 
 #include "build/build_config.h"
 
 #if defined(OS_POSIX)
 #include <unistd.h>
@@ skipping 23 matching lines @@
 #include "net/http/http_transaction.h"
 #include "net/http/http_util.h"
 #include "net/http/partial_data.h"
 
 using base::Time;
 using base::TimeDelta;
 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;
 };
 
 // If the request includes one of these request headers, then avoid caching
 // to avoid getting confused.
 static const HeaderNameAndValue kPassThroughHeaders[] = {
   { "if-unmodified-since", NULL },  // causes unexpected 412s
   { "if-match", NULL },             // causes unexpected 412s
@@ skipping 65 matching lines @@
       handling_206_(false),
       cache_pending_(false),
       done_reading_(false),
       read_offset_(0),
       effective_load_flags_(0),
       write_len_(0),
       final_upload_progress_(0),
       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);
 }
 
 HttpCache::Transaction::~Transaction() {
   // We may have to issue another IO, but we should never invoke the callback_
   // after this point.
   callback_.Reset();
 
@@ skipping 523 matching lines @@
                                     result);
   cache_pending_ = false;
 
   if (!ShouldPassThrough()) {
     cache_key_ = cache_->GenerateCacheKey(request_);
 
     // Requested cache access mode.
     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;
     }
 
     // Downgrade to UPDATE if the request has been externally conditionalized.
     if (external_validation_.initialized) {
       if (mode_ & WRITE) {
         // Strip off the READ_DATA bit (and maybe add back a READ_META bit
         // in case READ was off).
@@ skipping 28 matching lines @@
   // This is only set if we have something to do with the response.
   range_requested_ = (partial_.get() != NULL);
 
   return OK;
 }
 
 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)
     return rv;
 
   next_state_ = STATE_SEND_REQUEST_COMPLETE;
   rv = network_trans_->Start(request_, io_callback_, net_log_);
   return rv;
 }
 
 int HttpCache::Transaction::DoSendRequestComplete(int result) {
   if (!cache_)
     return ERR_UNEXPECTED;
 
   if (result == OK) {
     next_state_ = STATE_SUCCESSFUL_SEND_REQUEST;
     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,
     // so GetResponseInfo() should never return NULL here.
     DCHECK(response);
     response_.ssl_info = response->ssl_info;
   } else if (result == ERR_SSL_CLIENT_AUTH_CERT_NEEDED) {
     const HttpResponseInfo* response = network_trans_->GetResponseInfo();
     DCHECK(response);
     response_.cert_request_info = response->cert_request_info;
@@ skipping 10 matching lines @@
     auth_response_ = *new_response;
     return OK;
   }
 
   new_response_ = new_response;
   if (!ValidatePartialResponse() && !auth_response_.headers) {
     // Something went wrong with this request and we have to restart it.
     // 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;
     next_state_ = STATE_SEND_REQUEST;
     return OK;
   }
   if (handling_206_ && mode_ == READ_WRITE && !truncated_ && !is_sparse_) {
     // We have stored the full entry, but it changed and the server is
     // sending a range. We have to delete the old entry.
     DoneWritingToEntry(false);
   }
 

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

Do you mind keeping this line?

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

Done.

   if (new_response_->headers->response_code() == 416) {
     DCHECK_EQ(NONE, mode_);
     response_ = *new_response_;
     return OK;
   }
 
   if (mode_ == WRITE &&
       (request_->method == "PUT" || request_->method == "DELETE")) {
     if (new_response->headers->response_code() == 200) {
       int ret = cache_->DoomEntry(cache_key_, NULL);
       DCHECK_EQ(OK, ret);
     }
     mode_ = NONE;
   }
 
   // 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;
   }
 
   next_state_ = STATE_OVERWRITE_CACHED_RESPONSE;
   return OK;
 }
 
 int HttpCache::Transaction::DoNetworkRead() {
   next_state_ = STATE_NETWORK_READ_COMPLETE;
   return network_trans_->Read(read_buf_, io_buf_len_, io_callback_);
@@ skipping 27 matching lines @@
 
   next_state_ = STATE_OPEN_ENTRY;
   return OK;
 }
 
 int HttpCache::Transaction::DoOpenEntry() {
   DCHECK(!new_entry_);
   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);
 }
 
 int HttpCache::Transaction::DoOpenEntryComplete(int result) {
   // It is important that we go to STATE_ADD_TO_ENTRY whenever the result is
   // OK, otherwise the cache will end up with an active entry without any
   // transaction attached.
   net_log_.EndEventWithNetErrorCode(NetLog::TYPE_HTTP_CACHE_OPEN_ENTRY, result);
   cache_pending_ = false;
   if (result == OK) {
     next_state_ = STATE_ADD_TO_ENTRY;
     return OK;
   }
 
   if (result == ERR_CACHE_RACE) {
     next_state_ = STATE_INIT_ENTRY;
     return OK;
   }
 
+  MaybeUpdateDisposition(DISPOSITION_NO_ENTRY);
   if (request_->method == "PUT" || request_->method == "DELETE") {
     DCHECK(mode_ == READ_WRITE || mode_ == WRITE);
     mode_ = NONE;
     next_state_ = STATE_SEND_REQUEST;
     return OK;
   }
 
   if (mode_ == READ_WRITE) {
     mode_ = WRITE;
     next_state_ = STATE_CREATE_ENTRY;
@@ skipping 353 matching lines @@
   //  o if we can read or write, then we should check if the cache entry needs
   //    to be validated and then issue a network request if needed or just read
   //    from the cache if the cache entry is already valid.
   //
   //  o if we are set to UPDATE, then we are handling an externally
   //    conditionalized request (if-modified-since / if-none-match). We check
   //    if the request headers define a validation request.
   //
   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:
       result = BeginPartialCacheValidation();
       break;
     case UPDATE:
       result = BeginExternallyConditionalizedRequest();
       break;
     case WRITE:
     default:
@@ skipping 44 matching lines @@
   net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_READ_INFO);
   return entry_->disk_entry->ReadData(kMetadataIndex, 0, response_.metadata,
                                       response_.metadata->size(),
                                       io_callback_);
 }
 
 int HttpCache::Transaction::DoCacheReadMetadataComplete(int result) {
   net_log_.EndEventWithNetErrorCode(NetLog::TYPE_HTTP_CACHE_READ_INFO, result);
   if (result != response_.metadata->size())
     return OnCacheReadError(result, false);
 

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

do you mind keeping the line?

   return OK;
 }
 
 int HttpCache::Transaction::DoCacheQueryData() {
   next_state_ = STATE_CACHE_QUERY_DATA_COMPLETE;
 
   // Balanced in DoCacheQueryDataComplete.
   return entry_->disk_entry->ReadyForSparseIO(io_callback_);
 }
 
@@ skipping 22 matching lines @@
 
 int HttpCache::Transaction::DoCacheReadDataComplete(int result) {
   if (net_log_.IsLoggingAllEvents()) {
     net_log_.EndEventWithNetErrorCode(NetLog::TYPE_HTTP_CACHE_READ_DATA,
                                       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 {
     return OnCacheReadError(result, false);
   }
   return result;
 }
 
 int HttpCache::Transaction::DoCacheWriteData(int num_bytes) {
   next_state_ = STATE_CACHE_WRITE_DATA_COMPLETE;
@@ skipping 127 matching lines @@
 
   // If there is more than one validation header, we can't treat this request as
   // a cache validation, since we don't know for sure which header the server
   // will give us a response for (and they could be contradictory).
   if (external_validation_error) {
     LOG(WARNING) << "Multiple or malformed validation headers found.";
     effective_load_flags_ |= LOAD_DISABLE_CACHE;
   }
 
   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
       // let's remove the header here.
       custom_request_.reset(new HttpRequestInfo(*request_));
       custom_request_->extra_headers.RemoveHeader(HttpRequestHeaders::kRange);
       request_ = custom_request_.get();
       partial_->SetHeaders(custom_request_->extra_headers);
     } else {
       // The range is invalid or we cannot handle it properly.
@@ skipping 51 matching lines @@
 
   return OK;
 }
 
 int HttpCache::Transaction::BeginCacheValidation() {
   DCHECK(mode_ == READ_WRITE);
 
   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.
       next_state_ = STATE_PARTIAL_HEADERS_RECEIVED;
       return OK;
     }
     cache_->ConvertWriterToReader(entry_);
     mode_ = READ;
 
     if (entry_->disk_entry->GetDataSize(kMetadataIndex))
       next_state_ = STATE_CACHE_READ_METADATA;
   } else {
     // Make the network request conditional, to see if we may reuse our cached
     // response.  If we cannot do so, then we just resort to a normal fetch.
     // 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;
     }
     next_state_ = STATE_SEND_REQUEST;
   }
   return OK;
 }
 
 int HttpCache::Transaction::BeginPartialCacheValidation() {
   DCHECK(mode_ == READ_WRITE);
 
   if (response_.headers->response_code() != 206 && !partial_.get() &&
       !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;
   }
   // The request is not for a range, but we have stored just ranges.
   partial_.reset(new PartialData());
   partial_->SetHeaders(request_->extra_headers);
   if (!custom_request_.get()) {
     custom_request_.reset(new HttpRequestInfo(*request_));
     request_ = custom_request_.get();
@@ skipping 40 matching lines @@
     std::string validator;
     response_.headers->EnumerateHeader(
         NULL,
         kValidationHeaders[i].related_response_header_name,
         &validator);
 
     if (response_.headers->response_code() != 200 || truncated_ ||
         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);
     }
   }
 
   next_state_ = STATE_SEND_REQUEST;
   return OK;
 }
 
 int HttpCache::Transaction::RestartNetworkRequest() {
   DCHECK(mode_ & WRITE || mode_ == NONE);
@@ skipping 203 matching lines @@
     }
 
     // 304 is not expected here, but we'll spare the entry (unless it was
     // truncated).
     if (truncated_)
       failure = true;
   }
 
   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()) {
       // We'll attempt to issue another network request, this time without us
       // messing up the headers.
       partial_->RestoreHeaders(&custom_request_->extra_headers);
       partial_.reset();
       truncated_ = false;
       return false;
     }
@@ skipping 102 matching lines @@
 
   int current_size = entry_->disk_entry->GetDataSize(kResponseContentIndex);
   return WriteToEntry(kResponseContentIndex, current_size, data, data_len,
                       callback);
 }
 
 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;
   mode_ = NONE;  // switch to 'pass through' mode
 }
 
 int HttpCache::Transaction::OnCacheReadError(int result, bool restart) {
   DLOG(ERROR) << "ReadData failed: " << result;
 
   // Avoid using this entry in the future.
@@ skipping 74 matching lines @@
       !response_.headers->HasStrongValidators())
     return false;
 
   return true;
 }
 
 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