Bug 159577 - Web Inspector: Lots of time spent updating related resources in ResourceDetailsSidebar when loading a page with lots of resources
Summary: Web Inspector: Lots of time spent updating related resources in ResourceDetai...
Status: RESOLVED FIXED
Alias: None
Product: WebKit
Classification: Unclassified
Component: Web Inspector (show other bugs)
Version: WebKit Nightly Build
Hardware: All All
: P2 Normal
Assignee: Matt Baker
URL:
Keywords: InRadar
Depends on:
Blocks:
 
Reported: 2016-07-08 12:40 PDT by Joseph Pecoraro
Modified: 2019-02-05 17:01 PST (History)
5 users (show)

See Also:


Attachments
[IMAGE] Profile - 2s under createResourceLink (233.03 KB, image/png)
2016-07-08 12:40 PDT, Joseph Pecoraro
no flags Details
[Patch] Proposed Fix (4.19 KB, patch)
2016-07-13 16:11 PDT, Matt Baker
no flags Details | Formatted Diff | Diff
[Patch] Proposed Fix (16.54 KB, patch)
2016-07-22 18:03 PDT, Matt Baker
no flags Details | Formatted Diff | Diff
Patch (3.04 KB, patch)
2019-02-05 15:01 PST, Devin Rousso
no flags Details | Formatted Diff | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Joseph Pecoraro 2016-07-08 12:40:15 PDT
Created attachment 283192 [details]
[IMAGE] Profile - 2s under createResourceLink

Summary:
Lots of time spent updating ResourceDetailsSidebar when loading a page

See attached screenshot, 2s spent under createResourceLink during a reload of the inspector.

Backtrace:

- createResourceLink
    - _refreshRelatedResourcesSection
        - event dispatch
            - addInitiatedResource
Comment 1 Radar WebKit Bug Importer 2016-07-08 12:40:33 PDT
<rdar://problem/27251461>
Comment 2 Matt Baker 2016-07-13 16:11:32 PDT
Created attachment 283583 [details]
[Patch] Proposed Fix
Comment 3 Joseph Pecoraro 2016-07-13 22:17:32 PDT
Comment on attachment 283583 [details]
[Patch] Proposed Fix

View in context: https://bugs.webkit.org/attachment.cgi?id=283583&action=review

> Source/WebInspectorUI/UserInterface/Views/ResourceDetailsSidebarPanel.js:180
> +            this._boundRefreshRelatedResourcesSection = this.debounce(250)._refreshRelatedResourcesSection;

We chatted briefly about this. The debounce will prevent any updates if some new request goes out every 250ms or so.

If we want this to update at _at least some interval_ we would need to move off of debounce. That said, maybe debounce is fine here in practice.
Comment 4 Matt Baker 2016-07-14 12:26:21 PDT
(In reply to comment #3)
> Comment on attachment 283583 [details]
> [Patch] Proposed Fix
> 
> View in context:
> https://bugs.webkit.org/attachment.cgi?id=283583&action=review
> 
> > Source/WebInspectorUI/UserInterface/Views/ResourceDetailsSidebarPanel.js:180
> > +            this._boundRefreshRelatedResourcesSection = this.debounce(250)._refreshRelatedResourcesSection;
> 
> We chatted briefly about this. The debounce will prevent any updates if some
> new request goes out every 250ms or so.
> 
> If we want this to update at _at least some interval_ we would need to move
> off of debounce. That said, maybe debounce is fine here in practice.

It's probably fine in practice, but there is definitely room for improvement. What we actually want is to throttle, rather than debounce. I'll update our utilities.
Comment 5 BJ Burg 2016-07-21 09:57:23 PDT
Comment on attachment 283583 [details]
[Patch] Proposed Fix

Clearing r?, it seems an updated patch with throttle() is planned.
Comment 6 Matt Baker 2016-07-22 18:03:06 PDT
Created attachment 284391 [details]
[Patch] Proposed Fix
Comment 7 Joseph Pecoraro 2016-07-28 12:20:12 PDT
Comment on attachment 284391 [details]
[Patch] Proposed Fix

View in context: https://bugs.webkit.org/attachment.cgi?id=284391&action=review

Have I misunderstood how throttling is supposed to work with leading/trailing? My expectation was:

    - leading should mean that a call should trigger immediately if none is scheduled and the last was > delay
    - trailing should mean that the last scheduled call happens
    - cancel throttle should define what it does with the last scheduled call, either it cancels or allows the trailing call

Either way, we need tests that cover actual throttling of >1 call, to more accurately test these behaviors.

> Source/WebInspectorUI/UserInterface/Base/Utilities.js:1320
> +                let previousTime = null;
> +                let previousArguments = null;

Hmm, the "previous" confused me here.

How about:

    let lastFireTime = 0;
    let mostRecentArguments = null;

> Source/WebInspectorUI/UserInterface/Base/Utilities.js:1342
> +                                if (original[throttleTimeoutSymbol] || options.trailing === false)
> +                                    return;
> +                                original[throttleTimeoutSymbol] = setTimeout(performWork, remaining);

I do not understand this. If options.trailing === false, we only only schedule the timeout once? This doesn't feel right.

I'd expect options.trailing to be checked on cancelThrottle, to either include / exclude the last scheduled work.

> LayoutTests/inspector/unit-tests/throttle.html:21
> +                    InspectorTest.expectThat(performance.now() - startTime >= 10, "Call delayed at least 10ms.");

If there was a leading call, it should not have been delayed.

> LayoutTests/inspector/unit-tests/throttle.html:31
> +            let throttleProxy = object.throttle(10);
> +            throttleProxy.test();
> +            throttleProxy.test();
> +            throttleProxy.test();
> +            throttleProxy.test();

This doesn't match my expectation of how throttling with leading / trailing should work. I'd expect two calls here:

    let now = performance.now();
    let throttleProxy = object.throttle(10);
    throttleProxy.test(); // leading call, should trigger immediately ("now")
    throttleProxy.test(); // schedule a throttled call 10ms from the leading
    throttleProxy.test(); // already scheduled
    throttleProxy.test(); // already scheduled
    // ... trailing call should have triggered at ("now" + 10ms)

> LayoutTests/inspector/unit-tests/throttle.html:71
> +    suite.addTestCase({

I'd like to see non-basic tests that verify throttling is happening on a >1 call basis.

// Leading and Trailing:

    let now = performance.now();

    let throttleProxy = object.throttle(20);
    throttleProxy.test();
    for (let i = 0; i < 110; ++i)
        setTimeout(() => { thottleProxy.test(); }, i);
    setTimeout(() => { throttleProxy.cancelThrottle(); }, 111);

    // Expect calls at deltas from "now" of:
    [0 (leading), 20, 40, 60, 80, 100, 120 (trailing)]

// Leading and no Trailing

    let now = performance.now();

    let throttleProxy = object.throttle(20, {trailing: false});
    throttleProxy.test();
    for (let i = 0; i < 110; ++i)
        setTimeout(() => { thottleProxy.test(); }, i);
    setTimeout(() => { throttleProxy.cancelThrottle(); }, 111);

    // Expect calls at deltas from "now" of:
    [0 (leading), 20, 40, 60, 80, 100]

// No leading / trailing

    let now = performance.now();

    let throttleProxy = object.throttle(20, {leading: false, trailing: false});
    throttleProxy.test();
    for (let i = 0; i < 110; ++i)
        setTimeout(() => { thottleProxy.test(); }, i);
    setTimeout(() => { throttleProxy.cancelThrottle(); }, 111); // DEBATE: Should this cancel the trailing timer, or not?

    // Expect calls at deltas from "now" of:
    [20, 40, 60, 80, 100]

// Unusual intervals:

    let now = performance.now();

    let throttleProxy = object.throttle(20);
    throttleProxy.test();
    for (let i = 0; i < 30; ++i)
        setTimeout(() => { thottleProxy.test(); }, i);
    for (let i = 70; i < 100; ++i)
        setTimeout(() => { thottleProxy.test(); }, i);
    setTimeout(() => { throttleProxy.cancelThrottle(); }, 100); // DEBATE: Should this cancel the trailing timer, or not?

    // Expect calls at deltas from "now" of:
    [(leading) 0, 20, 40, (new leading) 70, 90, 110 (trailing)]

// Likewise, a test where throttling is cancelled after the trailing call:

    let now = performance.now();

    let throttleProxy = object.throttle(20);
    throttleProxy.test();
    for (let i = 0; i < 50; ++i)
        setTimeout(() => { thottleProxy.test(); }, i);
    setTimeout(() => { throttleProxy.cancelThrottle(); }, 100);

    // Expect calls at deltas from "now" of:
    // NOTE: The "trailing call" happened at 60, since there was no tickle between 60 and 100, the "60" was trailing the last tickle.
    [0 (leading), 20, 40, 60]
Comment 8 Devin Rousso 2019-02-05 15:01:00 PST
Created attachment 361223 [details]
Patch

Update, now that `throttle` exists.
Comment 9 Joseph Pecoraro 2019-02-05 16:12:38 PST
Comment on attachment 361223 [details]
Patch

r=me
Comment 10 WebKit Commit Bot 2019-02-05 17:01:43 PST
Comment on attachment 361223 [details]
Patch

Clearing flags on attachment: 361223

Committed r241004: <https://trac.webkit.org/changeset/241004>
Comment 11 WebKit Commit Bot 2019-02-05 17:01:45 PST
All reviewed patches have been landed.  Closing bug.