Add/improve tracing in navigation.

content/browser/frame_host/render_frame_host_impl.cc

Index: content/browser/frame_host/render_frame_host_impl.cc
diff --git a/content/browser/frame_host/render_frame_host_impl.cc b/content/browser/frame_host/render_frame_host_impl.cc
index 3ca2e9cc64cd7754f042bc22be700f33961f132a..c69627bcf9577ca1d5ff9829321229d0bda8538d 100644
--- a/content/browser/frame_host/render_frame_host_impl.cc
+++ b/content/browser/frame_host/render_frame_host_impl.cc
@@ -464,7 +464,7 @@ gfx::NativeViewAccessible
 }
 
 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
@@ -529,6 +529,8 @@ void RenderFrameHostImpl::OnOpenURL(
   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);
@@ -587,6 +589,8 @@ void RenderFrameHostImpl::OnNavigate(const IPC::Message& msg) {
   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
@@ -683,6 +687,16 @@ void RenderFrameHostImpl::OnDeferredAfterResponseStarted(
 }
 
 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()) {
@@ -713,6 +727,8 @@ 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()) {
@@ -785,6 +801,7 @@ void RenderFrameHostImpl::OnBeforeUnloadACK(
 
 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) {
@@ -1047,7 +1064,7 @@ bool RenderFrameHostImpl::CanCommitURL(const GURL& 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()) {
@@ -1112,6 +1129,8 @@ void RenderFrameHostImpl::Stop() {
 }
 
 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.