Closed Bug 761257 Opened 9 years ago Closed 9 years ago

Further improve Web Console output performance


(DevTools :: Console, defect)

Not set


(Not tracked)

Firefox 16


(Reporter: msucan, Assigned: msucan)




(1 file, 2 obsolete files)

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
... 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.
Depends on: 746869
Assignee: nobody → mihai.sucan
Attached patch proposed patch (obsolete) — Splinter Review
Proposed patch. This should complete our work on Web Console output performance.


- 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!
Attachment #631117 - Flags: review?(dcamp)
Attachment #631117 - Flags: feedback?(bzbarsky)
This patch depends on the patch from bug 761157.

Try push:
Depends on: 761157
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!
Attachment #631117 - Flags: feedback?(bzbarsky) → feedback+
Attached patch rebased patch (obsolete) — Splinter Review
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.
Attachment #631117 - Attachment is obsolete: true
Attachment #631117 - Flags: review?(dcamp)
Attachment #631975 - Flags: review?(dcamp)
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.
Attachment #631975 - Flags: review?(dcamp) → review+
Blocks: 762996
Thank you for the r+!

Try push results:
Attachment #631975 - Attachment is obsolete: true
Comment on attachment 632823 [details] [diff] [review]
[in-fx-team] review comment addressed
Attachment #632823 - Attachment description: review comment addressed → [in-fx-team] review comment addressed
Whiteboard: [fixed-in-fx-team]
Closed: 9 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 16
Whiteboard: [fixed-in-fx-team]
Product: Firefox → DevTools
You need to log in before you can comment on or make changes to this bug.