PageLoadTracker::WebContentsHidden called for backgrounded tab that was never foregrounded |
|||
Issue descriptionIn https://codereview.chromium.org/1740403002 I added some checks to make sure that WebContentsShown and WebContentsHidden behave sanely. In particular, I added checks to verify that the first time WCH is called, either: * started in the foreground and haven't been foregrounded yet * started in the background and have already been foregrounded It appears that this expectation is not met in some SessionRestoreTests. In particular we are getting WCH invocations for a tab that started in the background and was never foregrounded. The call stack looks like: [5846:5846:0227/162159:FATAL:metrics_web_contents_observer.cc(166)] Check failed: started_in_foreground_ == foreground_time_.is_null() (0 vs. 1) #0 0x7f963378253e base::debug::StackTrace::StackTrace() #1 0x7f96337e13df logging::LogMessage::~LogMessage() #2 0x0000061b861d page_load_metrics::PageLoadTracker::WebContentsHidden() #3 0x0000061bab70 page_load_metrics::MetricsWebContentsObserver::WasHidden() #4 0x7f962c36d9e9 content::WebContentsImpl::WasHidden() #5 0x000001f92acf TabLoader::LoadNextTab() #6 0x000001f92762 TabLoader::HandleTabClosedOrLoaded() #7 0x000001f92607 TabLoader::Observe() #8 0x7f962bf349f4 content::NotificationServiceImpl::Notify() #9 0x7f962c373b9d content::WebContentsImpl::LoadingStateChanged() #10 0x7f962c37afa6 content::WebContentsImpl::DidStopLoading() #11 0x7f962bbd07ac content::FrameTreeNode::DidStopLoading() #12 0x7f962bc1970a content::RenderFrameHostImpl::OnDidStopLoading()
,
Feb 27 2016
On further inspection it seems like WebContents have their WasShown and WasHidden invoked when WCImpl::should_normally_be_visible_ indicates that the WebContents is already in that state. Unclear if this is a bug or not but it seems like we should probably suppress shown/hidden calls in MWCO if the visibility state we are tracking indicates that the WebContents is already in that state.
,
Feb 27 2016
Note that this wouldn't have caused incorrect metrics tracking until https://codereview.chromium.org/1686643002/ was landed yesterday, so this is a new issue.
,
Feb 27 2016
,
Feb 29 2016
Looking through our code that depends on fg/bg times, the only thing that would be impacted by this issue is the metric added in the recent CL linked above.
The logic for that metric is recorded like so:
if (!info.started_in_foreground && !info.first_foreground_time.is_zero() &&
timing.first_paint > info.first_foreground_time &&
(info.first_background_time.is_zero() ||
timing.first_paint < info.first_background_time)) {
PAGE_LOAD_HISTOGRAM(
internal::kHistogramForegroundToFirstPaint,
timing.first_paint - info.first_foreground_time);
}
If a page load starts in the background, spuriously notifies that it is in the background, then foregrounds, we'll fail to record the histogram when we should have done so. This is better than recording an erroneous value in the histogram, but may still skew results.
pkotwicz did a really nice job making sure our other histograms would not be impacted as part of his change, so none of our other histograms should be impacted by this bug.
,
Feb 29 2016
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/8de43b1b18151fd3428cb9812a95254e36770f84 commit 8de43b1b18151fd3428cb9812a95254e36770f84 Author: bmcquade <bmcquade@chromium.org> Date: Mon Feb 29 15:38:02 2016 Suppress spurious foreground/background notifications WebContentsObserver::WasShown/WasHidden can be invoked for WebContents that are already in that state. This can cause us to track first foreground/background time incorrectly. This change suppresses shown/hidden notifications when we're already in that state, so our first fg/bg time tracking works correctly. BUG= 590476 Review URL: https://codereview.chromium.org/1740403002 Cr-Commit-Position: refs/heads/master@{#378212} [modify] https://crrev.com/8de43b1b18151fd3428cb9812a95254e36770f84/components/page_load_metrics/browser/metrics_web_contents_observer.cc
,
Feb 29 2016
The recently landed https://codereview.chromium.org/1740403002/ protects our code against this issue. The larger issue is being worked on as part of https://codereview.chromium.org/1743143002/. Once that lands, we should update our MWCO code to DCHECK that this never happens. |
|||
►
Sign in to add a comment |
|||
Comment 1 by bmcquade@chromium.org
, Feb 27 2016TabLoader::LoadNextTab has the following logic: Browser* browser = chrome::FindBrowserWithWebContents(contents); if (browser && browser->tab_strip_model()->GetActiveWebContents() != contents) { // By default tabs are marked as visible. As only the active tab is // visible we need to explicitly tell non-active tabs they are hidden. // Without this call non-active tabs are not marked as backgrounded. // // NOTE: We need to do this here rather than when the tab is added to // the Browser as at that time not everything has been created, so that // the call would do nothing. contents->WasHidden(); } If I understand this correctly, this code is calling WasHidden on a WebContents that is not the active web contents in the tab strip, in other words, calling WasHidden on a WebContents that is already hidden. This explains why our assertion would fire. This also seems like a bug - if a WC is already non-visible, we shouldn't be calling WasHidden on it. But I don't understand this code well enough to know for sure.