Fix incorrect assert in PageLoadTracker.

Fix incorrect assert in PageLoadTracker.

PageLoadTracker::~PageLoadTracker was setting page_end_time_ to Now() if it was null. However, if page_end_reason_ wasn't END_NONE then an assert will file a few lines down when ComputePageLoadExtraInfo is called.

This happened with PlzNavigate after r460581 landed, which sped up browser-initiated loads when there was no beforeunload handler.

This fixes IsolatedAppTest.CrossProcessClientRedirect.

BUG=651844

[jam, 2017-03-31 03:30:54]

The CQ bit was checked by jam@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2017-03-31 03:31:30]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[jam, 2017-03-31 03:39:27]

The CQ bit was checked by jam@chromium.org to run a CQ dry run

[jam, 2017-03-31 03:39:33]

Patchset #1 (id:1) has been deleted

[commit-bot: I haz the power, 2017-03-31 03:39:47]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[jam, 2017-03-31 03:40:20]

Description was changed from

==========
Fix incorrect assert in PageLoadTracker.

PageLoadTracker::~PageLoadTracker was setting page_end_time_ to Now() if it was
null. However, if page_end_reason_ wasn't END_NONE then an assert will file a
few lines down when ComputePageLoadExtraInfo is called.

This happened with PlzNavigate after r460581 landed, which sped up
browser-initiated loads when there was no beforeunload handler.

This fixes IsolatedAppTest.CrossProcessClientRedirect.

BUG=651844
==========

to

==========
Fix incorrect assert in PageLoadTracker.

PageLoadTracker::~PageLoadTracker was setting page_end_time_ to Now() if it was
null. However, if page_end_reason_ wasn't END_NONE then an assert will file a
few lines down when ComputePageLoadExtraInfo is called.

This happened with PlzNavigate after r460581 landed, which sped up
browser-initiated loads when there was no beforeunload handler.

This fixes IsolatedAppTest.CrossProcessClientRedirect.

BUG=651844
==========

[jam, 2017-03-31 03:40:21]

jam@chromium.org changed reviewers:
+ bmcquade@chromium.org

[commit-bot: I haz the power, 2017-03-31 04:34:56]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2017-03-31 04:34:57]

Dry run: This issue passed the CQ dry run.

[Bryan McQuade, 2017-03-31 17:51:33]

On 2017/03/31 at 03:40:35, jam wrote:
> 

Thank you!

It sounds like the issue here is that under some cases, in OOPIF, we see pages
where UpdatePageEndInternal is invoked with a timestamp before navigation start,
which resets the end time and reason, and then in the destructor we set
page_end_time_ to a timestamp which causes the DCHECK to fire in
ComputePageLoadExtraInfo. jam does that sound right?

If so, I do think we need to fix this, but I'm not yet sure what the right fix
is. I'm going to spend some time understanding
1. why we sometimes get a page end time *before* nav start (seems like a bug
somewhere)
2. what we should be doing differently in the destructor (likely setting
page_end_reason_ to END_OTHER when we set the page_end_time_

Thanks again for digging into this.
-bryan

[Bryan McQuade, 2017-03-31 18:07:44]

On 2017/03/31 at 17:51:33, Bryan McQuade wrote:
> On 2017/03/31 at 03:40:35, jam wrote:
> > 
> 
> Thank you!
> 
> It sounds like the issue here is that under some cases, in OOPIF, we see pages
where UpdatePageEndInternal is invoked with a timestamp before navigation start,
which resets the end time and reason, and then in the destructor we set
page_end_time_ to a timestamp which causes the DCHECK to fire in
ComputePageLoadExtraInfo. jam does that sound right?
> 
> If so, I do think we need to fix this, but I'm not yet sure what the right fix
is. I'm going to spend some time understanding
> 1. why we sometimes get a page end time *before* nav start (seems like a bug
somewhere)
> 2. what we should be doing differently in the destructor (likely setting
page_end_reason_ to END_OTHER when we set the page_end_time_
> 
> Thanks again for digging into this.
> -bryan

BTW r460581 looks like a great perf improvement. Thanks for driving that
forward!

[jam, 2017-03-31 19:17:02]

On 2017/03/31 17:51:33, Bryan McQuade wrote:
> On 2017/03/31 at 03:40:35, jam wrote:
> > 
> 
> Thank you!
> 
> It sounds like the issue here is that under some cases, in OOPIF, we see pages
> where UpdatePageEndInternal is invoked with a timestamp before navigation
start,
> which resets the end time and reason, and then in the destructor we set
> page_end_time_ to a timestamp which causes the DCHECK to fire in
> ComputePageLoadExtraInfo. jam does that sound right?

Yep
it should be possible to repro this pretty consistently locally.

> 
> If so, I do think we need to fix this, but I'm not yet sure what the right fix
> is. I'm going to spend some time understanding
> 1. why we sometimes get a page end time *before* nav start (seems like a bug
> somewhere)
> 2. what we should be doing differently in the destructor (likely setting
> page_end_reason_ to END_OTHER when we set the page_end_time_
> 
> Thanks again for digging into this.
> -bryan

[Bryan McQuade, 2017-04-03 17:08:55]

On 2017/03/31 at 19:17:02, jam wrote:
> On 2017/03/31 17:51:33, Bryan McQuade wrote:
> > On 2017/03/31 at 03:40:35, jam wrote:
> > > 
> > 
> > Thank you!
> > 
> > It sounds like the issue here is that under some cases, in OOPIF, we see
pages
> > where UpdatePageEndInternal is invoked with a timestamp before navigation
start,
> > which resets the end time and reason, and then in the destructor we set
> > page_end_time_ to a timestamp which causes the DCHECK to fire in
> > ComputePageLoadExtraInfo. jam does that sound right?
> 
> Yep
> it should be possible to repro this pretty consistently locally.
> 
> > 
> > If so, I do think we need to fix this, but I'm not yet sure what the right
fix
> > is. I'm going to spend some time understanding
> > 1. why we sometimes get a page end time *before* nav start (seems like a bug
> > somewhere)
> > 2. what we should be doing differently in the destructor (likely setting
> > page_end_reason_ to END_OTHER when we set the page_end_time_
> > 
> > Thanks again for digging into this.
> > -bryan

Just a quick update here: I'm working on a slightly different fix for this - I
hope to have it in review tomorrow.

[Bryan McQuade, 2017-04-04 16:08:28]

On 2017/04/03 at 17:08:55, Bryan McQuade wrote:
> On 2017/03/31 at 19:17:02, jam wrote:
> > On 2017/03/31 17:51:33, Bryan McQuade wrote:
> > > On 2017/03/31 at 03:40:35, jam wrote:
> > > > 
> > > 
> > > Thank you!
> > > 
> > > It sounds like the issue here is that under some cases, in OOPIF, we see
pages
> > > where UpdatePageEndInternal is invoked with a timestamp before navigation
start,
> > > which resets the end time and reason, and then in the destructor we set
> > > page_end_time_ to a timestamp which causes the DCHECK to fire in
> > > ComputePageLoadExtraInfo. jam does that sound right?
> > 
> > Yep
> > it should be possible to repro this pretty consistently locally.
> > 
> > > 
> > > If so, I do think we need to fix this, but I'm not yet sure what the right
fix
> > > is. I'm going to spend some time understanding
> > > 1. why we sometimes get a page end time *before* nav start (seems like a
bug
> > > somewhere)
> > > 2. what we should be doing differently in the destructor (likely setting
> > > page_end_reason_ to END_OTHER when we set the page_end_time_
> > > 
> > > Thanks again for digging into this.
> > > -bryan
> 
> Just a quick update here: I'm working on a slightly different fix for this - I
hope to have it in review tomorrow.

FYI the alternative fix can be found here:
https://codereview.chromium.org/2794603002 - I'm waiting to figure out how to
repro the original flake before I move forward, so I can be certain my fix
addresses the issue. Please see my last comment in the bug for this issue for
questions on how to properly repro. Thanks!

[Bryan McQuade, 2017-04-10 13:38:27]

On 2017/04/04 at 16:08:28, Bryan McQuade wrote:
> On 2017/04/03 at 17:08:55, Bryan McQuade wrote:
> > On 2017/03/31 at 19:17:02, jam wrote:
> > > On 2017/03/31 17:51:33, Bryan McQuade wrote:
> > > > On 2017/03/31 at 03:40:35, jam wrote:
> > > > > 
> > > > 
> > > > Thank you!
> > > > 
> > > > It sounds like the issue here is that under some cases, in OOPIF, we see
pages
> > > > where UpdatePageEndInternal is invoked with a timestamp before
navigation start,
> > > > which resets the end time and reason, and then in the destructor we set
> > > > page_end_time_ to a timestamp which causes the DCHECK to fire in
> > > > ComputePageLoadExtraInfo. jam does that sound right?
> > > 
> > > Yep
> > > it should be possible to repro this pretty consistently locally.
> > > 
> > > > 
> > > > If so, I do think we need to fix this, but I'm not yet sure what the
right fix
> > > > is. I'm going to spend some time understanding
> > > > 1. why we sometimes get a page end time *before* nav start (seems like a
bug
> > > > somewhere)
> > > > 2. what we should be doing differently in the destructor (likely setting
> > > > page_end_reason_ to END_OTHER when we set the page_end_time_
> > > > 
> > > > Thanks again for digging into this.
> > > > -bryan
> > 
> > Just a quick update here: I'm working on a slightly different fix for this -
I hope to have it in review tomorrow.
> 
> FYI the alternative fix can be found here:
https://codereview.chromium.org/2794603002 - I'm waiting to figure out how to
repro the original flake before I move forward, so I can be certain my fix
addresses the issue. Please see my last comment in the bug for this issue for
questions on how to properly repro. Thanks!

The alternative fix for this has been landed, so I'm going to close this out,
thanks!