Skip to content

Commit

Permalink
Postpone calling RenderFrameObserver::DidCommitProvisionalLoad
Browse files Browse the repository at this point in the history 
This change postpones calling RenderFrameObserver::DidCommitProvisionalLoad
until after RenderFrameImpl is done updating its own state and performing its
own work. This avoids running arbitrary other code from within the middle of
those state updates.

In particular, this ensures that observers that wish to execute script from
within DidCommitProvisionalLoad do not do so until after we have setup the new
BrowserInterfaceBrokerProxy and finished other critical steps associated with
committing a navigation in the renderer. See ChromeRenderFrameObserver, which
uses this signal to inject scripts for WebUI pages. (We might decide that is
non-ideal for other reasons and design a better injection point, but that can
be done in a subsequent CL.)

Injected script can call into local storage, which is a synchronous operation.
That operation requires a synchronous check of the ContentSettingsManager to
determine if the script can access local storage. That interface is acquired
through the BrowserInterfaceBrokerProxy. Hence, there is opportunity for a
dead-lock if the BrowserInterfaceBrokerProxy has not already been set-up
(meaning, not already had its receiver handle sent to the browser process) by
the time script tries to access local storage. In practice, this has not been
an issue, but in another change I am making, the ContentSettingsManager will
be lazily acquired causing this potential dead-lock to more easily occur and
to definitely occur in some of our WebUI browser tests.

As part of this change, the page_load_metrics/ module had to be revised to not
flush existing metrics from DidCommitProvisionalLoad. Doing so could attribute
metrics from the previous page to the newly committed page including especially
the navigation_start time which is used as a key to identify page loads by the
metrics system. That in turn could cause subsequent metrics on the newly loaded
page to simply be dropped. Fortunately, tests helped root out this issue. The
PageTimingMetricsSender grows a SendLatest method that can be used to trigger
when metrics should be flushed rather than having that be a side-effect of the
destructor running.

SendLatest is now called from ReadyToCommitNavigation to send any accumulated
metrics for the previous page before the new load commits. This may result in
dropping some metrics data between the calls to ReadyToCommitNavigation and
DidCommitProvisionalLoad, but that is probably reasonable. Also, a comment
from dgozman indicates that ReadyToCommitNavigation is something we want to
get rid of but MetricsRenderFrameObserver already implements this method so
whatever substitute there will be in the future for this method can hopefully
account for both this new use case as well as the existing use case.

Files w/ implementations potentially impacted:
  chrome/renderer/chrome_render_frame_observer.cc
  chrome/renderer/content_settings_agent_impl.cc
  chrome/renderer/content_settings_agent_impl_browsertest.cc
  chrome/renderer/net/net_error_helper.cc
  chrome/renderer/safe_browsing/phishing_classifier_delegate.cc
  chrome/renderer/searchbox/searchbox.cc
  components/autofill/content/renderer/autofill_agent.cc
  components/autofill/content/renderer/form_tracker.cc
  components/autofill/content/renderer/password_autofill_agent.cc
  components/autofill/content/renderer/password_generation_agent.cc
  components/data_reduction_proxy/content/renderer/content_previews_render_frame_observer.cc
  components/page_load_metrics/renderer/metrics_render_frame_observer.cc
  content/renderer/accessibility/render_accessibility_impl.cc
  content/renderer/media/audio/audio_renderer_sink_cache_impl.cc
  content/renderer/pepper/plugin_power_saver_helper.cc
  extensions/renderer/extension_frame_helper.cc

Change-Id: Ia6627b2db06ea51e769ed6c8889e37e554fcc1d1
Bug: 1023519
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/1898769
Reviewed-by: Bryan McQuade <bmcquade@chromium.org>
Reviewed-by: John Abd-El-Malek <jam@chromium.org>
Commit-Queue: Darin Fisher <darin@chromium.org>
Cr-Commit-Position: refs/heads/master@{#715460}
  • Loading branch information
Darin Fisher authored and Commit Bot committed Nov 14, 2019
1 parent 01f7c68 commit 2d2b194
Show file tree
Hide file tree
Showing 6 changed files with 80 additions and 60 deletions.
17 changes: 14 additions & 3 deletions components/page_load_metrics/renderer/metrics_render_frame_observer.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -67,7 +67,10 @@ MetricsRenderFrameObserver::MetricsRenderFrameObserver(
: content::RenderFrameObserver(render_frame),
scoped_ad_resource_observer_(this) {}

MetricsRenderFrameObserver::~MetricsRenderFrameObserver() {}
MetricsRenderFrameObserver::~MetricsRenderFrameObserver() {
if (page_timing_metrics_sender_)
page_timing_metrics_sender_->SendLatest();
}

void MetricsRenderFrameObserver::DidChangePerformanceTiming() {
SendMetrics();
Expand Down Expand Up @@ -196,7 +199,10 @@ void MetricsRenderFrameObserver::DidLoadResourceFromMemoryCache(
}

void MetricsRenderFrameObserver::FrameDetached() {
page_timing_metrics_sender_.reset();
if (page_timing_metrics_sender_) {
page_timing_metrics_sender_->SendLatest();
page_timing_metrics_sender_.reset();
}
}

void MetricsRenderFrameObserver::ReadyToCommitNavigation(
Expand All @@ -205,6 +211,11 @@ void MetricsRenderFrameObserver::ReadyToCommitNavigation(
provisional_frame_resource_data_use_ =
std::make_unique<PageResourceDataUse>();
provisional_frame_resource_id_ = 0;

// Send current metrics before the next page load commits. Don't reset here
// as it may be a same document load.
if (page_timing_metrics_sender_)
page_timing_metrics_sender_->SendLatest();
}

void MetricsRenderFrameObserver::DidFailProvisionalLoad() {
Expand Down Expand Up @@ -312,7 +323,7 @@ void MetricsRenderFrameObserver::SendMetrics() {
return;
if (HasNoRenderFrame())
return;
page_timing_metrics_sender_->Send(GetTiming());
page_timing_metrics_sender_->SendSoon(GetTiming());
}

mojom::PageLoadTimingPtr MetricsRenderFrameObserver::GetTiming() const {
Expand Down
39 changes: 23 additions & 16 deletions components/page_load_metrics/renderer/page_timing_metrics_sender.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -52,13 +52,11 @@ PageTimingMetricsSender::PageTimingMetricsSender(
}
}

// On destruction, we want to send any data we have if we have a timer
// currently running (and thus are talking to a browser process)
PageTimingMetricsSender::~PageTimingMetricsSender() {
if (timer_->IsRunning()) {
timer_->Stop();
SendNow();
}
// Make sure we don't have any unsent data. If this assertion fails, then it
// means metrics are somehow coming in between MetricsRenderFrameObserver's
// ReadyToCommitNavigation and DidCommitProvisionalLoad.
DCHECK(!timer_->IsRunning());
}

void PageTimingMetricsSender::DidObserveLoadingBehavior(
Expand Down Expand Up @@ -227,7 +225,7 @@ void PageTimingMetricsSender::UpdateResourceMetadata(
it->second->SetIsMainFrameResource(is_main_frame_resource);
}

void PageTimingMetricsSender::Send(mojom::PageLoadTimingPtr timing) {
void PageTimingMetricsSender::SendSoon(mojom::PageLoadTimingPtr timing) {
if (last_timing_->Equals(*timing)) {
return;
}
Expand All @@ -244,21 +242,30 @@ void PageTimingMetricsSender::Send(mojom::PageLoadTimingPtr timing) {
EnsureSendTimer();
}

void PageTimingMetricsSender::SendLatest() {
if (!timer_->IsRunning())
return;

timer_->Stop();
SendNow();
}

void PageTimingMetricsSender::UpdateCpuTiming(base::TimeDelta task_time) {
last_cpu_timing_->task_time += task_time;
EnsureSendTimer();
}

void PageTimingMetricsSender::EnsureSendTimer() {
if (!timer_->IsRunning()) {
// Send the first IPC eagerly to make sure the receiving side knows we're
// sending metrics as soon as possible.
int delay_ms =
have_sent_ipc_ ? buffer_timer_delay_ms_ : kInitialTimerDelayMillis;
timer_->Start(
FROM_HERE, base::TimeDelta::FromMilliseconds(delay_ms),
base::Bind(&PageTimingMetricsSender::SendNow, base::Unretained(this)));
}
if (timer_->IsRunning())
return;

// Send the first IPC eagerly to make sure the receiving side knows we're
// sending metrics as soon as possible.
int delay_ms =
have_sent_ipc_ ? buffer_timer_delay_ms_ : kInitialTimerDelayMillis;
timer_->Start(
FROM_HERE, base::TimeDelta::FromMilliseconds(delay_ms),
base::Bind(&PageTimingMetricsSender::SendNow, base::Unretained(this)));
}

void PageTimingMetricsSender::SendNow() {
Expand Down
12 changes: 7 additions & 5 deletions components/page_load_metrics/renderer/page_timing_metrics_sender.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -67,11 +67,13 @@ class PageTimingMetricsSender {
int64_t encoded_body_length,
const std::string& mime_type);

// TODO(ericrobinson): There should probably be a name change here:
// * Send: Sends immediately, functions as SendNow.
// * QueueSend: Queues the send by starting the timer, functions as Send.
void Send(mojom::PageLoadTimingPtr timing);
// Updates the PageLoadMetrics::CpuTiming data and starts the Send timer.
// Queues the send by starting the send timer.
void SendSoon(mojom::PageLoadTimingPtr timing);

// Sends any queued timing data immediately and stops the send timer.
void SendLatest();

// Updates the PageLoadMetrics::CpuTiming data and starts the send timer.
void UpdateCpuTiming(base::TimeDelta task_time);

void UpdateResourceMetadata(int resource_id,
Expand Down
43 changes: 21 additions & 22 deletions components/page_load_metrics/renderer/page_timing_metrics_sender_unittest.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -52,7 +52,7 @@ TEST_F(PageTimingMetricsSenderTest, Basic) {
timing.navigation_start = nav_start;
timing.document_timing->first_layout = first_layout;

metrics_sender_->Send(timing.Clone());
metrics_sender_->SendSoon(timing.Clone());

// Firing the timer should trigger sending of an SendTiming call.
validator_.ExpectPageLoadTiming(timing);
Expand All @@ -65,7 +65,7 @@ TEST_F(PageTimingMetricsSenderTest, Basic) {

// Attempt to send the same timing instance again. The send should be
// suppressed, since the timing instance hasn't changed since the last send.
metrics_sender_->Send(timing.Clone());
metrics_sender_->SendSoon(timing.Clone());
EXPECT_FALSE(metrics_sender_->mock_timer()->IsRunning());
}

Expand All @@ -79,13 +79,13 @@ TEST_F(PageTimingMetricsSenderTest, CoalesceMultipleTimings) {
timing.navigation_start = nav_start;
timing.document_timing->first_layout = first_layout;

metrics_sender_->Send(timing.Clone());
metrics_sender_->SendSoon(timing.Clone());
ASSERT_TRUE(metrics_sender_->mock_timer()->IsRunning());

// Send an updated PageLoadTiming before the timer has fired. When the timer
// fires, the updated PageLoadTiming should be sent.
timing.document_timing->load_event_start = load_event;
metrics_sender_->Send(timing.Clone());
metrics_sender_->SendSoon(timing.Clone());

// Firing the timer should trigger sending of the SendTiming call with
// the most recently provided PageLoadTiming instance.
Expand All @@ -104,7 +104,7 @@ TEST_F(PageTimingMetricsSenderTest, MultipleTimings) {
timing.navigation_start = nav_start;
timing.document_timing->first_layout = first_layout;

metrics_sender_->Send(timing.Clone());
metrics_sender_->SendSoon(timing.Clone());
ASSERT_TRUE(metrics_sender_->mock_timer()->IsRunning());
validator_.ExpectPageLoadTiming(timing);
metrics_sender_->mock_timer()->Fire();
Expand All @@ -114,14 +114,14 @@ TEST_F(PageTimingMetricsSenderTest, MultipleTimings) {
// Send an updated PageLoadTiming after the timer for the first send request
// has fired, and verify that a second timing is sent.
timing.document_timing->load_event_start = load_event;
metrics_sender_->Send(timing.Clone());
metrics_sender_->SendSoon(timing.Clone());
ASSERT_TRUE(metrics_sender_->mock_timer()->IsRunning());
validator_.ExpectPageLoadTiming(timing);
metrics_sender_->mock_timer()->Fire();
EXPECT_FALSE(metrics_sender_->mock_timer()->IsRunning());
}

TEST_F(PageTimingMetricsSenderTest, SendTimingOnDestructor) {
TEST_F(PageTimingMetricsSenderTest, SendTimingOnSendLatest) {
mojom::PageLoadTiming timing;
InitPageLoadTimingForTest(&timing);
timing.navigation_start = base::Time::FromDoubleT(10);
Expand All @@ -130,20 +130,19 @@ TEST_F(PageTimingMetricsSenderTest, SendTimingOnDestructor) {
// This test wants to verify behavior in the PageTimingMetricsSender
// destructor. The EXPECT_CALL will be satisfied when the |metrics_sender_|
// is destroyed below.
metrics_sender_->Send(timing.Clone());
metrics_sender_->SendSoon(timing.Clone());
validator_.ExpectPageLoadTiming(timing);
ASSERT_TRUE(metrics_sender_->mock_timer()->IsRunning());

// Destroy |metrics_sender_|, in order to force its destructor to run.
metrics_sender_.reset();
metrics_sender_->SendLatest();
}

TEST_F(PageTimingMetricsSenderTest, SendSingleFeature) {
mojom::PageLoadTiming timing;
InitPageLoadTimingForTest(&timing);
blink::mojom::WebFeature feature = blink::mojom::WebFeature::kFetch;

metrics_sender_->Send(timing.Clone());
metrics_sender_->SendSoon(timing.Clone());
validator_.ExpectPageLoadTiming(timing);
// Observe a single feature, update expected features sent across IPC.
metrics_sender_->DidObserveNewFeatureUsage(feature);
Expand All @@ -160,7 +159,7 @@ TEST_F(PageTimingMetricsSenderTest, SendMultipleFeatures) {
blink::mojom::WebFeature feature_1 =
blink::mojom::WebFeature::kFetchBodyStream;

metrics_sender_->Send(timing.Clone());
metrics_sender_->SendSoon(timing.Clone());
validator_.ExpectPageLoadTiming(timing);
// Observe the first feature, update expected features sent across IPC.
metrics_sender_->DidObserveNewFeatureUsage(feature_0);
Expand All @@ -178,7 +177,7 @@ TEST_F(PageTimingMetricsSenderTest, SendDuplicatedFeatures) {
InitPageLoadTimingForTest(&timing);
blink::mojom::WebFeature feature = blink::mojom::WebFeature::kFetch;

metrics_sender_->Send(timing.Clone());
metrics_sender_->SendSoon(timing.Clone());
validator_.ExpectPageLoadTiming(timing);
metrics_sender_->DidObserveNewFeatureUsage(feature);
validator_.UpdateExpectPageLoadFeatures(feature);
Expand All @@ -198,7 +197,7 @@ TEST_F(PageTimingMetricsSenderTest, SendMultipleFeaturesTwice) {
blink::mojom::WebFeature::kFetchBodyStream;
blink::mojom::WebFeature feature_2 = blink::mojom::WebFeature::kWindowFind;

metrics_sender_->Send(timing.Clone());
metrics_sender_->SendSoon(timing.Clone());
validator_.ExpectPageLoadTiming(timing);
// Observe the first feature, update expected features sent across IPC.
metrics_sender_->DidObserveNewFeatureUsage(feature_0);
Expand All @@ -217,7 +216,7 @@ TEST_F(PageTimingMetricsSenderTest, SendMultipleFeaturesTwice) {
// Send an updated PageLoadTiming after the timer for the first send request
// has fired, and verify that a second list of features is sent.
timing.document_timing->load_event_start = load_event;
metrics_sender_->Send(timing.Clone());
metrics_sender_->SendSoon(timing.Clone());
validator_.ExpectPageLoadTiming(timing);
// Observe duplicated feature usage, without updating expected features sent
// across IPC.
Expand All @@ -237,7 +236,7 @@ TEST_F(PageTimingMetricsSenderTest, SendSingleCssProperty) {
mojom::PageLoadTiming timing;
InitPageLoadTimingForTest(&timing);

metrics_sender_->Send(timing.Clone());
metrics_sender_->SendSoon(timing.Clone());
validator_.ExpectPageLoadTiming(timing);
// Observe a single CSS property, update expected CSS properties sent across
// IPC.
Expand All @@ -253,7 +252,7 @@ TEST_F(PageTimingMetricsSenderTest, SendCssPropertiesInRange) {
mojom::PageLoadTiming timing;
InitPageLoadTimingForTest(&timing);

metrics_sender_->Send(timing.Clone());
metrics_sender_->SendSoon(timing.Clone());
validator_.ExpectPageLoadTiming(timing);
// Observe the smallest CSS property ID.
metrics_sender_->DidObserveNewCssPropertyUsage(CSSSampleId::kColor,
Expand All @@ -272,7 +271,7 @@ TEST_F(PageTimingMetricsSenderTest, SendMultipleCssProperties) {
mojom::PageLoadTiming timing;
InitPageLoadTimingForTest(&timing);

metrics_sender_->Send(timing.Clone());
metrics_sender_->SendSoon(timing.Clone());
validator_.ExpectPageLoadTiming(timing);
// Observe the first CSS property, update expected CSS properties sent across
// IPC.
Expand All @@ -293,7 +292,7 @@ TEST_F(PageTimingMetricsSenderTest, SendDuplicatedCssProperties) {
mojom::PageLoadTiming timing;
InitPageLoadTimingForTest(&timing);

metrics_sender_->Send(timing.Clone());
metrics_sender_->SendSoon(timing.Clone());
validator_.ExpectPageLoadTiming(timing);
metrics_sender_->DidObserveNewCssPropertyUsage(CSSSampleId::kDirection,
false /*is_animated*/);
Expand All @@ -311,7 +310,7 @@ TEST_F(PageTimingMetricsSenderTest, SendMultipleCssPropertiesTwice) {
mojom::PageLoadTiming timing;
InitPageLoadTimingForTest(&timing);

metrics_sender_->Send(timing.Clone());
metrics_sender_->SendSoon(timing.Clone());
validator_.ExpectPageLoadTiming(timing);
// Observe the first CSS property, update expected CSS properties sent across
// IPC.
Expand All @@ -335,7 +334,7 @@ TEST_F(PageTimingMetricsSenderTest, SendMultipleCssPropertiesTwice) {
// Send an updated PageLoadTiming after the timer for the first send request
// has fired, and verify that a second list of CSS properties is sent.
timing.document_timing->load_event_start = load_event;
metrics_sender_->Send(timing.Clone());
metrics_sender_->SendSoon(timing.Clone());
validator_.ExpectPageLoadTiming(timing);
// Observe duplicated usage, without updating expected features sent across
// IPC.
Expand All @@ -361,7 +360,7 @@ TEST_F(PageTimingMetricsSenderTest, SendPageRenderData) {
// related to the PageRenderData. This is because metrics_sender_ sends
// its last_timing_ when the mock timer fires, causing the validator to
// look for a matching expectation.
metrics_sender_->Send(timing.Clone());
metrics_sender_->SendSoon(timing.Clone());
validator_.ExpectPageLoadTiming(timing);

metrics_sender_->DidObserveLayoutShift(0.5, false);
Expand Down
24 changes: 13 additions & 11 deletions content/renderer/render_frame_impl.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -4586,6 +4586,9 @@ void RenderFrameImpl::DidCommitProvisionalLoad(

// Check whether we have new encoding name.
UpdateEncoding(frame_, frame_->View()->PageEncoding().Utf8());

NotifyObserversOfNavigationCommit(false /* was_within_same_document */,
transition);
}

void RenderFrameImpl::DidCreateNewDocument() {
Expand Down Expand Up @@ -4835,6 +4838,9 @@ void RenderFrameImpl::DidFinishSameDocumentNavigation(
// If we end up reusing this WebRequest (for example, due to a #ref click),
// we don't want the transition type to persist. Just clear it.
data->navigation_state()->set_transition_type(ui::PAGE_TRANSITION_LINK);

NotifyObserversOfNavigationCommit(true /* was_within_same_document */,
transition);
}

void RenderFrameImpl::DidUpdateCurrentHistoryItem() {
Expand Down Expand Up @@ -5605,7 +5611,7 @@ RenderFrameImpl::MakeDidCommitProvisionalLoadParams(
return params;
}

bool RenderFrameImpl::UpdateNavigationHistory(
void RenderFrameImpl::UpdateNavigationHistory(
const blink::WebHistoryItem& item,
blink::WebHistoryCommitType commit_type) {
NavigationState* navigation_state =
Expand Down Expand Up @@ -5640,12 +5646,9 @@ bool RenderFrameImpl::UpdateNavigationHistory(
render_view_->history_list_offset_ =
navigation_state->commit_params().pending_history_list_offset;
}

return is_new_navigation;
}

void RenderFrameImpl::NotifyObserversOfNavigationCommit(
bool is_new_navigation,
bool is_same_document,
ui::PageTransition transition) {
for (auto& observer : observers_)
Expand All @@ -5665,9 +5668,7 @@ void RenderFrameImpl::UpdateStateForCommit(
// the previous page. Do this before updating the current history item.
SendUpdateState();

bool is_new_navigation = UpdateNavigationHistory(item, commit_type);
NotifyObserversOfNavigationCommit(
is_new_navigation, navigation_state->WasWithinSameDocument(), transition);
UpdateNavigationHistory(item, commit_type);

if (internal_data->must_reset_scroll_and_scale_state()) {
render_view_->webview()->ResetScrollAndScaleState();
Expand Down Expand Up @@ -5728,10 +5729,11 @@ void RenderFrameImpl::DidCommitNavigationInternal(
if (render_view_->renderer_wide_named_frame_lookup())
GetWebFrame()->SetAllowsCrossBrowsingInstanceFrameLookup();

// This invocation must precede any calls to allowScripts(), allowImages(), or
// allowPlugins() for the new page. This ensures that when these functions
// send ViewHostMsg_ContentBlocked messages, those arrive after the browser
// process has already been informed of the provisional load committing.
// This invocation must precede any calls to allowScripts(), allowImages(),
// or allowPlugins() for the new page. This ensures that when these functions
// call chrome::ContentSettingsManager::OnContentBlocked, those calls arrive
// after the browser process has already been informed of the provisional
// load committing.
auto params = MakeDidCommitProvisionalLoadParams(commit_type, transition);
if (was_within_same_document) {
GetFrameHost()->DidCommitSameDocumentNavigation(std::move(params));
Expand Down
5 changes: 2 additions & 3 deletions content/renderer/render_frame_impl.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -1279,12 +1279,11 @@ class CONTENT_EXPORT RenderFrameImpl
// This could result either in the creation of a new entry or a modification
// of the current entry or nothing. If a new entry was created,
// returns true, false otherwise.
bool UpdateNavigationHistory(const blink::WebHistoryItem& item,
void UpdateNavigationHistory(const blink::WebHistoryItem& item,
blink::WebHistoryCommitType commit_type);

// Notify render_view_ observers that a commit happened.
void NotifyObserversOfNavigationCommit(bool is_new_navigation,
bool is_same_document,
void NotifyObserversOfNavigationCommit(bool is_same_document,
ui::PageTransition transition);

// Updates the internal state following a navigation commit. This should be
Expand Down

0 comments on commit 2d2b194

Please sign in to comment.