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.
https://tbpl.mozilla.org/?tree=Try&rev=7b7cf32fc2df some tests were broken.
Attachment #8544716 - Flags: review?(mihai.sucan) → review?(past)
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.
Attachment #8544716 - Flags: review?(past) → review+
Oh, I'm also not a DOM peer, so you probably want to get someone else to give it a seal of approval.
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.
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
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.
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...
> 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.
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).
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?
Status: NEW → RESOLVED
Last Resolved: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla38
Component: DOM → DOM: Core & HTML
Product: Core → Core
You need to log in before you can comment on or make changes to this bug.