Initial UKMPageLoadMetricsObserver

Initial UKMPageLoadMetricsObserver

This sends FirstMeaningfulPaint to UKM

Builds on https://codereview.chromium.org/2567263003/

BUG=

[oystein (OOO til 10th of July), 2017-01-07 00:18:19]

Description was changed from

==========
Initial UKMPageLoadMetricsObserver

This sends FirstMeaningfulPaint to UKM

Builds on https://codereview.chromium.org/2567263003/

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

to

==========
Initial UKMPageLoadMetricsObserver

This sends FirstMeaningfulPaint to UKM

Builds on https://codereview.chromium.org/2567263003/

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

[oystein (OOO til 10th of July), 2017-01-07 00:18:19]

oysteine@chromium.org changed reviewers:
+ holte@chromium.org, zhenw@chromium.org

[Zhen Wang, 2017-01-09 17:34:51]

Cool!

https://codereview.chromium.org/2617883004/diff/1/chrome/browser/page_load_me...
File
chrome/browser/page_load_metrics/observers/ukm_page_load_metrics_observer.cc
(right):

https://codereview.chromium.org/2617883004/diff/1/chrome/browser/page_load_me...
chrome/browser/page_load_metrics/observers/ukm_page_load_metrics_observer.cc:22:
UKMPageLoadMetricsObserver::OnStart(
Probably also need to consider OnRedirect etc to make the picture complete.

https://codereview.chromium.org/2617883004/diff/1/chrome/browser/page_load_me...
chrome/browser/page_load_metrics/observers/ukm_page_load_metrics_observer.cc:34:
return STOP_OBSERVING;
Does this we ignore the metrics whenever a page is put in the background, even
if the page is brought to foreground later?

https://codereview.chromium.org/2617883004/diff/1/chrome/browser/page_load_me...
chrome/browser/page_load_metrics/observers/ukm_page_load_metrics_observer.cc:56:
source->set_navigation_start(navigation_start_);
The |timing| parameter passed in also has |timing.navigation_start|, why do we
need to use |navigation_start_| to track by ourselves? Is there a difference?

[Steven Holte, 2017-01-09 18:23:39]

https://codereview.chromium.org/2617883004/diff/1/components/ukm/ukm_service.cc
File components/ukm/ukm_service.cc (right):

https://codereview.chromium.org/2617883004/diff/1/components/ukm/ukm_service....
components/ukm/ukm_service.cc:184: for (auto& source : sources_) {
It seems like we probably want to drop Sources we've serialized to the log after
we've converted them to protos, so we don't just keep sending them.

[Steven Holte, 2017-01-10 23:53:52]

https://codereview.chromium.org/2617883004/diff/1/chrome/browser/page_load_me...
File
chrome/browser/page_load_metrics/observers/ukm_page_load_metrics_observer.cc
(right):

https://codereview.chromium.org/2617883004/diff/1/chrome/browser/page_load_me...
chrome/browser/page_load_metrics/observers/ukm_page_load_metrics_observer.cc:25:
bool started_in_foreground) {
This seems like a good place to check sync pref:

bool IsHistorySyncEnabled(content::NavigationHandle* navigation_handle) {
  Profile* profile =
Profile::FromBrowserContext(navigation_handle->GetWebContents()->GetBrowserContext());
  browser_sync::ProfileSyncService* sync =
      ProfileSyncServiceFactory::GetInstance()->GetForProfile(profile);
  return sync &&
      sync->GetPreferredDataTypes().Has(syncer::HISTORY_DELETE_DIRECTIVES);
}

[Bryan McQuade, 2017-01-17 21:54:28]

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

[Bryan McQuade, 2017-01-17 21:54:29]

Thanks, this is great to see! 2 suggestions.

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

https://codereview.chromium.org/2617883004/diff/20001/chrome/browser/page_loa...
chrome/browser/page_load_metrics/observers/ukm_page_load_metrics_observer.cc:37:
void UKMPageLoadMetricsObserver::OnComplete(
When logging via OnComplete, we've observed that we lose about 13% of page load
records on Android due to Chrome being killed when it goes into the background.
The loss shifts the resulting page load metrics distribution somewhat
substantially: the mean first contentful paint is 7% higher when logging in
OnComplete, for example, as opposed to logging in OnFirstContentfulPaint. More
details here:
https://groups.google.com/a/google.com/d/msg/uma-users/BcJRPxNlJ4E/7O1pJ2ULAgAJ

To address this, you could do one of the following:

1. emit the metrics data out to UKM as each event is observed, as opposed to
once in OnComplete (e.g. emit first contentful paint in OnFirstContentfulPaint,
etc)

or

2. implement PageLoadMetricsObserver::FlushMetricsOnAppEnterBackground and
PLMO::OnHidden, returning STOP_OBSERVING from both, and emitting any metrics
observed up to that point in those callbacks, as well as from OnComplete as you
do currently. This is what the data reduction proxy observer does in order to
address the data loss issue:
https://cs.chromium.org/chromium/src/chrome/browser/page_load_metrics/observe...

https://codereview.chromium.org/2617883004/diff/20001/chrome/browser/page_loa...
chrome/browser/page_load_metrics/observers/ukm_page_load_metrics_observer.cc:57:
source->set_first_meaningful_paint(timing.first_meaningful_paint.value());
FMP is a great metric in concept, but it's still experimental and actively being
modified. Given this, I'd suggest that we:

1. Be consistent with other places where we log this metric, and include
'experimental' in the field name, until we think FMP impl is stable. See the UMA
name: PageLoad.Experimental.PaintTiming.NavigationToFirstMeaningfulPaint as well
as the field name sent in the data reduction proxy pingback:
experimental_first_meaningful_paint
(https://cs.chromium.org/chromium/src/components/data_reduction_proxy/core/com...)
for other places where we do this. So I'd propose we rename the field to
'experimental_first_meaningful_paint' to be consistent w/ the other cases. We
can rename it to 'first_meaningful_paint' once it has stabilized and we're ready
to support the metric long term. It may continue to change after being
stabilized, but at a much less frequent rate. While it's being actively
developed I think we should reflect that in the field name somehow (e.g.
'experimental_' prefix).

2. Add a first_contentful_paint field, given that FCP is very stable & gives
another useful signal that we can have better confidence will not change
significantly going forward. This one is most important IMO, as we need at least
one page load metric that's stable so we can do analysis of performance over
time w/o being affected by changes in metric implementation that will happen for
FMP.

[oystein (OOO til 10th of July), 2017-01-24 19:21:41]

Thanks everyone!!

New version uploaded, but this CL is getting to the point where I'm going to
split it up a bit, so please hold off on reviewing this one.

Bryan: Awesome, thanks. As mentioned offline I changed the metric logged to FCP,
and I also ping back data in FlushMetricsOnAppEnterBackground and OnHidden now.

https://codereview.chromium.org/2617883004/diff/1/chrome/browser/page_load_me...
File
chrome/browser/page_load_metrics/observers/ukm_page_load_metrics_observer.cc
(right):

https://codereview.chromium.org/2617883004/diff/1/chrome/browser/page_load_me...
chrome/browser/page_load_metrics/observers/ukm_page_load_metrics_observer.cc:22:
UKMPageLoadMetricsObserver::OnStart(
On 2017/01/09 17:34:51, Zhen Wang wrote:
> Probably also need to consider OnRedirect etc to make the picture complete.

Bryan: How do the other pageload metrics handle OnRedirect?

https://codereview.chromium.org/2617883004/diff/1/chrome/browser/page_load_me...
chrome/browser/page_load_metrics/observers/ukm_page_load_metrics_observer.cc:25:
bool started_in_foreground) {
On 2017/01/10 23:53:52, Steven Holte wrote:
> This seems like a good place to check sync pref:
> 
> bool IsHistorySyncEnabled(content::NavigationHandle* navigation_handle) {
>   Profile* profile =
>
Profile::FromBrowserContext(navigation_handle->GetWebContents()->GetBrowserContext());
>   browser_sync::ProfileSyncService* sync =
>       ProfileSyncServiceFactory::GetInstance()->GetForProfile(profile);
>   return sync &&
>       sync->GetPreferredDataTypes().Has(syncer::HISTORY_DELETE_DIRECTIVES);
> }

we've had a couple of meetings since this; we decided to handle this elsewhere,
right?

https://codereview.chromium.org/2617883004/diff/1/chrome/browser/page_load_me...
chrome/browser/page_load_metrics/observers/ukm_page_load_metrics_observer.cc:34:
return STOP_OBSERVING;
On 2017/01/09 17:34:51, Zhen Wang wrote:
> Does this we ignore the metrics whenever a page is put in the background, even
> if the page is brought to foreground later?

Yep. My intuition is that it's reasonable to restrict (for now) our measurements
to only fully-foregrounded loads, to remove as many variables as possible. This
is something we can add events for later to UKM.

https://codereview.chromium.org/2617883004/diff/1/chrome/browser/page_load_me...
chrome/browser/page_load_metrics/observers/ukm_page_load_metrics_observer.cc:56:
source->set_navigation_start(navigation_start_);
On 2017/01/09 17:34:51, Zhen Wang wrote:
> The |timing| parameter passed in also has |timing.navigation_start|, why do we
> need to use |navigation_start_| to track by ourselves? Is there a difference?

Done.

https://codereview.chromium.org/2617883004/diff/1/components/ukm/ukm_service.cc
File components/ukm/ukm_service.cc (right):

https://codereview.chromium.org/2617883004/diff/1/components/ukm/ukm_service....
components/ukm/ukm_service.cc:184: for (auto& source : sources_) {
On 2017/01/09 18:23:39, Steven Holte wrote:
> It seems like we probably want to drop Sources we've serialized to the log
after
> we've converted them to protos, so we don't just keep sending them.

Done.

[Steven Holte, 2017-01-24 19:44:50]

lgtm

Update CL description

[Bryan McQuade, 2017-01-24 20:42:00]

The observer impementation looks really good, thanks! Just one question about
navigation_start, but otherwise I think the impl looks quite solid.

https://codereview.chromium.org/2617883004/diff/120001/chrome/browser/page_lo...
File
chrome/browser/page_load_metrics/observers/ukm_page_load_metrics_observer.cc
(right):

https://codereview.chromium.org/2617883004/diff/120001/chrome/browser/page_lo...
chrome/browser/page_load_metrics/observers/ukm_page_load_metrics_observer.cc:61:
source->set_navigation_start(timing.navigation_start);
ah, we're actually trying to move away from using this base::Time value, since
clock skew etc can make it hard to reason about a timestamp value from the
client.

what goals do we want to solve by including a navigation start value in the UKM
record? how do you see us using that? perhaps there are other ways to go about
this that don't require using a base::Time.

[oystein (OOO til 10th of July), 2017-01-24 21:44:35]

On 2017/01/24 20:42:00, Bryan McQuade wrote:
> The observer impementation looks really good, thanks! Just one question about
> navigation_start, but otherwise I think the impl looks quite solid.
> 
>
https://codereview.chromium.org/2617883004/diff/120001/chrome/browser/page_lo...
> File
> chrome/browser/page_load_metrics/observers/ukm_page_load_metrics_observer.cc
> (right):
> 
>
https://codereview.chromium.org/2617883004/diff/120001/chrome/browser/page_lo...
>
chrome/browser/page_load_metrics/observers/ukm_page_load_metrics_observer.cc:61:
> source->set_navigation_start(timing.navigation_start);
> ah, we're actually trying to move away from using this base::Time value, since
> clock skew etc can make it hard to reason about a timestamp value from the
> client.
> 
> what goals do we want to solve by including a navigation start value in the
UKM
> record? how do you see us using that? perhaps there are other ways to go about
> this that don't require using a base::Time.

I dug through the docs/email discussions to find the reasoning for this, and I
think the original purpose was to use as a constant offset for all of timestamps
in the proto (essentially for compression purposes). Since this first version
doesn't deal with generic events I've removed it for now (in the split-out CL),
and we can figure out a better way to handle this later.

[Bryan McQuade, 2017-01-26 00:50:59]

LGTM, thanks! Just a couple small comments.

https://codereview.chromium.org/2617883004/diff/120001/chrome/browser/page_lo...
File
chrome/browser/page_load_metrics/observers/ukm_page_load_metrics_observer_unittest.cc
(right):

https://codereview.chromium.org/2617883004/diff/120001/chrome/browser/page_lo...
chrome/browser/page_load_metrics/observers/ukm_page_load_metrics_observer_unittest.cc:5:
#include
"chrome/browser/page_load_metrics/observers/ukm_page_load_metrics_observer.h"
if it's reasonably straightforward, it'd be good to add a browser test in
page_load_metrics_browsertest.cc to make sure UKM logs are sent. This gets you
end to end testing coverage. If there isn't yet sufficient UKM test infra for
this, then it's fine to defer this.

https://codereview.chromium.org/2617883004/diff/120001/chrome/browser/page_lo...
chrome/browser/page_load_metrics/observers/ukm_page_load_metrics_observer_unittest.cc:56:
base::Time navigation_start_;
looks like this isn't used - remove?

https://codereview.chromium.org/2617883004/diff/120001/chrome/test/base/testi...
File chrome/test/base/testing_browser_process.cc (right):

https://codereview.chromium.org/2617883004/diff/120001/chrome/test/base/testi...
chrome/test/base/testing_browser_process.cc:79: rappor_service_(nullptr),
should set ukm_service_ to nullptr here

https://codereview.chromium.org/2617883004/diff/120001/components/ukm/ukm_sou...
File components/ukm/ukm_source.h (right):

https://codereview.chromium.org/2617883004/diff/120001/components/ukm/ukm_sou...
components/ukm/ukm_source.h:29: base::Time navigation_start() const { return
navigation_start_; }
should we remove this and the setter and member variable for now as well?

[oystein (OOO til 10th of July), 2017-01-28 01:23:32]

(Closed this as it was split into three CLs)