Add/improve tracing in navigation.

Add/improve tracing in navigation.

This CL adds tracing statement for the navigation functionality within Chrome and modifies some of the existing tracing already in place.

Committed: https://crrev.com/b8744d2cd9eac9af4cb16a83420e79f1684f06c2
Cr-Commit-Position: refs/heads/master@{#292406}

[nasko, 2014-08-27 21:09:11]

nasko@chromium.org changed reviewers:
+ creis@chromium.org

[nasko, 2014-08-27 21:09:11]

Hey Charlie,
Can you review this CL for me?
Thanks!
Nasko

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

This is going to be very helpful for debugging and profiling.  Thanks for doing
this!

A few thoughts below, and then let's get it landed.

https://codereview.chromium.org/498883002/diff/60001/content/browser/frame_ho...
File content/browser/frame_host/render_frame_host_impl.cc (right):

https://codereview.chromium.org/498883002/diff/60001/content/browser/frame_ho...
content/browser/frame_host/render_frame_host_impl.cc:690: // The end of the
trace event is in OnSwapOutACK for when the RenderFrame
nit: The end of this 
nit: for when -> when

https://codereview.chromium.org/498883002/diff/60001/content/browser/frame_ho...
content/browser/frame_host/render_frame_host_impl.cc:692: // In the case of
timeout on running the unload handler
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.

https://codereview.chromium.org/498883002/diff/60001/content/browser/frame_ho...
content/browser/frame_host/render_frame_host_impl.cc:804:
TRACE_EVENT_ASYNC_END0("navigation", "RenderFrameHostImpl::SwapOut", this);
Actually, if we put this in RFHI::OnSwappedOut below, does that solve the
timeout issue?  Or does the timer call the RVHI version directly?

https://codereview.chromium.org/498883002/diff/60001/content/browser/frame_ho...
content/browser/frame_host/render_frame_host_impl.cc:1067:
TRACE_EVENT0("navigation", "RenderFrameHostImpl::Navigate");
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.)

https://codereview.chromium.org/498883002/diff/60001/content/browser/frame_ho...
File content/browser/frame_host/render_frame_host_manager.cc (left):

https://codereview.chromium.org/498883002/diff/60001/content/browser/frame_ho...
content/browser/frame_host/render_frame_host_manager.cc:191:
TRACE_EVENT0("browser", "RenderFrameHostManager:Navigate");
I think it's better to keep this one than UpdateStateForNavigate, since this
includes all of the latter.

https://codereview.chromium.org/498883002/diff/60001/content/browser/frame_ho...
File content/browser/frame_host/render_frame_host_manager.cc (right):

https://codereview.chromium.org/498883002/diff/60001/content/browser/frame_ho...
content/browser/frame_host/render_frame_host_manager.cc:1451:
"RenderFrameHostManager::UpdateStateForNavigate:New SiteInstance",
Is this just so that we mark the cases that we have a cross-process navigation
in the trace?  Seems ok to me.

https://codereview.chromium.org/498883002/diff/60001/content/browser/loader/c...
File content/browser/loader/cross_site_resource_handler.cc (right):

https://codereview.chromium.org/498883002/diff/60001/content/browser/loader/c...
content/browser/loader/cross_site_resource_handler.cc:297: "navigation",
"CrossSiteResourceHandler::StartCrossSiteTransition", this);
What's the usual naming scheme for events with begin and end?  Is it usually the
method name that started it, or more of a semantic name like
"CrossSiteResourceHandler transition"?  I ask because it's currently ambiguous
in the trace diagram whether this is a really long-running method or an event
with separate begin and end events.

https://codereview.chromium.org/498883002/diff/60001/content/browser/web_cont...
File content/browser/web_contents/web_contents_impl.cc (right):

https://codereview.chromium.org/498883002/diff/60001/content/browser/web_cont...
content/browser/web_contents/web_contents_impl.cc:460:
TRACE_EVENT0("browser,navigation", "WebContentsImpl::CreateWithOpener");
Why is this a navigation event?

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

Fixes in. Feel free to check the CQ if it looks good.

https://codereview.chromium.org/498883002/diff/60001/content/browser/frame_ho...
File content/browser/frame_host/render_frame_host_impl.cc (right):

https://codereview.chromium.org/498883002/diff/60001/content/browser/frame_ho...
content/browser/frame_host/render_frame_host_impl.cc:690: // The end of the
trace event is in OnSwapOutACK for when the RenderFrame
On 2014/08/27 22:05:12, Charlie Reis wrote:
> nit: The end of this 
> nit: for when -> when

Done.

https://codereview.chromium.org/498883002/diff/60001/content/browser/frame_ho...
content/browser/frame_host/render_frame_host_impl.cc:692: // In the case of
timeout on running the unload handler
On 2014/08/27 22:05:12, Charlie Reis wrote:
> 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.

Sure! Thanks for rewriting it more concisely.

https://codereview.chromium.org/498883002/diff/60001/content/browser/frame_ho...
content/browser/frame_host/render_frame_host_impl.cc:804:
TRACE_EVENT_ASYNC_END0("navigation", "RenderFrameHostImpl::SwapOut", this);
On 2014/08/27 22:05:13, Charlie Reis wrote:
> Actually, if we put this in RFHI::OnSwappedOut below, does that solve the
> timeout issue?  Or does the timer call the RVHI version directly?

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

https://codereview.chromium.org/498883002/diff/60001/content/browser/frame_ho...
content/browser/frame_host/render_frame_host_impl.cc:1067:
TRACE_EVENT0("navigation", "RenderFrameHostImpl::Navigate");
On 2014/08/27 22:05:12, Charlie Reis wrote:
> 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.)

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

https://codereview.chromium.org/498883002/diff/60001/content/browser/frame_ho...
File content/browser/frame_host/render_frame_host_manager.cc (left):

https://codereview.chromium.org/498883002/diff/60001/content/browser/frame_ho...
content/browser/frame_host/render_frame_host_manager.cc:191:
TRACE_EVENT0("browser", "RenderFrameHostManager:Navigate");
On 2014/08/27 22:05:13, Charlie Reis wrote:
> I think it's better to keep this one than UpdateStateForNavigate, since this
> includes all of the latter.

Done.

https://codereview.chromium.org/498883002/diff/60001/content/browser/frame_ho...
File content/browser/frame_host/render_frame_host_manager.cc (right):

https://codereview.chromium.org/498883002/diff/60001/content/browser/frame_ho...
content/browser/frame_host/render_frame_host_manager.cc:1451:
"RenderFrameHostManager::UpdateStateForNavigate:New SiteInstance",
On 2014/08/27 22:05:13, Charlie Reis wrote:
> Is this just so that we mark the cases that we have a cross-process navigation
> in the trace?  Seems ok to me.

Yes. Also to log the new SiteInstance ID, in case we want to do correlation
later.

https://codereview.chromium.org/498883002/diff/60001/content/browser/loader/c...
File content/browser/loader/cross_site_resource_handler.cc (right):

https://codereview.chromium.org/498883002/diff/60001/content/browser/loader/c...
content/browser/loader/cross_site_resource_handler.cc:297: "navigation",
"CrossSiteResourceHandler::StartCrossSiteTransition", this);
On 2014/08/27 22:05:13, Charlie Reis wrote:
> What's the usual naming scheme for events with begin and end?  Is it usually
the
> method name that started it, or more of a semantic name like
> "CrossSiteResourceHandler transition"?  I ask because it's currently ambiguous
> in the trace diagram whether this is a really long-running method or an event
> with separate begin and end events.

The title of the event (second param) is free form. I kept it to method names,
but we can change it to anything we want if it makes more sense.

https://codereview.chromium.org/498883002/diff/60001/content/browser/web_cont...
File content/browser/web_contents/web_contents_impl.cc (right):

https://codereview.chromium.org/498883002/diff/60001/content/browser/web_cont...
content/browser/web_contents/web_contents_impl.cc:460:
TRACE_EVENT0("browser,navigation", "WebContentsImpl::CreateWithOpener");
On 2014/08/27 22:05:13, Charlie Reis wrote:
> Why is this a navigation event?

Done.

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

LGTM

https://codereview.chromium.org/498883002/diff/60001/content/browser/frame_ho...
File content/browser/frame_host/render_frame_host_impl.cc (right):

https://codereview.chromium.org/498883002/diff/60001/content/browser/frame_ho...
content/browser/frame_host/render_frame_host_impl.cc:804:
TRACE_EVENT_ASYNC_END0("navigation", "RenderFrameHostImpl::SwapOut", this);
On 2014/08/27 23:30:01, nasko wrote:
> On 2014/08/27 22:05:13, Charlie Reis wrote:
> > Actually, if we put this in RFHI::OnSwappedOut below, does that solve the
> > timeout issue?  Or does the timer call the RVHI version directly?
> 
> It calls RVH directly:
>
https://code.google.com/p/chromium/codesearch#chromium/src/content/browser/re...

Acknowledged.

[Charlie Reis, 2014-08-28 16:20:20]

The CQ bit was checked by creis@chromium.org

[commit-bot: I haz the power, 2014-08-28 16:21:05]

CQ is trying da patch. Follow status at
 https://chromium-status.appspot.com/cq/nasko@chromium.org/498883002/80001

[commit-bot: I haz the power, 2014-08-28 17:07:51]

Committed patchset #5 (id:80001) as a237f6b3d2678ea8b3f23b776a149a022e6384a7

[commit-bot: I haz the power, 2014-09-10 03:00:20]

Patchset 5 (id:??) landed as
https://crrev.com/b8744d2cd9eac9af4cb16a83420e79f1684f06c2
Cr-Commit-Position: refs/heads/master@{#292406}