Allow TimeTicks for serialized page load operations to be equal.

Allow TimeTicks for serialized page load operations to be equal.

This CL fixes an issue seen on the GCE bots whereby the result of two
base::TimeTicks::Now() calls can return the same value even if
separated by several instructions, due to the clock on GCE being
less fine grained.

Previously a time_to_commit of zero meant that the transaction had
not been committed successfully, now this information is carried in
a separate bool and checked independently.

BUG=596367

[Charlie Harrison, 2016-03-22 14:10:13]

csharrison@chromium.org changed reviewers:
+ bmcquade@chromium.org, csharrison@chromium.org

[Charlie Harrison, 2016-03-22 14:10:13]

I patched this CL locally and changed TimeTicks::Now to return a constant. I
found the same test failures as you did in GCE.

Replacing the <= with < caused all tests to pass. Thanks for writing up this
patch.

https://codereview.chromium.org/1817263003/diff/1/components/page_load_metric...
File components/page_load_metrics/browser/metrics_web_contents_observer.cc
(right):

https://codereview.chromium.org/1817263003/diff/1/components/page_load_metric...
components/page_load_metrics/browser/metrics_web_contents_observer.cc:407: if
(timestamp <= navigation_start_) {
Change to <

https://codereview.chromium.org/1817263003/diff/1/components/page_load_metric...
File components/page_load_metrics/browser/page_load_metrics_observer.h (right):

https://codereview.chromium.org/1817263003/diff/1/components/page_load_metric...
components/page_load_metrics/browser/page_load_metrics_observer.h:79: const bool
committed;
Can you add:
TODO(csharrison): Consider removing this in favor of Option<time_to_commit>.

[Will Harris, 2016-03-22 18:13:17]

done. PTAL. thanks for fix :)

I've run this manually on the Win10 GCE and it passes:

https://chromium-swarm-dev.appspot.com/user/task/2db83e064dea5410

https://codereview.chromium.org/1817263003/diff/1/components/page_load_metric...
File components/page_load_metrics/browser/metrics_web_contents_observer.cc
(right):

https://codereview.chromium.org/1817263003/diff/1/components/page_load_metric...
components/page_load_metrics/browser/metrics_web_contents_observer.cc:407: if
(timestamp <= navigation_start_) {
On 2016/03/22 14:10:13, csharrison wrote:
> Change to <

Done.

https://codereview.chromium.org/1817263003/diff/1/components/page_load_metric...
File components/page_load_metrics/browser/page_load_metrics_observer.h (right):

https://codereview.chromium.org/1817263003/diff/1/components/page_load_metric...
components/page_load_metrics/browser/page_load_metrics_observer.h:79: const bool
committed;
On 2016/03/22 14:10:13, csharrison wrote:
> Can you add:
> TODO(csharrison): Consider removing this in favor of Option<time_to_commit>.

Done.

[Will Harris, 2016-03-22 18:15:18]

Description was changed from

==========
WIP fix timings

BUG=596367
==========

to

==========
Allow TimeTicks for serialized page load operations to be equal.

This CL fixes an issue seen on the GCE bots whereby the result of two
base::TimeTicks::Now() calls can return the same value even if
separated by several instructions, due to the clock on GCE being
less fine grained.

Previously a time_to_commit of zero meant that the transaction had
not been committed successfully, now this information is carried in
a separate bool and checked independently.

BUG=596367
==========

[Charlie Harrison, 2016-03-22 18:26:30]

Looks good. One more cleanup that I missed in the first round.

https://codereview.chromium.org/1817263003/diff/20001/chrome/browser/page_loa...
File
chrome/browser/page_load_metrics/observers/core_page_load_metrics_observer.cc
(right):

https://codereview.chromium.org/1817263003/diff/20001/chrome/browser/page_loa...
chrome/browser/page_load_metrics/observers/core_page_load_metrics_observer.cc:164:
if (info.started_in_foreground && (info.first_background_time.is_zero() ||
This is... very unfortunate.

I think I would prefer adding "|| (info.time_to_commit.is_zero() &&
info.committed)" with a TODO to clean up the tests that depend on this.

[Will Harris, 2016-03-22 18:28:55]

https://codereview.chromium.org/1817263003/diff/20001/chrome/browser/page_loa...
File
chrome/browser/page_load_metrics/observers/core_page_load_metrics_observer.cc
(right):

https://codereview.chromium.org/1817263003/diff/20001/chrome/browser/page_loa...
chrome/browser/page_load_metrics/observers/core_page_load_metrics_observer.cc:164:
if (info.started_in_foreground && (info.first_background_time.is_zero() ||
On 2016/03/22 18:26:29, csharrison wrote:
> This is... very unfortunate.
> 
> I think I would prefer adding "|| (info.time_to_commit.is_zero() &&
> info.committed)" with a TODO to clean up the tests that depend on this.

info.committed is already true otherwise we would have returned on line 162

[Charlie Harrison, 2016-03-22 18:32:05]

https://codereview.chromium.org/1817263003/diff/20001/chrome/browser/page_loa...
File
chrome/browser/page_load_metrics/observers/core_page_load_metrics_observer.cc
(right):

https://codereview.chromium.org/1817263003/diff/20001/chrome/browser/page_loa...
chrome/browser/page_load_metrics/observers/core_page_load_metrics_observer.cc:164:
if (info.started_in_foreground && (info.first_background_time.is_zero() ||
On 2016/03/22 at 18:28:55, Will Harris wrote:
> On 2016/03/22 18:26:29, csharrison wrote:
> > This is... very unfortunate.
> > 
> > I think I would prefer adding "|| (info.time_to_commit.is_zero() &&
> > info.committed)" with a TODO to clean up the tests that depend on this.
> 
> info.committed is already true otherwise we would have returned on line 162

Right. Then can you just "|| info.time_to_commit.is_zero()" rather than
expanding WasStartedInForegroundEventInForeground"?

[Will Harris, 2016-03-22 19:01:57]

PTAL. Am going to run unit_tests on the win10 GCE bot before committing.

https://codereview.chromium.org/1817263003/diff/20001/chrome/browser/page_loa...
File
chrome/browser/page_load_metrics/observers/core_page_load_metrics_observer.cc
(right):

https://codereview.chromium.org/1817263003/diff/20001/chrome/browser/page_loa...
chrome/browser/page_load_metrics/observers/core_page_load_metrics_observer.cc:164:
if (info.started_in_foreground && (info.first_background_time.is_zero() ||
On 2016/03/22 18:32:05, csharrison wrote:
> On 2016/03/22 at 18:28:55, Will Harris wrote:
> > On 2016/03/22 18:26:29, csharrison wrote:
> > > This is... very unfortunate.
> > > 
> > > I think I would prefer adding "|| (info.time_to_commit.is_zero() &&
> > > info.committed)" with a TODO to clean up the tests that depend on this.
> > 
> > info.committed is already true otherwise we would have returned on line 162
> 
> Right. Then can you just "|| info.time_to_commit.is_zero()" rather than
> expanding WasStartedInForegroundEventInForeground"?

Done.

[Charlie Harrison, 2016-03-22 19:12:30]

lgtm, bmcquade@ can you take a quick look?

[Will Harris, 2016-03-22 19:46:27]

https://codereview.chromium.org/1817263003/diff/20001/chrome/browser/page_loa...
File
chrome/browser/page_load_metrics/observers/aborts_page_load_metrics_observer.cc
(right):

https://codereview.chromium.org/1817263003/diff/20001/chrome/browser/page_loa...
chrome/browser/page_load_metrics/observers/aborts_page_load_metrics_observer.cc:132:
DCHECK(!time_to_abort.is_zero());
this DCHECK seems to still be hitting in unit_tests

[Bryan McQuade, 2016-03-22 20:46:44]

LGTM. Thank you very much for cleaning this up!

https://codereview.chromium.org/1817263003/diff/20001/chrome/browser/page_loa...
File
chrome/browser/page_load_metrics/observers/aborts_page_load_metrics_observer.cc
(right):

https://codereview.chromium.org/1817263003/diff/20001/chrome/browser/page_loa...
chrome/browser/page_load_metrics/observers/aborts_page_load_metrics_observer.cc:132:
DCHECK(!time_to_abort.is_zero());
On 2016/03/22 at 19:46:27, Will Harris wrote:
> this DCHECK seems to still be hitting in unit_tests

Seems like this is also an invalid DCHECK. You can remove it.

[Charlie Harrison, 2016-03-22 20:53:44]

not lgtm we need to find another approach for observers unit tests.

[Will Harris, 2016-03-22 22:13:22]

closing this issue, as we'll take another approach.