Improve message batching debounce logic

RESOLVED FIXED in Firefox 56

Status

()

Firefox
Developer Tools: Console
P1
normal
RESOLVED FIXED
7 months ago
4 months ago

People

(Reporter: bgrins, Assigned: Honza)

Tracking

(Blocks: 3 bugs)

unspecified
Firefox 56
Points:
---
Dependency tree / graph
Bug Flags:
qe-verify -

Firefox Tracking Flags

(firefox56 fixed)

Details

(Whiteboard: [console-html])

MozReview Requests

()

Submitter Diff Changes Open Issues Last Updated
Loading...
Error loading review requests:

Attachments

(1 attachment, 2 obsolete attachments)

(Reporter)

Description

7 months ago
For now, we wait 50ms as we receive messages before attempting to re-render.  This leads to a slow response if a single message was logged.

We could try to debounce with a lower limit, but have a max wait time.  For example, if we waited only 16ms, but then restarted the timer when a new message is received up until a 50 or 100ms limit, it could improve both the stream and bulk logging cases.
(Reporter)

Comment 1

7 months ago
Some measurements I took locally:

Current implementation: 50ms delay, 10000 messages.  Batches:

Run 1: [249, 686, 27, 40, 78, 382, 2361, 1604, 5536]
Run 2: [27, 64, 259, 302, 1639, 2323, 5414]

With patch: 16ms delay min, 250ms delay max, 10000 messages.  Batches:

Run 1: [328, 1174, 1843, 6656]
Run 2: [312, 2015, 2677, 4997]

With patch: 50ms delay min, 250ms delay max, 10000 messages.  Batches:

Run 1: [334, 1439, 2765, 5463]
Run 2: [330, 1054, 5164, 3453]

With patch: 16ms delay min, 500ms delay max, 10000 messages.  Batches:

Run 1: [661, 4386, 4954]
Run 2: [97, 1244, 2816, 5844]

With patch: 50ms delay min, 500ms delay max, 10000 messages.  Batches:

Run 1: [625, 5238, 4138]
Run 2: [560, 2893, 4809, 1739]

Granted this is all just from local data, but my main takeaway is that this does generally limit churn and useless renders that don't end up staying on the page.

The least number of re-renders are 50ms/500ms, but that feels really slow for streaming logs.  16ms/500ms might be the best for bulk logging perf and streaming responsiveness.  Even when I log on rAF on the content page I still end up seeing about 1 or 2 per batch so it actually looks like streaming.  We could play with the numbers some more but I think it's worth proceeding.
Comment hidden (mozreview-request)

Updated

7 months ago
Flags: qe-verify?
Priority: -- → P2
(Assignee)

Comment 3

7 months ago
I like the patch and I think the same technique can be reused in other panels. I am thinking specifically about the Net panel that is using batching-enhancer too.

The batching logic is currently split into three pieces:
1) batchActions action creator (actions/enhancer.js)
2) batchingReducer an enhancer (store.js)
3) batchedMessageAdd helper function (new-console-output-wrapper.js)

I am wondering if the whole logic could be done at one place, so it's nicely shareable/reusable across our tools. Can we put all of these pieces together and build an independent enhancer object/module?

Another related question. Why we are clearing inside `messageAdd` action creator?
http://searchfox.org/mozilla-central/rev/cd8c561106d804e26bc09389f18f361846d005eb/devtools/client/webconsole/new-console-output/actions/messages.js#36

Honza

Updated

6 months ago
Flags: qe-verify? → qe-verify-
(Assignee)

Updated

6 months ago
Assignee: nobody → odvarko
Status: NEW → ASSIGNED
(Assignee)

Comment 4

6 months ago
Created attachment 8870041 [details] [diff] [review]
debounce-middleware.patch

I am attaching first version of debounce middleware.

Honza
(Assignee)

Comment 5

6 months ago
Patches from bug 1307884 are needed

Honza

Updated

6 months ago
Iteration: --- → 55.6 - May 29
Priority: P2 → P1
Comment hidden (mozreview-request)
(Assignee)

Updated

6 months ago
Attachment #8870041 - Attachment is obsolete: true
(Assignee)

Updated

6 months ago
Attachment #8870289 - Attachment is obsolete: true
Attachment #8870289 - Flags: review?(bgrinstead)
(Assignee)

Comment 7

6 months ago
Bug 1307884 landed and I am attaching proper patch for review.

Possible enhancements:

1) The middleware can return return something useful (making `dispatch` to return something useful). For example, a method that can be used to flush the current action queue.
2) `batchAction` action creator can be moved into separate module. Or we might want to rename the current module and keep all within.
3) `debounceFlag` can be true by default. Or `debouncing` might be done by default so, we could introduce `noDebounce` flag.

Might be as well done later.

Honza
Comment hidden (mozreview-request)
(Assignee)

Updated

6 months ago
Attachment #8866924 - Attachment is obsolete: true

Updated

6 months ago
Iteration: 55.6 - May 29 → 55.7 - Jun 12
(Reporter)

Comment 9

6 months ago
I know this code doesn't depend on Bug 1363678, but I'd like to do a clean set of measurements before/after this patch once that lands, so setting it up as a blocker
Depends on: 1363678
(Reporter)

Comment 10

6 months ago
mozreview-review
Comment on attachment 8870289 [details]
Bug 1364150 - Introduce debounce middleware;

https://reviewboard.mozilla.org/r/141754/#review148996

Sorry for the delay.  This needs a rebase after Bug 1363678

::: devtools/client/webconsole/new-console-output/new-console-output-wrapper.js:174
(Diff revision 2)
>      return Promise.resolve();
>    },
>  
>    dispatchMessagesAdd: function (messages) {
>      const batchedActions = messages.map(message => actions.messageAdd(message));
> -    store.dispatch(actions.batchActions(batchedActions));
> +    store.dispatch(batchActions(batchedActions));

Why does this still do batchActions?  Doesn't the debouncing do this automatically for us?
Attachment #8870289 - Flags: review?(bgrinstead)
(Reporter)

Comment 11

6 months ago
Also please check the mocha test output, this appears to be breaking some of the filtering tests
Comment hidden (mozreview-request)
(Assignee)

Comment 13

6 months ago
(In reply to Brian Grinstead [:bgrins] from comment #10)
> Comment on attachment 8870289 [details]
> Bug 1364150 - Introduce debounce middleware;
> 
> https://reviewboard.mozilla.org/r/141754/#review148996
> 
> Sorry for the delay.  This needs a rebase after Bug 1363678
Done

> >    dispatchMessagesAdd: function (messages) {
> >      const batchedActions = messages.map(message => actions.messageAdd(message));
> > -    store.dispatch(actions.batchActions(batchedActions));
> > +    store.dispatch(batchActions(batchedActions));
> 
> Why does this still do batchActions?  Doesn't the debouncing do this
> automatically for us?

`batchActions` is used as a helper. I think it's still useful in cases
like this since we don't have to loop over the array of actions
explicitly and the bouncing middle-ware understands that there
is an array of actions.

(In reply to Brian Grinstead [:bgrins] from comment #11)
> Also please check the mocha test output, this appears to be breaking some of
> the filtering tests
Fixed. Tests are expecting synchronous action processing.

Honza

Comment 14

6 months ago
mozreview-review
Comment on attachment 8870289 [details]
Bug 1364150 - Introduce debounce middleware;

https://reviewboard.mozilla.org/r/141754/#review149184

::: devtools/client/shared/redux/middleware/debounce.js:67
(Diff revision 3)
> +      maxTimeout = setTimeout(doFunction, maxWait);
> +    }
> +  };
> +}
> +
> +const BATCH_ACTIONS = "BATCH_ACTIONS";

In this case, since it's a shared middelware that can be used everywhere, I'd use a Symbol so we ensure that there isn't any naming clash with the app own actions.

::: devtools/client/webconsole/new-console-output/test/store/filters.test.js:212
(Diff revision 3)
> +  const options = {
> +    noDebounce: true
> +  };

Can we add a comment explaning why we do not use debounce on tests ?
Comment hidden (mozreview-request)
(Assignee)

Comment 16

6 months ago
(In reply to Nicolas Chevobbe [:nchevobbe] from comment #14)
> Comment on attachment 8870289 [details]
> In this case, since it's a shared middelware that can be used everywhere,
> I'd use a Symbol so we ensure that there isn't any naming clash with the app
> own actions.
Good point, done.

> devtools/client/webconsole/new-console-output/test/store/filters.test.js:212
> (Diff revision 3)
> > +  const options = {
> > +    noDebounce: true
> > +  };
> 
> Can we add a comment explaning why we do not use debounce on tests ?
Done

Honza
(Reporter)

Comment 17

6 months ago
mozreview-review
Comment on attachment 8870289 [details]
Bug 1364150 - Introduce debounce middleware;

https://reviewboard.mozilla.org/r/141754/#review149216

I'm a little concerned about not testing the same code that we are shipping, but to be fair we weren't doing that previously either so it's not necessary to address here.  Though I wonder how much complexity would we have to add to the tests to be able to wait for messages to be added before proceeding with assertions, instead of preventing debouncing altogether

::: devtools/client/webconsole/new-console-output/test/store/filters.test.js:211
(Diff revision 4)
>        "text": "",
>      });
>    });
>  });
>  
>  function prepareBaseStore() {

You should be able to modify the test's setupStore function at `devtools/client/webconsole/new-console-output/test/helpers` to provide a default value for noDebounce instead of modifying or adding prepareBaseStore functions in each test.  This way we won't need to remember to do this for new tests.  And if we want a test to explicitly cover debounced actions we can opt in for that test
Attachment #8870289 - Flags: review?(bgrinstead)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
(Assignee)

Comment 20

6 months ago
(In reply to Brian Grinstead [:bgrins] from comment #17)
> Comment on attachment 8870289 [details]
> Bug 1364150 - Introduce debounce middleware;
> 
> https://reviewboard.mozilla.org/r/141754/#review149216
> 
> I'm a little concerned about not testing the same code that we are shipping,
> but to be fair we weren't doing that previously either so it's not necessary
> to address here.  Though I wonder how much complexity would we have to add
> to the tests to be able to wait for messages to be added before proceeding
> with assertions, instead of preventing debouncing altogether
I think that this might be a good candidate for a follow up.
My first reaction is that tests should disable debouncing to stay
synchronous (and simple) and we should rather introduce a new test
for the debouncing middleware itself.

> You should be able to modify the test's setupStore function at
> `devtools/client/webconsole/new-console-output/test/helpers`
Good point, fixed.

Honza
(Assignee)

Updated

6 months ago
Blocks: 1370864
(Assignee)

Comment 21

6 months ago
(In reply to Jan Honza Odvarko [:Honza] from comment #20)
> (In reply to Brian Grinstead [:bgrins] from comment #17)
> > Comment on attachment 8870289 [details]
> > Bug 1364150 - Introduce debounce middleware;
> > 
> > https://reviewboard.mozilla.org/r/141754/#review149216
> > 
> > I'm a little concerned about not testing the same code that we are shipping,
> > but to be fair we weren't doing that previously either so it's not necessary
> > to address here.  Though I wonder how much complexity would we have to add
> > to the tests to be able to wait for messages to be added before proceeding
> > with assertions, instead of preventing debouncing altogether
> I think that this might be a good candidate for a follow up.

Bug 1370864

Honza
(Reporter)

Comment 22

6 months ago
mozreview-review
Comment on attachment 8870289 [details]
Bug 1364150 - Introduce debounce middleware;

https://reviewboard.mozilla.org/r/141754/#review150926
Attachment #8870289 - Flags: review?(bgrinstead) → review+
Comment hidden (mozreview-request)

Comment 24

6 months ago
We're sorry, Autoland could not rebase your commits for you automatically. Please manually rebase your commits and try again.

hg error in cmd: hg rebase -s cbbd2bbe2456 -d 41ba10aad446: rebasing 400726:cbbd2bbe2456 "Bug 1364150 - Introduce debounce middleware; r=bgrins" (tip)
merging devtools/client/webconsole/new-console-output/new-console-output-wrapper.js
warning: conflicts while merging devtools/client/webconsole/new-console-output/new-console-output-wrapper.js! (edit, then use 'hg resolve --mark')
unresolved conflicts (see hg resolve, then hg rebase --continue)
Comment hidden (mozreview-request)

Comment 26

6 months ago
Pushed by jodvarko@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/634b361b1b9d
Introduce debounce middleware; r=bgrins
Backed out for scroll position failures in devtools' browser_webconsole_keyboard_accessibility.js:

https://hg.mozilla.org/integration/autoland/rev/a3f4e0c311543afe8fb094bad0460befb679e235

Child of push with failures: https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=a08ea7f330370f90091ef1ee4b3a814bc2112755&filter-resultStatus=testfailed&filter-resultStatus=busted&filter-resultStatus=exception&filter-resultStatus=retry&filter-resultStatus=usercancel&filter-resultStatus=runnable
Failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=105518108&repo=autoland

08:13:19     INFO - TEST-START | devtools/client/webconsole/new-console-output/test/mochitest/browser_webconsole_keyboard_accessibility.js
08:13:20     INFO - TEST-INFO | started process screenshot
08:13:20     INFO - TEST-INFO | screenshot: exit 0
08:13:20     INFO - Buffered messages logged at 08:13:19
08:13:20     INFO - Entering test bound 
08:13:20     INFO - Adding a new tab with URL: data:text/html;charset=utf-8,<p>Test keyboard accessibility</p>
08:13:20     INFO -   <script>
08:13:20     INFO -     for (let i = 1; i <= 100; i++) {
08:13:20     INFO -       console.log("console message " + i);
08:13:20     INFO -     }
08:13:20     INFO -   </script>
08:13:20     INFO -   
08:13:20     INFO - Tab added and finished loading
08:13:20     INFO - Opening the toolbox
08:13:20     INFO - Buffered messages logged at 08:13:20
08:13:20     INFO - Toolbox opened and focused
08:13:20     INFO - Web Console opened
08:13:20     INFO - Buffered messages finished
08:13:20     INFO - TEST-UNEXPECTED-FAIL | devtools/client/webconsole/new-console-output/test/mochitest/browser_webconsole_keyboard_accessibility.js | scroll position changed after page up - Didn't expect 0, but got it
08:13:20     INFO - Stack trace:
08:13:20     INFO -     chrome://mochikit/content/browser-test.js:test_isnot:1002
08:13:20     INFO -     chrome://mochitests/content/browser/devtools/client/webconsole/new-console-output/test/mochitest/browser_webconsole_keyboard_accessibility.js:null:34
08:13:20     INFO -     Tester_execTest@chrome://mochikit/content/browser-test.js:801:9
08:13:20     INFO -     Tester.prototype.nextTest</<@chrome://mochikit/content/browser-test.js:714:7
08:13:20     INFO -     SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:795:59
08:13:20     INFO - TEST-PASS | devtools/client/webconsole/new-console-output/test/mochitest/browser_webconsole_keyboard_accessibility.js | scroll position now at bottom - 
08:13:20     INFO - TEST-PASS | devtools/client/webconsole/new-console-output/test/mochitest/browser_webconsole_keyboard_accessibility.js | scroll position now at top - 
08:13:20     INFO - Not taking screenshot here: see the one that was previously logged
08:13:20     INFO - TEST-UNEXPECTED-FAIL | devtools/client/webconsole/new-console-output/test/mochitest/browser_webconsole_keyboard_accessibility.js | scroll position now at bottom - 
08:13:20     INFO - Stack trace:
08:13:20     INFO -     chrome://mochitests/content/browser/devtools/client/webconsole/new-console-output/test/mochitest/browser_webconsole_keyboard_accessibility.js:null:50
08:13:20     INFO -     Tester_execTest@chrome://mochikit/content/browser-test.js:801:9
08:13:20     INFO -     Tester.prototype.nextTest</<@chrome://mochikit/content/browser-test.js:714:7
08:13:20     INFO -     SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:795:59
08:13:20     INFO - try ctrl-l to clear output
08:13:20     INFO - Synthesizing key shortcut: Ctrl+Shift+L
08:13:20     INFO - Console message: [JavaScript Warning: "Key event not available on some keyboard layouts: key=“r” modifiers=“accel,alt” id=“key_toggleReaderMode”" {file: "chrome://mochikit/content/tests/SimpleTest/EventUtils.js" line: 790}]
08:13:20     INFO - Console message: [JavaScript Warning: "Key event not available on some keyboard layouts: key=“i” modifiers=“accel,alt,shift” id=“key_browserToolbox”" {file: "chrome://mochikit/content/tests/SimpleTest/EventUtils.js" line: 790}]
08:13:20     INFO - TEST-PASS | devtools/client/webconsole/new-console-output/test/mochitest/browser_webconsole_keyboard_accessibility.js | jsterm input is focused -
Flags: needinfo?(odvarko)

Comment 28

6 months ago
Backout by kwierso@gmail.com:
https://hg.mozilla.org/mozilla-central/rev/f4262773c433
Backed out changeset 634b361b1b9d for scroll position failures in devtools' browser_webconsole_keyboard_accessibility.js. r=backout a=merge

Comment 29

6 months ago
backoutbugherder
also backed out from m-c
https://hg.mozilla.org/mozilla-central/rev/a3f4e0c31154
Status: ASSIGNED → RESOLVED
Last Resolved: 6 months ago
status-firefox55: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 55
(Reporter)

Updated

6 months ago
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
(Reporter)

Updated

6 months ago
See Also: → bug 1371721

Updated

6 months ago
Status: REOPENED → ASSIGNED

Updated

6 months ago
Iteration: 55.7 - Jun 12 → 56.1 - Jun 26
Comment hidden (mozreview-request)
(Assignee)

Comment 31

5 months ago
No integration with the Console panel (ready for Net panel though) + test appended.

Honza
Flags: needinfo?(odvarko)
(Assignee)

Comment 32

5 months ago
Try push:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=68dbd7d5994a93a98680b0612d8e032f43b56d37

Honza
(Assignee)

Comment 33

5 months ago
One more try push:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=4973ef3da248cd521f77b835679fbc92bd667a74

@Brian: Any tips if the failures are related?

Honza
Flags: needinfo?(bgrinstead)
Comment hidden (mozreview-request)
(Assignee)

Comment 35

5 months ago
I think I fixed it, landing.

Honza
Flags: needinfo?(bgrinstead)

Comment 36

5 months ago
Pushed by jodvarko@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/0a4be8d5a019
Introduce debounce middleware; r=bgrins

Comment 37

5 months ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/0a4be8d5a019
Status: ASSIGNED → RESOLVED
Last Resolved: 6 months ago5 months ago
status-firefox56: --- → fixed
Resolution: --- → FIXED
status-firefox55: fixed → ---
Target Milestone: Firefox 55 → Firefox 56
You need to log in before you can comment on or make changes to this bug.