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 "base/time/time.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"
 #include "net/http/http_server_properties.h"
 #include "net/url_request/url_request.h"
 #include "net/url_request/url_request_context.h"
 
 namespace content {
 
+namespace {
+
+void PostHistogram(const char* base_name,
+                   const char* suffix,
+                   base::TimeDelta time) {
+  std::string histogram_name =
+      base::StringPrintf("ResourceScheduler.%s_%s", base_name, suffix);

[Ilya Sherman, 2014/11/03 23:03:45]

Optional nit: Out of curiousity, why are you using an underscore rather than a
dot for the second separator?

[aiolos (Not reviewing), 2014/11/04 00:15:31]

It's the form I saw used with the only other histograms I've messed with
(SessionRestore.AllTabsLoaded_1, etc). I have no preference I was just trying to
be consistent with what I knew. After looking at other histograms, the dot does
seem to be used more often. Changing.

+  base::HistogramBase* histogram_counter = base::Histogram::FactoryTimeGet(
+      histogram_name,
+      base::TimeDelta::FromMilliseconds(1),
+      base::TimeDelta::FromMinutes(5),
+      50,
+      base::Histogram::kUmaTargetedHistogramFlag);
+  histogram_counter->AddTime(time);
+}
+
+}  // namespace
+
 static const size_t kCoalescedTimerPeriod = 5000;
 static const size_t kMaxNumDelayableRequestsPerClient = 10;
 static const size_t kMaxNumDelayableRequestsPerHost = 6;
 static const size_t kMaxNumThrottledRequestsPerClient = 1;
 
 struct ResourceScheduler::RequestPriorityParams {
   RequestPriorityParams()
     : priority(net::DEFAULT_PRIORITY),
       intra_priority(0) {
   }
@@ skipping 80 matching lines @@
 class ResourceScheduler::ScheduledResourceRequest
     : public ResourceMessageDelegate,
       public ResourceThrottle {
  public:
   ScheduledResourceRequest(const ClientId& client_id,
                            net::URLRequest* request,
                            ResourceScheduler* scheduler,
                            const RequestPriorityParams& priority)
       : ResourceMessageDelegate(request),
         client_id_(client_id),
+        client_state_on_creation_(scheduler->GetClientState(client_id_)),
         request_(request),
         ready_(false),
         deferred_(false),
         classification_(NORMAL_REQUEST),
         scheduler_(scheduler),
         priority_(priority),
         fifo_ordering_(0) {
     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()) {
+    if (!request_->status().is_success())
+      return;
+    base::TimeTicks time = base::TimeTicks::Now();
+    ClientState current_state = scheduler_->GetClientState(client_id_);
+    // Note: the client state isn't perfectly accurate since it won't capture
+    // tabs which have switched between active and background multiple times.
+    // Ex: A tab with the following transitions Active -> Background -> Active
+    // will be recorded as Active.
+    const char* client_state = "Other";
+    if (current_state == client_state_on_creation_ && current_state == ACTIVE) {
+      client_state = "Active";
+    } else if (current_state == client_state_on_creation_ &&
+               current_state == BACKGROUND) {
+      client_state = "Background";
+    }
+
+    if (deferred_) {
       deferred_ = false;
       controller()->Resume();
+      PostHistogram("RequestTimeDeferred", client_state, time - time_deferred_);
+    } else {
+      PostHistogram("RequestTimeDeferred",

[Ilya Sherman, 2014/11/03 23:03:45]

In general, it's nice not to have to repeat histogram names, to reduce the risk
of typos sneaking in to just one of the code paths.  I'll defer to your
judgement here, but something to think about.

[aiolos (Not reviewing), 2014/11/04 00:15:31]

Done.

+                    client_state,
+                    base::TimeDelta::FromMicroseconds(0));
     }
+    PostHistogram(
+        "RequestTimeThrottled", client_state, time - request_->creation_time());
+    // TODO(aiolos): Remove one of the above sets of histograms after gaining an
+    // understanding of the difference between them and which one is more
+    // interesting.
   }
 
   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 14 matching lines @@
   bool OnMessageReceived(const IPC::Message& message) override {
     bool handled = true;
     IPC_BEGIN_MESSAGE_MAP(ScheduledResourceRequest, message)
       IPC_MESSAGE_HANDLER(ResourceHostMsg_DidChangePriority, DidChangePriority)
       IPC_MESSAGE_UNHANDLED(handled = false)
     IPC_END_MESSAGE_MAP()
     return handled;
   }
 
   // ResourceThrottle interface:
-  void WillStartRequest(bool* defer) override { deferred_ = *defer = !ready_; }
+  void WillStartRequest(bool* defer) override {
+    deferred_ = *defer = !ready_;
+    time_deferred_ = base::TimeTicks::Now();
+  }
 
   const char* GetNameForLogging() const override { return "ResourceScheduler"; }
 
   void DidChangePriority(int request_id, net::RequestPriority new_priority,
                          int intra_priority_value) {
     scheduler_->ReprioritizeRequest(this, new_priority, intra_priority_value);
   }
 
-  ClientId client_id_;
+  const ClientId client_id_;
+  const ResourceScheduler::ClientState client_state_on_creation_;
   net::URLRequest* request_;
   bool ready_;
   bool deferred_;
   RequestClassification classification_;
   ResourceScheduler* scheduler_;
   RequestPriorityParams priority_;
   uint32 fifo_ordering_;
+  base::TimeTicks time_deferred_;
 
   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 540 matching lines @@
   DCHECK(client);
   return client->throttle_state();
 }
 
 scoped_ptr<ResourceThrottle> ResourceScheduler::ScheduleRequest(
     int child_id,
     int route_id,
     net::URLRequest* url_request) {
   DCHECK(CalledOnValidThread());
   ClientId client_id = MakeClientId(child_id, route_id);
-  scoped_ptr<ScheduledResourceRequest> request(
-      new ScheduledResourceRequest(client_id, url_request, this,
-          RequestPriorityParams(url_request->priority(), 0)));
+  scoped_ptr<ScheduledResourceRequest> request(new ScheduledResourceRequest(
+      client_id,
+      url_request,
+      this,
+      RequestPriorityParams(url_request->priority(), 0)));
 
   ClientMap::iterator it = client_map_.find(client_id);
   if (it == client_map_.end()) {
     // There are several ways this could happen:
     // 1. <a ping> requests don't have a route_id.
     // 2. Most unittests don't send the IPCs needed to register Clients.
     // 3. The tab is closed while a RequestResource IPC is in flight.
     unowned_requests_.insert(request.get());
     request->Start();
     return request.Pass();
@@ skipping 221 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;
   }
 }
 
+ResourceScheduler::ClientState ResourceScheduler::GetClientState(
+    ClientId client_id) const {
+  ClientMap::const_iterator client_it = client_map_.find(client_id);
+  if (client_it == client_map_.end())
+    return UNKNOWN;
+  return client_it->second->is_active() ? ACTIVE : BACKGROUND;
+}
+
 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