New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 726387 link

Starred by 1 user

Issue metadata

Status: Fixed
Owner:
Last visit > 30 days ago
Closed: Jun 2017
EstimatedDays: ----
NextAction: ----
OS: ----
Pri: 3
Type: Bug

Blocked on:
issue 728176
issue 728179



Sign in to add a comment

buffer cross-frame paint timing updates in browser process

Project Member Reported by bmcquade@chromium.org, May 25 2017

Issue description

We recently landed a few changes to move us closer to being able to merge cross-frame paint timings in the browser process:

1. zhenw@ fixed a bug where paint timings in child frames where reported in the top frame: https://bugs.chromium.org/p/chromium/issues/detail?id=705315
2. I landed a patch that merges paint timings for all frames in a page when reporting first paints to observers: https://codereview.chromium.org/2859393002

With this change we continue to report page-level first paints however the implementation is somewhat different: instead of merging timings in the render process (due to the bug zhen fixed) we now merge timings reported from different frames in the browser process.

This should be a no-op but there is some risk for timings to arrive out of order - for example we might see:

1. main frame starts parsing
2. main frame sends initial timing update
3. main frame paints
4. main frame schedules a timer to send updated timing to browser process
5. child frame created
6. child frame paints
7. child frame sends initial timing update
8. main frame dispatches timing update

In this case, the browser will most likely receive the paint message for the child frame first, even though the main frame painted first. I expected this to be rare, but metrics suggest that this happens more than I had hoped - it affects about 4% of pages, adding on average 370ms for affected pages, increasing mean TTFP by 15ms across all page loads (on canary, anyway).

So I think we need to fix this, given that it adds a significant delay to mean paint timings.

Observers only want their First*PaintInPage callbacks to be invoked once per page. So if we know that we sometimes receive per-frame first paints out of order, unless we want to complicate observers to understand that this can happen, we probably want to buffer timing updates in the browser process, at the PageLoadTracker level, for a period before dispatching to observers, so we are able to wait to dispatch the real/correct first paint times to observers.

We already have some logic in the browser to buffer timing updates that we know are received out of order before dispatching them to observers. If for example we receive a first paint in a child frame before we'e received first parse in the main frame, we buffer the paint update until we've received the parse update, since observers reasonably assume we can't paint without having started parsing.

I believe what we need to do here is also buffer paint timing updates for a period of time before dispatching to observers, in case we receive subsequent updates for a paint that happened earlier in the page. The UMA suggests that a delay of 1s is reasonable - this makes sense since this is our buffering timer delay in the render process. So I will plan to buffer paint updates for 1s: when we receive our first first paint of a given type (e.g. FP, FCP, FMP, etc) across all frames in the page, we will set a timer for 1s, and dispatch the most recently received PageLoadTiming during that 1s to observers once the timer fires. This allows us to receive out of order updates that arrive up to 1s late, and still report the right page level information to observers. I'll add UMA to see how much this corrects the issue & we can tune the timeout accordingly.

 
Project Member

Comment 1 by bugdroid1@chromium.org, May 31 2017

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/457de7596c43cbce74ea3cbae7d9ab1e93fe9d5a

commit 457de7596c43cbce74ea3cbae7d9ab1e93fe9d5a
Author: bmcquade <bmcquade@chromium.org>
Date: Wed May 31 11:41:06 2017

Buffer cross frame paint timing updates.

With the recent change to merge cross-frame paint timings, we sometimes encounter
cases where these timings arrive out of order.

For example, we may receive a first paint notification for frame A first,
then a first paint notification for frame B, but frame B's first paint
time may have happened before frame A's first paint time.

In the current implementation, we dispatch a first paint notification to observers
as soon as we receive a first paint notification from any frame in the page.

This means we don't end up recording the true page-level first paint time on
all pages.

This change adds a 1s buffering period before we dispatch first paint notifications
to observers. During this buffering period, we accumulate all first paint updates
across all frames, and retain the minimum first paint time. We then dispatch the min
observed first paint time across this window.

This change should significantly reduce the frequency with which we log out of order
paint timings. We have added new UMA to keep track of how often this continues to
happen, even with the 1s buffering.

BUG= 726387 

Review-Url: https://codereview.chromium.org/2901383002
Cr-Commit-Position: refs/heads/master@{#475878}

[modify] https://crrev.com/457de7596c43cbce74ea3cbae7d9ab1e93fe9d5a/chrome/browser/page_load_metrics/metrics_web_contents_observer.cc
[modify] https://crrev.com/457de7596c43cbce74ea3cbae7d9ab1e93fe9d5a/chrome/browser/page_load_metrics/metrics_web_contents_observer.h
[modify] https://crrev.com/457de7596c43cbce74ea3cbae7d9ab1e93fe9d5a/chrome/browser/page_load_metrics/metrics_web_contents_observer_unittest.cc
[modify] https://crrev.com/457de7596c43cbce74ea3cbae7d9ab1e93fe9d5a/chrome/browser/page_load_metrics/observers/page_load_metrics_observer_test_harness.cc
[modify] https://crrev.com/457de7596c43cbce74ea3cbae7d9ab1e93fe9d5a/chrome/browser/page_load_metrics/observers/page_load_metrics_observer_test_harness.h
[modify] https://crrev.com/457de7596c43cbce74ea3cbae7d9ab1e93fe9d5a/chrome/browser/page_load_metrics/page_load_metrics_embedder_interface.h
[modify] https://crrev.com/457de7596c43cbce74ea3cbae7d9ab1e93fe9d5a/chrome/browser/page_load_metrics/page_load_metrics_initialize.cc
[modify] https://crrev.com/457de7596c43cbce74ea3cbae7d9ab1e93fe9d5a/chrome/browser/page_load_metrics/page_load_metrics_update_dispatcher.cc
[modify] https://crrev.com/457de7596c43cbce74ea3cbae7d9ab1e93fe9d5a/chrome/browser/page_load_metrics/page_load_metrics_update_dispatcher.h
[modify] https://crrev.com/457de7596c43cbce74ea3cbae7d9ab1e93fe9d5a/chrome/browser/page_load_metrics/page_load_metrics_util.cc
[modify] https://crrev.com/457de7596c43cbce74ea3cbae7d9ab1e93fe9d5a/chrome/browser/page_load_metrics/page_load_metrics_util.h
[modify] https://crrev.com/457de7596c43cbce74ea3cbae7d9ab1e93fe9d5a/chrome/browser/page_load_metrics/page_load_tracker.cc
[modify] https://crrev.com/457de7596c43cbce74ea3cbae7d9ab1e93fe9d5a/chrome/browser/prerender/prerender_browsertest.cc
[modify] https://crrev.com/457de7596c43cbce74ea3cbae7d9ab1e93fe9d5a/chrome/common/BUILD.gn
[add] https://crrev.com/457de7596c43cbce74ea3cbae7d9ab1e93fe9d5a/chrome/common/page_load_metrics/page_load_metrics_util.cc
[add] https://crrev.com/457de7596c43cbce74ea3cbae7d9ab1e93fe9d5a/chrome/common/page_load_metrics/page_load_metrics_util.h
[add] https://crrev.com/457de7596c43cbce74ea3cbae7d9ab1e93fe9d5a/chrome/common/page_load_metrics/test/page_load_metrics_test_util.cc
[add] https://crrev.com/457de7596c43cbce74ea3cbae7d9ab1e93fe9d5a/chrome/common/page_load_metrics/test/page_load_metrics_test_util.h
[add] https://crrev.com/457de7596c43cbce74ea3cbae7d9ab1e93fe9d5a/chrome/common/page_load_metrics/test/weak_mock_timer.cc
[add] https://crrev.com/457de7596c43cbce74ea3cbae7d9ab1e93fe9d5a/chrome/common/page_load_metrics/test/weak_mock_timer.h
[modify] https://crrev.com/457de7596c43cbce74ea3cbae7d9ab1e93fe9d5a/chrome/renderer/page_load_metrics/metrics_render_frame_observer.cc
[modify] https://crrev.com/457de7596c43cbce74ea3cbae7d9ab1e93fe9d5a/chrome/renderer/page_load_metrics/metrics_render_frame_observer.h
[modify] https://crrev.com/457de7596c43cbce74ea3cbae7d9ab1e93fe9d5a/chrome/renderer/page_load_metrics/metrics_render_frame_observer_unittest.cc
[modify] https://crrev.com/457de7596c43cbce74ea3cbae7d9ab1e93fe9d5a/chrome/test/BUILD.gn
[modify] https://crrev.com/457de7596c43cbce74ea3cbae7d9ab1e93fe9d5a/tools/metrics/histograms/histograms.xml

Project Member

Comment 2 by bugdroid1@chromium.org, May 31 2017

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/a49b11bb29ce7018da6f440703ec983009c98cc5

commit a49b11bb29ce7018da6f440703ec983009c98cc5
Author: Mathieu Perreault <mathp@chromium.org>
Date: Wed May 31 14:22:04 2017

Revert "Buffer cross frame paint timing updates."

This reverts commit 457de7596c43cbce74ea3cbae7d9ab1e93fe9d5a.

Suspected for browsertest failures: https://build.chromium.org/p/chromium.win/builders/Win7%20Tests%20%28dbg%29%281%29/builds/60448

TBR=isherman,mattcary,csharrison

Bug:  726387 
Change-Id: I323c25a19a9ab62cea2bdd313329661f1bdd43d8
Reviewed-on: https://chromium-review.googlesource.com/519363
Reviewed-by: Mathieu Perreault <mathp@chromium.org>
Reviewed-by: Charles Harrison <csharrison@chromium.org>
Commit-Queue: Mathieu Perreault <mathp@chromium.org>
Cr-Commit-Position: refs/heads/master@{#475903}
[modify] https://crrev.com/a49b11bb29ce7018da6f440703ec983009c98cc5/chrome/browser/page_load_metrics/metrics_web_contents_observer.cc
[modify] https://crrev.com/a49b11bb29ce7018da6f440703ec983009c98cc5/chrome/browser/page_load_metrics/metrics_web_contents_observer.h
[modify] https://crrev.com/a49b11bb29ce7018da6f440703ec983009c98cc5/chrome/browser/page_load_metrics/metrics_web_contents_observer_unittest.cc
[modify] https://crrev.com/a49b11bb29ce7018da6f440703ec983009c98cc5/chrome/browser/page_load_metrics/observers/page_load_metrics_observer_test_harness.cc
[modify] https://crrev.com/a49b11bb29ce7018da6f440703ec983009c98cc5/chrome/browser/page_load_metrics/observers/page_load_metrics_observer_test_harness.h
[modify] https://crrev.com/a49b11bb29ce7018da6f440703ec983009c98cc5/chrome/browser/page_load_metrics/page_load_metrics_embedder_interface.h
[modify] https://crrev.com/a49b11bb29ce7018da6f440703ec983009c98cc5/chrome/browser/page_load_metrics/page_load_metrics_initialize.cc
[modify] https://crrev.com/a49b11bb29ce7018da6f440703ec983009c98cc5/chrome/browser/page_load_metrics/page_load_metrics_update_dispatcher.cc
[modify] https://crrev.com/a49b11bb29ce7018da6f440703ec983009c98cc5/chrome/browser/page_load_metrics/page_load_metrics_update_dispatcher.h
[modify] https://crrev.com/a49b11bb29ce7018da6f440703ec983009c98cc5/chrome/browser/page_load_metrics/page_load_metrics_util.cc
[modify] https://crrev.com/a49b11bb29ce7018da6f440703ec983009c98cc5/chrome/browser/page_load_metrics/page_load_metrics_util.h
[modify] https://crrev.com/a49b11bb29ce7018da6f440703ec983009c98cc5/chrome/browser/page_load_metrics/page_load_tracker.cc
[modify] https://crrev.com/a49b11bb29ce7018da6f440703ec983009c98cc5/chrome/browser/prerender/prerender_browsertest.cc
[modify] https://crrev.com/a49b11bb29ce7018da6f440703ec983009c98cc5/chrome/common/BUILD.gn
[delete] https://crrev.com/93fdbfecc3703f4b1459d8dec0fb412ed508f90a/chrome/common/page_load_metrics/page_load_metrics_util.cc
[delete] https://crrev.com/93fdbfecc3703f4b1459d8dec0fb412ed508f90a/chrome/common/page_load_metrics/page_load_metrics_util.h
[delete] https://crrev.com/93fdbfecc3703f4b1459d8dec0fb412ed508f90a/chrome/common/page_load_metrics/test/page_load_metrics_test_util.cc
[delete] https://crrev.com/93fdbfecc3703f4b1459d8dec0fb412ed508f90a/chrome/common/page_load_metrics/test/page_load_metrics_test_util.h
[delete] https://crrev.com/93fdbfecc3703f4b1459d8dec0fb412ed508f90a/chrome/common/page_load_metrics/test/weak_mock_timer.cc
[delete] https://crrev.com/93fdbfecc3703f4b1459d8dec0fb412ed508f90a/chrome/common/page_load_metrics/test/weak_mock_timer.h
[modify] https://crrev.com/a49b11bb29ce7018da6f440703ec983009c98cc5/chrome/renderer/page_load_metrics/metrics_render_frame_observer.cc
[modify] https://crrev.com/a49b11bb29ce7018da6f440703ec983009c98cc5/chrome/renderer/page_load_metrics/metrics_render_frame_observer.h
[modify] https://crrev.com/a49b11bb29ce7018da6f440703ec983009c98cc5/chrome/renderer/page_load_metrics/metrics_render_frame_observer_unittest.cc
[modify] https://crrev.com/a49b11bb29ce7018da6f440703ec983009c98cc5/chrome/test/BUILD.gn
[modify] https://crrev.com/a49b11bb29ce7018da6f440703ec983009c98cc5/tools/metrics/histograms/enums.xml
[modify] https://crrev.com/a49b11bb29ce7018da6f440703ec983009c98cc5/tools/metrics/histograms/histograms.xml

Blockedon: 728176
Blockedon: 728179
Status: Fixed (was: Started)

Sign in to add a comment