Buffer timing callbacks until timing state converges.

Buffer timing callbacks until timing state converges.

With our recent change to merge paint timings across all frames in
a page, some of the timing ordering assumptions we make, such as 
parse and layout always starting before paint, can be violated.

More specifically, we can observe sequences like the following:
* parse starts in main frame
* child frame created
* child frame paints
* child frame reports paint event
* parent frame reports parse start event

Even though the events happened in the expected order, due to cross
frame buffering, we are notified of the child paint before the 
main frame parse start.

This change addresses this issue, by buffering observer callbacks until
we've received events with the expected ordering.

zhenw's recent change https://codereview.chromium.org/2872793002 encountered
this issue and had to be rolled back as a result.

I confirmed that, with zhen's patch applied, the flaky test failed on 8 of
10 runs. With zhen's patch and this patch applied, that same test passed 10
of 10 times.

BUG=722860
Review-Url: https://codereview.chromium.org/2885053002
Cr-Commit-Position: refs/heads/master@{#472199}
Committed: https://chromium.googlesource.com/chromium/src/+/8a886995ef55f7c165f50a27a309761c7432bc2c

[Bryan McQuade, 2017-05-16 15:13:42]

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

[commit-bot: I haz the power, 2017-05-16 15:14:06]

Dry run: CQ is trying da patch.

Follow status at:
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[Bryan McQuade, 2017-05-16 15:29:07]

Description was changed from

==========
Buffer timing callbacks until timing state converges.

BUG=
==========

to

==========
Buffer timing callbacks until timing state converges.

With our recent change to merge paint timings across all frames in
a page, some of the timing ordering assumptions we make, such as 
parse and layout always starting before paint, can be violated.

More specifically, we can observe sequences like the following:
* parse starts in main frame
* child frame created
* child frame paints
* child frame reports paint event
* parent frame reports parse start event

Even though the events happened in the expected order, due to cross
frame buffering, we are notified of the child paint before the 
main frame parse start.

This change addresses this issue, by buffering observer callbacks until
we've received events with the expected ordering.

zhenw's recent change https://codereview.chromium.org/2872793002 encountered
this issue and had to be rolled back as a result.

I confirmed that, with zhen's patch applied, the flaky test failed on 8 of
10 runs. With zhen's patch and this patch applied, that same test passed 10
of 10 times.

BUG=722860
==========

[Bryan McQuade, 2017-05-16 15:36:34]

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

[commit-bot: I haz the power, 2017-05-16 15:36:52]

Dry run: CQ is trying da patch.

Follow status at:
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[Bryan McQuade, 2017-05-16 15:38:26]

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

[Bryan McQuade, 2017-05-16 15:38:39]

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

[Bryan McQuade, 2017-05-16 15:38:57]

jkarlin, PTAL for page_load_metrics, thanks!
isherman, PTAL for histograms.xml, thanks!

[jkarlin, 2017-05-16 15:40:50]

I think this warrants some tests.

[Bryan McQuade, 2017-05-16 16:06:12]

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

[commit-bot: I haz the power, 2017-05-16 16:06:36]

Dry run: CQ is trying da patch.

Follow status at:
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[Bryan McQuade, 2017-05-16 16:06:41]

On 2017/05/16 at 15:40:50, jkarlin wrote:
> I think this warrants some tests.

Yes, makes sense. I'd verified that the browser test that was failing no longer
fails, but we should have our own tests for this as well. Added a unit test.
PTAL, thanks!

[jkarlin, 2017-05-16 16:23:11]

https://codereview.chromium.org/2885053002/diff/40001/chrome/browser/page_loa...
File chrome/browser/page_load_metrics/metrics_web_contents_observer_unittest.cc
(right):

https://codereview.chromium.org/2885053002/diff/40001/chrome/browser/page_loa...
chrome/browser/page_load_metrics/metrics_web_contents_observer_unittest.cc:711:
TEST_F(MetricsWebContentsObserverTest, OutOfOrderCrossFrameTiming) {
Please add a comment that links to the crbug that instigated this change.

https://codereview.chromium.org/2885053002/diff/40001/chrome/browser/page_loa...
File chrome/browser/page_load_metrics/page_load_tracker.cc (right):

https://codereview.chromium.org/2885053002/diff/40001/chrome/browser/page_loa...
chrome/browser/page_load_metrics/page_load_tracker.cc:774: observer.get(),
last_dispatched_merged_page_timing_,
Do you really want to dispatch the last observed timings? I figured you'd want
to dispatch the new ones here.

[Bryan McQuade, 2017-05-16 16:32:59]

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

[Bryan McQuade, 2017-05-16 16:33:48]

https://codereview.chromium.org/2885053002/diff/40001/chrome/browser/page_loa...
File chrome/browser/page_load_metrics/metrics_web_contents_observer_unittest.cc
(right):

https://codereview.chromium.org/2885053002/diff/40001/chrome/browser/page_loa...
chrome/browser/page_load_metrics/metrics_web_contents_observer_unittest.cc:711:
TEST_F(MetricsWebContentsObserverTest, OutOfOrderCrossFrameTiming) {
On 2017/05/16 at 16:23:11, jkarlin wrote:
> Please add a comment that links to the crbug that instigated this change.

Done

https://codereview.chromium.org/2885053002/diff/40001/chrome/browser/page_loa...
File chrome/browser/page_load_metrics/page_load_tracker.cc (right):

https://codereview.chromium.org/2885053002/diff/40001/chrome/browser/page_loa...
chrome/browser/page_load_metrics/page_load_tracker.cc:774: observer.get(),
last_dispatched_merged_page_timing_,
On 2017/05/16 at 16:23:11, jkarlin wrote:
> Do you really want to dispatch the last observed timings? I figured you'd want
to dispatch the new ones here.

DispatchObserverTimingCallbacks takes both the old and new timing so it can diff
them and only dispatch callbacks for values that changed. There should be no
behavior change here (see in the old code that we passed 'last_timing' in this
param).

[commit-bot: I haz the power, 2017-05-16 16:34:16]

Dry run: CQ is trying da patch.

Follow status at:
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[jkarlin, 2017-05-16 17:07:14]

lgtm

https://codereview.chromium.org/2885053002/diff/40001/chrome/browser/page_loa...
File chrome/browser/page_load_metrics/page_load_tracker.cc (right):

https://codereview.chromium.org/2885053002/diff/40001/chrome/browser/page_loa...
chrome/browser/page_load_metrics/page_load_tracker.cc:774: observer.get(),
last_dispatched_merged_page_timing_,
On 2017/05/16 16:33:48, Bryan McQuade wrote:
> On 2017/05/16 at 16:23:11, jkarlin wrote:
> > Do you really want to dispatch the last observed timings? I figured you'd
want
> to dispatch the new ones here.
> 
> DispatchObserverTimingCallbacks takes both the old and new timing so it can
diff
> them and only dispatch callbacks for values that changed. There should be no
> behavior change here (see in the old code that we passed 'last_timing' in this
> param).

Completely missed that merged_paint_timing_ was going through as well. Looks
good.

[commit-bot: I haz the power, 2017-05-16 18:37:03]

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

[commit-bot: I haz the power, 2017-05-16 18:37:04]

Dry run: This issue passed the CQ dry run.

[Steven Holte, 2017-05-16 19:37:21]

holte@chromium.org changed reviewers:
+ holte@chromium.org

[Steven Holte, 2017-05-16 19:37:22]

histograms lgtm

[Bryan McQuade, 2017-05-16 19:45:31]

The CQ bit was checked by bmcquade@chromium.org

[commit-bot: I haz the power, 2017-05-16 19:46:55]

CQ is trying da patch.

Follow status at:
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2017-05-16 20:09:47]

CQ is committing da patch.

Bot data: {"patchset_id": 60001, "attempt_start_ts": 1494963931899560,
"parent_rev": "f2db02a021e6a68054c3f8a0fef88ce6584ad9af", "commit_rev":
"8a886995ef55f7c165f50a27a309761c7432bc2c"}

[commit-bot: I haz the power, 2017-05-16 20:09:59]

Description was changed from

==========
Buffer timing callbacks until timing state converges.

With our recent change to merge paint timings across all frames in
a page, some of the timing ordering assumptions we make, such as 
parse and layout always starting before paint, can be violated.

More specifically, we can observe sequences like the following:
* parse starts in main frame
* child frame created
* child frame paints
* child frame reports paint event
* parent frame reports parse start event

Even though the events happened in the expected order, due to cross
frame buffering, we are notified of the child paint before the 
main frame parse start.

This change addresses this issue, by buffering observer callbacks until
we've received events with the expected ordering.

zhenw's recent change https://codereview.chromium.org/2872793002 encountered
this issue and had to be rolled back as a result.

I confirmed that, with zhen's patch applied, the flaky test failed on 8 of
10 runs. With zhen's patch and this patch applied, that same test passed 10
of 10 times.

BUG=722860
==========

to

==========
Buffer timing callbacks until timing state converges.

With our recent change to merge paint timings across all frames in
a page, some of the timing ordering assumptions we make, such as 
parse and layout always starting before paint, can be violated.

More specifically, we can observe sequences like the following:
* parse starts in main frame
* child frame created
* child frame paints
* child frame reports paint event
* parent frame reports parse start event

Even though the events happened in the expected order, due to cross
frame buffering, we are notified of the child paint before the 
main frame parse start.

This change addresses this issue, by buffering observer callbacks until
we've received events with the expected ordering.

zhenw's recent change https://codereview.chromium.org/2872793002 encountered
this issue and had to be rolled back as a result.

I confirmed that, with zhen's patch applied, the flaky test failed on 8 of
10 runs. With zhen's patch and this patch applied, that same test passed 10
of 10 times.

BUG=722860

Review-Url: https://codereview.chromium.org/2885053002
Cr-Commit-Position: refs/heads/master@{#472199}
Committed:
https://chromium.googlesource.com/chromium/src/+/8a886995ef55f7c165f50a27a309...
==========

[commit-bot: I haz the power, 2017-05-16 20:10:00]

Committed patchset #4 (id:60001) as
https://chromium.googlesource.com/chromium/src/+/8a886995ef55f7c165f50a27a309...