Skip to content

Commit

Permalink
LoadingMetrics: Add UKMs for loading breakdown metrics for navigation
Browse files Browse the repository at this point in the history
This CL adds UKMs for loading breakdown metrics for navigation. These
are the same as the existing UMAs for loading breakdown metrics. We
record these metrics when the current page navigates away like other
PageLoad metrics.

In page_load_metrics_browsertest.cc, this CL wraps |histogram_tester_|
with std::unique_ptr so that we can swap it with a new instance in the
CachedPage testcase. This makes behavior of the UMA tester aligned with
behavior of the UKM recorder, and code becomes simpler.

UKM Privacy Review (Google-internal):
https://docs.google.com/document/d/1Doc2E2XgCDbC2KI6M71_aA3XH7S61wBYaDSY3vLTOuk/edit?usp=sharing

DesignDoc:
https://docs.google.com/document/d/16oqu9lyPbfgZIjQsRaCfaKE8r1Cdlb3d4GVSdth4AN8/edit?usp=sharing

Change-Id: If58eb2d5626d465d8fa2a06ca0fd9049295408af
Bug: 1068843
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2193194
Commit-Queue: Hiroki Nakagawa <nhiroki@chromium.org>
Reviewed-by: Bryan McQuade <bmcquade@chromium.org>
Reviewed-by: Kinuko Yasuda <kinuko@chromium.org>
Reviewed-by: Matt Falkenhagen <falken@chromium.org>
Cr-Commit-Position: refs/heads/master@{#782338}
  • Loading branch information
nhiroki authored and Commit Bot committed Jun 25, 2020
1 parent 43f238c commit 5666f23
Show file tree
Hide file tree
Showing 6 changed files with 524 additions and 320 deletions.
Expand Up @@ -219,6 +219,7 @@ UkmPageLoadMetricsObserver::ObservePolicy UkmPageLoadMetricsObserver::OnCommit(
// The PageTransition for the navigation may be updated on commit.
page_transition_ = navigation_handle->GetPageTransition();
was_cached_ = navigation_handle->WasResponseCached();
navigation_handle_timing_ = navigation_handle->GetNavigationHandleTiming();
RecordNoStatePrefetchMetrics(navigation_handle, source_id);
RecordGeneratedNavigationUKM(source_id, navigation_handle->GetURL());
navigation_is_cross_process_ = !navigation_handle->IsSameProcess();
Expand All @@ -237,6 +238,7 @@ UkmPageLoadMetricsObserver::FlushMetricsOnAppEnterBackground(
return STOP_OBSERVING;

if (!was_hidden_) {
RecordNavigationTimingMetrics();
RecordPageLoadMetrics(base::TimeTicks::Now(), true /* became_hidden */);
RecordTimingMetrics(timing);
RecordInputTimingMetrics();
Expand All @@ -251,6 +253,7 @@ UkmPageLoadMetricsObserver::ObservePolicy UkmPageLoadMetricsObserver::OnHidden(
return CONTINUE_OBSERVING;

if (!was_hidden_) {
RecordNavigationTimingMetrics();
RecordPageLoadMetrics(base::TimeTicks() /* no app_background_time */,
true /* became_hidden */);
RecordTimingMetrics(timing);
Expand Down Expand Up @@ -288,6 +291,7 @@ void UkmPageLoadMetricsObserver::OnComplete(
return;

if (!was_hidden_) {
RecordNavigationTimingMetrics();
RecordPageLoadMetrics(base::TimeTicks() /* no app_background_time */,
false /* became_hidden */);
RecordTimingMetrics(timing);
Expand Down Expand Up @@ -344,6 +348,72 @@ void UkmPageLoadMetricsObserver::OnLoadedResource(
}
}

void UkmPageLoadMetricsObserver::RecordNavigationTimingMetrics() {
const base::TimeTicks navigation_start_time =
GetDelegate().GetNavigationStart();
const content::NavigationHandleTiming& timing = navigation_handle_timing_;

// Record metrics for navigation only when all relevant milestones are
// recorded and in the expected order. It is allowed that they have the same
// value for some cases (e.g., internal redirection for HSTS).
if (navigation_start_time.is_null() ||
timing.first_request_start_time.is_null() ||
timing.first_response_start_time.is_null() ||
timing.first_loader_callback_time.is_null() ||
timing.final_request_start_time.is_null() ||
timing.final_response_start_time.is_null() ||
timing.final_loader_callback_time.is_null() ||
timing.navigation_commit_sent_time.is_null()) {
return;
}
// TODO(https://crbug.com/1076710): Change these early-returns to DCHECKs
// after the issue 1076710 is fixed.
if (navigation_start_time > timing.first_request_start_time ||
timing.first_request_start_time > timing.first_response_start_time ||
timing.first_response_start_time > timing.first_loader_callback_time ||
timing.first_loader_callback_time > timing.navigation_commit_sent_time) {
return;
}
if (navigation_start_time > timing.final_request_start_time ||
timing.final_request_start_time > timing.final_response_start_time ||
timing.final_response_start_time > timing.final_loader_callback_time ||
timing.final_loader_callback_time > timing.navigation_commit_sent_time) {
return;
}
DCHECK_LE(timing.first_request_start_time, timing.final_request_start_time);
DCHECK_LE(timing.first_response_start_time, timing.final_response_start_time);
DCHECK_LE(timing.first_loader_callback_time,
timing.final_loader_callback_time);

ukm::builders::NavigationTiming builder(GetDelegate().GetSourceId());

// Record the elapsed time from the navigation start milestone.
builder
.SetFirstRequestStart(
(timing.first_request_start_time - navigation_start_time)
.InMilliseconds())
.SetFirstResponseStart(
(timing.first_response_start_time - navigation_start_time)
.InMilliseconds())
.SetFirstLoaderCallback(
(timing.first_loader_callback_time - navigation_start_time)
.InMilliseconds())
.SetFinalRequestStart(
(timing.final_request_start_time - navigation_start_time)
.InMilliseconds())
.SetFinalResponseStart(
(timing.final_response_start_time - navigation_start_time)
.InMilliseconds())
.SetFinalLoaderCallback(
(timing.final_loader_callback_time - navigation_start_time)
.InMilliseconds())
.SetNavigationCommitSent(
(timing.navigation_commit_sent_time - navigation_start_time)
.InMilliseconds());

builder.Record(ukm::UkmRecorder::Get());
}

void UkmPageLoadMetricsObserver::RecordTimingMetrics(
const page_load_metrics::mojom::PageLoadTiming& timing) {
ukm::builders::PageLoad builder(GetDelegate().GetSourceId());
Expand Down
Expand Up @@ -97,6 +97,8 @@ class UkmPageLoadMetricsObserver
virtual bool IsOfflinePreview(content::WebContents* web_contents) const;

private:
void RecordNavigationTimingMetrics();

// Records page load timing related metrics available in PageLoadTiming, such
// as first contentful paint.
void RecordTimingMetrics(
Expand Down Expand Up @@ -180,6 +182,7 @@ class UkmPageLoadMetricsObserver
base::TimeDelta total_foreground_cpu_time_;

// Load timing metrics of the main frame resource request.
content::NavigationHandleTiming navigation_handle_timing_;
base::Optional<net::LoadTimingInfo> main_frame_timing_;

// PAGE_TRANSITION_LINK is the default PageTransition value.
Expand Down
Expand Up @@ -1795,3 +1795,36 @@ TEST_F(OfflinePreviewsUKMPageLoadMetricsObserverTest, OfflinePreviewReported) {
page_load_metrics::END_CLOSE);
}
}

TEST_F(UkmPageLoadMetricsObserverTest, NavigationTiming) {
GURL url(kTestUrl1);
NavigateAndCommit(url);

// Simulate closing the tab.
DeleteContents();

using ukm::builders::NavigationTiming;
std::map<ukm::SourceId, ukm::mojom::UkmEntryPtr> merged_entries =
tester()->test_ukm_recorder().GetMergedEntriesByName(
NavigationTiming::kEntryName);
EXPECT_EQ(1ul, merged_entries.size());

const std::vector<const char*> metrics = {
NavigationTiming::kFirstRequestStartName,
NavigationTiming::kFirstResponseStartName,
NavigationTiming::kFirstLoaderCallbackName,
NavigationTiming::kFinalRequestStartName,
NavigationTiming::kFinalResponseStartName,
NavigationTiming::kFinalLoaderCallbackName,
NavigationTiming::kNavigationCommitSentName};

for (const auto& kv : merged_entries) {
tester()->test_ukm_recorder().ExpectEntrySourceHasUrl(kv.second.get(), url);

// Verify if the elapsed times from the navigation start are recorded.
for (const char* metric : metrics) {
EXPECT_TRUE(tester()->test_ukm_recorder().EntryHasMetric(kv.second.get(),
metric));
}
}
}

0 comments on commit 5666f23

Please sign in to comment.