Closed
Bug 1364150
Opened 7 years ago
Closed 7 years ago
Improve message batching debounce logic
Categories
(DevTools :: Console, enhancement, P1)
DevTools
Console
Tracking
(firefox56 fixed)
Tracking | Status | |
---|---|---|
firefox56 | --- | fixed |
People
(Reporter: bgrins, Assigned: Honza)
References
(Blocks 1 open bug)
Details
(Whiteboard: [console-html])
Attachments
(1 file, 2 obsolete files)
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 years 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 years ago
|
Flags: qe-verify?
Priority: -- → P2
Assignee | ||
Comment 3•7 years 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•7 years ago
|
Flags: qe-verify? → qe-verify-
Assignee | ||
Updated•7 years ago
|
Assignee: nobody → odvarko
Status: NEW → ASSIGNED
Assignee | ||
Comment 4•7 years ago
|
||
I am attaching first version of debounce middleware. Honza
Assignee | ||
Comment 5•7 years ago
|
||
Patches from bug 1307884 are needed Honza
Updated•7 years ago
|
Iteration: --- → 55.6 - May 29
Priority: P2 → P1
Comment hidden (mozreview-request) |
Assignee | ||
Updated•7 years ago
|
Attachment #8870041 -
Attachment is obsolete: true
Assignee | ||
Updated•7 years ago
|
Attachment #8870289 -
Attachment is obsolete: true
Attachment #8870289 -
Flags: review?(bgrinstead)
Assignee | ||
Comment 7•7 years 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•7 years ago
|
Attachment #8866924 -
Attachment is obsolete: true
Updated•7 years ago
|
Iteration: 55.6 - May 29 → 55.7 - Jun 12
Reporter | ||
Comment 9•7 years 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•7 years 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•7 years 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•7 years 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•7 years 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•7 years 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•7 years 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•7 years 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 | ||
Comment 21•7 years 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•7 years 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•7 years 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•7 years ago
|
||
Pushed by jodvarko@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/634b361b1b9d Introduce debounce middleware; r=bgrins
Comment 27•7 years ago
|
||
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•7 years 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•7 years ago
|
||
backout bugherder |
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
Reporter | ||
Updated•7 years ago
|
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Updated•7 years ago
|
Status: REOPENED → ASSIGNED
Updated•7 years ago
|
Iteration: 55.7 - Jun 12 → 56.1 - Jun 26
Comment hidden (mozreview-request) |
Assignee | ||
Comment 31•7 years ago
|
||
No integration with the Console panel (ready for Net panel though) + test appended. Honza
Flags: needinfo?(odvarko)
Assignee | ||
Comment 32•7 years ago
|
||
Try push: https://treeherder.mozilla.org/#/jobs?repo=try&revision=68dbd7d5994a93a98680b0612d8e032f43b56d37 Honza
Assignee | ||
Comment 33•7 years 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) |
Comment 36•7 years ago
|
||
Pushed by jodvarko@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/0a4be8d5a019 Introduce debounce middleware; r=bgrins
Comment 37•7 years ago
|
||
bugherder |
https://hg.mozilla.org/mozilla-central/rev/0a4be8d5a019
Status: ASSIGNED → RESOLVED
Closed: 7 years ago → 7 years ago
status-firefox56:
--- → fixed
Resolution: --- → FIXED
Updated•7 years ago
|
status-firefox55:
fixed → ---
Target Milestone: Firefox 55 → Firefox 56
Updated•6 years ago
|
Product: Firefox → DevTools
You need to log in
before you can comment on or make changes to this bug.
Description
•