1107699 - Remove timeout before Console.log() and the dispatching of ConsoleEvents

Status: RESOLVED FIXED

(Core :: DOM: Core & HTML, defect)

Comment 1

[Andrea Marchesini [:baku]]

Attachment: console.patch

https://tbpl.mozilla.org/?tree=Try&rev=a5037c6d6113

built on top of bug 1058644
Asking for a review once I see a green result on try.

Comment 2

[Andrea Marchesini [:baku]]

https://tbpl.mozilla.org/?tree=Try&rev=7b7cf32fc2df

some tests were broken.

Comment 3

[Andrea Marchesini [:baku]]

Attachment: console.patch

Comment 4

[Panos Astithas (he/him) [:past] (please ni?)]

Comment on attachment 8544716 [details] [diff] [review]
console.patch

Review of attachment 8544716 [details] [diff] [review]:
-----------------------------------------------------------------

Everything looks fine code-wise, I'm just uneasy about the performance impact this will have.

Comment 5

[Panos Astithas (he/him) [:past] (please ni?)]

Oh, I'm also not a DOM peer, so you probably want to get someone else to give it a seal of approval.

Comment 6

[Panos Astithas (he/him) [:past] (please ni?)]

I used this page to test the behavior change and I can't say it was terrible, even in a pathological case like this:

http://htmlpad.org/console-repeated-messages/

The content now appears frozen until the loop is done (a few seconds before the console displays the final messages), but that also happens in Chrome. We used to be better in that regard, at the expense of lower throughput.

I'm going to NI? :bz who IIRC had suggested this optimization and :BenWa who had argued in bug 722685 comment 4 that game developers often do this sort of thing, to weigh in.

Comment 7

[Andrea Marchesini [:baku]]

It was green on try when I wrote the patch. Let me push it again and see what happens:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=4ce70b28b0df

Comment 8

[Benoit Girard (:BenWa)]

Do you have anything you want to me elaborate on? My point is:
* console.log() a string should be just as fast, actually faster because you don't need a sys call to write() to pipe, than dump() when the console is hidden.
* When you print something it's because you want the value *then*. Deferring the logging makes 'printf' debugging impossible: http://en.wikipedia.org/wiki/Debugging#Techniques. If I print something in a for() loop I want the value at -that- iteration otherwise console.log() is useless.
* console.log() a large object might want to do some tricks instead of deep copying a massive object. But the UI should be absolutely clear.
* A lovely feature would be to keep a pointer to the live object, show the logged state and allow the user to see (and even diff) against the live object to see what state has changed.

(In reply to Panos Astithas [:past] from comment #4)
> -----------------------------------------------------------------
> 
> Everything looks fine code-wise, I'm just uneasy about the performance
> impact this will have.

It's a logging API on a modern CPU. If it's not performing well we should fix the underlying problem not make it async.

Comment 9

[Boris Zbarsky [:bzbarsky]]

The basic issue is that logging is not just a simple string operation.  It's more akin to a system call except worse, because our equivalent of a system call and context switch (calling into chrome) is not nearly as low-level and optimized as what kernels do.

The other basic issue is that we want to minimize doing _unnecessary_ work.  That means avoiding snapshotting data that no one will look at because the console is closed...

There is a clear tension here with the "I want the value at the log() point" requirement, of course.

That said, there's a bunch of console-specific inefficiency here too; see bug 746869 and the bugs it depends on that point out specific performance problems.

In the interests of having some numbers in this discussion, I tried running my testcase from bug 746869 comment 0 in today's inbound build, today's inbound build with this patch applied, and Chrome, with both console open and console closed.  I also tested what happens if the logged thing is the constant string "hello" instead of the iteration index.  And in the "with patch" case in both e10s mode and not, because there were significant differences.  The results are, in microseconds per log() call:

Inbound, index, console closed: ~24
Inbound+patch, index, console closed: ~24
Inbound+patch, index, e10s, console closed: ~70
Chrome, index, console closed: ~15

Inbound, index, console open: ~27
Inbound+patch, index, console open: ~170
Inbound+patch, index, e10s, console open: ~200
Chrome, index, console open: ~60

Inbound, string, console closed: ~24
Inbound+patch, string, console closed: ~24
Inbound+patch, string, e10s, console closed: ~70
Chrome, string, console closed: ~15

Inbound, string, console open: ~20
Inbound+patch, string, console open: ~160
Inbound+patch, string, e10s, console open: ~200
Chrome, string, console open: ~50

OK, so no matter what we're way better than the number when I filed bug 746869 (which, for scale, was about 4000).  So at least talking about the change is not completely insane...

Comment 10

[Benoit Girard (:BenWa)]

(In reply to Boris Zbarsky [:bz] from comment #9)
> The basic issue is that logging is not just a simple string operation.  It's
> more akin to a system call except worse, because our equivalent of a system
> call and context switch (calling into chrome) is not nearly as low-level and
> optimized as what kernels do.

The cost of us sending a message between our Content->Process and then painting it is, to my best understanding, fundamentally equivalent to a program doing a printf (writing to a pipe) and having the console pick that up and paint it. The only measurable additional overhead we have is going through the layout engine when a terminal application can have a much simpler layout+rendering code.

> 
> The other basic issue is that we want to minimize doing _unnecessary_ work. 
> That means avoiding snapshotting data that no one will look at because the
> console is closed...

This is a good point and I agree we should do less unnecessary work. I just disagree deferring the snapshot is the right thing to optimize, particularly since it ruins printf debugging.

Instead we should optimize things that make no functional changes. If the console is closed we don't need to send any IPC calls and context switches. As simple as that. Any logged messages are stored in the content process in some (circular-like) buffer to with some threshold similar to the scroll back limit of the console. Only when the console opens do we need to start doing the IPC traffic, including a single batched message to send the data that was logged while the console was hidden.

When the console is open logged messages don't need to be sent faster than the console can display them (60Hz for more device, rAF will give you the right callback for this). So you're looking at 60 IPC messages and they're likely context switches that you'll need to be making anyways if the page is active and you need to be painting it.

Here's a test I ran in about:blank which makes my browser totally unresponsive:
for (var i = 0; i < 100000; i++) { console.log(i); console.log(window); }

http://people.mozilla.org/~bgirard/cleopatra/#report=bcdc7020dfb807bf3030e21e509b109d6989f3f1&selection=0,1,2,108,3,146,147,148,2109

Looking at the profile we're not being held back by context switches, we just running a mountain of javascript for something that can boiled down to 'Keep a buffer, when the console is open flush (write()) once per frame the changes'.

Comment 11

[Boris Zbarsky [:bzbarsky]]

> is, to my best understanding, fundamentally equivalent 

In theory, yes?  Whether it's true in practice is unclear.

To put more numbers to this, printf takes about 60us per call with my terminal.  But this is entirely due to the terminal being slow, scrolling, etc.  If I pipe to a file, I get about .13us per call.  Same thing for /dev/null.

> If the console is closed we don't need to send any IPC calls and context switches.

Yes, that would be nice.

> Looking at the profile we're not being held back by context switches,

Sure.

Comment 12

[Panos Astithas (he/him) [:past] (please ni?)]

OK, so since the perf impact doesn't seem too bad and considering the fact that this patch improves the much-requested bug 754861 (when the console is open while logging takes place), I think we should land this. My main concern was whether delivering all the logs synchronously (and thus beachballing) would be considered worse than draining the queue every 15 msec, which makes the page more responsive (e.g. the button is depressed in my test page above).

Comment 13

[Andrea Marchesini [:baku]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/cc20ed1a63ff

Comment 14

[Boris Zbarsky [:bzbarsky]]

Can we please still fix the remaining perf issues?  In e10s with console open this is a 10x perf regression, which is only "not too bad" compared to the 200x perf improvement we had initially with this stuff...

Again, the times above are _microseconds_.  ~100 log calls with this patch, console _closed_ is half a frame budget, right?

Comment 16

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/cc20ed1a63ff