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

Issue 692112 link

Starred by 1 user

Issue metadata

Status: WontFix
Owner:
Closed: Oct 2017
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: ----
Pri: 3
Type: Bug



Sign in to add a comment

The TTI metric returns incorrect values when benchmark navigates to another page

Project Member Reported by u...@chromium.org, Feb 14 2017

Issue description

The addFirstInteractiveSample function [1] looks for interactive window starting from the FMP until the end of the traces.
But it should stop when new page load starts.

Here is an example of loading metrics timestamps I obtained by running v8.browsing_desktop using this CL (https://codereview.chromium.org/2695063002).

onload timestamps:
[2012.4950000047684,2336.774999976158,2338.348999977112,5393.100000023842,5730.2300000190735,5730.582000017166,12416.012000024319,12491.569999992847,12606.333000004292,13282.557999968529,14007.943000018597,14171.489000022411,14173.598999977112,20288.450999975204,20379.93900001049,20487.907000005245,20611.944000005722,23134.764999985695,23219.241999983788,23219.938000023365,28266.936999976635,29837.769999980927,29889.81400001049,29993.288999974728,30763.59700000286,33431.69800001383,33544.59700000286,33545.082000017166,40293.17900002003]

first contentful paint timestamps:
[2012.4950000047684,2336.774999976158,2338.348999977112,5393.100000023842,5730.2300000190735,5730.582000017166,12416.012000024319,12491.569999992847,12606.333000004292,13282.557999968529,14007.943000018597,14171.489000022411,14173.598999977112,20288.450999975204,20379.93900001049,20487.907000005245,20611.944000005722,23134.764999985695,23219.241999983788,23219.938000023365,28266.936999976635,29837.769999980927,29889.81400001049,29993.288999974728,30763.59700000286,33431.69800001383,33544.59700000286,33545.082000017166,40293.17900002003]

first meaningful paint timestamps:
[2337.847000002861,5589.356000006199,12491.350000023842,14091.962000012398,20379.733999967575,23220.57999998331,29889.57800000906,33480.967999994755,40362.33399999142]

first interactive timestamps:
[43073.93599999905,43073.93599999905,43073.93599999905,43073.93599999905,43073.93599999905,43073.93599999905,43073.93599999905,43073.93599999905,43073.93599999905]

There are multiple page loads but they all get the same TTI.

To reproduce the log above:
1. Download and unpack the trace https://drive.google.com/a/google.com/file/d/0B32SjC0_2KAdMkljWDZscWFvNWs/view?usp=sharing

2. ./third_party/catapult/tracing/bin/html2trace browse_news_nytimes02017-02-14_17-35-00.html nytimes

3. apply https://codereview.chromium.org/2695063002 to ./third_party/catapult

4. ./third_party/catapult/tracing/bin/run_metric nytimes loadingMetric

Links:
[1] https://cs.chromium.org/chromium/src/third_party/catapult/tracing/tracing/metrics/system_health/loading_metric.html?rcl=e720bbeab573f1e2733f1607a5841f374a091057&l=234
 
browse_news_nytimes02017-02-14_17-35-00.html.tar.gz
14.0 MB Download
Yup, we should fix this.

ulan@, do you want to take this, or would you prefer dproy@ take it on?
Components: Speed>Metrics

Comment 3 by dproy@chromium.org, Feb 14 2017

I think we had a discussion about this before: 
https://bugs.chromium.org/p/chromium/issues/detail?id=640957#c6

We didn't fix the issue back then because we wanted to detect TTI across redirects. Is that still the case? 

Comment 4 by dproy@chromium.org, Feb 14 2017

This issue will come up a lot more as people start to use TTI in their metrics, and if we cannot find a big enough quiet window to fire TTI for a navigation, the saner default is to just return null meaning we don't know when TTI is, as opposed to returning the TTI value from the next navigation. Quietly returning the TTI for the next navigation can lead to many unintended bugs in other metrics. 

From ksakamoto's comment here [1] It seems to me that the only case we want TTI across navigations is when a webpage redirect happens through something like setting window.location. In the long run we can try detecting this case and then perhaps not count it as a TTI-search-stopping navigation, but I have a feeling that number of times this happens is not high enough to warrant changing the default TTI behavior. 

+nednguyen: What do you think? 

Links: 
[1]: https://bugs.chromium.org/p/chromium/issues/detail?id=640957#c4

Comment 5 by u...@chromium.org, Feb 14 2017

Owner: u...@chromium.org
Status: Assigned (was: Untriaged)
Yep, I'll take it.

I agree with dproy@. For now we could proceed with the simplest solution, i.e. compute TTI from FMP to new page load and return null if there is no TTI.

I am thinking what event to use as the "new page load" marker. I logged the number of events for v8.browsing_desktop/nytimes. The benchmark does 9 page loads, but surprisingly I get:

onload timestamps: 29
first contentful paint timestamps: 29
first meaningful paint timestamps: 9
first interactive timestamps: 9
navigationStart: 576

I suspect that onload and navigationStart events include iframes. I'll try to find a way to filter out iframe navigations.



My thoughts:
1) If the redirection happens due to the page, TTI should cover the next navigations. If people navigate to facebook.com and it redirects to m.facebook.com, users get a delay in term of visiblity & interaction, hence the metrics should penalize facebook for doing so.

2) If the redirection happens due to a user actions (typing on the browsing bar, click on the page, ...), the TTI should not include the extra navigation. If there is not a big enough quiet windows to fire TTI, then we return null as "we don't know".

The only concern I have with "null" is it may create some numerical difficulty for integration service, so maybe we use an absurdly large value instead of "null"? 

Comment 7 by dproy@chromium.org, Feb 14 2017

Re (1): I agree. But it's non-trivial to detect when this happens and this should be part of future work on TTI. Right now just keeping values for the current navigation makes things a lot simpler. Plus the tbmv2 metrics are mostly intended for chrome engineers as opposed to external developers, and the issue of whether or not an external site should be penalized becomes even less important. The more public facing TTI metric, which will be implemented in lighthouse/devtools, should handle this with more care.

I think the other bug thread mentions something about null being preferable. I can imagine if you have absurdly big numbers for some undetected TTI cases and a small reasonable number for detected TTI cases, we might end up reporting misleading big mean/stddev numbers somewhere. I'd rather return null and make the integration service explicitly handle this case instead of someone having to do cumbersome investigations into why some numbers look odd. 

Comment 8 by dproy@chromium.org, Feb 14 2017

@ulan: I think it should be enough to just look at navigationStart events in the current frame. I had a patch I never landed that I think got the job done[1]. Maybe see if this works for you?

[1] https://codereview.chromium.org/2337023004 

Comment 9 by dproy@chromium.org, Feb 14 2017

Ok no it doesn't look like that patch is checking for frames. You may have to do something more involved. 

Comment 10 by u...@chromium.org, Feb 20 2017

Cc: kouhei@chromium.org
Re #5: onload and FCP metrics do check that for iframes by looking at isLoadingMainFrame of a frameloader snapshot in the trace.
The problem is that a trace can contain multiple frameloaders that claim that they are loading the main frame at the same time.

In the attached trace only the frameloader with id=0x10d91bd81dd0 corresponds to the actual main frame. Other frameloaders have either empty url, or "about:black", or "data:text/html,pluginplaceholderdata".

I think onload and FCP metrics are confused by the latter frameloaders.

kouhei@, any idea why we have multiple frameloaders that have isLoadingMainFrame = true? 


frame-trace.txt
46.8 KB View Download

Comment 11 by u...@chromium.org, Feb 21 2017

Frame::IsMainFrame() just checks that the frame does not have a parent. This check does not guarantee that the frame is the main frame of the renderer.

For example, blink::SVGImage::dataChanged creates a frame without a parent, which is considered the main frame by tracing infra.

#0  blink::FrameLoader::init (this=0x7e16726e638) at ../../third_party/WebKit/Source/core/loader/FrameLoader.cpp:238
#1  0x00005555600fe75c in blink::LocalFrame::init (this=0x7e16726e578) at ../../third_party/WebKit/Source/core/frame/LocalFrame.h:281
#2  0x000055556178dd89 in blink::SVGImage::dataChanged (this=0x169c1f0b8d00, allDataReceived=true) at ../../third_party/WebKit/Source/core/svg/graphics/SVGImage.cpp:640
#3  0x000055555feefa7c in blink::Image::setData (this=0x169c1f0b8d00, data=..., allDataReceived=true) at ../../third_party/WebKit/Source/platform/graphics/Image.cpp:88
#4  0x0000555561544122 in blink::ImageResourceContent::updateImage (this=0x1ad6921cc938, data=..., updateImageOption=blink::ImageResourceContent::UpdateImage, allDataReceived=true) at ../../third_party/WebKit/Source/core/loader/resource/ImageResourceContent.cpp:362
#5  0x000055556153e978 in blink::ImageResource::updateImage (this=0x7e167290188, sharedBuffer=..., updateImageOption=blink::ImageResourceContent::UpdateImage, allDataReceived=true) at ../../third_party/WebKit/Source/core/loader/resource/ImageResource.cpp:522
#6  0x000055556153f311 in blink::ImageResource::finish (this=0x7e167290188, loadFinishTime=1134297.468166) at ../../third_party/WebKit/Source/core/loader/resource/ImageResource.cpp:356

Comment 12 by u...@chromium.org, Feb 22 2017

One way to fix it: https://codereview.chromium.org/2712773002/
Project Member

Comment 13 by bugdroid1@chromium.org, Mar 6 2017

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

commit 88feea0a921c2a57904b09c58f815e14f4def106
Author: ulan <ulan@chromium.org>
Date: Mon Mar 06 11:46:21 2017

Add trace event for detecting main frame in loading metrics.

The loading metrics use trace events with the "frame" argument to
compute the time to FCP, FMP, TTI. Example: https://goo.gl/U1qsqW.

In order to work properly the metrics need a way to filter out all
events that are not related to the main frame of the renderer.

This patch adds a trace event named "markAsMainFrame" in the "loading"
category with the "frame" argument equal to the local frame address in
- WebLocalFrameImpl::initializeCoreFrame,
- WebFrame::swap.

BUG= 692112 

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

[modify] https://crrev.com/88feea0a921c2a57904b09c58f815e14f4def106/third_party/WebKit/Source/web/WebFrame.cpp
[modify] https://crrev.com/88feea0a921c2a57904b09c58f815e14f4def106/third_party/WebKit/Source/web/WebLocalFrameImpl.cpp

Project Member

Comment 14 by bugdroid1@chromium.org, May 15 2017

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

commit b4783809cfe3a53ba12ca6b0fb9803aa9cab2b72
Author: catapult-deps-roller@chromium.org <catapult-deps-roller@chromium.org>
Date: Mon May 15 18:38:25 2017

Roll src/third_party/catapult/ 37015fb47..9e7bc18ce (1 commit)

https://chromium.googlesource.com/external/github.com/catapult-project/catapult.git/+log/37015fb470d8..9e7bc18ce705

$ git log 37015fb47..9e7bc18ce --date=short --no-merges --format='%ad %ae %s'
2017-05-15 ulan Fix main frame detection in loading metrics.

Created with:
  roll-dep src/third_party/catapult
BUG= 692112 


Documentation for the AutoRoller is here:
https://skia.googlesource.com/buildbot/+/master/autoroll/README.md

If the roll is causing failures, see:
http://www.chromium.org/developers/tree-sheriffs/sheriff-details-chromium#TOC-Failures-due-to-DEPS-rolls


CQ_INCLUDE_TRYBOTS=master.tryserver.chromium.android:android_optional_gpu_tests_rel
TBR=sullivan@chromium.org

Change-Id: I2549971663d855f4ce3dadcb41901e8a4bd0b1bb
Reviewed-on: https://chromium-review.googlesource.com/506049
Reviewed-by: <catapult-deps-roller@chromium.org>
Commit-Queue: <catapult-deps-roller@chromium.org>
Cr-Commit-Position: refs/heads/master@{#471841}
[modify] https://crrev.com/b4783809cfe3a53ba12ca6b0fb9803aa9cab2b72/DEPS

Project Member

Comment 15 by bugdroid1@chromium.org, May 15 2017

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

commit 35d4f7020e94ad8e800544fb9fc01721dc942912
Author: Justin Donnelly <jdonnelly@chromium.org>
Date: Mon May 15 23:51:08 2017

Revert "Roll src/third_party/catapult/ 37015fb47..9e7bc18ce (1 commit)"

This reverts commit b4783809cfe3a53ba12ca6b0fb9803aa9cab2b72.

Reason for revert: This roll appears to have broken a test (TimelineBasedPageTestTest.testFirstPaintMetricSmoke) on a couple of the Mac bots. See, for example:

https://uberchromegw.corp.google.com/i/chromium.mac/builders/Mac10.12%20Tests/builds/531

Original change's description:
> Roll src/third_party/catapult/ 37015fb47..9e7bc18ce (1 commit)
> 
> https://chromium.googlesource.com/external/github.com/catapult-project/catapult.git/+log/37015fb470d8..9e7bc18ce705
> 
> $ git log 37015fb47..9e7bc18ce --date=short --no-merges --format='%ad %ae %s'
> 2017-05-15 ulan Fix main frame detection in loading metrics.
> 
> Created with:
>   roll-dep src/third_party/catapult
> BUG= 692112 
> 
> 
> Documentation for the AutoRoller is here:
> https://skia.googlesource.com/buildbot/+/master/autoroll/README.md
> 
> If the roll is causing failures, see:
> http://www.chromium.org/developers/tree-sheriffs/sheriff-details-chromium#TOC-Failures-due-to-DEPS-rolls
> 
> 
> CQ_INCLUDE_TRYBOTS=master.tryserver.chromium.android:android_optional_gpu_tests_rel
> TBR=sullivan@chromium.org
> 
> Change-Id: I2549971663d855f4ce3dadcb41901e8a4bd0b1bb
> Reviewed-on: https://chromium-review.googlesource.com/506049
> Reviewed-by: <catapult-deps-roller@chromium.org>
> Commit-Queue: <catapult-deps-roller@chromium.org>
> Cr-Commit-Position: refs/heads/master@{#471841}

TBR=sullivan@chromium.org,catapult-deps-roller@chromium.org
NOPRESUBMIT=true
NOTREECHECKS=true
NOTRY=true
BUG= 692112 
CQ_INCLUDE_TRYBOTS=master.tryserver.chromium.android:android_optional_gpu_tests_rel

Change-Id: I4c80c64c90b0d9b22301500b2ca9189fb71f126b
Reviewed-on: https://chromium-review.googlesource.com/506609
Reviewed-by: Justin Donnelly <jdonnelly@chromium.org>
Commit-Queue: Justin Donnelly <jdonnelly@chromium.org>
Cr-Commit-Position: refs/heads/master@{#471947}
[modify] https://crrev.com/35d4f7020e94ad8e800544fb9fc01721dc942912/DEPS

Project Member

Comment 16 by bugdroid1@chromium.org, May 17 2017

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

commit 26d71b4f8cbf1fd071ae1817918857613d9338f7
Author: catapult-deps-roller@chromium.org <catapult-deps-roller@chromium.org>
Date: Wed May 17 05:16:56 2017

Roll src/third_party/catapult/ 37015fb47..dab2aa44c (13 commits)

https://chromium.googlesource.com/external/github.com/catapult-project/catapult.git/+log/37015fb470d8..dab2aa44c6cd

$ git log 37015fb47..dab2aa44c --date=short --no-merges --format='%ad %ae %s'
2017-05-16 nednguyen Revert of Remove webrtc_rendering_stats TBMv1 metrics (patchset #2 id:20001 of https://codereview.chromium.org/2890443002/ )
2017-05-16 rnephew Revert of [Telemetry][CodeHealth] Make unittests with fake platforms use fakes.FakePlatform (patchset #3 id:60001 of https://codereview.chromium.org/2889583003/ )
2017-05-16 rnephew [Telemetry][CodeHealth] Make unittests with fake platforms use fakes.FakePlatform
2017-05-16 ctzsm Remove android-webview-shell
2017-05-16 rnephew [Telemetry] Add Expectation module that enables disabling benchmarks/stories
2017-05-16 perezju [common/battor] Fix errors while logging
2017-05-16 nednguyen Remove webrtc_rendering_stats TBMv1 metrics
2017-05-16 perezju [Telemetry] Stop tracing/metrics before closing the browser
2017-05-16 nednguyen Remove v8_gc_latency TBMv1 metric
2017-05-16 ulan Revert of Fix main frame detection in loading metrics. (patchset #7 id:120001 of https://codereview.chromium.org/2862103002/ )
2017-05-15 jreck Quick fix to avoid corruption from binder_parser
2017-05-15 ctzsm Rename AndroidWebView.apk to WebViewInstrumentation.apk
2017-05-15 ulan Fix main frame detection in loading metrics.

Created with:
  roll-dep src/third_party/catapult
BUG= 701938 ,711065, 719447 , 720317 , 692112 , 701938 , 692112 


Documentation for the AutoRoller is here:
https://skia.googlesource.com/buildbot/+/master/autoroll/README.md

If the roll is causing failures, see:
http://www.chromium.org/developers/tree-sheriffs/sheriff-details-chromium#TOC-Failures-due-to-DEPS-rolls


CQ_INCLUDE_TRYBOTS=master.tryserver.chromium.android:android_optional_gpu_tests_rel
TBR=sullivan@chromium.org

Change-Id: I01ecaf24a0ad46e599b4e1272e8bb6204cabf75f
Reviewed-on: https://chromium-review.googlesource.com/507032
Reviewed-by: <catapult-deps-roller@chromium.org>
Commit-Queue: <catapult-deps-roller@chromium.org>
Cr-Commit-Position: refs/heads/master@{#472336}
[modify] https://crrev.com/26d71b4f8cbf1fd071ae1817918857613d9338f7/DEPS

Should this be marked fixed?

Comment 18 by u...@chromium.org, Oct 5 2017

Status: WontFix (was: Assigned)
I re-run v8.browsing_deskop/nytimes test at TOT and TTI values seem right:

first interactive timestamps:
[4019.462000013351,11363.683999897003,14288.922999979019,22143.097000003814,25235.414999843597,32853.409999967575,35007.99399983978,43439.558999897,46062.17299997902]

My fix got reverted and I didn't not reland it, so someone else must have fixed TTI in the meantime.

Closing the issue.
Components: Test>Telemetry
Components: -Speed>Telemetry

Sign in to add a comment