Closed Bug 1364150 Opened 7 years ago Closed 7 years ago

Improve message batching debounce logic

Categories

(DevTools :: Console, enhancement, P1)

Product:
DevTools
Component:
Console
Type:
enhancement

Tracking

(firefox56 fixed)

Status:
RESOLVED FIXED
Milestone:
Firefox 56
Iteration:
56.1 - Jun 26
Tracking Flags:
Tracking Status
firefox56 --- fixed

People

(Reporter: bgrins, Assigned: Honza)

References

(Blocks 1 open bug)

Details

(Whiteboard: [console-html])

Attachments

(1 file, 2 obsolete files)

Bug 1364150 - Introduce debounce middleware;
59 bytes, text/x-review-board-request
bgrins
: review+
Details 
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.
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.
Flags: qe-verify?
Priority: -- → P2
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
Flags: qe-verify? → qe-verify-
Assignee: nobody → odvarko
Status: NEW → ASSIGNED
Attached patch debounce-middleware.patch (obsolete) — — Splinter Review 
I am attaching first version of debounce middleware.

Honza
Patches from bug 1307884 are needed

Honza
Iteration: --- → 55.6 - May 29
Priority: P2 → P1
Attachment #8870041 - Attachment is obsolete: true
Attachment #8870289 - Attachment is obsolete: true
Attachment #8870289 - Flags: review?(bgrinstead)
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
Attachment #8866924 - Attachment is obsolete: true
Iteration: 55.6 - May 29 → 55.7 - Jun 12
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
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)
Also please check the mocha test output, this appears to be breaking some of the filtering tests
(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 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 ?
(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
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)
(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
(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
Comment on attachment 8870289 [details]
Bug 1364150 - Introduce debounce middleware;

https://reviewboard.mozilla.org/r/141754/#review150926
Attachment #8870289 - Flags: review?(bgrinstead) → review+
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)
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)
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
also backed out from m-c
https://hg.mozilla.org/mozilla-central/rev/a3f4e0c31154
Status: ASSIGNED → RESOLVED
Closed: 7 years ago
status-firefox55: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 55
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
See Also: → 1371721
Status: REOPENED → ASSIGNED
Iteration: 55.7 - Jun 12 → 56.1 - Jun 26
No integration with the Console panel (ready for Net panel though) + test appended.

Honza
Flags: needinfo?(odvarko)
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)
I think I fixed it, landing.

Honza
Flags: needinfo?(bgrinstead)
Pushed by jodvarko@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/0a4be8d5a019
Introduce debounce middleware; r=bgrins
https://hg.mozilla.org/mozilla-central/rev/0a4be8d5a019
Status: ASSIGNED → RESOLVED
Closed: 7 years ago → 7 years ago
status-firefox56: --- → fixed
Resolution: --- → FIXED
status-firefox55: fixed → ---
Target Milestone: Firefox 55 → Firefox 56
Product: Firefox → DevTools
See Also: → 1615691
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: