1367866 - Really long GC pauses when running code in devtools vs content

Status: NEW

(Core :: JavaScript: GC, defect, P3)

Description

[Greg Tatum [:gregtatum]]

In the new debugger project there are some performance issues with CodeMirror, the text editor used to display sources. One of these is searching through a minified source. This is extremely slow because most likely it's splitting the work on newlines, and on minified sources, there are not many (if any) new lines. While diagnosing this issue I came across a test case where running a code search on the debugger inside of devtools took 60 seconds, and would block the entire main thread. I did another test case running the debugger independently in a browser, and the code took 6 seconds to run.

Here are the two different profiles:

Searching while running in devtools (thread "Main Thread"): https://perfht.ml/2qgO6rn
Searching while running in a tab (thread "Content 3 of 3"): https://perfht.ml/2qhaYXS

The striking thing between the two profiles is the amount of time spent in GC and cross compartment wrappers in the devtools case.

STR for searching in the debugger:

Visit http://alteredqualia.com/xg/examples/hannibal_draco.html
Open up devtools
Go to debugger source "xg.min.625.js"
Search for something

To repeat in content, follow the instructions on launching the debugger from https://github.com/devtools-html/debugger.html and repeat the above STR.

The source code in CodeMirror that is doing the searching is:

http://searchfox.org/mozilla-central/rev/35b37316149108d53a02fb8498e250ea8a22ab5d/devtools/client/sourceeditor/codemirror/codemirror.bundle.js#6278-6292

 > StringStream.prototype.match = function (pattern, consume, caseInsensitive) {
 >   if (typeof pattern == "string") {
 >     var cased = function (str) { return caseInsensitive ? str.toLowerCase() : str; };
 >     var substr = this.string.substr(this.pos, pattern.length);
 >     if (cased(substr) == cased(pattern)) {
 >       if (consume !== false) { this.pos += pattern.length; }
 >       return true
 >     }
 >   } else {
 >     var match = this.string.slice(this.pos).match(pattern);
 >     if (match && match.index > 0) { return null }
 >     if (match && consume !== false) { this.pos += match[0].length; }
 >    return match
 >  }
 >};

Comment 1

[Greg Tatum [:gregtatum]]

I ran this again, but rewrote the devtools memory panel to only include an iframe of the locally running debugger, it's exhibiting the same behavior as running in a tab.

https://perfht.ml/2qhcRnA

Comment 2

[Steve Fink [:sfink] [:s:]]

In the devtools case, we have a long succession of 150-170ms nonincremental TOO_MUCH_MALLOC slices. I would guess this is from allocating lots of strings. Bug 903519 (allocating strings in the nursery) has the potential to help a lot here, if they're short-lived as they probably are.

But that doesn't explain the difference between xul and content. Given the presence of cross-compartment wrappers, my guess is that we're copying a ton of strings when wrapping them across compartments.

In the content case, we have a single major GC spanning 2.5 seconds, but only consuming a total of 65ms. It is a 9-slice incremental GC of a single zone (out of 4 total). All slices but one kept within their 10ms budget. The long one was 42.57ms out of a 10ms slice. (Note that some things aren't completely adding up here; see bug 1367876.)

I should also note that 150ms just happens to be our release criterion threshold. Our malloc threshold here seems to put us just over that limit, on Greg's machine for this test case.

Comment 3

[Brian Grinstead [:bgrins]]

Sounds like we should re-run the profile after Bug 903519 to see if that helps

Comment 4

[Steve Fink [:sfink] [:s:]]

Is this still happening? I'm wondering if this was another instance of bug 1374797.

Comment 5

[Brian Grinstead [:bgrins]]

Setting needinfo for comment 4

Comment 6

[Greg Tatum [:gregtatum]]

Still looks to be an issue: https://perfht.ml/2wpflPh