diff options
| -rw-r--r-- | chrome/browser/extensions/extension_webrequest_api.cc | 39 | ||||
| -rw-r--r-- | chrome/browser/extensions/extension_webrequest_api.h | 6 | ||||
| -rwxr-xr-x | chrome/browser/extensions/extension_webrequest_time_tracker.cc | 154 | ||||
| -rwxr-xr-x | chrome/browser/extensions/extension_webrequest_time_tracker.h | 95 | ||||
| -rwxr-xr-x | chrome/browser/extensions/extension_webrequest_time_tracker_unittest.cc | 84 | ||||
| -rw-r--r-- | chrome/chrome_browser.gypi | 2 | ||||
| -rw-r--r-- | chrome/chrome_tests.gypi | 1 |
7 files changed, 374 insertions, 7 deletions
diff --git a/chrome/browser/extensions/extension_webrequest_api.cc b/chrome/browser/extensions/extension_webrequest_api.cc index 3844151..e9b32e5 100644 --- a/chrome/browser/extensions/extension_webrequest_api.cc +++ b/chrome/browser/extensions/extension_webrequest_api.cc @@ -17,6 +17,7 @@ #include "chrome/browser/extensions/extension_service.h" #include "chrome/browser/extensions/extension_tab_id_map.h" #include "chrome/browser/extensions/extension_webrequest_api_constants.h" +#include "chrome/browser/extensions/extension_webrequest_time_tracker.h" #include "chrome/browser/profiles/profile.h" #include "chrome/browser/renderer_host/chrome_render_message_filter.h" #include "chrome/common/extensions/extension.h" @@ -431,7 +432,8 @@ ExtensionWebRequestEventRouter* ExtensionWebRequestEventRouter::GetInstance() { return Singleton<ExtensionWebRequestEventRouter>::get(); } -ExtensionWebRequestEventRouter::ExtensionWebRequestEventRouter() { +ExtensionWebRequestEventRouter::ExtensionWebRequestEventRouter() + : request_time_tracker_(new ExtensionWebRequestTimeTracker) { } ExtensionWebRequestEventRouter::~ExtensionWebRequestEventRouter() { @@ -450,6 +452,10 @@ int ExtensionWebRequestEventRouter::OnBeforeRequest( if (!HasWebRequestScheme(request->url())) return net::OK; + request_time_tracker_->LogRequestStartTime(request->identifier(), + base::Time::Now(), + request->url()); + bool is_main_frame = false; int64 frame_id = -1; int frame_id_for_extension = -1; @@ -734,6 +740,9 @@ void ExtensionWebRequestEventRouter::OnCompleted( if (!HasWebRequestScheme(request->url())) return; + request_time_tracker_->LogRequestEndTime(request->identifier(), + base::Time::Now()); + DCHECK(request->status().status() == net::URLRequestStatus::SUCCESS); DCHECK(!GetAndSetSignaled(request->identifier(), kOnCompleted)); @@ -785,6 +794,9 @@ void ExtensionWebRequestEventRouter::OnErrorOccurred( if (!HasWebRequestScheme(request->url())) return; + request_time_tracker_->LogRequestEndTime(request->identifier(), + base::Time::Now()); + DCHECK(request->status().status() == net::URLRequestStatus::FAILED || request->status().status() == net::URLRequestStatus::CANCELED); @@ -821,6 +833,9 @@ void ExtensionWebRequestEventRouter::OnURLRequestDestroyed( void* profile, net::URLRequest* request) { blocked_requests_.erase(request->identifier()); signaled_requests_.erase(request->identifier()); + + request_time_tracker_->LogRequestEndTime(request->identifier(), + base::Time::Now()); } bool ExtensionWebRequestEventRouter::DispatchEvent( @@ -893,7 +908,7 @@ void ExtensionWebRequestEventRouter::OnEventHandled( if (found != listeners_[profile][event_name].end()) found->blocked_requests.erase(request_id); - DecrementBlockCount(profile, event_name, request_id, response); + DecrementBlockCount(profile, extension_id, event_name, request_id, response); } void ExtensionWebRequestEventRouter::AddEventListener( @@ -949,7 +964,7 @@ void ExtensionWebRequestEventRouter::RemoveEventListener( // Unblock any request that this event listener may have been blocking. for (std::set<uint64>::iterator it = found->blocked_requests.begin(); it != found->blocked_requests.end(); ++it) { - DecrementBlockCount(profile, event_name, *it, NULL); + DecrementBlockCount(profile, extension_id, event_name, *it, NULL); } listeners_[profile][event_name].erase(listener); @@ -1237,6 +1252,7 @@ void ExtensionWebRequestEventRouter::MergeOnBeforeSendHeadersResponses( void ExtensionWebRequestEventRouter::DecrementBlockCount( void* profile, + const std::string& extension_id, const std::string& event_name, uint64 request_id, EventResponse* response) { @@ -1256,11 +1272,13 @@ void ExtensionWebRequestEventRouter::DecrementBlockCount( CalculateDelta(&blocked_request, response)); } + base::TimeDelta block_time = + base::Time::Now() - blocked_request.blocking_time; + request_time_tracker_->IncrementExtensionBlockTime( + extension_id, request_id, block_time); + if (num_handlers_blocking == 0) { - // TODO(mpcomplete): it would be better if we accumulated the blocking times - // for a given request over all events. - HISTOGRAM_TIMES("Extensions.NetworkDelay", - base::Time::Now() - blocked_request.blocking_time); + request_time_tracker_->IncrementTotalBlockTime(request_id, block_time); EventResponseDeltas::iterator i; EventResponseDeltas& deltas = blocked_request.response_deltas; @@ -1300,6 +1318,13 @@ void ExtensionWebRequestEventRouter::DecrementBlockCount( "modifications."; } + if (canceled) { + request_time_tracker_->SetRequestCanceled(request_id); + } else if (blocked_request.new_url && + !blocked_request.new_url->is_empty()) { + request_time_tracker_->SetRequestRedirected(request_id); + } + // This signals a failed request to subscribers of onErrorOccurred in case // a request is cancelled because net::ERR_EMPTY_RESPONSE cannot be // distinguished from a regular failure. diff --git a/chrome/browser/extensions/extension_webrequest_api.h b/chrome/browser/extensions/extension_webrequest_api.h index cb58b48..f44d5b7 100644 --- a/chrome/browser/extensions/extension_webrequest_api.h +++ b/chrome/browser/extensions/extension_webrequest_api.h @@ -22,6 +22,7 @@ #include "webkit/glue/resource_type.h" class ExtensionInfoMap; +class ExtensionWebRequestTimeTracker; class GURL; namespace base { @@ -301,6 +302,7 @@ class ExtensionWebRequestEventRouter { // method assumes ownership. void DecrementBlockCount( void* profile, + const std::string& extension_id, const std::string& event_name, uint64 request_id, EventResponse* response); @@ -349,6 +351,10 @@ class ExtensionWebRequestEventRouter { // versa). CrossProfileMap cross_profile_map_; + // Keeps track of time spent waiting on extensions using the blocking + // webRequest API. + scoped_ptr<ExtensionWebRequestTimeTracker> request_time_tracker_; + DISALLOW_COPY_AND_ASSIGN(ExtensionWebRequestEventRouter); }; diff --git a/chrome/browser/extensions/extension_webrequest_time_tracker.cc b/chrome/browser/extensions/extension_webrequest_time_tracker.cc new file mode 100755 index 0000000..9ccdef7 --- /dev/null +++ b/chrome/browser/extensions/extension_webrequest_time_tracker.cc @@ -0,0 +1,154 @@ +// Copyright (c) 2011 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/browser/extensions/extension_webrequest_time_tracker.h" + +#include "base/metrics/histogram.h" + +// TODO(mpcomplete): tweak all these constants. +namespace { +// The number of requests we keep track of at a time. +const size_t kMaxRequestsLogged = 100u; + +// If a request completes faster than this amount (in ms), then we ignore it. +// Any delays on such a request was negligible. +const int kMinRequestTimeToCareMs = 10; + +// Thresholds above which we consider a delay caused by an extension to be "too +// much". This is given in percentage of total request time that was spent +// waiting on the extension. +const double kThresholdModerateDelay = 0.20; +const double kThresholdExcessiveDelay = 0.50; + +// If this many requests (of the past kMaxRequestsLogged) have had "too much" +// delay, then we will warn the user. +const size_t kNumModerateDelaysBeforeWarning = 50u; +const size_t kNumExcessiveDelaysBeforeWarning = 10u; +} // namespace + +ExtensionWebRequestTimeTracker::RequestTimeLog::RequestTimeLog() + : completed(false) { +} + +ExtensionWebRequestTimeTracker::RequestTimeLog::~RequestTimeLog() { +} + +ExtensionWebRequestTimeTracker::ExtensionWebRequestTimeTracker() { +} + +ExtensionWebRequestTimeTracker::~ExtensionWebRequestTimeTracker() { +} + +void ExtensionWebRequestTimeTracker::LogRequestStartTime( + int64 request_id, const base::Time& start_time, const GURL& url) { + // Trim old completed request logs. + while (request_ids_.size() > kMaxRequestsLogged) { + int64 to_remove = request_ids_.front(); + request_ids_.pop(); + std::map<int64, RequestTimeLog>::iterator iter = + request_time_logs_.find(to_remove); + if (iter != request_time_logs_.end() && iter->second.completed) { + request_time_logs_.erase(iter); + moderate_delays_.erase(to_remove); + excessive_delays_.erase(to_remove); + } + } + request_ids_.push(request_id); + + if (request_time_logs_.find(request_id) != request_time_logs_.end()) { + RequestTimeLog& log = request_time_logs_[request_id]; + DCHECK(!log.completed); + return; + } + RequestTimeLog& log = request_time_logs_[request_id]; + log.request_start_time = start_time; + log.url = url; +} + +void ExtensionWebRequestTimeTracker::LogRequestEndTime( + int64 request_id, const base::Time& end_time) { + if (request_time_logs_.find(request_id) == request_time_logs_.end()) + return; + + RequestTimeLog& log = request_time_logs_[request_id]; + if (log.completed) + return; + + log.request_duration = end_time - log.request_start_time; + log.completed = true; + + if (log.extension_block_durations.empty()) + return; + + HISTOGRAM_TIMES("Extensions.NetworkDelay", log.block_duration); + + Analyze(request_id); +} + +void ExtensionWebRequestTimeTracker::Analyze(int64 request_id) { + RequestTimeLog& log = request_time_logs_[request_id]; + + // Ignore really short requests. Time spent on these is negligible, and any + // extra delay the extension adds is likely to be noise. + if (log.request_duration.InMilliseconds() < kMinRequestTimeToCareMs) + return; + + double percentage = + log.block_duration.InMillisecondsF() / + log.request_duration.InMillisecondsF(); + LOG(ERROR) << "WR percent " << request_id << ": " << log.url << ": " << + log.block_duration.InMilliseconds() << "/" << + log.request_duration.InMilliseconds() << " = " << percentage; + + // TODO(mpcomplete): need actual UI for the warning. + // TODO(mpcomplete): blame a specific extension. Maybe go through the list + // of recent requests and find the extension that has caused the most delays. + if (percentage > kThresholdExcessiveDelay) { + excessive_delays_.insert(request_id); + if (excessive_delays_.size() > kNumExcessiveDelaysBeforeWarning) { + LOG(ERROR) << "WR excessive delays:" << excessive_delays_.size(); + } + } else if (percentage > kThresholdModerateDelay) { + moderate_delays_.insert(request_id); + if (moderate_delays_.size() > kNumModerateDelaysBeforeWarning) { + LOG(ERROR) << "WR moderate delays:" << moderate_delays_.size(); + } + } +} + +void ExtensionWebRequestTimeTracker::IncrementExtensionBlockTime( + const std::string& extension_id, + int64 request_id, + const base::TimeDelta& block_time) { + if (request_time_logs_.find(request_id) == request_time_logs_.end()) + return; + RequestTimeLog& log = request_time_logs_[request_id]; + log.extension_block_durations[extension_id] += block_time; +} + +void ExtensionWebRequestTimeTracker::IncrementTotalBlockTime( + int64 request_id, + const base::TimeDelta& block_time) { + if (request_time_logs_.find(request_id) == request_time_logs_.end()) + return; + RequestTimeLog& log = request_time_logs_[request_id]; + log.block_duration += block_time; +} + +void ExtensionWebRequestTimeTracker::SetRequestCanceled(int64 request_id) { + // Canceled requests won't actually hit the network, so we can't compare + // their request time to the time spent waiting on the extension. Just ignore + // them. + // TODO(mpcomplete): may want to count cancels as "bonuses" for an extension. + // i.e. if it slows down 50% of requests but cancels 25% of the rest, that + // might average out to only being "25% slow". + request_time_logs_.erase(request_id); +} + +void ExtensionWebRequestTimeTracker::SetRequestRedirected(int64 request_id) { + // When a request is redirected, we have no way of knowing how long the + // request would have taken, so we can't say how much an extension slowed + // down this request. Just ignore it. + request_time_logs_.erase(request_id); +} diff --git a/chrome/browser/extensions/extension_webrequest_time_tracker.h b/chrome/browser/extensions/extension_webrequest_time_tracker.h new file mode 100755 index 0000000..b9911b1 --- /dev/null +++ b/chrome/browser/extensions/extension_webrequest_time_tracker.h @@ -0,0 +1,95 @@ +// Copyright (c) 2011 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. + +#ifndef CHROME_BROWSER_EXTENSIONS_EXTENSION_WEBREQUEST_TIME_TRACKER_H_ +#define CHROME_BROWSER_EXTENSIONS_EXTENSION_WEBREQUEST_TIME_TRACKER_H_ +#pragma once + +#include <map> +#include <queue> +#include <set> +#include <string> + +#include "base/time.h" +#include "base/gtest_prod_util.h" +#include "googleurl/src/gurl.h" + +namespace base { +class Time; +} + +// This class keeps monitors how much delay extensions add to network requests +// by using the webRequest API. If the delay is sufficient, we will warn the +// user that extensions are slowing down the browser. +class ExtensionWebRequestTimeTracker { + public: + ExtensionWebRequestTimeTracker(); + ~ExtensionWebRequestTimeTracker(); + + // Records the time that a request was created. + void LogRequestStartTime(int64 request_id, const base::Time& start_time, + const GURL& url); + + // Records the time that a request either completed or encountered an error. + void LogRequestEndTime(int64 request_id, const base::Time& end_time); + + // Records an additional delay for the given request caused by the given + // extension. + void IncrementExtensionBlockTime( + const std::string& extension_id, + int64 request_id, + const base::TimeDelta& block_time); + + // Records an additional delay for the given request caused by all extensions + // combined. + void IncrementTotalBlockTime( + int64 request_id, + const base::TimeDelta& block_time); + + // Called when an extension has canceled the given request. + void SetRequestCanceled(int64 request_id); + + // Called when an extension has redirected the given request to another URL. + void SetRequestRedirected(int64 request_id); + + private: + // Timing information for a single request. + struct RequestTimeLog { + GURL url; // used for debug purposes only + bool completed; + base::Time request_start_time; + base::TimeDelta request_duration; + base::TimeDelta block_duration; + std::map<std::string, base::TimeDelta> extension_block_durations; + RequestTimeLog(); + ~RequestTimeLog(); + }; + + // Called after a request finishes, to analyze the delays and warn the user + // if necessary. + void Analyze(int64 request_id); + + // A map of recent request IDs to timing info for each request. + std::map<int64, RequestTimeLog> request_time_logs_; + + // A list of recent request IDs that we know about. Used to limit the size of + // the logs. + std::queue<int64> request_ids_; + + // The set of recent requests that have been delayed either a large or + // moderate amount by extensions. + std::set<int64> excessive_delays_; + std::set<int64> moderate_delays_; + + FRIEND_TEST_ALL_PREFIXES(ExtensionWebRequestTimeTrackerTest, Basic); + FRIEND_TEST_ALL_PREFIXES(ExtensionWebRequestTimeTrackerTest, + IgnoreFastRequests); + FRIEND_TEST_ALL_PREFIXES(ExtensionWebRequestTimeTrackerTest, + CancelOrRedirect); + FRIEND_TEST_ALL_PREFIXES(ExtensionWebRequestTimeTrackerTest, Delays); + + DISALLOW_COPY_AND_ASSIGN(ExtensionWebRequestTimeTracker); +}; + +#endif // CHROME_BROWSER_EXTENSIONS_EXTENSION_WEBREQUEST_TIME_TRACKER_H_ diff --git a/chrome/browser/extensions/extension_webrequest_time_tracker_unittest.cc b/chrome/browser/extensions/extension_webrequest_time_tracker_unittest.cc new file mode 100755 index 0000000..9439354 --- /dev/null +++ b/chrome/browser/extensions/extension_webrequest_time_tracker_unittest.cc @@ -0,0 +1,84 @@ +// Copyright (c) 2011 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/browser/extensions/extension_webrequest_time_tracker.h" + +#include "testing/gtest/include/gtest/gtest.h" + +namespace { +const base::TimeDelta kRequestDelta = base::TimeDelta::FromMilliseconds(100); +const base::TimeDelta kTinyDelay = base::TimeDelta::FromMilliseconds(1); +const base::TimeDelta kModerateDelay = base::TimeDelta::FromMilliseconds(25); +const base::TimeDelta kExcessiveDelay = base::TimeDelta::FromMilliseconds(75); +} // namespace + +//class ExtensionWebRequestTimeTrackerTest : public testing::Test {}; + +TEST(ExtensionWebRequestTimeTrackerTest, Basic) { + ExtensionWebRequestTimeTracker tracker; + base::Time start; + + tracker.LogRequestStartTime(42, start, GURL()); + EXPECT_EQ(1u, tracker.request_time_logs_.size()); + ASSERT_EQ(1u, tracker.request_ids_.size()); + EXPECT_EQ(42, tracker.request_ids_.front()); + tracker.LogRequestEndTime(42, start + kRequestDelta); + EXPECT_EQ(1u, tracker.request_time_logs_.size()); + EXPECT_EQ(0u, tracker.moderate_delays_.size()); + EXPECT_EQ(0u, tracker.excessive_delays_.size()); +} + +TEST(ExtensionWebRequestTimeTrackerTest, CancelOrRedirect) { + ExtensionWebRequestTimeTracker tracker; + base::Time start; + + tracker.LogRequestStartTime(1, start, GURL()); + EXPECT_EQ(1u, tracker.request_time_logs_.size()); + tracker.SetRequestCanceled(1); + tracker.LogRequestEndTime(1, start + kRequestDelta); + EXPECT_EQ(0u, tracker.request_time_logs_.size()); + + tracker.LogRequestStartTime(2, start, GURL()); + EXPECT_EQ(1u, tracker.request_time_logs_.size()); + tracker.SetRequestRedirected(2); + tracker.LogRequestEndTime(2, start + kRequestDelta); + EXPECT_EQ(0u, tracker.request_time_logs_.size()); +} + +TEST(ExtensionWebRequestTimeTrackerTest, Delays) { + ExtensionWebRequestTimeTracker tracker; + base::Time start; + std::string extension1_id("1"); + std::string extension2_id("2"); + + // Start 3 requests with different amounts of delay from 2 extensions. + tracker.LogRequestStartTime(1, start, GURL()); + tracker.LogRequestStartTime(2, start, GURL()); + tracker.LogRequestStartTime(3, start, GURL()); + tracker.IncrementExtensionBlockTime(extension1_id, 1, kTinyDelay); + tracker.IncrementExtensionBlockTime(extension1_id, 2, kTinyDelay); + tracker.IncrementExtensionBlockTime(extension1_id, 3, kTinyDelay); + tracker.IncrementExtensionBlockTime(extension2_id, 2, kModerateDelay); + tracker.IncrementExtensionBlockTime(extension2_id, 3, kExcessiveDelay); + tracker.IncrementTotalBlockTime(1, kTinyDelay); + tracker.IncrementTotalBlockTime(2, kModerateDelay); + tracker.IncrementTotalBlockTime(3, kExcessiveDelay); + tracker.LogRequestEndTime(1, start + kRequestDelta); + tracker.LogRequestEndTime(2, start + kRequestDelta); + tracker.LogRequestEndTime(3, start + kRequestDelta); + EXPECT_EQ(3u, tracker.request_time_logs_.size()); + EXPECT_EQ(1u, tracker.moderate_delays_.size()); + EXPECT_EQ(1u, tracker.moderate_delays_.count(2)); + EXPECT_EQ(1u, tracker.excessive_delays_.size()); + EXPECT_EQ(1u, tracker.excessive_delays_.count(3)); + + // Now issue a bunch more requests and ensure that the old delays are + // forgotten. + for (int64 i = 4; i < 500; ++i) { + tracker.LogRequestStartTime(i, start, GURL()); + tracker.LogRequestEndTime(i, start + kRequestDelta); + } + EXPECT_EQ(0u, tracker.moderate_delays_.size()); + EXPECT_EQ(0u, tracker.excessive_delays_.size()); +} diff --git a/chrome/chrome_browser.gypi b/chrome/chrome_browser.gypi index 025954b..bf03bf6 100644 --- a/chrome/chrome_browser.gypi +++ b/chrome/chrome_browser.gypi @@ -1113,6 +1113,8 @@ 'browser/extensions/extension_webrequest_api.h', 'browser/extensions/extension_webrequest_api_constants.cc', 'browser/extensions/extension_webrequest_api_constants.h', + 'browser/extensions/extension_webrequest_time_tracker.cc', + 'browser/extensions/extension_webrequest_time_tracker.h', 'browser/extensions/extension_webstore_private_api.cc', 'browser/extensions/extension_webstore_private_api.h', 'browser/extensions/extensions_quota_service.cc', diff --git a/chrome/chrome_tests.gypi b/chrome/chrome_tests.gypi index fe1fd91..f1b902a 100644 --- a/chrome/chrome_tests.gypi +++ b/chrome/chrome_tests.gypi @@ -1443,6 +1443,7 @@ 'browser/extensions/extension_updater_unittest.cc', 'browser/extensions/extension_webnavigation_unittest.cc', 'browser/extensions/extension_webrequest_api_unittest.cc', + 'browser/extensions/extension_webrequest_time_tracker_unittest.cc', 'browser/extensions/extensions_quota_service_unittest.cc', 'browser/extensions/external_policy_extension_loader_unittest.cc', 'browser/extensions/file_reader_unittest.cc', |