Closed Bug 1425273 Opened 7 years ago Closed 7 years ago

eventTimings should be loaded lazily

Categories

(DevTools :: Netmonitor, defect, P1)

Product:
DevTools
Component:
Netmonitor
Type:
defect

Tracking

(firefox59 fixed)

Status:
RESOLVED FIXED
Milestone:
Firefox 59
Tracking Flags:
Tracking Status
firefox59 --- fixed

People

(Reporter: rickychien, Assigned: rickychien)

References

Details

Attachments

(4 files, 1 obsolete file)

Bug 1425273 - eventTimings should be loaded lazily
59 bytes, text/x-review-board-request
ochameau
: review+
Details
Bug 1425273 - Waiting for event timings in damp test
59 bytes, text/x-review-board-request
ochameau
: review+
Details
lazy-fetch-timings.mov
7.85 MB, video/quicktime
Details
original.mov
9.59 MB, video/quicktime
Details
Lazy fetch eventTimings looks promising for improving netmonitor perf.
Assignee: nobody → rchien
Status: NEW → ASSIGNED
Priority: P2 → P1
Split damp.js fix into another patch. Try is green and ready for review.
Comment on attachment 8938645 [details] Bug 1425273 - Waiting for event timings in damp test https://reviewboard.mozilla.org/r/209240/#review215430 ::: testing/talos/talos/tests/devtools/addon/content/damp.js:805 (Diff revision 1) > requests.set(id, true); > maybeResolve(); > } > > + function onTimingsUpdating(_, id) { > + if (!requests.has(id)) { There is a typo here, it should be `if (timings.has(id) {` this ends up making DAMP results for requestsFinished being wrong. I pushed with a fixed, but now DAMP reports a regression: https://treeherder.mozilla.org/perf.html#/comparesubtest?originalProject=mozilla-central&newProject=try&newRevision=4218e197ad8327b33c229ae4da6eb41898fdb73c&originalSignature=edaec66500db21d37602c99daa61ac983f21a6ac&newSignature=edaec66500db21d37602c99daa61ac983f21a6ac&showOnlyImportant=1&framework=1&selectedTimeRange=172800 Could you push youself with a fix for this just to be sure? Also, here, we use a Map, but it would be simplier to use a Set and check if both Sets are empty in maybeResolve.
Attachment #8938645 - Flags: review?(poirot.alex) → review-
Attachment #8938645 - Attachment is obsolete: true
Attachment #8938645 - Flags: review?(poirot.alex)
Comment on attachment 8936909 [details] Bug 1425273 - eventTimings should be loaded lazily https://reviewboard.mozilla.org/r/207636/#review215796 As results weren't good, I pushed with a custom base build to have number we can trust. https://treeherder.mozilla.org/perf.html#/comparesubtest?originalProject=try&originalRevision=346dcfeb0f47fd4dffbac0944bf6b58618fd91d6&newProject=try&newRevision=8985f8c0a9813ac0e386af77cc36299999a670ad&originalSignature=edaec66500db21d37602c99daa61ac983f21a6ac&newSignature=edaec66500db21d37602c99daa61ac983f21a6ac&showOnlyImportant=1&framework=1 complicated.reload -5.90% complicated.requestsFinished +2.24% simple.requestsFinished +7.74% It means that the page is faster to reload, but netmonitor is slower to update. I think that's because this patch introduces additional reflows/redux actions. Without this patch, we have only one "updateRequest" call, once payload is ready. With this patch, we have an additional one, for each request. That fires when we fetch eventTimings for all the requests. I don't think we should proceed with this. eventTimings is always used. There is no value in moving it outside of the payload logic. ::: devtools/client/netmonitor/src/components/RequestListItem.js:143 (Diff revision 8) > if (requestFilterTypes.xhr || requestFilterTypes.ws) { > - fetchNetworkUpdatePacket(connector.requestData, item, [ > + requestTypes = [ > + ...requestTypes, > "requestHeaders", > "responseHeaders", > - ]); > + ]; You can prevent re-creating a new array by doing this: requestTypes.push("requestHeaders", "responseHeaders"); ::: devtools/client/netmonitor/src/components/RequestListItem.js:159 (Diff revision 8) > if (requestFilterTypes.xhr || requestFilterTypes.ws) { > - fetchNetworkUpdatePacket(connector.requestData, item, [ > + requestTypes = [ > + ...requestTypes, > "requestHeaders", > "responseHeaders", > - ]); > + ]; Same use, please use Array.push.
Attachment #8936909 - Flags: review?(poirot.alex) → review-
Latest damp test result base on your base (346dcfeb0f47 - try) on comment 17. https://treeherder.mozilla.org/perf.html#/comparesubtest?originalProject=try&originalRevision=346dcfeb0f47&newProject=try&newRevision=7c9f07505882&originalSignature=edaec66500db21d37602c99daa61ac983f21a6ac&newSignature=edaec66500db21d37602c99daa61ac983f21a6ac&showOnlyImportant=1&framework=1 complicated.reload -6.27% simple.requestsFinished +7.86% It indicates a win for complicated.reload and slower update only happens in simple.requestsFinished. My complicated.requestsFinished shows +1.70% (med) comparing with your result +2.24% (high). I believe that the 1% ~ 2% is small regression we can take if it can bring other benefits. Right now eventTimings is using by RequestListColumnWaterfall, StatisticPanel & TimingsPanel. RequestListColumnWaterfall component is enabled by default, so the default performance will drop a little. However, if someone hides waterfall column, we can expect that the update will be faster. IMO, damp result is just a benchmark. Ideally, I believe lazily fetching eventTimings can bring us perceived perf. Because we don't have to wait for eventTimings packet arrival to update request item component. Instead, all requests would be rendered earlier without waiting for eventTimings (no complete waterfall info at the moment), so user can start checking other request columns earlier. What do you think?
(In reply to Ricky Chien [:rickychien] from comment #18) > I believe that the 1% ~ 2% is small regression we can take if it can bring > other benefits. Right now eventTimings is using by > RequestListColumnWaterfall, StatisticPanel & TimingsPanel. > RequestListColumnWaterfall component is enabled by default, so the default > performance will drop a little. However, if someone hides waterfall column, > we can expect that the update will be faster. Default setting's performance prevails custom setup. I doubt many people (if anyone?) hide the waterfall. > IMO, damp result is just a benchmark. No. This isn't "just a benchmark". It translates to perceived performance. The limitation is its test script, which only covers some particular scenarios. So if it doesn't report a win, it doesn't necessarely mean that there is no win. A win is still possible on another scenario, not being covered by DAMP. For example, if we hide the waterfall. But, if DAMP regress, you are very likely going to regress a real use case. And we made it so that the use cases covered by DAMP represent important want we want to prevent regressing. > Ideally, I believe lazily fetching eventTimings can bring us perceived perf. It would help if you can prove that. With the profiler, screen recording, custom console log timings,... anything else but a feeling. > Because we don't have to wait for eventTimings packet arrival to update request item component. > Instead, all requests would be rendered earlier without waiting for eventTimings (no > complete waterfall info at the moment), so user can start checking other > request columns earlier. I'm concerned because this patch most likely double the number of reflows. And reflows are known to be slow in netmonitor. The issue is that there is so many reflows, that it is hard to compare by looking at the profiler. We lack from good tooling that would help comparing reflow performances. I wouldn't be concerned if reflows in netmonitor weren't a known issue...
Attached video original.mov —
Good suggestion, I've uploaded screen recordings for showing difference of perceived performance. Note that I didn't combine two videos into one for frame by frame comparison, because loading speed of real website (e.g cnn.com) performs randomly depends on network condition). With using lazy fetching timings (attachment 8940953 [details]), I can recognize the "updated info" of the added request will be displayed earlier. It's obvious distinguishable in most of my cases. Please pay attention on "Status Column", the green icon will be replaced the grey dot icon soon since the updated info is arrived sooner than before. On the other hand, you can notice that there are more grey dots appear in original approach (attachment 8940954 [details]) because we always want for eventTimings to update entire request instance.
Flags: needinfo?(poirot.alex)
(In reply to Ricky Chien [:rickychien] from comment #26) > Good suggestion, I've uploaded screen recordings for showing difference of > perceived performance. Thanks for the record, that is helpful. I see your point. I've been trying to profile your patch to ensure we are not going to introduce additional hangs on slow machines. (do not forget your computer is high end compared to the one used by many developers) Profiler results looks good: * profile without the patch https://perfht.ml/2CSMiuh 1.360s spent on ::Reflow methods * profile with patch https://perfht.ml/2CW5urj 1020s spent on ::Reflow methods So even if we end up dispatching more Redux actions, doing more React updates and more reflows, it seems to make the reflows be overall faster to execute. I would like to assert that via DAMP, for that I introduced reflow count and duration in a new subtest, but I think I poorly rebased your patch: https://treeherder.mozilla.org/perf.html#/comparesubtest?originalProject=try&originalRevision=f32584178d2dc2f0f7281488e1868056fcd4f8d8&newProject=try&newRevision=6e5705bc7fcc5fe9deaa2433476e111145339ad6&originalSignature=edaec66500db21d37602c99daa61ac983f21a6ac&newSignature=edaec66500db21d37602c99daa61ac983f21a6ac&showOnlyImportant=1&framework=1 Could you remove the modification you made on the waterfall and only keep the eventTiming patch in this bug? (if you found some optimization to be made against the waterfall, please open another bug)
Flags: needinfo?(poirot.alex)
Cool! thanks for helping profiling. It's nice result that we almost get 300ms reduction for the time we spending on ::Reflow. Sorry I didn't explain the latest update since comment 29. I noticed there is something doing wrong in my previous patch. Lazy fetching "eventTimings" should be done in RequestListColumnWaterfall instead of RequestListItem. Otherwise, eventTimings packet will be fetched all the time even though the waterfall column is hidden. Other modifications: * getWaterfallScale() selector will be invoked more frequently, so it makes sense to introduce reselect for reducing redundant calculation. * Removing "--timings-scale": scale, "--timings-rev-scale": 1 / scale approach but update scale value directly in RequestListColumnWaterfall component. * Make RequestListColumnWaterfall as connected component (pulling timingsScaleX props from redux directly instead parent component). Because water column is optional and can be hide by user, so we can avoid watching timingsScaleX props changes in RequestListItem & RequestListContent.
One more thing, I'm going to update the damp.js according to the definition change of perceived perf. If we're targeting on getting our major request info faster (e.g. status, method, file, domain, size column...etc) except waterfall timeline, and we should not wait for RECEIVED_EVENT_TIMINGS in damp.js anymore. Instead, PAYLOAD_READY event would be enough for our major request info.
Patch updated for improving damp test stability. Currently, we're using Map object to record the request status [1]. However, the worst case would be, if there some followed PAYLOAD_READY events arrive soon after REQUEST_ADDED events, and then all requests will be set to true and pass the maybeResolve() condition [2]. This issue happens occasionally in my local run, even without applying this patch. Therefore, I try to wait for TOTAL_REQUESTS = 280. [1] https://searchfox.org/mozilla-central/source/testing/talos/talos/tests/devtools/addon/content/damp.js#821,824,828 [2] https://searchfox.org/mozilla-central/source/testing/talos/talos/tests/devtools/addon/content/damp.js#834
Could you keep this bug only for eventTimings and remove every other modifications? i.e. revert back to revision 8, but with a rebase against latest tip. Feel free to submit patches for all other modification in other bugs, and do not mix unrelated modifications. Regarding DAMP fix. Please keep waiting for event timings. We want to wait for all netmonitor UI updates. We still want to track waterfall rendering as it is known to be a costly operation. If you want, we can introduce another subtest, tracking a subset of requestsFinished. We already have "reload" test, which tracks page load event and is a test tracked in parallel to requestsFinished.
> Regarding DAMP fix. Please keep waiting for event timings. We want to wait for all netmonitor UI updates. Done. > Could you keep this bug only for eventTimings and remove every other modifications? Sorry, it wasn't clear in comment 31. All modifications are related to eventTimings. The revision 8 was wrong because I fetch eventTimings from RequestListItem. After fetching eventTimings in RequestListColumnWaterfall, some of those followed modifications are needed. If you have concerns, some new modifications could be reverted: > * getWaterfallScale() selector will be invoked more frequently, so it makes sense to introduce reselect for reducing redundant calculation. Using reselector for getWaterfallScale can be reverted, but lacking reselect we cannot memorize preceding value of each input-selector (e.g. state.requests, state.timingMarkers, state.ui). > * Removing "--timings-scale": scale, "--timings-rev-scale": 1 / scale approach but update scale value directly in RequestListColumnWaterfall component. The follow-up change after fetching eventTimings in RequestListColumnWaterfall is reasonable. I moved transform: `scaleX(${timingsScaleX}) to RequestListColumnWaterfall since it's the responsibility for RequestListColumnWaterfall component to watch timingsScaleX props and update itself. Once the waterfall column is hidden, we're no longer to watch timingsScaleX and update CSS transform. It's way better than always updating CSS transform in RequestListContent. > * Make RequestListColumnWaterfall as connected component (pulling timingsScaleX props from redux directly instead parent component). Because water column is optional and can be hide by user, so we can avoid watching timingsScaleX props changes in RequestListItem & RequestListContent. This change is required and cannot be reverted reflecting to the change of fetching eventTimings in RequestListColumnWaterfall. As a result, I think using reselect in getWaterfallScale is revertible. But I don't think it will introduce so much effort or complexity for review or perf test. Please tell me if I'm wrong or maybe your opinion why think revision 8 is better.
Flags: needinfo?(poirot.alex)
> Regarding DAMP fix. Please keep waiting for event timings. We want to wait for all netmonitor UI updates. Okay, it also means lazy fetching eventTimings will cause damp regression but it's okay and we can take. It makes sense to me to keep tracking eventTimings for our requestsFinished test as well.
(In reply to Ricky Chien [:rickychien] from comment #41) > As a result, I think using reselect in getWaterfallScale is revertible. But > I don't think it will introduce so much effort or complexity for review or > perf test. Please tell me if I'm wrong or maybe your opinion why think > revision 8 is better. You are modifying too many things in a single patch, there is no way to evaluate the performance impact of individual changes. I'm interested to evaluate the impact of --timing-scale removal alone. As well as your change to stop using requestIdleCallback, which was here for a reason and you removed without justifying it.
Flags: needinfo?(poirot.alex)
The real cost of --timing-scale is transform itself, I moved transform into waterfall component so the result ideally should be the same. I'm fine to split it as an independent patch for your evaluation work. For requestIdleCallback, it is using for postponing `this.props.resizeWaterfall` action (not debounce) when componentDidMount & window.resize event. I believe it's obvious no impact on requestFinish or damp result unless you want to track window resizing.
If your concerns is mainly about perf evaluation, could you tell me which part of patch you're interested? I'd love to split it into smaller pieces as you want. Thanks :)
Flags: needinfo?(poirot.alex)
P.S. The movement of this.resizeWaterfall() to waterfallLabel() is reasonable because calling in componentDidMount won't work properly when user hides / unhides the timeline column. It requires to dispatch this.props.resizeWaterfall action immediately without delaying by requestIdleCallback, otherwise the resizeWaterfall action will never be invoked and the timeline column will be empty.
(In reply to Ricky Chien [:rickychien] from comment #45) > The real cost of --timing-scale is transform itself, I moved transform into > waterfall component so the result ideally should be the same. I'm fine to > split it as an independent patch for your evaluation work. This is another significant difference. With your patch, you no longer use a CSS var, but style attribute via React. This may have an impact. Please, factor this out. This can be landed independantly from event timing patch. I think this may bring a direct performance improvement (perceived and on DAMP) and would like you to land this first. > For requestIdleCallback, it is using for postponing > `this.props.resizeWaterfall` action (not debounce) when componentDidMount & > window.resize event. I believe it's obvious no impact on requestFinish or > damp result unless you want to track window resizing. https://searchfox.org/mozilla-central/source/devtools/client/netmonitor/src/components/RequestListHeader.js#95-98 // Measure its width and update the 'waterfallWidth' property in the store. // The 'waterfallWidth' will be further updated on every window resize. window.cancelIdleCallback(this._resizeTimerId); this._resizeTimerId = window.requestIdleCallback(() => this.props.resizeWaterfall(waterfallHeader.getBoundingClientRect().width)); This doesn't only postpone. It agreggates the updates. Everyime there is a new call to resizeWaterfall, we cancel any pending idle callback and register a brand new one. Whe we do so we prevent an additional call to props.resizeWaterfall. I'm expecting this particular modification to have a negative impact on perf. It will fallback to default redux throttle (batching.js) and use setTimeout of 50ms, which isn't waiting as much as requestIdleCallback. Can you also factor this out? This can also be landed before the event timing patch. I understand that you may need this patch before landing event timings, but you don't need lazy fetching event timing patch before landing this. Note that you can attach multiple patches to a single bug. Feel free to attach all the patches to this bug. Also, I don't know if you saw, but comment 43's try push report a 24% regression on complicated.requestsFinished, this looks very bad. It sounds even more important to understand the impact of your individual modifications.
Flags: needinfo?(poirot.alex)
Patch has updated reflecting comment 48. Reverting --timing-scale changes & requestIdleCallback. Note that the removal of the requestIdleCallback for this.props.resizeWaterfall only affect on window resizing behavior, it shouldn't have impact on requestFinished benchmark.
Comment on attachment 8936909 [details] Bug 1425273 - eventTimings should be loaded lazily https://reviewboard.mozilla.org/r/207636/#review218818 Thanks a lot Ricky, it looks good. Perceived performance looks better, even on slow computer. Local profiling now shows a small regression in reflow duration: With your patch: https://perfht.ml/2Dn3pEI 1210ms Without your patch: https://perfht.ml/2mzXPoc 980ms But this is small and may just be related to some noise on my machine. So to get better numbers I pushed it to try with a custom tweak made to DAMP in order to record reflows count and duration: https://treeherder.mozilla.org/perf.html#/comparesubtest?originalProject=try&originalRevision=bcf0d3c5f5ebebbdbff07650f319833c32725296&newProject=try&newRevision=b05b26e97a89f304468e53df721417c3161ec1b9&originalSignature=edaec66500db21d37602c99daa61ac983f21a6ac&newSignature=edaec66500db21d37602c99daa61ac983f21a6ac&filter=reflows&framework=1 Your patch reduces a bit the number of reflows and reduces significantly their overall duration. ::: devtools/client/netmonitor/src/components/RequestListItem.js:178 (Diff revision 17) > ]); > } > } > > componentWillReceiveProps(nextProps) { > - let { connector, item, requestFilterTypes } = nextProps; > + let { connector, item, requestFilterTypes } = this.props; You should keep using `nextProps` here. Otherwise fetchNetworkUpdatePatcket will misbehave.
Attachment #8936909 - Flags: review?(poirot.alex) → review+
Comment on attachment 8939763 [details] Bug 1425273 - Waiting for event timings in damp test https://reviewboard.mozilla.org/r/210068/#review218814 ::: testing/talos/talos/tests/devtools/addon/content/damp.js:974 (Diff revision 13) > let toolbox = gDevTools.getToolbox(target); > let window = toolbox.getCurrentPanel().panelWin; > > return new Promise(resolve => { > - // Key is the request id, value is a boolean - is request finished or not? > - let requests = new Map(); > + // Explicitly waiting for specific number of requests arrived > + let requestCount = (type === "simple.netmonitor") ? 1 : 280; Could you name this variable `expectedRequests` and instead of passing `type` to waitForAllRequestsFinished, pass `expectedRequests`? See `_getToolLoadingTests` and existing expectedSources, expectedMessages as example.
Attachment #8939763 - Flags: review?(poirot.alex)
Thanks for helping profiling the result. Issue of damp test has been addressed, please check it again.
Comment on attachment 8939763 [details] Bug 1425273 - Waiting for event timings in damp test https://reviewboard.mozilla.org/r/210068/#review218844 Looks good, thanks.
Attachment #8939763 - Flags: review?(poirot.alex) → review+
Pushed by rchien@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/68e67e45eb90 eventTimings should be loaded lazily r=ochameau https://hg.mozilla.org/integration/autoland/rev/2366aeabd64c Waiting for event timings in damp test r=ochameau
https://hg.mozilla.org/mozilla-central/rev/68e67e45eb90 https://hg.mozilla.org/mozilla-central/rev/2366aeabd64c
Status: ASSIGNED → RESOLVED
Closed: 7 years ago
status-firefox59: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 59
Depends on: 1431912
Product: Firefox → DevTools
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: