[devtools] Emit timing event for queuing of a request from the browser

The devtools network tab receives a notification via "requestWillBeSent"
that corresponds to the time when the browser process queues a network
request. This enables the network tab to calculate how long the task
was queued.

The timeline (performance) panel does not receive a corresponding
tracing event, and hence does not know how long a task was queued. This
results in different times being reported as totals in the network vs
the performance panel if the task was initiated from the browser (and
not from the renderer).

This CL adds a tracing event to the browser that indicates that a
network request will be queued, and processes the event in DevTools
so that the network access time reported in the performance tab matches
the time reported in the network tab for requests initiated in the
browser.

For requests initiated in the renderer, the ResourceSendRequest tracing
event already has the time when the request gets queued (up to a few
1/100 ms).

Bug: chromium:865066
Change-Id: I1edfac4ec7ada8407b5dd931920e26e139b4f8df
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/1771398
Commit-Queue: Sigurd Schneider <sigurds@chromium.org>
Reviewed-by: Alexei Filippov <alph@chromium.org>
Cr-Commit-Position: refs/heads/master@{#695614}

content/browser/devtools/devtools_instrumentation.cc

@@ -130,16 +130,34 @@ void OnSignedExchangeReceived(
                    envelope, certificate, ssl_info, errors);
 }
 
+namespace inspector_will_send_navigation_request_event {
+std::unique_ptr<base::trace_event::TracedValue> Data(
+    const base::UnguessableToken& request_id) {
+  auto value = std::make_unique<base::trace_event::TracedValue>();
+  value->SetString("requestId", request_id.ToString());
+  return value;
+}
+}  // namespace inspector_will_send_navigation_request_event
+
 void OnSignedExchangeCertificateRequestSent(
     FrameTreeNode* frame_tree_node,
     const base::UnguessableToken& request_id,
     const base::UnguessableToken& loader_id,
     const network::ResourceRequest& request,
     const GURL& signed_exchange_url) {
+  // Make sure both back-ends yield the same timestamp.
+  auto timestamp = base::TimeTicks::Now();
   DispatchToAgents(frame_tree_node, &protocol::NetworkHandler::RequestSent,
                    request_id.ToString(), loader_id.ToString(), request,
                    protocol::Network::Initiator::TypeEnum::SignedExchange,
-                   signed_exchange_url);
+                   signed_exchange_url, timestamp);
+
+  auto value = std::make_unique<base::trace_event::TracedValue>();
+  value->SetString("requestId", request_id.ToString());
+  TRACE_EVENT_INSTANT_WITH_TIMESTAMP1(
+      "devtools.timeline", "ResourceWillSendRequest", TRACE_EVENT_SCOPE_PROCESS,
+      timestamp, "data",
+      inspector_will_send_navigation_request_event::Data(request_id));
 }
 
 void OnSignedExchangeCertificateResponseReceived(
@@ -356,9 +374,16 @@ bool WillCreateURLLoaderFactory(
 
 void OnNavigationRequestWillBeSent(
     const NavigationRequest& navigation_request) {
+  // Make sure both back-ends yield the same timestamp.
+  auto timestamp = base::TimeTicks::Now();
   DispatchToAgents(navigation_request.frame_tree_node(),
                    &protocol::NetworkHandler::NavigationRequestWillBeSent,
-                   navigation_request);
+                   navigation_request, timestamp);
+  TRACE_EVENT_INSTANT_WITH_TIMESTAMP1(
+      "devtools.timeline", "ResourceWillSendRequest", TRACE_EVENT_SCOPE_PROCESS,
+      timestamp, "data",
+      inspector_will_send_navigation_request_event::Data(
+          navigation_request.devtools_navigation_token()));
 }
 
 // Notify the provided agent host of a certificate error. Returns true if one of

content/browser/devtools/protocol/network_handler.cc

@@ -1510,7 +1510,8 @@ Maybe<String> GetBlockedReasonFor(
 }  // namespace
 
 void NetworkHandler::NavigationRequestWillBeSent(
-    const NavigationRequest& nav_request) {
+    const NavigationRequest& nav_request,
+    base::TimeTicks timestamp) {
   if (!enabled_)
     return;
 
@@ -1571,8 +1572,7 @@ void NetworkHandler::NavigationRequestWillBeSent(
                     .Build();
   }
   std::string id = nav_request.devtools_navigation_token().ToString();
-  double current_ticks =
-      (base::TimeTicks::Now() - base::TimeTicks()).InSecondsF();
+  double current_ticks = timestamp.since_origin().InSecondsF();
   double current_wall_time = base::Time::Now().ToDoubleT();
   std::string frame_token =
       nav_request.frame_tree_node()->devtools_frame_token().ToString();
@@ -1587,7 +1587,8 @@ void NetworkHandler::RequestSent(const std::string& request_id,
                                  const std::string& loader_id,
                                  const network::ResourceRequest& request,
                                  const char* initiator_type,
-                                 const base::Optional<GURL>& initiator_url) {
+                                 const base::Optional<GURL>& initiator_url,
+                                 base::TimeTicks timestamp) {
   if (!enabled_)
     return;
   std::unique_ptr<DictionaryValue> headers_dict(DictionaryValue::create());
@@ -1612,10 +1613,8 @@ void NetworkHandler::RequestSent(const std::string& request_id,
     request_object->SetUrlFragment(url_fragment);
   frontend_->RequestWillBeSent(
       request_id, loader_id, url_without_fragment, std::move(request_object),
-      base::TimeTicks::Now().ToInternalValue() /
-          static_cast<double>(base::Time::kMicrosecondsPerSecond),
-      base::Time::Now().ToDoubleT(), std::move(initiator),
-      std::unique_ptr<Network::Response>(),
+      timestamp.since_origin().InSecondsF(), base::Time::Now().ToDoubleT(),
+      std::move(initiator), std::unique_ptr<Network::Response>(),
       std::string(Network::ResourceTypeEnum::Other),
       Maybe<std::string>() /* frame_id */, request.has_user_gesture);
 }

content/browser/devtools/protocol/network_handler.h

@@ -157,12 +157,14 @@ class NetworkHandler : public DevToolsDomainHandler,
   void ApplyOverrides(net::HttpRequestHeaders* headers,
                       bool* skip_service_worker,
                       bool* disable_cache);
-  void NavigationRequestWillBeSent(const NavigationRequest& nav_request);
+  void NavigationRequestWillBeSent(const NavigationRequest& nav_request,
+                                   base::TimeTicks timestamp);
   void RequestSent(const std::string& request_id,
                    const std::string& loader_id,
                    const network::ResourceRequest& request,
                    const char* initiator_type,
-                   const base::Optional<GURL>& initiator_url);
+                   const base::Optional<GURL>& initiator_url,
+                   base::TimeTicks timestamp);
   void ResponseReceived(const std::string& request_id,
                         const std::string& loader_id,
                         const GURL& url,

content/browser/devtools/service_worker_devtools_manager.cc

@@ -188,11 +188,12 @@ void ServiceWorkerDevToolsManager::NavigationPreloadRequestSent(
   auto it = live_hosts_.find(worker_id);
   if (it == live_hosts_.end())
     return;
+  auto timestamp = base::TimeTicks::Now();
   for (auto* network :
        protocol::NetworkHandler::ForAgentHost(it->second.get())) {
     network->RequestSent(request_id, std::string(), request,
                          protocol::Network::Initiator::TypeEnum::Preload,
-                         base::nullopt /* initiator_url */);
+                         base::nullopt /* initiator_url */, timestamp);
   }
 }
 

third_party/blink/renderer/devtools/front_end/timeline/TimelineUIUtils.js

@@ -104,6 +104,7 @@ Timeline.TimelineUIUtils = class {
     eventStyles[type.TimeStamp] = new Timeline.TimelineRecordStyle(ls`Timestamp`, scripting);
     eventStyles[type.ConsoleTime] = new Timeline.TimelineRecordStyle(ls`Console Time`, scripting);
     eventStyles[type.UserTiming] = new Timeline.TimelineRecordStyle(ls`User Timing`, scripting);
+    eventStyles[type.ResourceWillSendRequest] = new Timeline.TimelineRecordStyle(ls`Will Send Request`, loading);
     eventStyles[type.ResourceSendRequest] = new Timeline.TimelineRecordStyle(ls`Send Request`, loading);
     eventStyles[type.ResourceReceiveResponse] = new Timeline.TimelineRecordStyle(ls`Receive Response`, loading);
     eventStyles[type.ResourceFinish] = new Timeline.TimelineRecordStyle(ls`Finish Loading`, loading);
@@ -523,6 +524,7 @@ Timeline.TimelineUIUtils = class {
       case recordType.WebSocketSendHandshakeRequest:
       case recordType.WebSocketReceiveHandshakeResponse:
       case recordType.WebSocketDestroy:
+      case recordType.ResourceWillSendRequest:
       case recordType.ResourceSendRequest:
       case recordType.ResourceReceivedData:
       case recordType.ResourceReceiveResponse:
@@ -630,6 +632,7 @@ Timeline.TimelineUIUtils = class {
       case recordType.DecodeLazyPixelRef:
       case recordType.XHRReadyStateChange:
       case recordType.XHRLoad:
+      case recordType.ResourceWillSendRequest:
       case recordType.ResourceSendRequest:
       case recordType.ResourceReceivedData:
       case recordType.ResourceReceiveResponse:
@@ -828,6 +831,7 @@ Timeline.TimelineUIUtils = class {
       case recordTypes.FireAnimationFrame:
         contentHelper.appendTextRow(ls`Callback ID`, eventData['id']);
         break;
+      case recordTypes.ResourceWillSendRequest:
       case recordTypes.ResourceSendRequest:
       case recordTypes.ResourceReceiveResponse:
       case recordTypes.ResourceReceivedData:

third_party/blink/renderer/devtools/front_end/timeline/timeline_strings.grdp

@@ -160,6 +160,9 @@ Click the reload button <ph name="RELOADBUTTON">$3s<ex>reload</ex></ph> or hit <
   <message name="IDS_DEVTOOLS_24aa4117da86c41684ad25742832dfa6" desc="Text in Timeline UIUtils of the Performance panel">
     Async
   </message>
+  <message name="IDS_DEVTOOLS_24ed51e784c08847f2c1bafe1a6428a4" desc="Text in Timeline UIUtils of the Performance panel">
+    Will Send Request
+  </message>
   <message name="IDS_DEVTOOLS_25a5e1f05232eae2d3a9c1ff4cb83869" desc="Text in Timeline UIUtils of the Performance panel">
     Function Call
   </message>

third_party/blink/renderer/devtools/front_end/timeline_model/TimelineModel.js

@@ -951,6 +951,13 @@ TimelineModel.TimelineModel = class {
       return;
     }
 
+    if (event.name === TimelineModel.TimelineModel.RecordType.ResourceWillSendRequest) {
+      const requestId = event.args['data']['requestId'];
+      if (typeof requestId === 'string')
+        this._requestsFromBrowser.set(requestId, event);
+      return;
+    }
+
     if (event.hasCategory(SDK.TracingModel.DevToolsMetadataEventCategory) && event.args['data']) {
       const data = event.args['data'];
       if (event.name === TimelineModel.TimelineModel.DevToolsMetadataEvent.TracingStartedInBrowser) {
@@ -1074,6 +1081,8 @@ TimelineModel.TimelineModel = class {
     /** @type {!Map<string, !TimelineModel.TimelineModel.PageFrame>} */
     this._pageFrames = new Map();
     this._mainFrame = null;
+    /** @type {!Map<string, !SDK.TracingModel.Event>} */
+    this._requestsFromBrowser = new Map();
 
     this._minimumRecordTime = 0;
     this._maximumRecordTime = 0;
@@ -1171,8 +1180,8 @@ TimelineModel.TimelineModel = class {
     const zeroStartRequestsList = [];
     const types = TimelineModel.TimelineModel.RecordType;
     const resourceTypes = new Set([
-      types.ResourceSendRequest, types.ResourceReceiveResponse, types.ResourceReceivedData, types.ResourceFinish,
-      types.ResourceMarkAsCached
+      types.ResourceWillSendRequest, types.ResourceSendRequest, types.ResourceReceiveResponse,
+      types.ResourceReceivedData, types.ResourceFinish, types.ResourceMarkAsCached
     ]);
     const events = this.inspectedTargetEvents();
     for (let i = 0; i < events.length; ++i) {
@@ -1180,6 +1189,11 @@ TimelineModel.TimelineModel = class {
       if (!resourceTypes.has(e.name))
         continue;
       const id = TimelineModel.TimelineModel.globalEventId(e, 'requestId');
+      if (e.name === types.ResourceSendRequest && this._requestsFromBrowser.has(e.args.data.requestId))
+        addRequest(this._requestsFromBrowser.get(e.args.data.requestId), id);
+      addRequest(e, id);
+    }
+    function addRequest(e, id) {
       let request = requests.get(id);
       if (request) {
         request.addEvent(e);
@@ -1267,6 +1281,7 @@ TimelineModel.TimelineModel.RecordType = {
   ConsoleTime: 'ConsoleTime',
   UserTiming: 'UserTiming',
 
+  ResourceWillSendRequest: 'ResourceWillSendRequest',
   ResourceSendRequest: 'ResourceSendRequest',
   ResourceReceiveResponse: 'ResourceReceiveResponse',
   ResourceReceivedData: 'ResourceReceivedData',
@@ -1522,7 +1537,10 @@ TimelineModel.TimelineModel.NetworkRequest = class {
    * @param {!SDK.TracingModel.Event} event
    */
   constructor(event) {
-    this.startTime = event.name === TimelineModel.TimelineModel.RecordType.ResourceSendRequest ? event.startTime : 0;
+    const recordType = TimelineModel.TimelineModel.RecordType;
+    const isInitial =
+        event.name === recordType.ResourceSendRequest || event.name === recordType.ResourceWillSendRequest;
+    this.startTime = isInitial ? event.startTime : 0;
     this.endTime = Infinity;
     this.encodedDataLength = 0;
     this.decodedBodyLength = 0;

third_party/blink/web_tests/http/tests/devtools/tracing/timeline-network/timeline-network-resource-navigation-expected.txt

+Tests presence and order of tracing events for a browser navigation.
+
+Page reloaded.
+Recording stopped
+Number of events in request: 5
+ResourceWillSendRequest from thread CrBrowserMain
+ResourceSendRequest from thread CrRendererMain
+ResourceReceiveResponse from thread CrRendererMain
+ResourceReceivedData from thread CrRendererMain
+ResourceFinish from thread CrRendererMain
+

third_party/blink/web_tests/http/tests/devtools/tracing/timeline-network/timeline-network-resource-navigation-sgx-expected.txt

+Tests presence and order of tracing events for a browser navigation.
+
+Page reloaded.
+Recording stopped
+Number of events in request: 5
+ResourceWillSendRequest from thread CrBrowserMain
+ResourceSendRequest from thread CrRendererMain
+ResourceReceiveResponse from thread CrRendererMain
+ResourceReceivedData from thread CrRendererMain
+ResourceFinish from thread CrRendererMain
+

third_party/blink/web_tests/http/tests/devtools/tracing/timeline-network/timeline-network-resource-navigation-sgx.js

+// Copyright 2019 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.
+
+(async function() {
+  TestRunner.addResult(`Tests presence and order of tracing events for a browser navigation.\n`);
+  await TestRunner.loadModule(`performance_test_runner`);
+  await TestRunner.showPanel(`timeline`);
+  await TestRunner.NetworkAgent.setCacheDisabled(true);
+  await TestRunner.navigatePromise('/loading/sxg/resources/sxg-location.sxg');
+
+  TestRunner.resourceTreeModel.addEventListener(SDK.ResourceTreeModel.Events.Load, TestRunner.pageLoaded);
+
+  const panel = UI.panels.timeline;
+  PerformanceTestRunner.runWhenTimelineIsReady(recordingStopped);
+  panel._millisecondsToRecordAfterLoadEvent = 1;
+  panel._recordReload();
+
+  async function recordingStopped() {
+    TestRunner.addResult('Recording stopped');
+    const sendRequests = PerformanceTestRunner.timelineModel().networkRequests();
+    for (const request of sendRequests) {
+      TestRunner.addResult(`Number of events in request: ${request.children && request.children.length}`);
+      let requestId = null;
+      for (const event of request.children.sort((a,b) => a.startTime - b.startTime)) {
+        if (requestId === null) {
+          requestId = event.args.data.requestId;
+        } else if (requestId !== event.args.data.requestId) {
+          TestRunner.addResult(`Events did not have the same request id.`)
+        }
+        TestRunner.addResult(`${event.name} from thread ${event.thread._name}`);
+      }
+    }
+    TestRunner.completeTest();
+}
+})();

third_party/blink/web_tests/http/tests/devtools/tracing/timeline-network/timeline-network-resource-navigation.js

+// Copyright 2019 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.
+
+(async function() {
+  TestRunner.addResult(`Tests presence and order of tracing events for a browser navigation.\n`);
+  await TestRunner.loadModule(`performance_test_runner`);
+  await TestRunner.showPanel(`timeline`);
+  await TestRunner.NetworkAgent.setCacheDisabled(true);
+
+  TestRunner.resourceTreeModel.addEventListener(SDK.ResourceTreeModel.Events.Load, TestRunner.pageLoaded);
+
+  const panel = UI.panels.timeline;
+  PerformanceTestRunner.runWhenTimelineIsReady(recordingStopped);
+  panel._millisecondsToRecordAfterLoadEvent = 1;
+  panel._recordReload();
+
+  async function recordingStopped() {
+    TestRunner.addResult('Recording stopped');
+    const sendRequests = PerformanceTestRunner.timelineModel().networkRequests();
+    for (const request of sendRequests) {
+      TestRunner.addResult(`Number of events in request: ${request.children && request.children.length}`);
+      let requestId = null;
+      for (const event of request.children.sort((a,b) => a.startTime - b.startTime)) {
+        if (requestId === null) {
+          requestId = event.args.data.requestId;
+        } else if (requestId !== event.args.data.requestId) {
+          TestRunner.addResult(`Events did not have the same request id.`)
+        }
+        TestRunner.addResult(`${event.name} from thread ${event.thread._name}`);
+      }
+    }
+    TestRunner.completeTest();
+}
+})();