Add more navigation tracing to RenderFrameHost and NavigationRequest.

content/browser/frame_host/navigation_request.cc

 // Copyright 2014 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 "content/browser/frame_host/navigation_request.h"
 
 #include <utility>
 
 #include "base/memory/ptr_util.h"
 #include "content/browser/appcache/appcache_navigation_handle.h"
@@ skipping 298 matching lines @@
       request_params_(request_params),
       browser_initiated_(browser_initiated),
       state_(NOT_STARTED),
       restore_type_(RestoreType::NONE),
       is_view_source_(false),
       bindings_(NavigationEntryImpl::kInvalidBindings),
       response_should_be_rendered_(true),
       associated_site_instance_type_(AssociatedSiteInstanceType::NONE),
       may_transfer_(may_transfer) {
   DCHECK(!browser_initiated || (entry != nullptr && frame_entry != nullptr));
+  TRACE_EVENT_ASYNC_BEGIN2("navigation", "NavigationRequest", this,
+                           "frame_tree_node",
+                           frame_tree_node_->frame_tree_node_id(), "url",
+                           common_params_.url.possibly_invalid_spec());
 
   // Sanitize the referrer.
   common_params_.referrer =
       Referrer::SanitizeForRequest(common_params_.url, common_params_.referrer);
 
   if (may_transfer) {
     FrameNavigationEntry* frame_entry = entry->GetFrameEntry(frame_tree_node);
     if (frame_entry) {
       source_site_instance_ = frame_entry->source_site_instance();
       dest_site_instance_ = frame_entry->site_instance();
@@ skipping 24 matching lines @@
   net::HttpRequestHeaders headers;
   headers.AddHeadersFromString(begin_params_.headers);
   AddAdditionalRequestHeaders(
       &headers, common_params_.url, common_params_.navigation_type,
       frame_tree_node_->navigator()->GetController()->GetBrowserContext(),
       common_params.method, user_agent_override, frame_tree_node);
   begin_params_.headers = headers.ToString();
 }
 
 NavigationRequest::~NavigationRequest() {
+  TRACE_EVENT_ASYNC_END0("navigation", "NavigationRequest", this);
 }
 
 void NavigationRequest::BeginNavigation() {
   DCHECK(!loader_);
   DCHECK(state_ == NOT_STARTED || state_ == WAITING_FOR_RENDERER_RESPONSE);
+  TRACE_EVENT_ASYNC_STEP_INTO0("navigation", "NavigationRequest", this,
+                               "BeginNavigation");
   state_ = STARTED;
   RenderFrameDevToolsAgentHost::OnBeforeNavigation(navigation_handle_.get());
 
   if (ShouldMakeNetworkRequestForURL(common_params_.url) &&
       !navigation_handle_->IsSameDocument()) {
     // It's safe to use base::Unretained because this NavigationRequest owns
     // the NavigationHandle where the callback will be stored.
     // TODO(clamy): pass the method to the NavigationHandle instead of a
     // boolean.
     bool is_external_protocol =
         !GetContentClient()->browser()->IsHandledURL(common_params_.url);
     navigation_handle_->WillStartRequest(
         common_params_.method, common_params_.post_data,
         Referrer::SanitizeForRequest(common_params_.url,
                                      common_params_.referrer),
         begin_params_.has_user_gesture, common_params_.transition,
         is_external_protocol, begin_params_.request_context_type,
         begin_params_.mixed_content_context_type,
         base::Bind(&NavigationRequest::OnStartChecksComplete,
                    base::Unretained(this)));
     return;
   }
 
   // There is no need to make a network request for this navigation, so commit
   // it immediately.
+  TRACE_EVENT_ASYNC_STEP_INTO0("navigation", "NavigationRequest", this,
+                               "ResponseStarted");
   state_ = RESPONSE_STARTED;
 
   // Select an appropriate RenderFrameHost.
   RenderFrameHostImpl* render_frame_host =
       frame_tree_node_->render_manager()->GetFrameHostForNavigation(*this);
   NavigatorImpl::CheckWebUIRendererDoesNotDisplayNormalURL(render_frame_host,
                                                            common_params_.url);
 
   // Inform the NavigationHandle that the navigation will commit.
   navigation_handle_->ReadyToCommitNavigation(render_frame_host);
 
   CommitNavigation();
 }
 
+void NavigationRequest::SetWaitingForRendererResponse() {
+  TRACE_EVENT_ASYNC_STEP_INTO0("navigation", "NavigationRequest", this,
+                               "WaitingForRendererResponse");
+  DCHECK(state_ == NOT_STARTED);
+  state_ = WAITING_FOR_RENDERER_RESPONSE;
+}
+
 void NavigationRequest::CreateNavigationHandle(int pending_nav_entry_id) {
   DCHECK_EQ(frame_tree_node_->navigation_request(), this);
   FrameTreeNode* frame_tree_node = frame_tree_node_;
 
   std::vector<GURL> redirect_chain;
   if (!begin_params_.client_side_redirect_url.is_empty())
     redirect_chain.push_back(begin_params_.client_side_redirect_url);
   redirect_chain.push_back(common_params_.url);
 
   std::unique_ptr<NavigationHandleImpl> navigation_handle =
@@ skipping 92 matching lines @@
     const scoped_refptr<ResourceResponse>& response,
     std::unique_ptr<StreamHandle> body,
     mojo::ScopedDataPipeConsumerHandle consumer_handle,
     const SSLStatus& ssl_status,
     std::unique_ptr<NavigationData> navigation_data,
     const GlobalRequestID& request_id,
     bool is_download,
     bool is_stream) {
   DCHECK(state_ == STARTED);
   DCHECK(response);
+  TRACE_EVENT_ASYNC_STEP_INTO0("navigation", "NavigationRequest", this,
+                               "OnResponseStarted");
   state_ = RESPONSE_STARTED;
 
   // Check if the response should be sent to a renderer.
   response_should_be_rendered_ =
       !is_download && (!response->head.headers.get() ||
                        (response->head.headers->response_code() != 204 &&
                         response->head.headers->response_code() != 205));
 
   // Response that will not commit should be marked as aborted in the
   // NavigationHandle.
@@ skipping 60 matching lines @@
       response->head.connection_info, ssl_status, request_id,
       common_params_.should_replace_current_entry, is_download, is_stream,
       base::Closure(),
       base::Bind(&NavigationRequest::OnWillProcessResponseChecksComplete,
                  base::Unretained(this)));
 }
 
 void NavigationRequest::OnRequestFailed(bool has_stale_copy_in_cache,
                                         int net_error) {
   DCHECK(state_ == STARTED || state_ == RESPONSE_STARTED);
+  TRACE_EVENT_ASYNC_STEP_INTO1("navigation", "NavigationRequest", this,
+                               "OnRequestFailed", "error", net_error);
   state_ = FAILED;
   navigation_handle_->set_net_error_code(static_cast<net::Error>(net_error));
 
   // With PlzNavigate, debug URLs will give a failed navigation because the
   // WebUI backend won't find a handler for them. They will be processed in the
   // renderer, however do not discard the pending entry so that the URL bar
   // shows them correctly.
   if (!IsRendererDebugURL(common_params_.url)) {
     frame_tree_node_->navigator()->DiscardPendingEntryIfNeeded(
         navigation_handle_.get());
@@ skipping 43 matching lines @@
     TRACE_EVENT_ASYNC_END_WITH_TIMESTAMP0(
         "navigation", "Navigation timeToNetworkStack", navigation_handle_.get(),
         timestamp);
   }
 
   frame_tree_node_->navigator()->LogResourceRequestTime(timestamp,
                                                         common_params_.url);
 }
 
 void NavigationRequest::OnStartChecksComplete(
     NavigationThrottle::ThrottleCheckResult result) {

[clamy, 2017/04/28 14:07:15]

How about adding some traces in the On*ChecksComplete methods here and below?
These are the ones that will actually do stuff such as sending the request to
the net stack or committing it.

[nasko, 2017/04/28 14:18:56]

All NavigationThrottle checks are already instrumented in NavigationHandle. If
we get to this method, we already have a trace of what happened with UI thread
throttles and otherwise we will proceed on sending the request to the network
stack. My approach was to add trace events at the places where I see state_
changes. Is there anything else specific that you care about that I should add?

[clamy, 2017/04/28 14:21:00]

Acknowledged. Seems we should be covered enough.

   DCHECK(result != NavigationThrottle::DEFER);
   DCHECK(result != NavigationThrottle::BLOCK_RESPONSE);
 
   if (on_start_checks_complete_closure_)
     on_start_checks_complete_closure_.Run();
 
   // Abort the request if needed. This will destroy the NavigationRequest.
   if (result == NavigationThrottle::CANCEL_AND_IGNORE ||
       result == NavigationThrottle::CANCEL) {
     // TODO(clamy): distinguish between CANCEL and CANCEL_AND_IGNORE.
@@ skipping 167 matching lines @@
   DCHECK_EQ(request_params_.has_user_gesture, begin_params_.has_user_gesture);
 
   render_frame_host->CommitNavigation(response_.get(), std::move(body_),
                                       std::move(handle_), common_params_,
                                       request_params_, is_view_source_);
 
   frame_tree_node_->ResetNavigationRequest(true, true);
 }
 
 }  // namespace content