Add UMA that periodically logs number of outstanding requests

content/browser/loader/resource_dispatcher_host_impl.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.
 
 // See http://dev.chromium.org/developers/design-documents/multi-process-resource-loading
 
 #include "content/browser/loader/resource_dispatcher_host_impl.h"
 
 #include <stddef.h>
 
@@ skipping 150 matching lines @@
 
 namespace content {
 
 namespace {
 
 static ResourceDispatcherHostImpl* g_resource_dispatcher_host;
 
 // The interval for calls to ResourceDispatcherHostImpl::UpdateLoadStates
 const int kUpdateLoadStatesIntervalMsec = 250;
 
+// The interval for calls to RecordOutstandingRequestsStats.
+const int kRecordOutstandingRequestsStatsIntervalMsec = 60000;
+
 // Maximum byte "cost" of all the outstanding requests for a renderer.
 // See declaration of |max_outstanding_requests_cost_per_process_| for details.
 // This bound is 25MB, which allows for around 6000 outstanding requests.
 const int kMaxOutstandingRequestsCostPerProcess = 26214400;
 
 // The number of milliseconds after noting a user gesture that we will
 // tag newly-created URLRequest objects with the
 // net::LOAD_MAYBE_USER_GESTURE load flag. This is a fairly arbitrary
 // guess at how long to expect direct impact from a user gesture, but
 // this should be OK as the load flag is a best-effort thing only,
@@ skipping 151 matching lines @@
     : request_id_(-1),
       is_shutdown_(false),
       num_in_flight_requests_(0),
       max_num_in_flight_requests_(base::SharedMemory::GetHandleLimit()),
       max_num_in_flight_requests_per_process_(static_cast<int>(
           max_num_in_flight_requests_ * kMaxRequestsPerProcessRatio)),
       max_outstanding_requests_cost_per_process_(
           kMaxOutstandingRequestsCostPerProcess),
       largest_outstanding_request_count_seen_(0),
       largest_outstanding_request_per_process_count_seen_(0),
+      peak_outstanding_request_count_(0),
+      peak_outstanding_request_count_multitab_(0),
       delegate_(nullptr),
       loader_delegate_(nullptr),
       allow_cross_origin_auth_prompt_(false),
       create_download_handler_intercept_(download_handler_intercept),
       main_thread_task_runner_(base::ThreadTaskRunnerHandle::Get()),
       io_thread_task_runner_(io_thread_runner),
       experimental_web_features_enabled_(
           base::CommandLine::ForCurrentProcess()->HasSwitch(
               switches::kEnableExperimentalWebPlatformFeatures)) {
   DCHECK(main_thread_task_runner_->BelongsToCurrentThread());
   DCHECK(!g_resource_dispatcher_host);
   g_resource_dispatcher_host = this;
 
   ANNOTATE_BENIGN_RACE(
       &last_user_gesture_time_,
       "We don't care about the precise value, see http://crbug.com/92889");
 
   io_thread_task_runner_->PostTask(
       FROM_HERE,
       base::Bind(&ResourceDispatcherHostImpl::OnInit, base::Unretained(this)));
 
   update_load_states_timer_.reset(new base::RepeatingTimer());
+  record_outstanding_requests_stats_timer_.reset(new base::RepeatingTimer());
 }
 
 // The default ctor is only used by unittests. It is reasonable to assume that
 // the main thread and the IO thread are the same for unittests.
 ResourceDispatcherHostImpl::ResourceDispatcherHostImpl()
     : ResourceDispatcherHostImpl(CreateDownloadHandlerIntercept(),
                                  base::ThreadTaskRunnerHandle::Get()) {}
 
 ResourceDispatcherHostImpl::~ResourceDispatcherHostImpl() {
   DCHECK(outstanding_requests_stats_map_.empty());
@@ skipping 208 matching lines @@
 
   const net::URLRequestJobFactory* job_factory =
       info->GetContext()->GetRequestContext()->job_factory();
   if (!url.is_valid() || job_factory->IsHandledProtocol(url.scheme()))
     return false;
 
   return delegate_->HandleExternalProtocol(url, info);
 }
 
 void ResourceDispatcherHostImpl::DidStartRequest(ResourceLoader* loader) {
-  // Make sure we have the load state monitor running.
+  // Make sure we have the load state monitors running.
   if (!update_load_states_timer_->IsRunning() &&
       scheduler_->HasLoadingClients()) {
     update_load_states_timer_->Start(
         FROM_HERE, TimeDelta::FromMilliseconds(kUpdateLoadStatesIntervalMsec),
         this, &ResourceDispatcherHostImpl::UpdateLoadInfo);
   }
+  if (!record_outstanding_requests_stats_timer_->IsRunning()) {
+    record_outstanding_requests_stats_timer_->Start(
+        FROM_HERE,
+        TimeDelta::FromMilliseconds(
+            kRecordOutstandingRequestsStatsIntervalMsec),
+        this, &ResourceDispatcherHostImpl::RecordOutstandingRequestsStats);
+  }
 }
 
 void ResourceDispatcherHostImpl::DidReceiveRedirect(
     ResourceLoader* loader,
     const GURL& new_url,
     ResourceResponse* response) {
   ResourceRequestInfoImpl* info = loader->GetRequestInfo();
   if (delegate_) {
     delegate_->OnRequestRedirected(
         new_url, loader->request(), info->GetContext(), response);
@@ skipping 168 matching lines @@
 void ResourceDispatcherHostImpl::OnInit() {
   scheduler_.reset(new ResourceScheduler);
 }
 
 void ResourceDispatcherHostImpl::OnShutdown() {
   DCHECK(io_thread_task_runner_->BelongsToCurrentThread());
 
   is_shutdown_ = true;
   pending_loaders_.clear();
 
-  // Make sure we shutdown the timer now, otherwise by the time our destructor
+  // Make sure we shutdown the timers now, otherwise by the time our destructor
   // runs if the timer is still running the Task is deleted twice (once by
   // the MessageLoop and the second time by RepeatingTimer).
   update_load_states_timer_.reset();
+  record_outstanding_requests_stats_timer_.reset();
 
   // Clear blocked requests if any left.
   // Note that we have to do this in 2 passes as we cannot call
   // CancelBlockedRequestsForRoute while iterating over
   // blocked_loaders_map_, as it modifies it.
   std::set<GlobalFrameRoutingId> ids;
   for (const auto& blocked_loaders : blocked_loaders_map_) {
     std::pair<std::set<GlobalFrameRoutingId>::iterator, bool> result =
         ids.insert(blocked_loaders.first);
     // We should not have duplicates.
@@ skipping 1161 matching lines @@
   }
 
   if (stats.num_requests >
       largest_outstanding_request_per_process_count_seen_) {
     largest_outstanding_request_per_process_count_seen_ = stats.num_requests;
     UMA_HISTOGRAM_COUNTS_1M(
         "Net.ResourceDispatcherHost.OutstandingRequests.PerProcess",
         largest_outstanding_request_per_process_count_seen_);
   }
 
+  if (num_in_flight_requests_ > peak_outstanding_request_count_) {
+    peak_outstanding_request_count_ = num_in_flight_requests_;
+  }
+
+  if (HasRequestsFromMultipleActiveProcesses() &&
+      num_in_flight_requests_ > peak_outstanding_request_count_multitab_) {
+    peak_outstanding_request_count_multitab_ = num_in_flight_requests_;
+  }
+
   return stats;
 }
 
 bool ResourceDispatcherHostImpl::HasSufficientResourcesForRequest(
     net::URLRequest* request) {
   ResourceRequestInfoImpl* info = ResourceRequestInfoImpl::ForRequest(request);
   OustandingRequestsStats stats = IncrementOutstandingRequestsCount(1, info);
 
   if (stats.num_requests > max_num_in_flight_requests_per_process_)
     return false;
@@ skipping 508 matching lines @@
   // We need to be able to compare all requests to find the most important one
   // per tab. Since some requests may be navigation requests and we don't have
   // their render frame routing IDs yet (which is what we have for subresource
   // requests), we must go to the UI thread and compare the requests using their
   // WebContents.
   main_thread_task_runner_->PostTask(
       FROM_HERE,
       base::Bind(UpdateLoadStateOnUI, loader_delegate_, base::Passed(&infos)));
 }
 
+void ResourceDispatcherHostImpl::RecordOutstandingRequestsStats() {
+  if (peak_outstanding_request_count_ != 0) {
+    UMA_HISTOGRAM_COUNTS_1M(
+        "Net.ResourceDispatcherHost.PeakOutstandingRequests",
+        peak_outstanding_request_count_);
+    peak_outstanding_request_count_ = num_in_flight_requests_;

[kinuko, 2017/06/21 04:00:10]

Intuitively I feel this should be reset to 0 because the current
num_in_flight_requests is already rolled into the previous shot?

[Kunihiko Sakamoto, 2017/06/21 05:25:32]

My intuition is that if there are n outstanding requests at the beginning of the
time interval, the peak of the interval shouldn't be less than n.
(Edge case: if there's no inc/dec event in the period, the peak should be n
instead of 0.)

[kinuko, 2017/06/21 07:06:48]

Hm, ok I think that makes sense.

+  }
+
+  if (peak_outstanding_request_count_multitab_ != 0) {
+    UMA_HISTOGRAM_COUNTS_1M(
+        "Net.ResourceDispatcherHost.PeakOutstandingRequests.MultiTabLoading",

[kinuko, 2017/06/21 04:00:10]

The map we rely on groups requests per-process rather than per-tab, so calling
this 'MultiTab' feels a bit misleading...

[Kunihiko Sakamoto, 2017/06/21 05:25:32]

Yeah, you're right. Renamed the suffix to 'MultipleLoadingProcesses'.

[kinuko, 2017/06/21 07:06:48]

We could use routing_id to gather per-tab stats, how much more code would we
need if we want to have that data?  Clicking to open multiple tabs from single
tab could easily end up with having all tabs within the same process (e.g. if
rel=noopener is specified).  I assume we need to add similar map code to the
per-process one then.

(We could wait for csharrison/Helen's response to see their gut feeling as well)

+        peak_outstanding_request_count_multitab_);
+    peak_outstanding_request_count_multitab_ =
+        HasRequestsFromMultipleActiveProcesses() ? num_in_flight_requests_ : 0;
+  }
+}
+
 void ResourceDispatcherHostImpl::BlockRequestsForRoute(
     const GlobalFrameRoutingId& global_routing_id) {
   DCHECK(io_thread_task_runner_->BelongsToCurrentThread());
   DCHECK(blocked_loaders_map_.find(global_routing_id) ==
          blocked_loaders_map_.end())
       << "BlockRequestsForRoute called  multiple time for the same RFH";
   blocked_loaders_map_[global_routing_id] =
       base::MakeUnique<BlockedLoadersList>();
 }
 
@@ skipping 189 matching lines @@
                                  is_content_initiated, true, is_new_request,
                                  &throttles);
     if (!throttles.empty()) {
       handler.reset(new ThrottlingResourceHandler(std::move(handler), request,
                                                   std::move(throttles)));
     }
   }
   return handler;
 }
 
+bool ResourceDispatcherHostImpl::HasRequestsFromMultipleActiveProcesses() {
+  if (outstanding_requests_stats_map_.size() < 2)
+    return false;
+
+  int active_processes = 0;
+  for (auto iter = outstanding_requests_stats_map_.begin();
+       iter != outstanding_requests_stats_map_.end(); ++iter) {
+    if (iter->second.num_requests > 2) {
+      active_processes++;
+      if (active_processes >= 2)
+        return true;
+    }
+  }
+  return false;
+}
+
 }  // namespace content