Add/improve tracing in navigation.

content/browser/frame_host/render_frame_host_impl.cc

 // Copyright 2013 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/render_frame_host_impl.h"
 
 #include "base/bind.h"
 #include "base/command_line.h"
 #include "base/containers/hash_tables.h"
 #include "base/lazy_instance.h"
@@ skipping 446 matching lines @@
 gfx::NativeViewAccessible
     RenderFrameHostImpl::AccessibilityGetNativeViewAccessible() {
   RenderWidgetHostViewBase* view = static_cast<RenderWidgetHostViewBase*>(
       render_view_host_->GetView());
   if (view)
     return view->AccessibilityGetNativeViewAccessible();
   return NULL;
 }
 
 bool RenderFrameHostImpl::CreateRenderFrame(int parent_routing_id) {
-  TRACE_EVENT0("frame_host", "RenderFrameHostImpl::CreateRenderFrame");
+  TRACE_EVENT0("navigation", "RenderFrameHostImpl::CreateRenderFrame");
   DCHECK(!IsRenderFrameLive()) << "Creating frame twice";
 
   // The process may (if we're sharing a process with another host that already
   // initialized it) or may not (we have our own process or the old process
   // crashed) have been initialized. Calling Init multiple times will be
   // ignored, so this is safe.
   if (!GetProcess()->Init())
     return false;
 
   DCHECK(GetProcess()->HasConnection());
@@ skipping 44 matching lines @@
 
 void RenderFrameHostImpl::OnFrameFocused() {
   frame_tree_->SetFocusedFrame(frame_tree_node_);
 }
 
 void RenderFrameHostImpl::OnOpenURL(
     const FrameHostMsg_OpenURL_Params& params) {
   GURL validated_url(params.url);
   GetProcess()->FilterURL(false, &validated_url);
 
+  TRACE_EVENT1("navigation", "RenderFrameHostImpl::OnOpenURL",
+               "url", validated_url.possibly_invalid_spec());
   frame_tree_node_->navigator()->RequestOpenURL(
       this, validated_url, params.referrer, params.disposition,
       params.should_replace_current_entry, params.user_gesture);
 }
 
 void RenderFrameHostImpl::OnDocumentOnLoadCompleted() {
   // This message is only sent for top-level frames. TODO(avi): when frame tree
   // mirroring works correctly, add a check here to enforce it.
   delegate_->DocumentOnLoadCompleted(this);
 }
@@ skipping 38 matching lines @@
 // get a new page_id because we need to create a new navigation entry for that
 // action.
 void RenderFrameHostImpl::OnNavigate(const IPC::Message& msg) {
   // Read the parameters out of the IPC message directly to avoid making another
   // copy when we filter the URLs.
   PickleIterator iter(msg);
   FrameHostMsg_DidCommitProvisionalLoad_Params validated_params;
   if (!IPC::ParamTraits<FrameHostMsg_DidCommitProvisionalLoad_Params>::
       Read(&msg, &iter, &validated_params))
     return;
+  TRACE_EVENT1("navigation", "RenderFrameHostImpl::OnNavigate",
+               "url", validated_params.url.possibly_invalid_spec());
 
   // If we're waiting for a cross-site beforeunload ack from this renderer and
   // we receive a Navigate message from the main frame, then the renderer was
   // navigating already and sent it before hearing the FrameMsg_Stop message.
   // We do not want to cancel the pending navigation in this case, since the
   // old page will soon be stopped.  Instead, treat this as a beforeunload ack
   // to allow the pending navigation to continue.
   if (render_view_host_->is_waiting_for_beforeunload_ack_ &&
       render_view_host_->unload_ack_is_for_cross_site_transition_ &&
       PageTransitionIsMainFrame(validated_params.transition)) {
@@ skipping 76 matching lines @@
   frame_tree_node_->render_manager()->OnDeferredAfterResponseStarted(
       global_request_id, this);
 
   if (GetParent() || !delegate_->WillHandleDeferAfterResponseStarted())
     frame_tree_node_->render_manager()->ResumeResponseDeferredAtStart();
   else
     delegate_->DidDeferAfterResponseStarted(transition_data);
 }
 
 void RenderFrameHostImpl::SwapOut(RenderFrameProxyHost* proxy) {
+  // The end of the trace event is in OnSwapOutACK for when the RenderFrame

[Charlie Reis, 2014/08/27 22:05:12]

nit: The end of this 
nit: for when -> when

[nasko, 2014/08/27 23:30:01]

Done.

+  // has completed the operation and sends back an IPC message.
+  // In the case of timeout on running the unload handler

[Charlie Reis, 2014/08/27 22:05:12]

This gets pretty confusing and hard to follow (e.g., what "this problem" means
in practice).  Can we simplify it to say something like: 

The trace event may not end properly if the ACK times out.  We expect this to be
fixed when RenderViewHostImpl::OnSwapOut moves to RenderFrameHost.

[nasko, 2014/08/27 23:30:01]

Sure! Thanks for rewriting it more concisely. 

+  // RenderViewHostImpl::OnSwapOut is called. In this case it doesn't know
+  // which frame initiated the swap out and if it is for subframe, it won't
+  // balance out (this will happen only with --site-per-process).
+  // This problem will disappear once swap out state is moved out of
+  // RenderViewHost.
+  TRACE_EVENT_ASYNC_BEGIN0("navigation", "RenderFrameHostImpl::SwapOut", this);
+
   // TODO(creis): Move swapped out state to RFH.  Until then, only update it
   // when swapping out the main frame.
   if (!GetParent()) {
     // If this RenderViewHost is not in the default state, it must have already
     // gone through this, therefore just return.
     if (render_view_host_->rvh_state_ != RenderViewHostImpl::STATE_DEFAULT)
       return;
 
     render_view_host_->SetState(
         RenderViewHostImpl::STATE_PENDING_SWAP_OUT);
@@ skipping 10 matching lines @@
   if (!GetParent())
     delegate_->SwappedOut(this);
   else
     set_swapped_out(true);
 }
 
 void RenderFrameHostImpl::OnBeforeUnloadACK(
     bool proceed,
     const base::TimeTicks& renderer_before_unload_start_time,
     const base::TimeTicks& renderer_before_unload_end_time) {
+  TRACE_EVENT_ASYNC_END0(
+      "navigation", "RenderFrameHostImpl::BeforeUnload", this);
   // TODO(creis): Support properly beforeunload on subframes. For now just
   // pretend that the handler ran and allowed the navigation to proceed.
   if (GetParent()) {
     render_view_host_->is_waiting_for_beforeunload_ack_ = false;
     frame_tree_node_->render_manager()->OnBeforeUnloadACK(
         render_view_host_->unload_ack_is_for_cross_site_transition_, proceed,
         renderer_before_unload_end_time);
     return;
   }
 
@@ skipping 52 matching lines @@
       render_view_host_->unload_ack_is_for_cross_site_transition_, proceed,
       before_unload_end_time);
 
   // If canceled, notify the delegate to cancel its pending navigation entry.
   if (!proceed)
     render_view_host_->GetDelegate()->DidCancelLoading();
 }
 
 void RenderFrameHostImpl::OnSwapOutACK() {
   OnSwappedOut(false);
+  TRACE_EVENT_ASYNC_END0("navigation", "RenderFrameHostImpl::SwapOut", this);

[Charlie Reis, 2014/08/27 22:05:13]

Actually, if we put this in RFHI::OnSwappedOut below, does that solve the
timeout issue?  Or does the timer call the RVHI version directly?

[nasko, 2014/08/27 23:30:01]

It calls RVH directly:
https://code.google.com/p/chromium/codesearch#chromium/src/content/browser/re...

[Charlie Reis, 2014/08/28 16:20:09]

Acknowledged.

 }
 
 void RenderFrameHostImpl::OnSwappedOut(bool timed_out) {
   // For now, we only need to update the RVH state machine for top-level swaps.
   if (!GetParent())
     render_view_host_->OnSwappedOut(timed_out);
 }
 
 void RenderFrameHostImpl::OnContextMenu(const ContextMenuParams& params) {
   // Validate the URLs in |params|.  If the renderer can't request the URLs
@@ skipping 242 matching lines @@
 bool RenderFrameHostImpl::CanCommitURL(const GURL& url) {
   // TODO(creis): We should also check for WebUI pages here.  Also, when the
   // out-of-process iframes implementation is ready, we should check for
   // cross-site URLs that are not allowed to commit in this process.
 
   // Give the client a chance to disallow URLs from committing.
   return GetContentClient()->browser()->CanCommitURL(GetProcess(), url);
 }
 
 void RenderFrameHostImpl::Navigate(const FrameMsg_Navigate_Params& params) {
-  TRACE_EVENT0("frame_host", "RenderFrameHostImpl::Navigate");
+  TRACE_EVENT0("navigation", "RenderFrameHostImpl::Navigate");

[Charlie Reis, 2014/08/27 22:05:12]

This one's subtle.  In many cross-process navigations, we won't actually send
the IPC until SetNavigationsSuspended(false), thanks to line 1090 below.  That
happens on the beforeunload ack.

Maybe we want a trace event for the duration of SetNavigationSuspended being
true?  That would let us visualize how long the navigation IPC is being held.

(I know we already have an event for the duration of BeforeUnload, but there
appears to be a giant gap between the end of that and the renderer starting to
navigate.  I wonder if those two durations can differ substantially.)

[nasko, 2014/08/27 23:30:01]

I've added a trace event for the duration of navigation_suspended_ being true.

   // Browser plugin guests are not allowed to navigate outside web-safe schemes,
   // so do not grant them the ability to request additional URLs.
   if (!GetProcess()->IsIsolatedGuest()) {
     ChildProcessSecurityPolicyImpl::GetInstance()->GrantRequestURL(
         GetProcess()->GetID(), params.url);
     if (params.url.SchemeIs(url::kDataScheme) &&
         params.base_url_for_data_url.SchemeIs(url::kFileScheme)) {
       // If 'data:' is used, and we have a 'file:' base url, grant access to
       // local files.
       ChildProcessSecurityPolicyImpl::GetInstance()->GrantRequestURL(
@@ skipping 44 matching lines @@
   params.navigation_type = FrameMsg_Navigate_Type::NORMAL;
   params.browser_navigation_start = base::TimeTicks::Now();
   Navigate(params);
 }
 
 void RenderFrameHostImpl::Stop() {
   Send(new FrameMsg_Stop(routing_id_));
 }
 
 void RenderFrameHostImpl::DispatchBeforeUnload(bool for_cross_site_transition) {
+  TRACE_EVENT_ASYNC_BEGIN0(
+      "navigation", "RenderFrameHostImpl::BeforeUnload", this);
   // TODO(creis): Support subframes.
   if (!render_view_host_->IsRenderViewLive() || GetParent()) {
     // We don't have a live renderer, so just skip running beforeunload.
     render_view_host_->is_waiting_for_beforeunload_ack_ = true;
     render_view_host_->unload_ack_is_for_cross_site_transition_ =
         for_cross_site_transition;
     base::TimeTicks now = base::TimeTicks::Now();
     OnBeforeUnloadACK(true, now, now);
     return;
   }
@@ skipping 178 matching lines @@
 }
 
 void RenderFrameHostImpl::CancelSuspendedNavigations() {
   // Clear any state if a pending navigation is canceled or preempted.
   if (suspended_nav_params_)
     suspended_nav_params_.reset();
   navigations_suspended_ = false;
 }
 
 }  // namespace content