The TTI metric returns incorrect values when benchmark navigates to another page |
|||||||
Issue descriptionThe 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
,
Feb 14 2017
,
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?
,
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
,
Feb 14 2017
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.
,
Feb 14 2017
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"?
,
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.
,
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
,
Feb 14 2017
Ok no it doesn't look like that patch is checking for frames. You may have to do something more involved.
,
Feb 20 2017
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?
,
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
,
Feb 22 2017
One way to fix it: https://codereview.chromium.org/2712773002/
,
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
,
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
,
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
,
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
,
Oct 3 2017
Should this be marked fixed?
,
Oct 5 2017
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.
,
Jan 16
,
Jan 16
|
|||||||
►
Sign in to add a comment |
|||||||
Comment 1 by tdres...@chromium.org
, Feb 14 2017