877773 - If Browser console is staying opened, Browser UI freezes for a while when open youtube page

Status: RESOLVED FIXED

(DevTools :: Console, defect, P1)

Description

[Alice0775 White]

Build Identifier:
http://hg.mozilla.org/mozilla-central/rev/e58336e81395
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:24.0) Gecko/20130529 Firefox/24.0 ID:20130529031131

Steps to Reproduce:
1. Open Browser Console
2. Open youtube page 
   ex. http://www.youtube.com/watch?v=FEm8PZ_lUh8

Actual Rresults:
Browser UI freezes for a while.
Tab spinning icon stops.

Expected Results:
The performance should not drop.

Comment 1

[Mihai Sucan [:msucan]]

Thank you for the bug report. I can confirm the problem on Linux. This is a rather serious issue and I am going to investigate to see why it happens.

Comment 2

[Mihai Sucan [:msucan]]

More testing shows this bug also happens when you have the web console open for the youtube tab.

Comment 3

[Mihai Sucan [:msucan]]

Spent time this evening to investigate this performance issue and I hope I am on the right track. If things go well, I should have a patch by tomorrow.

Comment 4

[Mihai Sucan [:msucan]]

(In reply to Mihai Sucan [:msucan] from comment #3)
> Spent time this evening to investigate this performance issue and I hope I
> am on the right track. If things go well, I should have a patch by tomorrow.

s/tomorrow/Monday/ (I forgot it's Friday!)

Comment 5

[Mihai Sucan [:msucan]]

Investigation results:

I found that youtube.com spews errors and warnings from big minified CSS and JS files. We send error messages and source lines over the protocol as we receive them from the nsIConsoleService.

The first approach to fix this issue was to add LongStringActors for the properties where we can end up with really long strings. I did that locally and we no longer send very long strings over the protocol when we log exceptions.

However, the freeze remains. After further investigation I determined that the if (aMessage.message) check in CSL_observe() from WebConsoleUtils.jsm alone causes browser freezes on youtube. I removed that, but then I found that LongStringActors check the string length, so they also cause browser freezes.

At this point I am not sure what is the best way to fix the bug. It seems that simply checking the presence of content (or the length) of a very long string causes browser freezes. If we have to fix this in JS code we would need to change how LSA works.

I also tried to remove the use of LSA and just construct the packet to send to the client - without any value checks, without any length checks. Still, even doing something as simple as what follows still causes browser freezes:

  let foo = { sourceLine: nsiscripterror.sourceLine };

Thus, I cannot copy any property to a different object for the purpose of preparing a packet to send over the protocol.

As I understand it, there is some kind of optimization that avoids perf-sensitive work until someone tries to read any of those very long strings. This is good - for example, if we never show the sourceLine there is no point reading that and slowing the browser for it.

Did the JS engine / XPCOM teams make any changes related to this kind of stuff? I am not an expert but the above example with |foo| should not cause any freeze - it should not cause the retrieval of the full string. Does it do a string copy even if I do not change it?

Any help is much appreciated. Thank you!

Comment 6

[Jim Blandy :jimb]

That sounds really painful. What is the type of the 'aMessage' argument to ConsoleServiceListener.prototype.observe? If it is an nsIScriptError, then the 'message' property of such objects is a getter:

http://dxr.mozilla.org/mozilla-central/source/js/xpconnect/src/nsScriptError.cpp#l38

That calls nsScriptError::ToString, and then calls UTF8ToNewUnicode on that, so there's a copy. This happens every time the 'message' property is accessed.

nsScriptError::ToString is here:

http://dxr.mozilla.org/mozilla-central/source/js/xpconnect/src/nsScriptError.cpp#l155

That does a lot of copies (all the ToNewUTF8String calls), including one of mSourceLine, which I gather is very long. (How long are these strings, exactly?)

nsScriptError::GetSourceLine, the getter for the 'sourceLine' property, seems simpler; I can't tell if it makes a copy or not. It probably does.

But what this all means is that:

if (aMessage.message) {
   ... use aMessage.message ...
}

is actually generating a fresh string each time; this would be better:

let message = aMessage.message;
if (message) {
    ... use message ...
}

The protocol should definitely avoid sending across giant strings.

Is it possible to use our profiler to get C++ backtraces and see what these hangs really are? I'm offering guesses here, but data would keep us from going astray.

Comment 7

[Mihai Sucan [:msucan]]

(In reply to Jim Blandy :jimb from comment #6)
> That sounds really painful. What is the type of the 'aMessage' argument to
> ConsoleServiceListener.prototype.observe? If it is an nsIScriptError, then
> the 'message' property of such objects is a getter:

Yes, these are nsIScriptErrors I am working with.

> http://dxr.mozilla.org/mozilla-central/source/js/xpconnect/src/nsScriptError.
> cpp#l38
> 
> That calls nsScriptError::ToString, and then calls UTF8ToNewUnicode on that,
> so there's a copy. This happens every time the 'message' property is
> accessed.
> 
> nsScriptError::ToString is here:
> 
> http://dxr.mozilla.org/mozilla-central/source/js/xpconnect/src/nsScriptError.
> cpp#l155
> 
> That does a lot of copies (all the ToNewUTF8String calls), including one of
> mSourceLine, which I gather is very long. (How long are these strings,
> exactly?)

How long: I see one .message property has 282340 bytes and a .sourceLine of about the same size. We get about 800 messages in a single page load of youtube. That's not a singular example.


> nsScriptError::GetSourceLine, the getter for the 'sourceLine' property,
> seems simpler; I can't tell if it makes a copy or not. It probably does.

Can we change the nsIScriptError implementation to keep the number of copies to a minimum?


> But what this all means is that:
> 
> if (aMessage.message) {
>    ... use aMessage.message ...
> }
> 
> is actually generating a fresh string each time; this would be better:
> 
> let message = aMessage.message;
> if (message) {
>     ... use message ...
> }

Interesting idea. I will try this.

> The protocol should definitely avoid sending across giant strings.
> 
> Is it possible to use our profiler to get C++ backtraces and see what these
> hangs really are? I'm offering guesses here, but data would keep us from
> going astray.

Good point. Who should we ping for this kind of analysis? Can you do that?

Comment 8

[Jim Blandy :jimb]

(In reply to Mihai Sucan [:msucan] from comment #5)
> Did the JS engine / XPCOM teams make any changes related to this kind of
> stuff? I am not an expert but the above example with |foo| should not cause
> any freeze - it should not cause the retrieval of the full string. Does it
> do a string copy even if I do not change it?

Assuming 'nsiscripterror' is an nsIScriptError instance, the 'sourceLine' accessor does indeed copy the text every time it is called.

If these copies are the problem, you will want to take care to call the accessor only once, and then retain the giant string it gave you in JS. Some performance hints:

- If you have a giant string, JS 'substring' will return a new string that simply points into the original, called a 'dependent string'. So taking substrings of a giant string is quick.

- Concatenating two strings with '+' is also quick: it just produces a node that points to the left and right side strings, unchanged. This is called a 'rope'. You can concatenate two ropes, yielding another rope; eventually, you can end up with a whole tree (or a DAG, really; consider x + x) whose interior nodes are ropes, and whose leaves are real strings.

However, one must be careful with ropes, because the concatenation is only delayed, not eliminated: once you try to print a rope, or take a substring of a rope, or pass a rope to JSON.stringify, or do any of a number of other things, the rope is 'flattened': the concatenations that we put off for later now get done all at once, and the ropes are replaced with a big flat string, and a bunch of dependent strings pointing into it.

But it does mean that you can assume that a long sequence of + operations, mixed with other operations, will only do one copy for each non-+ operation. For example, code that does this:

   let chunks = []

   for (...) ... chunk.push(piece); ...

   ... chunks.join('') ...

is just needlessly obscure: you get exactly the same effect (probably better) with this:

   let result = ""

   for (...) ... result += piece; ...

   ... result ...

which is a lot simpler.

For what it's worth, the 'message' and 'sourceLine' accessors return ordinary 'flat' strings, not ropes, so you don't need to tiptoe around the string once you've got it.

Good luck with the LongStringActor. Those are a painful necessity, not much fun to work with.

Comment 9

[Jim Blandy :jimb]

(In reply to Mihai Sucan [:msucan] from comment #7)
> How long: I see one .message property has 282340 bytes and a .sourceLine of
> about the same size. We get about 800 messages in a single page load of
> youtube. That's not a singular example.

Wow --- that's a huge problem.

> Can we change the nsIScriptError implementation to keep the number of copies
> to a minimum?

I think we need to teach the code that touches mSourceLine not to return the whole darn thing; it should truncate gracefully. Giant blocks of minimized code on a single line are hardly rare.

Comment 10

[Jim Blandy :jimb]

(In reply to Mihai Sucan [:msucan] from comment #7)
> > The protocol should definitely avoid sending across giant strings.
> > 
> > Is it possible to use our profiler to get C++ backtraces and see what these
> > hangs really are? I'm offering guesses here, but data would keep us from
> > going astray.
> 
> Good point. Who should we ping for this kind of analysis? Can you do that?

I'm not able to do this immediately; let's talk on IRC about how to make progress here.

Comment 11

[Mihai Sucan [:msucan]]

Attachment: proposed patch

More investigation shows that only |error.message| is very slow to read. The |sourceLine| property doesn't cause so many copies to happen and it's faster to read.

This patch removes the |error.message| property from the page error packet and we no longer freeze the browser while users load youtube page or similar pages.

The |message| property only prints a formatted error message, which we did not use. We had it in packets simply for completeness.

Another change in this patch is to use LongStringActors for packets that send page errors.

The error console is also affected by the same performance issue. Loading youtube with the error console causes the browser to freeze for 1-3 seconds. See bug 840451.

Comment 12

[Mihai Sucan [:msucan]]

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

Jim: thanks for your feedback! It has been helpful for me to find the way to fix this issue in the browser and web consoles. The real fix should be in nsScriptError, in the |message| property getter.

Comment 13

[Zack Weinberg (:zwol)]

The CSS parser passes the entire line containing an error to the nsIScriptError constructor, no matter how long it is.  I understand that the JS parser truncates it to something like 60 characters on either side of the error.  It seems to me that trimming should be handled inside nsIScriptError so that we don't need to replicate it into every parser we have.

Comment 14

[Mihai Sucan [:msucan]]

Thank you Rob!

Landed:
https://hg.mozilla.org/integration/fx-team/rev/72b104307890

Comment 15

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/72b104307890