Note: There are a few cases of duplicates in user autocompletion which are being worked on.

Further improve Web Console output performance

RESOLVED FIXED in Firefox 16

Status

()

Firefox
Developer Tools: Console
RESOLVED FIXED
5 years ago
5 years ago

People

(Reporter: msucan, Assigned: msucan)

Tracking

Trunk
Firefox 16
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(Not tracked)

Details

Attachments

(1 attachment, 2 obsolete attachments)

(Assignee)

Description

5 years ago
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.
(Assignee)

Updated

5 years ago
Depends on: 746869
(Assignee)

Updated

5 years ago
Assignee: nobody → mihai.sucan
Status: NEW → ASSIGNED
(Assignee)

Comment 1

5 years ago
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!
Attachment #631117 - Flags: review?(dcamp)
Attachment #631117 - Flags: feedback?(bzbarsky)
(Assignee)

Comment 2

5 years ago
This patch depends on the patch from bug 761157.

Try push:
https://tbpl.mozilla.org/?tree=Try&rev=ad2b6e81c01f
Depends on: 761157

Comment 3

5 years ago
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+
(Assignee)

Comment 4

5 years ago
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.
Attachment #631117 - Attachment is obsolete: true
Attachment #631117 - Flags: review?(dcamp)
Attachment #631975 - Flags: review?(dcamp)

Comment 5

5 years ago
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+
(Assignee)

Updated

5 years ago
Blocks: 762996
(Assignee)

Comment 6

5 years ago
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
Attachment #631975 - Attachment is obsolete: true
(Assignee)

Comment 7

5 years ago
Comment on attachment 632823 [details] [diff] [review]
[in-fx-team] review comment addressed

https://hg.mozilla.org/integration/fx-team/rev/dff9bab548bf
Attachment #632823 - Attachment description: review comment addressed → [in-fx-team] review comment addressed
(Assignee)

Updated

5 years ago
Whiteboard: [fixed-in-fx-team]
https://hg.mozilla.org/mozilla-central/rev/dff9bab548bf
Status: ASSIGNED → RESOLVED
Last Resolved: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 16
Whiteboard: [fixed-in-fx-team]
You need to log in before you can comment on or make changes to this bug.