diff --git a/chrome/browser/resources/net_internals/source_entry.js b/chrome/browser/resources/net_internals/source_entry.js index bca0e04b1103a3..14e98a4049f837 100644 --- a/chrome/browser/resources/net_internals/source_entry.js +++ b/chrome/browser/resources/net_internals/source_entry.js @@ -186,8 +186,10 @@ var SourceEntry = (function() { /** * Returns the starting entry for this source. Conceptually this is the * first entry that was logged to this source. However, we skip over the - * TYPE_REQUEST_ALIVE entries which wrap TYPE_URL_REQUEST_START_JOB - * entries. + * TYPE_REQUEST_ALIVE entries without parameters which wrap + * TYPE_URL_REQUEST_START_JOB entries. (TYPE_REQUEST_ALIVE may or may not + * have parameters depending on what version of Chromium they were + * generated from.) */ getStartEntry_: function() { if (this.entries_.length < 1) diff --git a/content/browser/loader/resource_scheduler.cc b/content/browser/loader/resource_scheduler.cc index 9bbae929191aad..1cd91c3e6c0b77 100644 --- a/content/browser/loader/resource_scheduler.cc +++ b/content/browser/loader/resource_scheduler.cc @@ -52,6 +52,38 @@ const RequestAttributes kAttributeInFlight = 0x01; const RequestAttributes kAttributeDelayable = 0x02; const RequestAttributes kAttributeLayoutBlocking = 0x04; +// Reasons why pending requests may be started. For logging only. +enum class RequestStartTrigger { + NONE, + COMPLETION_PRE_BODY, + COMPLETION_POST_BODY, + BODY_REACHED, + CLIENT_KILL, + SPDY_PROXY_DETECTED, + REQUEST_REPRIORITIZED, +}; + +const char* RequestStartTriggerString(RequestStartTrigger trigger) { + switch (trigger) { + case RequestStartTrigger::NONE: + return "NONE"; + case RequestStartTrigger::COMPLETION_PRE_BODY: + return "COMPLETION_PRE_BODY"; + case RequestStartTrigger::COMPLETION_POST_BODY: + return "COMPLETION_POST_BODY"; + case RequestStartTrigger::BODY_REACHED: + return "BODY_REACHED"; + case RequestStartTrigger::CLIENT_KILL: + return "CLIENT_KILL"; + case RequestStartTrigger::SPDY_PROXY_DETECTED: + return "SPDY_PROXY_DETECTED"; + case RequestStartTrigger::REQUEST_REPRIORITIZED: + return "REQUEST_REPRIORITIZED"; + } + NOTREACHED(); + return "Unknown"; +} + } // namespace // The maximum number of delayable requests to allow to be in-flight at any @@ -331,7 +363,7 @@ class ResourceScheduler::Client { SetRequestAttributes(request, DetermineRequestAttributes(request)); if (ShouldStartRequest(request) == START_REQUEST) { // New requests can be started synchronously without issue. - StartRequest(request, START_SYNC); + StartRequest(request, START_SYNC, RequestStartTrigger::NONE); } else { pending_requests_.Insert(request); } @@ -345,7 +377,10 @@ class ResourceScheduler::Client { EraseInFlightRequest(request); // Removing this request may have freed up another to load. - LoadAnyStartablePendingRequests(); + LoadAnyStartablePendingRequests( + has_html_body_ + ? RequestStartTrigger::COMPLETION_POST_BODY + : RequestStartTrigger::COMPLETION_PRE_BODY); } } @@ -362,7 +397,7 @@ class ResourceScheduler::Client { pending_requests_.Erase(request); // Starting requests asynchronously ensures no side effects, and avoids // starting a bunch of requests that may be about to be deleted. - StartRequest(request, START_ASYNC); + StartRequest(request, START_ASYNC, RequestStartTrigger::CLIENT_KILL); } RequestSet unowned_requests; for (RequestSet::iterator it = in_flight_requests_.begin(); @@ -387,13 +422,13 @@ class ResourceScheduler::Client { void OnWillInsertBody() { has_html_body_ = true; - LoadAnyStartablePendingRequests(); + LoadAnyStartablePendingRequests(RequestStartTrigger::BODY_REACHED); } void OnReceivedSpdyProxiedHttpResponse() { if (!using_spdy_proxy_) { using_spdy_proxy_ = true; - LoadAnyStartablePendingRequests(); + LoadAnyStartablePendingRequests(RequestStartTrigger::SPDY_PROXY_DETECTED); } } @@ -414,7 +449,8 @@ class ResourceScheduler::Client { if (new_priority_params.priority > old_priority_params.priority) { // Check if this request is now able to load at its new priority. - LoadAnyStartablePendingRequests(); + LoadAnyStartablePendingRequests( + RequestStartTrigger::REQUEST_REPRIORITIZED); } } @@ -560,7 +596,16 @@ class ResourceScheduler::Client { } void StartRequest(ScheduledResourceRequest* request, - StartMode start_mode) { + StartMode start_mode, + RequestStartTrigger trigger) { + // Only log on requests that were blocked by the ResourceScheduler. + if (start_mode == START_ASYNC) { + DCHECK_NE(RequestStartTrigger::NONE, trigger); + request->url_request()->net_log().AddEvent( + net::NetLogEventType::RESOURCE_SCHEDULER_REQUEST_STARTED, + net::NetLog::StringCallback( + "trigger", RequestStartTriggerString(trigger))); + } InsertInFlightRequest(request); request->Start(start_mode); } @@ -670,7 +715,7 @@ class ResourceScheduler::Client { return START_REQUEST; } - void LoadAnyStartablePendingRequests() { + void LoadAnyStartablePendingRequests(RequestStartTrigger trigger) { // We iterate through all the pending requests, starting with the highest // priority one. For each entry, one of three things can happen: // 1) We start the request, remove it from the list, and keep checking. @@ -688,7 +733,7 @@ class ResourceScheduler::Client { if (query_result == START_REQUEST) { pending_requests_.Erase(request); - StartRequest(request, START_ASYNC); + StartRequest(request, START_ASYNC, trigger); // StartRequest can modify the pending list, so we (re)start evaluation // from the currently highest priority request. Avoid copying a singular diff --git a/net/log/net_log_event_type_list.h b/net/log/net_log_event_type_list.h index 37cb81497b5153..e7b4227fb47b55 100644 --- a/net/log/net_log_event_type_list.h +++ b/net/log/net_log_event_type_list.h @@ -850,7 +850,7 @@ EVENT_TYPE(URL_REQUEST_DELEGATE) // Logged when a delegate informs the URL_REQUEST of what's currently blocking // the request. The parameters attached to the begin event are: // { -// "delegate_info": , +// "delegate_blocked_by": , // } EVENT_TYPE(DELEGATE_INFO) @@ -3030,3 +3030,13 @@ EVENT_TYPE(UPLOAD_DATA_STREAM_INIT) // the end of file. Result < 0 means an error.> // } EVENT_TYPE(UPLOAD_DATA_STREAM_READ) + +// ----------------------------------------------------------------------------- +// ResourceScheduler related events +// ----------------------------------------------------------------------------- + +// The ResourceScheduler has started a previously blocked request. Parameters: +// { +// "trigger": +// } +EVENT_TYPE(RESOURCE_SCHEDULER_REQUEST_STARTED) diff --git a/net/url_request/url_request.cc b/net/url_request/url_request.cc index 75eb4220106fe4..f687beccf6a5d2 100644 --- a/net/url_request/url_request.cc +++ b/net/url_request/url_request.cc @@ -294,7 +294,7 @@ std::unique_ptr URLRequest::GetStateAsValue() const { if (!load_state.param.empty()) dict->SetString("load_state_param", load_state.param); if (!blocked_by_.empty()) - dict->SetString("delegate_info", blocked_by_); + dict->SetString("delegate_blocked_by", blocked_by_); dict->SetString("method", method_); dict->SetBoolean("has_upload", has_upload()); @@ -335,8 +335,9 @@ void URLRequest::LogBlockedBy(const char* blocked_by) { blocked_by_ = blocked_by; use_blocked_by_as_load_param_ = false; - net_log_.BeginEvent(NetLogEventType::DELEGATE_INFO, - NetLog::StringCallback("delegate_info", &blocked_by_)); + net_log_.BeginEvent( + NetLogEventType::DELEGATE_INFO, + NetLog::StringCallback("delegate_blocked_by", &blocked_by_)); } void URLRequest::LogAndReportBlockedBy(const char* source) { @@ -584,7 +585,9 @@ URLRequest::URLRequest(const GURL& url, DCHECK(base::ThreadTaskRunnerHandle::IsSet()); context->url_requests()->insert(this); - net_log_.BeginEvent(NetLogEventType::REQUEST_ALIVE); + net_log_.BeginEvent( + NetLogEventType::REQUEST_ALIVE, + base::Bind(&NetLogURLRequestConstructorCallback, &url, priority_)); } void URLRequest::BeforeRequestComplete(int error) { @@ -627,7 +630,6 @@ void URLRequest::StartJob(URLRequestJob* job) { net_log_.BeginEvent( NetLogEventType::URL_REQUEST_START_JOB, base::Bind(&NetLogURLRequestStartCallback, &url(), &method_, load_flags_, - priority_, upload_data_stream_ ? upload_data_stream_->identifier() : -1)); job_.reset(job); @@ -1024,12 +1026,11 @@ void URLRequest::SetPriority(RequestPriority priority) { return; priority_ = priority; - if (job_.get()) { - net_log_.AddEvent( - NetLogEventType::URL_REQUEST_SET_PRIORITY, - NetLog::StringCallback("priority", RequestPriorityToString(priority_))); + net_log_.AddEvent( + NetLogEventType::URL_REQUEST_SET_PRIORITY, + NetLog::StringCallback("priority", RequestPriorityToString(priority_))); + if (job_.get()) job_->SetPriority(priority_); - } } void URLRequest::NotifyAuthRequired(AuthChallengeInfo* auth_info) { diff --git a/net/url_request/url_request_netlog_params.cc b/net/url_request/url_request_netlog_params.cc index 97b67badcdad20..9fc0f22db50861 100644 --- a/net/url_request/url_request_netlog_params.cc +++ b/net/url_request/url_request_netlog_params.cc @@ -13,18 +13,26 @@ namespace net { +std::unique_ptr NetLogURLRequestConstructorCallback( + const GURL* url, + RequestPriority priority, + NetLogCaptureMode /* capture_mode */) { + std::unique_ptr dict(new base::DictionaryValue()); + dict->SetString("url", url->possibly_invalid_spec()); + dict->SetString("priority", RequestPriorityToString(priority)); + return std::move(dict); +} + std::unique_ptr NetLogURLRequestStartCallback( const GURL* url, const std::string* method, int load_flags, - RequestPriority priority, int64_t upload_id, NetLogCaptureMode /* capture_mode */) { std::unique_ptr dict(new base::DictionaryValue()); dict->SetString("url", url->possibly_invalid_spec()); dict->SetString("method", *method); dict->SetInteger("load_flags", load_flags); - dict->SetString("priority", RequestPriorityToString(priority)); if (upload_id > -1) dict->SetString("upload_id", base::Int64ToString(upload_id)); return std::move(dict); diff --git a/net/url_request/url_request_netlog_params.h b/net/url_request/url_request_netlog_params.h index a42ca3f3bc965e..2d672f5767cfa0 100644 --- a/net/url_request/url_request_netlog_params.h +++ b/net/url_request/url_request_netlog_params.h @@ -23,12 +23,17 @@ namespace net { class NetLogCaptureMode; +// Returns a Value containing NetLog parameters for constructing a URLRequest. +NET_EXPORT std::unique_ptr NetLogURLRequestConstructorCallback( + const GURL* url, + RequestPriority priority, + NetLogCaptureMode /* capture_mode */); + // Returns a Value containing NetLog parameters for starting a URLRequest. NET_EXPORT std::unique_ptr NetLogURLRequestStartCallback( const GURL* url, const std::string* method, int load_flags, - RequestPriority priority, int64_t upload_id, NetLogCaptureMode /* capture_mode */); diff --git a/net/url_request/url_request_unittest.cc b/net/url_request/url_request_unittest.cc index 616eb319bfcb98..e5c941f48b2c30 100644 --- a/net/url_request/url_request_unittest.cc +++ b/net/url_request/url_request_unittest.cc @@ -4861,7 +4861,7 @@ class AsyncDelegateLogger : public base::RefCounted { std::string delegate_info; EXPECT_EQ(NetLogEventType::DELEGATE_INFO, entries[log_position].type); EXPECT_EQ(NetLogEventPhase::BEGIN, entries[log_position].phase); - EXPECT_TRUE(entries[log_position].GetStringValue("delegate_info", + EXPECT_TRUE(entries[log_position].GetStringValue("delegate_blocked_by", &delegate_info)); EXPECT_EQ(kFirstDelegateInfo, delegate_info); @@ -4872,7 +4872,7 @@ class AsyncDelegateLogger : public base::RefCounted { ++log_position; EXPECT_EQ(NetLogEventType::DELEGATE_INFO, entries[log_position].type); EXPECT_EQ(NetLogEventPhase::BEGIN, entries[log_position].phase); - EXPECT_TRUE(entries[log_position].GetStringValue("delegate_info", + EXPECT_TRUE(entries[log_position].GetStringValue("delegate_blocked_by", &delegate_info)); EXPECT_EQ(kSecondDelegateInfo, delegate_info);