Last Comment Bug 761257 - Further improve Web Console output performance
: Further improve Web Console output performance
Status: RESOLVED FIXED
:
Product: Firefox
Classification: Client Software
Component: Developer Tools: Console (show other bugs)
: Trunk
: All All
: -- normal (vote)
: Firefox 16
Assigned To: Mihai Sucan [:msucan]
:
Mentors:
Depends on: 746869 761157
Blocks: 762996
  Show dependency treegraph
 
Reported: 2012-06-04 11:48 PDT by Mihai Sucan [:msucan]
Modified: 2012-06-16 03:49 PDT (History)
3 users (show)
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
Has Regression Range: ---
Has STR: ---


Attachments
proposed patch (64.97 KB, patch)
2012-06-07 13:54 PDT, Mihai Sucan [:msucan]
bzbarsky: feedback+
Details | Diff | Splinter Review
rebased patch (65.51 KB, patch)
2012-06-11 12:05 PDT, Mihai Sucan [:msucan]
dcamp: review+
Details | Diff | Splinter Review
[in-fx-team] review comment addressed (66.65 KB, patch)
2012-06-13 13:00 PDT, Mihai Sucan [:msucan]
no flags Details | Diff | Splinter Review

Description Mihai Sucan [:msucan] 2012-06-04 11:48:30 PDT
In bug 722685 we've done work to improve the Web Console output performance, but due to time constraints we only implemented queuing of message output. Messages are still created all at once. This can still cause problems with a lot of calls to the console API.

We should also use
https://developer.mozilla.org/en/Performance/Reporting_a_Performance_Problem
... to investigate how our code executes, which are the hot spots.

We should also finetune the queuing behavior, because at this point it is a simple implementation that outputs N messages, every M milliseconds until the queue is empty.
Comment 1 Mihai Sucan [:msucan] 2012-06-07 13:54:49 PDT
Created attachment 631117 [details] [diff] [review]
proposed patch

Proposed patch. This should complete our work on Web Console output performance.

Changes:

- make a single call to the timer that outputs messages to process DEFAULT_LOG_LIMIT (200), so we do not spend time scrolling too often. This is based on a suggestion from Boris (if well understood!). This has better perceived performance - UI is more responsive when you update more messages at once and you do less reflows as a consequence.

- different output throttle strategy based on how slow we update the UI: decided to try to update output every one second - irrespective of how many messages are added to the queue or how many are displayed the given timer interval.

- went down to 50ms for the timer resolution, to check more often what needs to be done. In normal use updates happen in 50ms. When there's "heavy fire" we throttle to 1000ms (as explained above).

- rewire the message creation and output mechanisms in the the entire Web Console to queue not just output but message creation - unlike the previous performance patch. This allows the code to prevent freezing the browser while, say, 50000 messages are created.

- added code to ConsoleAPI.js to split processing the console API calls into chunks in the timer that was added in the previous performance patch. I did this again to avoid browser freezing for a long time while waiting for N calls to be processed.

The results:

I ran 50000 calls to console.log("foo " +i ), with the Web Console open.

  Firefox 13:
    Time to display all messages: ~306 s
    Time to return from page script loop: ~306 s
    Note: 5 minutes ... browser is frozen all of the time, entirely unusable.

  Firefox 15:
    Display: ~30 s
    Return: ~2600 ms
    Note: browser stalls and updates and stalls, as it processes the calls. This only lasts for about ~33 seconds.

  Firefox 16 (with this patch):
    Display: ~14 s
    Return: ~2600 ms
    Note: browser stalls for ~2600 ms until the return from loop happens, then the browser is usable for the duration of visual updates, but you can feel work is happening - you feel it's slowish. This is an improvement that avoid the browser being killed for being unresponsive.

  Chromium 18:
    Display: after 600 s I closed the browser.
    Return: ~3000 ms
    Note: page is frozen until return from loop happens, then Web Inspector freezes after a few thousands of messages and I couldn't get it unfreeze.

  Opera 12:
    Display: after 600 s I closed the browser.
    Return: ~1100 ms
    Note: browser stalls for about one second then Dragonfly starts updating the output and freezing its window. Browser is sluggish until Dragonfly completes - which it didn't for me.

I should note that at this point we should do well enough for games that log a lot of data at once. If the Web Console still feels slow, I'd like to see a test case that shows typical work load when working on a game in Firefox.

There are a number of test changes because the Web Console still has some tests that expected specific timings for certain kinds of output messages.

Boris: I am asking you for feedback, since you've been very helpful with suggestions. Any comments on how to improve this code are much appreciated. Thank you!

Looking forward to comments!
Comment 2 Mihai Sucan [:msucan] 2012-06-07 13:56:19 PDT
This patch depends on the patch from bug 761157.

Try push:
https://tbpl.mozilla.org/?tree=Try&rev=ad2b6e81c01f
Comment 3 Boris Zbarsky [:bz] 2012-06-08 19:39:53 PDT
Comment on attachment 631117 [details] [diff] [review]
proposed patch

Those changes sound great (and the numbers bear it out).  I don't think I have anything to add!
Comment 4 Mihai Sucan [:msucan] 2012-06-11 12:05:42 PDT
Created attachment 631975 [details] [diff] [review]
rebased patch

Rebased the patch so it applies cleanly on top of the dependent patch.

Boris: thank you very much for your time to look into the patch and to provide us with suggestions on how to improve the Web Console output performance.
Comment 5 Dave Camp (:dcamp) 2012-06-11 13:25:12 PDT
Comment on attachment 631975 [details] [diff] [review]
rebased patch

Looks good!  If you want to rename your nsITimer variable to gTimer in this patch, I won't complain.
Comment 6 Mihai Sucan [:msucan] 2012-06-13 13:00:05 PDT
Created attachment 632823 [details] [diff] [review]
[in-fx-team] review comment addressed

Thank you for the r+!

Try push results:
https://tbpl.mozilla.org/?tree=Try&rev=665e11e32550
Comment 7 Mihai Sucan [:msucan] 2012-06-14 05:05:03 PDT
Comment on attachment 632823 [details] [diff] [review]
[in-fx-team] review comment addressed

https://hg.mozilla.org/integration/fx-team/rev/dff9bab548bf
Comment 8 Tim Taubert [:ttaubert] (on PTO, back Aug 29th) 2012-06-16 03:45:06 PDT
https://hg.mozilla.org/mozilla-central/rev/dff9bab548bf

Note You need to log in before you can comment on or make changes to this bug.