Limit the time spent on a single iteration of PhishingDOMFeatureExtractor.

chrome/renderer/safe_browsing/phishing_dom_feature_extractor.cc

 // Copyright (c) 2010 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 "chrome/renderer/safe_browsing/phishing_dom_feature_extractor.h"
 
 #include "base/compiler_specific.h"
 #include "base/hash_tables.h"
 #include "base/histogram.h"
 #include "base/logging.h"
+#include "base/message_loop.h"
+#include "base/time.h"
 #include "chrome/renderer/render_view.h"
+#include "chrome/renderer/safe_browsing/feature_extractor_clock.h"
 #include "chrome/renderer/safe_browsing/features.h"
 #include "net/base/registry_controlled_domain.h"
 #include "third_party/WebKit/WebKit/chromium/public/WebDocument.h"
 #include "third_party/WebKit/WebKit/chromium/public/WebElement.h"
 #include "third_party/WebKit/WebKit/chromium/public/WebFrame.h"
 #include "third_party/WebKit/WebKit/chromium/public/WebNodeCollection.h"
 #include "third_party/WebKit/WebKit/chromium/public/WebString.h"
 #include "third_party/WebKit/WebKit/chromium/public/WebView.h"
 
 namespace safe_browsing {
 
+// This time should be short enough that it doesn't noticeably disrupt the
+// user's interaction with the page.
+const int PhishingDOMFeatureExtractor::kMaxTimePerChunkMs = 50;
+
+// Experimenting shows that we get a reasonable gain in performance by
+// increasing this up to around 10, but there's not much benefit in
+// increasing it past that.
+const int PhishingDOMFeatureExtractor::kClockCheckGranularity = 10;
+
+// This should be longer than we expect feature extraction to take on any
+// actual phishing page.
+const int PhishingDOMFeatureExtractor::kMaxTotalTimeMs = 500;
+
 // Intermediate state used for computing features.  See features.h for
 // descriptions of the DOM features that are computed.
 struct PhishingDOMFeatureExtractor::PageFeatureState {
   // Link related features
   int external_links;
   base::hash_set<std::string> external_domains;
   int secure_links;
   int total_links;
 
   // Form related features
   int num_forms;
   int num_text_inputs;
   int num_pswd_inputs;
   int num_radio_inputs;
   int num_check_inputs;
   int action_other_domain;
   int total_actions;
 
   // Image related features
   int img_other_domain;
   int total_imgs;
 
   // How many script tags
   int num_script_tags;
 
-  PageFeatureState()
+  // The time at which we started feature extraction for the current page.
+  base::TimeTicks start_time;
+
+  // The number of iterations we've done for the current extraction.
+  int num_iterations;
+
+  explicit PageFeatureState(base::TimeTicks start_time_ticks)
       : external_links(0),
         secure_links(0),
         total_links(0),
         num_forms(0),
         num_text_inputs(0),
         num_pswd_inputs(0),
         num_radio_inputs(0),
         num_check_inputs(0),
         action_other_domain(0),
         total_actions(0),
         img_other_domain(0),
         total_imgs(0),
-        num_script_tags(0) {}
+        num_script_tags(0),
+        start_time(start_time_ticks),
+        num_iterations(0) {}
 
   ~PageFeatureState() {}
 };
 
 // Per-frame state
 struct PhishingDOMFeatureExtractor::FrameData {
   // This is our reference to document.all, which is an iterator over all
   // of the elements in the document.  It keeps track of our current position.
   WebKit::WebNodeCollection elements;
   // The domain of the document URL, stored here so that we don't need to
   // recompute it every time it's needed.
   std::string domain;
 };
 
 PhishingDOMFeatureExtractor::PhishingDOMFeatureExtractor(
-    RenderView* render_view)
+    RenderView* render_view,
+    FeatureExtractorClock* clock)
     : render_view_(render_view),
+      clock_(clock),
       ALLOW_THIS_IN_INITIALIZER_LIST(method_factory_(this)) {
   Clear();
 }
 
 PhishingDOMFeatureExtractor::~PhishingDOMFeatureExtractor() {
   // The RenderView should have called CancelPendingExtraction() before
   // we are destroyed.
   CheckNoPendingExtraction();
 }
 
 void PhishingDOMFeatureExtractor::ExtractFeatures(
     FeatureMap* features,
     DoneCallback* done_callback) {
   // The RenderView should have called CancelPendingExtraction() before
   // starting a new extraction, so DCHECK this.
   CheckNoPendingExtraction();
   // However, in an opt build, we will go ahead and clean up the pending
   // extraction so that we can start in a known state.
   CancelPendingExtraction();
 
   features_ = features;
   done_callback_.reset(done_callback);
+
+  page_feature_state_.reset(new PageFeatureState(clock_->Now()));
   MessageLoop::current()->PostTask(
       FROM_HERE,
       method_factory_.NewRunnableMethod(
           &PhishingDOMFeatureExtractor::ExtractFeaturesWithTimeout));
 }
 
 void PhishingDOMFeatureExtractor::CancelPendingExtraction() {
   // Cancel any pending callbacks, and clear our state.
   method_factory_.RevokeAll();
   Clear();
 }
 
 void PhishingDOMFeatureExtractor::ExtractFeaturesWithTimeout() {
+  DCHECK(page_feature_state_.get());
+  ++page_feature_state_->num_iterations;
+  base::TimeTicks current_chunk_start_time = clock_->Now();
+
   if (!cur_frame_) {
     WebKit::WebView* web_view = render_view_->webview();
     if (!web_view) {
       // When the WebView is going away, the render view should have called
       // CancelPendingExtraction() which should have stopped any pending work,
       // so this case should not happen.
       NOTREACHED();
       RunCallback(false);
       return;
     }
     cur_frame_ = web_view->mainFrame();
-    page_feature_state_.reset(new PageFeatureState);
   }
 
+  int num_elements = 0;
   for (; cur_frame_;
        cur_frame_ = cur_frame_->traverseNext(false /* don't wrap around */)) {
     WebKit::WebNode cur_node;
     if (cur_frame_data_.get()) {
       // We're resuming traversal of a frame, so just advance to the next node.
       cur_node = cur_frame_data_->elements.nextItem();
+      // When we resume the traversal, the first call to nextItem() potentially
+      // has to walk through the document again from the beginning, if it was
+      // modified between our chunks of work.  Log how long this takes, so we
+      // can tell if it's too slow.
+      UMA_HISTOGRAM_TIMES("SBClientPhishing.DOMFeatureResumeTime",
+                          clock_->Now() - current_chunk_start_time);
     } else {
       // We just moved to a new frame, so update our frame state
       // and advance to the first element.
       if (!ResetFrameData()) {
         // Nothing in this frame, move on to the next one.
         LOG(WARNING) << "No content in frame, skipping";
         continue;
       }
       cur_node = cur_frame_data_->elements.firstItem();
     }
 
     for (; !cur_node.isNull();
          cur_node = cur_frame_data_->elements.nextItem()) {
       if (!cur_node.isElementNode()) {
         continue;
       }
       WebKit::WebElement element = cur_node.to<WebKit::WebElement>();
       if (element.hasTagName("a")) {
         HandleLink(element);
       } else if (element.hasTagName("form")) {
         HandleForm(element);
       } else if (element.hasTagName("img")) {
         HandleImage(element);
       } else if (element.hasTagName("input")) {
         HandleInput(element);
       } else if (element.hasTagName("script")) {
         HandleScript(element);
       }
 
-      // TODO(bryner): stop if too much time has elapsed, and add histograms
-      // for the time spent processing.
+      if (++num_elements >= kClockCheckGranularity) {
+        num_elements = 0;
+        base::TimeTicks now = clock_->Now();
+        if (now - page_feature_state_->start_time >=
+            base::TimeDelta::FromMilliseconds(kMaxTotalTimeMs)) {
+          DLOG(ERROR) << "Feature extraction took too long, giving up";
+          // We expect this to happen infrequently, so record when it does.
+          UMA_HISTOGRAM_COUNTS("SBClientPhishing.DOMFeatureTimeout", 1);
+          RunCallback(false);
+          return;
+        }
+        base::TimeDelta chunk_elapsed = now - current_chunk_start_time;
+        if (chunk_elapsed >=
+            base::TimeDelta::FromMilliseconds(kMaxTimePerChunkMs)) {
+          // The time limit for the current chunk is up, so post a task to
+          // continue extraction.
+          //
+          // Record how much time we actually spent on the chunk. If this is
+          // much higher than kMaxTimePerChunkMs, we may need to adjust the
+          // clock granularity.
+          UMA_HISTOGRAM_TIMES("SBClientPhishing.DOMFeatureChunkTime",
+                              chunk_elapsed);
+          MessageLoop::current()->PostTask(
+              FROM_HERE,
+              method_factory_.NewRunnableMethod(
+                  &PhishingDOMFeatureExtractor::ExtractFeaturesWithTimeout));
+          return;
+        }
+        // Otherwise, continue.
+      }
     }
 
     // We're done with this frame, recalculate the FrameData when we
     // advance to the next frame.
     cur_frame_data_.reset();
   }
 
   InsertFeatures();
   RunCallback(true);
 }
@@ skipping 114 matching lines @@
   DCHECK(!done_callback_.get());
   DCHECK(!cur_frame_data_.get());
   DCHECK(!cur_frame_);
   if (done_callback_.get() || cur_frame_data_.get() || cur_frame_) {
     LOG(ERROR) << "Extraction in progress, missing call to "
                << "CancelPendingExtraction";
   }
 }
 
 void PhishingDOMFeatureExtractor::RunCallback(bool success) {
+  // Record some timing stats that we can use to evaluate feature extraction
+  // performance.  These include both successful and failed extractions.
+  DCHECK(page_feature_state_.get());
+  UMA_HISTOGRAM_COUNTS("SBClientPhishing.DOMFeatureIterations",
+                       page_feature_state_->num_iterations);
+  UMA_HISTOGRAM_TIMES("SBClientPhishing.DOMFeatureTotalTime",
+                      clock_->Now() - page_feature_state_->start_time);
+
   DCHECK(done_callback_.get());
   done_callback_->Run(success);
   Clear();
 }
 
 void PhishingDOMFeatureExtractor::Clear() {
   features_ = NULL;
   done_callback_.reset(NULL);
   cur_frame_data_.reset(NULL);
   cur_frame_ = NULL;
@@ skipping 98 matching lines @@
   // Record number of script tags (discretized for numerical stability.)
   if (page_feature_state_->num_script_tags > 1) {
     features_->AddBooleanFeature(features::kPageNumScriptTagsGTOne);
     if (page_feature_state_->num_script_tags > 6) {
       features_->AddBooleanFeature(features::kPageNumScriptTagsGTSix);
     }
   }
 }
 
 }  // namespace safe_browsing