Introduce a new histogram: SB2.NoUserActionResourceLoadingDelay

It reports the total delay, in milliseconds, caused by SafeBrowsing for a
resource load, if the SafeBrowsing interstitial page is not showed and therefore
no user action is involved. At most one value is reported for each resource
load. If SafeBrowsing causes delays at different stages of a load, the sum of
all the delays will be reported.

BUG=782418

Change-Id: Ie467d181c4f535dbb4e5fcc67a8e23c284a4b4f7
Reviewed-on: https://chromium-review.googlesource.com/756962
Commit-Queue: Yuzhu Shen <yzshen@chromium.org>
Reviewed-by: Varun Khaneja <vakh@chromium.org>
Reviewed-by: Mark Pearson <mpearson@chromium.org>
Cr-Commit-Position: refs/heads/master@{#515379}

components/safe_browsing/base_resource_throttle.cc

@@ -65,6 +65,9 @@ BaseResourceThrottle::~BaseResourceThrottle() {
         NetLogEventType::SAFE_BROWSING_CHECKING_URL, "result",
         "request_canceled");
   }
+
+  if (!user_action_involved_)
+    LogNoUserActionResourceLoadingDelay(total_delay_);
 }
 
 void BaseResourceThrottle::WillStartRequest(bool* defer) {
@@ -177,6 +180,7 @@ void BaseResourceThrottle::OnCheckBrowseUrlResult(
   state_ = STATE_NONE;
 
   if (defer_state_ != DEFERRED_NONE) {
+    total_delay_ += base::TimeTicks::Now() - defer_start_time_;
     net_event_logger_.EndNetLogEvent(NetLogEventType::SAFE_BROWSING_DEFERRED,
                                      nullptr, nullptr);
   }
@@ -213,6 +217,8 @@ void BaseResourceThrottle::OnCheckBrowseUrlResult(
   UMA_HISTOGRAM_ENUMERATION("SB2.ResourceTypes2.Unsafe", resource_type_,
                             content::RESOURCE_TYPE_LAST_TYPE);
 
+  user_action_involved_ = true;
+
   security_interstitials::UnsafeResource resource;
   resource.url = url;
   resource.original_url = request_->original_url();
@@ -341,6 +347,7 @@ void BaseResourceThrottle::ResumeRequest() {
     if (!CheckUrl(unchecked_redirect_url_)) {
       // We're now waiting for the unchecked_redirect_url_.
       defer_state_ = DEFERRED_REDIRECT;
+      defer_start_time_ = base::TimeTicks::Now();
       resume = false;
       net_event_logger_.BeginNetLogEvent(
           NetLogEventType::SAFE_BROWSING_DEFERRED, unchecked_redirect_url_,

components/safe_browsing/base_resource_throttle.h

@@ -169,6 +169,12 @@ class BaseResourceThrottle
   const content::ResourceType resource_type_;
   NetEventLogger net_event_logger_;
 
+  // The total delay caused by SafeBrowsing deferring the resource load.
+  base::TimeDelta total_delay_;
+  // Whether the interstitial page has been shown and therefore user action has
+  // been involved.
+  bool user_action_involved_ = false;
+
   DISALLOW_COPY_AND_ASSIGN(BaseResourceThrottle);
 };
 

components/safe_browsing/browser/browser_url_loader_throttle.cc

@@ -39,6 +39,9 @@ BrowserURLLoaderThrottle::BrowserURLLoaderThrottle(
 BrowserURLLoaderThrottle::~BrowserURLLoaderThrottle() {
   if (deferred_)
     TRACE_EVENT_ASYNC_END0("safe_browsing", "Deferred", this);
+
+  if (!user_action_involved_)
+    LogNoUserActionResourceLoadingDelay(total_delay_);
 }
 
 void BrowserURLLoaderThrottle::WillStartRequest(
@@ -91,10 +94,8 @@ void BrowserURLLoaderThrottle::WillProcessResponse(
     return;
   }
 
-  if (pending_checks_ == 0) {
-    LogDelay(base::TimeDelta());
+  if (pending_checks_ == 0)
     return;
-  }
 
   DCHECK(!deferred_);
   deferred_ = true;
@@ -117,15 +118,19 @@ void BrowserURLLoaderThrottle::OnCompleteCheck(bool slow_check,
     pending_slow_checks_--;
   }
 
+  user_action_involved_ = user_action_involved_ || showed_interstitial;
+  // If the resource load is currently deferred and is going to exit that state
+  // (either being cancelled or resumed), record the total delay.
+  if (deferred_ && (!proceed || pending_checks_ == 0))
+    total_delay_ = base::TimeTicks::Now() - defer_start_time_;
+
   if (proceed) {
     if (pending_slow_checks_ == 0 && slow_check)
       delegate_->ResumeReadingBodyFromNet();
 
     if (pending_checks_ == 0 && deferred_) {
-      LogDelay(base::TimeTicks::Now() - defer_start_time_);
       deferred_ = false;
       TRACE_EVENT_ASYNC_END0("safe_browsing", "Deferred", this);
-
       delegate_->Resume();
     }
   } else {

components/safe_browsing/browser/browser_url_loader_throttle.h

@@ -84,6 +84,12 @@ class BrowserURLLoaderThrottle : public content::URLLoaderThrottle {
   base::TimeTicks defer_start_time_;
   bool deferred_ = false;
 
+  // The total delay caused by SafeBrowsing deferring the resource load.
+  base::TimeDelta total_delay_;
+  // Whether the interstitial page has been shown and therefore user action has
+  // been involved.
+  bool user_action_involved_ = false;
+
   GURL original_url_;
 
   DISALLOW_COPY_AND_ASSIGN(BrowserURLLoaderThrottle);

components/safe_browsing/common/utils.cc

@@ -27,4 +27,8 @@ void LogDelay(base::TimeDelta time) {
   UMA_HISTOGRAM_LONG_TIMES("SB2.Delay", time);
 }
 
+void LogNoUserActionResourceLoadingDelay(base::TimeDelta time) {
+  UMA_HISTOGRAM_LONG_TIMES("SB2.NoUserActionResourceLoadingDelay", time);
+}
+
 }  // namespace safe_browsing

components/safe_browsing/common/utils.h

@@ -23,6 +23,13 @@ std::string ShortURLForReporting(const GURL& url);
 // page is 'safe'.
 void LogDelay(base::TimeDelta time);
 
+// UMA histogram helper for logging "SB2.NoUserActionResourceLoadingDelay".
+// Logs the total delay caused by SafeBrowsing for a resource load, if the
+// SafeBrowsing interstitial page is not showed. At most one value is reported
+// for each resource load. If SafeBrowsing causes delays at different stages of
+// a load, the sum of all the delays will be reported.
+void LogNoUserActionResourceLoadingDelay(base::TimeDelta time);
+
 }  // namespace safe_browsing
 
 #endif  // COMPONENTS_SAFE_BROWSING_COMMON_UTILS_H_

components/safe_browsing/renderer/renderer_url_loader_throttle.cc

@@ -23,6 +23,9 @@ RendererURLLoaderThrottle::RendererURLLoaderThrottle(
 RendererURLLoaderThrottle::~RendererURLLoaderThrottle() {
   if (deferred_)
     TRACE_EVENT_ASYNC_END0("safe_browsing", "Deferred", this);
+
+  if (!user_action_involved_)
+    LogNoUserActionResourceLoadingDelay(total_delay_);
 }
 
 void RendererURLLoaderThrottle::DetachFromCurrentSequence() {
@@ -91,10 +94,8 @@ void RendererURLLoaderThrottle::WillProcessResponse(
   // shouldn't be such a notification.
   DCHECK(!blocked_);
 
-  if (pending_checks_ == 0) {
-    LogDelay(base::TimeDelta());
+  if (pending_checks_ == 0)
     return;
-  }
 
   DCHECK(!deferred_);
   deferred_ = true;
@@ -156,13 +157,18 @@ void RendererURLLoaderThrottle::OnCompleteCheckInternal(
     pending_slow_checks_--;
   }
 
+  user_action_involved_ = user_action_involved_ || showed_interstitial;
+  // If the resource load is currently deferred and is going to exit that state
+  // (either being cancelled or resumed), record the total delay.
+  if (deferred_ && (!proceed || pending_checks_ == 0))
+    total_delay_ = base::TimeTicks::Now() - defer_start_time_;
+
   if (proceed) {
     if (pending_slow_checks_ == 0 && slow_check)
       delegate_->ResumeReadingBodyFromNet();
 
     if (pending_checks_ == 0 && deferred_) {
       deferred_ = false;
-      LogDelay(base::TimeTicks::Now() - defer_start_time_);
       TRACE_EVENT_ASYNC_END0("safe_browsing", "Deferred", this);
       delegate_->Resume();
     }
@@ -192,8 +198,9 @@ void RendererURLLoaderThrottle::OnConnectionError() {
   }
 
   if (deferred_) {
+    total_delay_ = base::TimeTicks::Now() - defer_start_time_;
+
     deferred_ = false;
-    LogDelay(base::TimeTicks::Now() - defer_start_time_);
     TRACE_EVENT_ASYNC_END0("safe_browsing", "Deferred", this);
     delegate_->Resume();
   }

components/safe_browsing/renderer/renderer_url_loader_throttle.h

@@ -74,6 +74,12 @@ class RendererURLLoaderThrottle : public content::URLLoaderThrottle,
   base::TimeTicks defer_start_time_;
   bool deferred_ = false;
 
+  // The total delay caused by SafeBrowsing deferring the resource load.
+  base::TimeDelta total_delay_;
+  // Whether the interstitial page has been shown and therefore user action has
+  // been involved.
+  bool user_action_involved_ = false;
+
   std::unique_ptr<mojo::BindingSet<mojom::UrlCheckNotifier>> notifier_bindings_;
 
   GURL original_url_;

tools/metrics/histograms/histograms.xml

@@ -71603,6 +71603,17 @@ http://cs/file:chrome/histograms.xml - but prefer this file for new entries.
   </summary>
 </histogram>
 
+<histogram name="SB2.NoUserActionResourceLoadingDelay" units="ms">
+  <owner>yzshen@chromium.org</owner>
+  <summary>
+    The total delay, in milliseconds, caused by SafeBrowsing for a resource
+    load, if the SafeBrowsing interstitial page is not shown and therefore no
+    user action is involved. At most one value is reported for each resource
+    load. If SafeBrowsing causes delays at different stages of a load, the sum
+    of all the delays will be reported.
+  </summary>
+</histogram>
+
 <histogram name="SB2.OldDatabaseKilobytes" units="KB">
   <obsolete>
     Deprecated 7/2014. No longer generated.