1066581 - console.log is slow (4x slower on desktop, 6x slower on B2G) when DevTools is turned on

Status: RESOLVED WORKSFORME

(DevTools :: Console, defect)

Description

[Tim Guan-tin Chien [:timdream] (please needinfo)]

Consider the following code (See URL):

var t = performance.now();
var i = 10000; while (i--) {
  console.log(i);
}
console.log('timer', performance.now() - t);
setTimeout(function() {
  console.log('timer', performance.now() - t);
}, 0);

STR1:
1. Without turning on the DevTools, click on "test"
2. Turn on the DevTools to see the output

Outputs:
"timer" 57.114508000000114
"timeout timer" 107.51943000000006

STR2:
1. Turn on the DevTools
2. Click on "test"

Outputs:
"timer" 69.80704200000037
"timeout timer" 435.59202899999946

Output on Flame w/ AppManager:
"timer" 326.2022389999984
"timeout timer" 3747.020102000006

Note:

1. So base on the above result, it seems that although console.log() does not block the calling function, it blocks the main loop a lot.
2. By reading

http://dxr.mozilla.org/mozilla-central/source/dom/base/Console.cpp#802

w/o understanding C++, it seems expected because we queue the call and notify the observer message in a timer.

http://dxr.mozilla.org/mozilla-central/source/dom/base/Console.cpp#729

and it seems that observer blocks the NotifyObservers(), thus blocks the main loop.

I wonder if, instead of queue the console API methods in a timer, if it's possible to send the work to another thread.

Comment 1

[Tim Guan-tin Chien [:timdream] (please needinfo)]

The B2G number is a bit misleading. I should compare STR1 w/ STR2 on a Flame. The result for STR1 is:

"timer" 327.66348899999997
"timeout timer" 600.2927599999998

So that's around 6 times slower.

Comment 2

[Tim Guan-tin Chien [:timdream] (please needinfo)]

PS Desktop numbers did not improve between Fx Beta and latest Nightly (bug 1045715 inc.)

Comment 3

[Eric Rahm [:erahm]]

For reference I just tested on my MacBook Pro (OS X 10.9.4) w/ STR 1 on Firefox Aurora 34.0a2 (2014-09-10) and Chrome 37.0.2062.120. It looks like we're actually faster on desktop:

Fx:
"timer" 26.60610699999961
"timeout timer" 50.35030999999981

Cr:
timer 198.25700018554926
timeout timer 201.07499975711107

I also tested Chrome 37.0.2062.117 on my Nexus 5:
I/chromium(24715): [INFO:CONSOLE(1)] "3267.6399999909336"
I/chromium(24715): [INFO:CONSOLE(1)] "3272.3620000033407"

So it seems like our non-devtools times are quite respectable. Andreas, you previously indicated that console logging is too slow and should be improved before embracing it in gaia, do you still think that's the case given these numbers?

Comment 4

[Tim Guan-tin Chien [:timdream] (please needinfo)]

bug 1000532 is probably related.

Comment 5

[Alexandre Poirot [:ochameau]]

I'm still seeing this behavior on desktop, with this test URL:
data:text/html,<script>var s = new Date().getTime(); for(var i=0; i<1000; i++) console.log("foo");console.log("time",new Date().getTime()-s);</script>

Without devtools:
  non-e10s: ~25ms
  e10s: ~120ms

With devtools, on the webconsole:
  non-e10s: 160ms
  e10s: 260-320ms

We now have to distinguish e10s/non-e10s as the codepaths are quite different now,
but both results expose how much enabling devtools slow down console.log calls.

Note that enabling e10s has already been reported to slow down devtools (bug 1073926).

May be we should redo perf tweak like bug 1045715 and, then it would be interesting to integrate console API performances in talos via bug 1150215.

Comment 6

[Tim Guan-tin Chien [:timdream] (please needinfo)]

(In reply to Alexandre Poirot [:ochameau] from comment #5)
> I'm still seeing this behavior on desktop, with this test URL:
> data:text/html,<script>var s = new Date().getTime(); for(var i=0; i<1000;
> i++) console.log("foo");console.log("time",new Date().getTime()-s);</script>

I thought this bug is about NotifyObservers() blocking the main loop after the calling function, instead of the call itself?

Anyhow, we should fix both if both of them hit us.

Comment 7

[Alexandre Poirot [:ochameau]]

There is no more notifyobservers call directly from Console.cpp.
It looks like it is now using another thread to dispatch the console message to the main thread (unless the console call is already done from the main thread.

Comment 8

[Tim Guan-tin Chien [:timdream] (please needinfo)]

So the original bug described should be WFM by now... I am going to leave this bug to you then.

Comment 9

[Eric Rahm [:erahm]]

Per comment 8.