Navigation start to commit trace

content/browser/frame_host/navigation_handle_impl.cc

 // Copyright 2015 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_handle_impl.h"
 
 #include <utility>
 
 #include "content/browser/frame_host/frame_tree_node.h"
 #include "content/browser/frame_host/navigator.h"
@@ skipping 51 matching lines @@
       was_redirected_(false),
       state_(INITIAL),
       is_transferring_(false),
       frame_tree_node_(frame_tree_node),
       next_index_(0),
       navigation_start_(navigation_start),
       pending_nav_entry_id_(pending_nav_entry_id),
       is_in_commit_(false) {
   DCHECK(!navigation_start.is_null());
   GetDelegate()->DidStartNavigation(this);
+
+  if (IsInMainFrame()) {
+    TRACE_EVENT_ASYNC_BEGIN_WITH_TIMESTAMP1(
+        "navigation", "Navigation StartToCommit", this,
+        navigation_start.ToInternalValue(), "URL", url_.spec());

[clamy, 2016/03/23 12:12:16]

Are you trying to index the navigation using the url? The url may change between
the start and the commit of a navigation if it encounters a server redirect. I
suggest you use the FrameTreeNode id instead, which is guaranteed to be constant
over the whole navigation.

[Bryan McQuade, 2016/03/23 12:17:33]

That's a good point. We shouldn't assume the URL is fixed for the duration of
the navigation. I do think it's also valuable to record the URL that the
navigation was initiated with, and then perhaps separately in a different trace
record the redirected URL and/or the committed URL. Perhaps we should use the
argument name provisional_url rather than url here to reflect that this is the
initial URL during the navigation and may change?

[shivanisha, 2016/03/23 13:56:09]

the navigation handle pointer is the index here and not the url . The URL is
just an argument. Since the Navigation handle pointer remains the same
throughout the navigation, this should be fine. Having said that, if
FrameTreeNode id is also visible to network level traces (that might be added in
a future enhancement) then may be I can index these traces with FrameTreeNode id
so that it is easier to link with those future traces. I will look into this.

Agree with Bryan's suggestion of changing the URL argument to provisional_url

[carlosk, 2016/03/23 14:40:34]

Mind that there can be 2 simultaneously ongoing navigations happening on the
same frame (one must be same site and the other cross-site) and so you can have
mixed up traces. Granted this might be an considered a non-supported exception
case but it can happen.

I tried to avoid it in my implementation but it does indeed make things simpler
to match async traces inserted in different parts of the code, when one does not
have a pointer to the NavigationHandle.

FYI in regards to redirects and changes to the URL I'd like to point you to the
doc I wrote when I was creating those traces for our benchmark: 
https://docs.google.com/document/d/1dyJejYZouBwyL6lCd5IJ3nU74lQKtCPra0M5tXrbI...
It describes what each trace would record and one of the things I tried to make
sure was that in the end all URL changes were tracked.

[shivanisha, 2016/03/23 18:07:08]

That's a good point that if we use frameTreeNode id then it can lead to mixed
traces between two navigations in the same frame. So , leaving it as it is be
indexed by Navigation Handle pointer.

I understand from the design doc that the redirect delays for PlzNavigate are
being traced currently. As you mention in the design doc at a later stage it
could be extended for both navigation flows.
(Mentioning here for completeness, my change will show Navigation Start to
Commit time which includes any redirect delays as well.)

[clamy, 2016/03/24 10:36:32]

Indexing on the NavigationHandle is good (I was worried you were doing it on the
url, which would have been a problem).

You can track the time to redirects in both navigation paths by putting traces
in NavigationHandleImpl::WillRedirectRequest.

[shivanisha, 2016/03/29 19:49:32]

Actually since we are logging the URL in the end trace as well, it will have the
updated value of the URL in case there was a redirect so leaving the name as URL

[carlosk, 2016/03/31 10:10:29]

IIUC there's no much use in doing that. The END url recording will (I think)
override the former and as the trace itself will not exist without the END step,
the URL recording in BEGIN would be always overwritten.

My suggestion is to record both but with different labels.

[shivanisha, 2016/04/12 14:10:03]

Applying 2 different labels is making things clear. Here is an example of a
redirected navigation. Note I have named the beginning url as "Initial URL" and
committed url as "URL":

Title	Navigation StartToCommit
Category	navigation
Start	14,126.555 ms
Wall Duration	549.542 ms
▶Args	
Initial URL	"http://mit.edu/"
URL	"http://web.mit.edu/"
Net Error Code	0

+  }
 }
 
 NavigationHandleImpl::~NavigationHandleImpl() {
   GetDelegate()->DidFinishNavigation(this);
 
   CHECK(!is_in_commit_);
 
   // Cancel the navigation on the IO thread if the NavigationHandle is being
   // destroyed in the middle of the NavigationThrottles checks.
   if (!IsBrowserSideNavigationEnabled() && !complete_callback_.is_null())
     RunCompleteCallback(NavigationThrottle::CANCEL_AND_IGNORE);
+
+  if (IsInMainFrame()) {
+    TRACE_EVENT_ASYNC_END2("navigation", "Navigation StartToCommit", this,
+                           "URL", url_.spec(), "Net Error Code",

[clamy, 2016/03/23 12:12:16]

You may also want to add a boolean to check whether the navigation resulted in a
commit (page or error page), or whether it was aborted before commit.

[shivanisha, 2016/03/23 13:56:09]

Sure, that sounds good

[shivanisha, 2016/03/29 19:49:32]

Actually, it seems we can assume that net error code of 0 will imply a committed
page. May be then we do not need the boolean?

+                           net_error_code_);
+  }
 }
 
 NavigatorDelegate* NavigationHandleImpl::GetDelegate() const {
   return frame_tree_node_->navigator()->GetDelegate();
 }
 
 const GURL& NavigationHandleImpl::GetURL() {
   return url_;
 }
 
@@ skipping 394 matching lines @@
   complete_callback_.Reset();
 
   if (!callback.is_null())
     callback.Run(result);
 
   // No code after running the callback, as it might have resulted in our
   // destruction.
 }
 
 }  // namespace content