Last Comment Bug 722685 - Console logging is slow
: Console logging is slow
Status: RESOLVED FIXED
[fixed-in-fx-team]
:
Product: Firefox
Classification: Client Software
Component: Developer Tools: Console (show other bugs)
: Trunk
: All All
: P2 normal (vote)
: Firefox 15
Assigned To: Mihai Sucan [:msucan]
:
Mentors:
: 597461 757113 (view as bug list)
Depends on: 746869
Blocks:
  Show dependency treegraph
 
Reported: 2012-01-31 06:36 PST by Kevin Dangoor
Modified: 2012-06-02 17:00 PDT (History)
10 users (show)
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
Has Regression Range: ---
Has STR: ---


Attachments
Simple test to show the speed difference (1.65 KB, text/html)
2012-01-31 06:36 PST, Kevin Dangoor
no flags Details
proposed patch (56.05 KB, patch)
2012-06-01 05:23 PDT, Mihai Sucan [:msucan]
no flags Details | Diff | Splinter Review
Console API tests fixed (63.59 KB, patch)
2012-06-01 09:23 PDT, Mihai Sucan [:msucan]
rcampbell: review+
Details | Diff | Splinter Review
addressed review comments (72.92 KB, patch)
2012-06-02 07:08 PDT, Mihai Sucan [:msucan]
no flags Details | Diff | Splinter Review

Description Kevin Dangoor 2012-01-31 06:36:20 PST
Created attachment 593077 [details]
Simple test to show the speed difference

Along the way, a couple of people had told me that "logging to the web console is slow", so I thought I'd see if that's true/quantifiable. This might be related to bug 597461, or those may be two different problems.

See the attached file for a simple, stupid benchmark but I think it highlights an issue. How the results are computed:

1. With console not visible: 1000 iterations of console.log called with a string
2. With console not visible: 1000 iterations of console.log with a single %s replacement
3. With console visible: 1000 iterations of console.log called with a string
4. With console visible: 1000 iterations of console.log with a single %s replacement  

With Nightly (2012-01-30) on my Mac, I get the following results (times in ms):

Closed Console

Simple string: 335
Interpolation: 259

(the last 200 results were saved and displayed on open)

Open Console

Simple string: 3797
Interpolation: 3820


Contrast with Chrome 18.0.1017.2 dev

Closed Console

Simple string: 42
Interpolation: 39

(the last 900 results were saved and displayed on open)

Open Console

Simple string: 186
Interpolation: 198


I noticed that Chrome's display of console output when the console was open was asynchronous.
Comment 1 Kevin Dangoor 2012-01-31 06:45:52 PST
I also tested with Firebug. I opened Firebug and then closed it to make sure that Firebug's console object was on the page:

Closed Console

Simple string: 182
Interpolation: 184


Open Console

Simple string: 758
Interpolation: 632


Firebug displayed the results asynchronously. I don't have timings for when the last of the console messages was displayed, but I think the 7-8 seconds spent displaying the results in the Web Console is pretty similar to how long Firebug took to display the results (though the JavaScript returned much sooner).
Comment 2 Paul Rouget [:paul] 2012-02-01 02:44:44 PST
If I am not mistaken, we use `appendChild` for every message (if not repeated). That explains the perf problem.

We could populate a fragment that we could "flush" regularly. Not very elegant though.
Making the whole logging mechanism asynchronous would be better.
Comment 3 Kevin Dangoor 2012-02-29 13:50:51 PST
*** Bug 597461 has been marked as a duplicate of this bug. ***
Comment 4 Benoit Girard (:BenWa) 2012-05-14 08:18:42 PDT
The Mozilla team ran into this while developing a WebGL games. The console logging interferes with performance of the running game even if we we're just logging 60 numbers per second (1 per frame at 60 FPS). I would expect the performance to be comparable to using 'dump();' and for the performance impact to be negligible while the console is closed. This bug is a big pain point for developing games on Gecko.
Comment 5 Rob Campbell [:rc] (:robcee) 2012-05-14 15:42:13 PDT
could you test again in tonight's nightly? I'm curious to know if you see any improvement.
Comment 6 Kevin Dangoor 2012-05-15 07:04:19 PDT
Running on the same Mac as in the original description, but with Nightly 2012-05-15, I now see these results:

Closed console:

Simple string: 189
Interpolation: 185

Open Console:

Simple string: 340
Interpolation: 349


These numbers are much better... but, I'll note that the "open console" test still locks up the browser for about 4s, despite the measured numbers being much better. This is in line with bz's comments in other bugs about how the display of console output is particularly slow.
Comment 7 Benoit Girard (:BenWa) 2012-05-15 07:40:21 PDT
It would be worth comparing with dump(str) and 'browser.dom.window.dump.enabled' set with a terminal attached.
Comment 8 Mihai Sucan [:msucan] 2012-05-21 10:17:05 PDT
*** Bug 757113 has been marked as a duplicate of this bug. ***
Comment 9 Luke Wagner [:luke] 2012-05-21 22:26:00 PDT
I'd just like to add that this issue has been causing gamedevs to use Chrome instead of FF for debugging.
Comment 10 Mihai Sucan [:msucan] 2012-05-29 11:37:39 PDT
Initial analysis with Kevin's test file:

Opera 12 (latest snapshot, with "cutting-edge" Dragonfly):
  Closed console:
    Simple string: 4
    Interpolation: 1
  Open console:
    Simple string: 17
    Interpolation: 12

Display performance is sufficiently good. However, it becomes slower and slower after several runs. No message pruning happens.

Chromium 18 (beta):
  Closed console:
    Simple string: 21
    Interpolation: 11
  Open console:
    Simple string: 66
    Interpolation: 68

Performance in content pages is very good. However, display performance is actually poor. First run is fast. Subsequent runs take far more. The web inspector tool UI is frozen for many seconds when the second and third runs happen.

Content process separation helps a lot. Even if Web Inspector's display is frozen, web pages continue to run smoothly.

Firefox 13 (beta):
  Closed console:
    Simple string: 135
    Interpolation: 128
  Open console:
    Simple string: 6941
    Interpolation: 7376

Firefox locks up badly, turns gray. Subsequent runs take the same amount of time - not slower.  We prune old messages.

Firefox 15 nightly (with bug 673148 landed):

  Closed console:
    Simple string: 139
    Interpolation: 134

  Open console:
    Simple string: 235
    Interpolation: 240

Firefox freezes for less time, it doesn't turn gray and content script impact is reduced. Subsequent runs are not slower.

As it seems we should target performance on par with Opera's Dragonfly. Will see what I can do.
Comment 11 Mihai Sucan [:msucan] 2012-06-01 05:23:07 PDT
Created attachment 629149 [details] [diff] [review]
proposed patch

Proposed patch.

Performance problems:

- as pointed out by Boris Zbarsky in bug 746869 we do a *lot* of work for every single message we output. notifyObserver() is sync, which means that when console.log() is called (or any other method) the page script waits for ConsoleAPI.js to complete its work and the associated observers. When the Web Console is open, scripts had to wait for the whole UI to update.

- ConsoleAPI performance is fairly acceptable, except that we call a full getStacktrace() for every method call, which means performance is degraded. Performance improves a lot if we eliminate the stacktrace or if we limit it. Since we only really used the youngest frame in the stack, that's what we have to do.

In bug 673148 we have decoupled the UI from the listeners and made console API calls somewhat faster, but UI is still very slow and console methods still have to wait for HUDService-content.js to prepare every message to be sent to the UI.

Changes:

- unrelated: in HUDService-content.js I made a small fix to avoid exceptions during the handling of late events in the network response listener (post-destroy). Found these while making changes for performance in other parts of the Web Console. The rest of async ConsoleAPI and output changes somehow exposed these problems in HUDService-content.js.

- in ConsoleAPI.js I made all stacktraces to be limited to a depth of one. Only console.trace() retrieves the full stack.

- to keep page scripts as fast as possible I also made the console API queue calls and process them later, async - every 30ms (we can change this as we see fit). This change gets us as close as possible to the performance of dump() calls.

- in HUDService.jsm made all outputMessageNode() calls to be async. Messages are displayed instantly (no queuing) if the queue is not full, otherwise they are displayed later, in batches. Scrolling happens per batch output, not for every message, similarly for pruning and regrouping of messages. We can configure how many messages we output at once and how often. I also added code that prunes messages before they even get to be displayed - so we cleanup the queue itself.

- Luckily only a few tests needed to be updated to no longer assume display is sync. Without the fixes in bug 673148 these changes would've broken many more tests.

Concerns:

- in ConsoleAPIStorage we notify observers of adding a new item to the cache, which seems superfluous, given that we already had notification for the console API event. Why was that added?

- to make things even faster in ConsoleAPI and ConsoleAPIStorage we get to "nit-picking": we'd have to trim superfluous checks for window ID in recordEvent(), we shouldn't call storage.shift() for every new event, etc.

- in HUDService.jsm with the proposed changes we still create the message nodes when the event is received from HUDService-content.js. Ideally, we should avoid even creating the message nodes - we should queue these as well. Taking pruning into account, we shouldn't even create the message nodes that we will remove anyway.

I can do this change as well, but the ConsoleUtils.outputMessageNode() was the obvious "attack" point. This is the common method called by all code that outputs messages. If we want to queue "higher" in the hierarchy of things, we would need more changes.

I can do the changes, but it really depends how far we want to take things at this point. Please let me know.

Results:

  Closed console:
    Simple string: 50
    Interpolated string: 48

  Open console:
    Simple string: 51
    Interpolated string: 48

(for comparison: 1000 dump() calls take around 10-20 ms)

Having the web console open or closed no longer directly impacts console API calls. Now the UI no longer freezes and results show up quickly.

I tried with 5000 calls and we now do better than Opera's Dragonfly and Chrome's Web Inspector - in terms of UI updates. Console API calls finish faster, for some reason, in those two browsers.

I am looking forward to your review and comments on how we can take things further with this patch. Thanks!


Pushed to try:
https://tbpl.mozilla.org/?tree=Try&rev=bcc8360fc224
Comment 12 Mihai Sucan [:msucan] 2012-06-01 09:23:01 PDT
Created attachment 629218 [details] [diff] [review]
Console API tests fixed

I forgot to update the console API-specific tests from dom/browser. They needed an update to deal with the new async nature of console.* methods.

Previous try run is all orange. New try push:
https://tbpl.mozilla.org/?tree=Try&rev=13e4624d9503
Comment 13 Rob Campbell [:rc] (:robcee) 2012-06-01 11:43:46 PDT
(In reply to Mihai Sucan [:msucan] from comment #12)
> Created attachment 629218 [details] [diff] [review]
> Console API tests fixed
> 
> I forgot to update the console API-specific tests from dom/browser. They
> needed an update to deal with the new async nature of console.* methods.
> 
> Previous try run is all orange. New try push:
> https://tbpl.mozilla.org/?tree=Try&rev=13e4624d9503

d'oh! good catch. Thanks for the update!
Comment 14 Rob Campbell [:rc] (:robcee) 2012-06-01 13:40:03 PDT
Comment on attachment 629218 [details] [diff] [review]
Console API tests fixed

+// The number of messages to display in a single display update. If we display
+// too many messages at once we slow the Firefox UI too much.
+const MESSAGES_IN_INTERVAL = 30;
+
+// The delay between display updates - tells how often we should push new
+// messages to screen.
+const OUTPUT_INTERVAL = 90; // milliseconds
+

just curious, did you try any other values before you stuck on these?

...

+  /**
+   * The number of messages displayed in the last interval. The interval is
+   * given by OUTPUT_INTERVAL.
+   */
+  _messagesDisplayedInInterval: 0,
+

@private? @type? You included that for the others here.

_flushMessageQueue is QUITE a method! I believe I have decoded it and it is awesome. It'd be nice if you could break it up a bit, but I'm fine with leaving it large and in charge.

+  _pruneOutputQueue: function HUD__pruneOutputQueue()

+    // Group the messages per category.
+    this._outputQueue.forEach(function(aItem, aIndex) {

you could use for .. of here. Would remove the extra anonymous function – might be marginally quicker but probably not by much.

pruneOutputQueue looks good!

I have not reviewed all of the test code. That's what try is for.

This looks great. I can find no fault with it.
Comment 15 Mihai Sucan [:msucan] 2012-06-02 03:51:50 PDT
(In reply to Rob Campbell [:rc] (:robcee) from comment #14)
> Comment on attachment 629218 [details] [diff] [review]
> Console API tests fixed
> 
> +// The number of messages to display in a single display update. If we
> display
> +// too many messages at once we slow the Firefox UI too much.
> +const MESSAGES_IN_INTERVAL = 30;
> +
> +// The delay between display updates - tells how often we should push new
> +// messages to screen.
> +const OUTPUT_INTERVAL = 90; // milliseconds
> +
> 
> just curious, did you try any other values before you stuck on these?

Based on user testing, I picked values that have good perceived speed on my system. We can change these values as we see fit. We need to control how many messages and how often we output. Similarly we should control how often pruning happens.

> 
> +  /**
> +   * The number of messages displayed in the last interval. The interval is
> +   * given by OUTPUT_INTERVAL.
> +   */
> +  _messagesDisplayedInInterval: 0,
> +
> 
> @private? @type? You included that for the others here.

Good catch!

> _flushMessageQueue is QUITE a method! I believe I have decoded it and it is
> awesome. It'd be nice if you could break it up a bit, but I'm fine with
> leaving it large and in charge.

Good point! Will split out the batch.forEach() function.

> +  _pruneOutputQueue: function HUD__pruneOutputQueue()
> 
> +    // Group the messages per category.
> +    this._outputQueue.forEach(function(aItem, aIndex) {
> 
> you could use for .. of here. Would remove the extra anonymous function –
> might be marginally quicker but probably not by much.

for-of gives me the item and no index. I need the index.

> pruneOutputQueue looks good!
> 
> This looks great. I can find no fault with it.

Thank you for the r+! Will update the patch once I get the greens. :)
Comment 16 Mihai Sucan [:msucan] 2012-06-02 07:08:16 PDT
Created attachment 629470 [details] [diff] [review]
addressed review comments

Addressed review comments, made some fixes to the code that does message pruning, and other minor fixes.


Green try run:
https://tbpl.mozilla.org/?tree=Try&rev=09098534abfc
Comment 17 Panos Astithas [:past] (away until 7/21) 2012-06-02 08:49:13 PDT
https://hg.mozilla.org/integration/fx-team/rev/05eeabb5db0a
Comment 18 Dave Camp (:dcamp) 2012-06-02 17:00:18 PDT
https://hg.mozilla.org/mozilla-central/rev/05eeabb5db0a

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