Add histograms to gather ResourceScheduler information.

content/browser/loader/resource_scheduler.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 <set>
 
 #include "content/browser/loader/resource_scheduler.h"
 
 #include "base/metrics/field_trial.h"
+#include "base/metrics/histogram.h"
 #include "base/stl_util.h"
 #include "content/common/resource_messages.h"
 #include "content/browser/loader/resource_message_delegate.h"
 #include "content/public/browser/resource_controller.h"
 #include "content/public/browser/resource_request_info.h"
 #include "content/public/browser/resource_throttle.h"
 #include "ipc/ipc_message_macros.h"
 #include "net/base/host_port_pair.h"
 #include "net/base/load_flags.h"
 #include "net/base/request_priority.h"
@@ skipping 102 matching lines @@
                            ResourceScheduler* scheduler,
                            const RequestPriorityParams& priority)
       : ResourceMessageDelegate(request),
         client_id_(client_id),
         request_(request),
         ready_(false),
         deferred_(false),
         classification_(NORMAL_REQUEST),
         scheduler_(scheduler),
         priority_(priority),
-        fifo_ordering_(0) {
+        fifo_ordering_(0),
+        request_seen_(base::TimeTicks::Now()) {

[mmenke, 2014/10/30 15:14:19]

Should include base/time.h (Timer, included in the header, includes it, but
seems like we should be including it explicitly)

[aiolos (Not reviewing), 2014/10/31 23:33:27]

Done.

     TRACE_EVENT_ASYNC_BEGIN1("net", "URLRequest", request_,
                              "url", request->url().spec());
   }
 
   ~ScheduledResourceRequest() override { scheduler_->RemoveRequest(this); }
 
   void Start() {
     TRACE_EVENT_ASYNC_STEP_PAST0("net", "URLRequest", request_, "Queued");
     ready_ = true;
     if (deferred_ && request_->status().is_success()) {

[mmenke, 2014/10/30 15:14:19]

If request_->status() isn't success, should we even be recording anything?  That
means something else cancelled the request, or it failed.  Will presumably be
deleted on resume.  Rare case, so maybe we don't really care anyways.

Hrm...Also, I wonder if this is a bug.  If a request is paused, and then
cancelled, I can't remember if it has to be resumed or not (If a request is
paused while passing around the ERR_ABORTED result, it does have to be resumed).

[aiolos (Not reviewing), 2014/10/30 16:58:47]

Easy enough to change.
Hmm. Good question.  I'm not sure.

[mmenke, 2014/10/30 17:30:40]

Glancing at the loader, looks like we're fine.

       deferred_ = false;
       controller()->Resume();
     }
+    base::TimeDelta time_deferred = base::TimeTicks::Now() - request_seen_;

[mmenke, 2014/10/30 15:14:19]

This this the time we want?  We could measure time we actually delayed the
request actually paused instead (Time between when WillStartRequest() was
called, and we called controller()->Resume(), if we paused the request, or 0 if
we chose not to pause it).

It is a less direct measure than the time we *tried* to delay the request for,
but it is closed to our practical impact.

Not sure how much difference there'll be between the two histograms - probably
not much.

[aiolos (Not reviewing), 2014/10/30 16:58:47]

I can see value from both options. I'm guessing we probably don't need both,
although knowing how much impact we're actually having on requests wouldn't be a
bad thing. Would it make sense to have histograms for both for this experiment
just to see, and then take out whichever one we feel is less helpful afterward?

[mmenke, 2014/10/30 17:30:40]

I'm fine with adding both, and a TODO to remove one of them fairly promptly. 
Definitely agree we don't need/want both longer term.

Nice to know if there's any meaningful difference between the two.  If not, can
throw one away pretty quickly.  If not, can figure out if the difference is
relevant, and then get rid of the one we decide we care less about.

[aiolos (Not reviewing), 2014/10/31 23:33:27]

Done.

+    std::string histogram_name = base::StringPrintf(
+        "ResourceScheduler.%sRequestTimeDeferred",

[Ilya Sherman, 2014/10/30 03:18:11]

Optional nit: I'd recommend having the Active vs. Background string appear as a
suffix, so that the related histograms are alphabetized to be right next to each
other.

[mmenke, 2014/10/30 15:14:19]

It also makes the histograms more searchable.

[aiolos (Not reviewing), 2014/10/31 23:33:27]

Done.

+        scheduler_->IsClientActive(client_id_) ? "Active" : "Background");
+    base::HistogramBase* histogram_counter = base::Histogram::FactoryTimeGet(
+        histogram_name,
+        base::TimeDelta::FromMilliseconds(1),
+        base::TimeDelta::FromMinutes(5),
+        100,

[mmenke, 2014/10/30 15:14:19]

Do we really need 100 buckets?  Think 50 should be fine.  This is just about
reducing size of the histogram in memory.

[aiolos (Not reviewing), 2014/10/31 23:33:27]

Done.

+        base::Histogram::kUmaTargetedHistogramFlag);
+    histogram_counter->AddTime(time_deferred);
   }
 
   void set_request_priority_params(const RequestPriorityParams& priority) {
     priority_ = priority;
   }
   const RequestPriorityParams& get_request_priority_params() const {
     return priority_;
   }
   const ClientId& client_id() const { return client_id_; }
   net::URLRequest* url_request() { return request_; }
@@ skipping 31 matching lines @@
   }
 
   ClientId client_id_;
   net::URLRequest* request_;
   bool ready_;
   bool deferred_;
   RequestClassification classification_;
   ResourceScheduler* scheduler_;
   RequestPriorityParams priority_;
   uint32 fifo_ordering_;
+  base::TimeTicks request_seen_;

[mmenke, 2014/10/30 15:14:19]

"request_seen_" makes me think "Did we see the request", not "when was this
request seen".

Suggest calling it time_seen_...  Or could just use request_->creation_time() 
(Throttles are created right after the URLRequest is scheduled, so that should
basically be the same thing).

[aiolos (Not reviewing), 2014/10/31 23:33:27]

Acknowledged.

 
   DISALLOW_COPY_AND_ASSIGN(ScheduledResourceRequest);
 };
 
 bool ResourceScheduler::ScheduledResourceSorter::operator()(
     const ScheduledResourceRequest* a,
     const ScheduledResourceRequest* b) const {
   // Want the set to be ordered first by decreasing priority, then by
   // decreasing intra_priority.
   // ie. with (priority, intra_priority)
@@ skipping 784 matching lines @@
 void ResourceScheduler::LoadCoalescedRequests() {
   DCHECK(should_coalesce_);
   ClientMap::iterator client_it = client_map_.begin();
   while (client_it != client_map_.end()) {
     Client* client = client_it->second;
     client->LoadCoalescedRequests();
     ++client_it;
   }
 }
 
+bool ResourceScheduler::IsClientActive(ClientId client_id) {
+    ClientMap::iterator client_it = client_map_.find(client_id);

[mmenke, 2014/10/30 15:14:19]

const_iterator

[aiolos (Not reviewing), 2014/10/31 23:33:27]

Done.

+      if (client_it == client_map_.end()) {
+            return false;

[mmenke, 2014/10/30 15:14:19]

When there's no client, we just let requests through the scheduler, so this
seems the wrong bucket to put that case into.

Also, when a client goes away, are its requests typically deleted first, or the
client?

[aiolos (Not reviewing), 2014/10/31 23:33:27]

I made a separate histogram for those requests plus requests from clients that
have switched states since the request was issued. I'm debating changing this to
add a histogram that gets counts from all requests instead.

ie:

ResourceScheduler.RequestTimeDeferred_Active
ResourceScheduler.RequestTimeDeferred_Background
ResourceScheduler.RequestTimeDeferred_Other

vs 

ResourceScheduler.RequestTimeDeferred
ResourceScheduler.RequestTimeDeferred_Active
ResourceScheduler.RequestTimeDeferred_Background

Thoughts?

+              }

[mmenke, 2014/10/30 15:14:19]

don't use braces when both condition and body of an if take up one line.

[aiolos (Not reviewing), 2014/10/31 23:33:27]

Done.

+        return client_it->second->is_active();

[mmenke, 2014/10/30 15:14:19]

Formatting here is off

[aiolos (Not reviewing), 2014/10/31 23:33:27]

Done.

+}
+
 void ResourceScheduler::ReprioritizeRequest(ScheduledResourceRequest* request,
                                             net::RequestPriority new_priority,
                                             int new_intra_priority_value) {
   if (request->url_request()->load_flags() & net::LOAD_IGNORE_LIMITS) {
     // We should not be re-prioritizing requests with the
     // IGNORE_LIMITS flag.
     NOTREACHED();
     return;
   }
   RequestPriorityParams new_priority_params(new_priority,
@@ skipping 18 matching lines @@
   client->ReprioritizeRequest(
       request, old_priority_params, new_priority_params);
 }
 
 ResourceScheduler::ClientId ResourceScheduler::MakeClientId(
     int child_id, int route_id) {
   return (static_cast<ResourceScheduler::ClientId>(child_id) << 32) | route_id;
 }
 
 }  // namespace content