670689 - compartment slowly grows for page on samuelsidler.com

Status: RESOLVED INVALID

(Web Compatibility :: Site Reports, defect)

Description

[Timothy Nikkel (:tnikkel)]

I opened http://samuelsidler.com/2011/03/09/quote/ (and about:memory) in a fairly clean profile. The compartment for this page was using under 4MBe. I left my browser overnight and the compartment was then using over 30MB. Seems reproducible. Clicking any of the GC/CC buttons doesn't make it go down. I was using the 2011-07-10 nightly.

Comment 1

[Boris Zbarsky [:bzbarsky]]

Maybe something to do with the "featured posts" ticker?  Does ripping out just enough to run that at a high rate show the growth too?

Comment 2

[Timothy Nikkel (:tnikkel)]

It does seem to be that ticker. I made a reduced testcase that only includes the jquery scripts and the simple HTML that makes up the ticker and sped the ticker up 10x and it climbed from about 3mb to close to 10mb in about an hour.

Comment 3

[Timothy Nikkel (:tnikkel)]

Attachment: standalone reduced testcase

This uses the jquery.custom.js from the server so that the testcase can be standalone. To increase the speed of the ticker save a local copy of that file and change the "interval" in it.

Comment 4

[Nicholas Nethercote [inactive]]

I love standalone reduced test cases!  Thanks, Timothy.

Comment 5

[Boris Zbarsky [:bzbarsky]]

Well, the HTML is reduced.  The JS ... is not quite.  ;)

njn, are you looking into minimizing/deobfuscating the JS a bit, or should I?

Comment 6

[Nicholas Nethercote [inactive]]

(In reply to comment #5)
> 
> njn, are you looking into minimizing/deobfuscating the JS a bit, or should I?

I haven't looked, if you want to that would be great!  I've assigned it to you, hope that's ok :)

Comment 7

[Timothy Nikkel (:tnikkel)]

This might be a recent regression, either because the site changed or Firefox changed.

Comment 8

[Timothy Nikkel (:tnikkel)]

Opening the testcase in Chrome also seems to cause a slow increase in the size of the "tab" for the testcase.

Comment 9

[Boris Zbarsky [:bzbarsky]]

Attachment: Testcase including all the JS (unminified), running as fast as it can

This includes a slightly newer jquery tools, since I couldn't find an unminified copy of the older version.  But I still see the memory growth.

The growth is mostly GC heap and unclassified (I'll bet money on the DOM).

Comment 10

[Boris Zbarsky [:bzbarsky]]

Attachment: All-in-one file for real

Comment 11

[Boris Zbarsky [:bzbarsky]]

OK, some more data.  This script is crazy-happy allocating text nodes and document fragments.  Which is fine as far as it goes.  I put in counters to count document fragments (as well as nsGenericElement, which is a superclass) and when I hit "minimize memory usage" the number goes down to the baseline number... but memory usage in general does not.

Oh, our normal GC knocks that generic element number down to baseline too, every so often.  So everything really is good on that front.

Which leave the question of what's being allocated....

Comment 12

[Boris Zbarsky [:bzbarsky]]

OK, so here's about:memory for that compartment after running the testcase for 2 minutes or so:


   ├──20.07 MB (19.77%) -- compartment(file:///Users/bzbarsky/test.html)
   │  ├──13.20 MB (13.00%) -- gc-heap
   │  │  ├───6.20 MB (06.11%) -- objects
   │  │  ├───5.61 MB (05.53%) -- arena-unused
   │  │  ├───0.84 MB (00.82%) -- strings
   │  │  └───0.54 MB (00.54%) -- (4 omitted)
   │  ├───4.56 MB (04.49%) -- mjit-code
   │  ├───1.05 MB (01.03%) -- tjit-data
   │  │   ├──0.91 MB (00.90%) -- allocators-main
   │  │   └──0.14 MB (00.14%) -- (1 omitted)
   │  ├───0.69 MB (00.68%) -- object-slots
   │  └───0.57 MB (00.57%) -- (4 omitted)

Here it is after running for about 20 more minutes:


   ├──276.12 MB (65.21%) -- compartment(file:///Users/bzbarsky/test.html)
   │  ├──150.53 MB (35.55%) -- gc-heap
   │  │  ├──125.71 MB (29.69%) -- objects
   │  │  ├───13.96 MB (03.30%) -- arena-unused
   │  │  ├────7.19 MB (01.70%) -- strings
   │  │  ├────2.50 MB (00.59%) -- arena-padding
   │  │  └────1.18 MB (00.28%) -- (3 omitted)
   │  ├──107.63 MB (25.42%) -- mjit-code
   │  ├───15.36 MB (03.63%) -- object-slots
   │  └────2.61 MB (00.62%) -- (5 omitted)

In the same time, heap-unclassified went from about 40MB to about 77MB.  There was also a 5MB increase in the urlclassifier sqlite cache.  Those were the only memory increases.

I'm not sure what's up with the heap-unclassified and gc-heap, necessarily, but why the heck did we pick up 100MB of mjit-code?  I'm probably the wrong person to answer that particular question....

Comment 13

[Boris Zbarsky [:bzbarsky]]

Oh, and I'm no longer convinced that the unclassified allocations here are DOM.  I wonder whether there's something over in JS-land we're not counting correctly yet.  For example, are we counting the space for property tables in dictionary shapes?  We don't seem to be, offhand...

Comment 14

[Nicholas Nethercote [inactive]]

> For example, are we counting the space for property tables
> in dictionary shapes?  We don't seem to be, offhand...

You're right, we are not.  That's bug 671150.

100MB+ of mjit-code is ridiculous, and reminds me of bug 671759.

Comment 15

[Johnny Stenback (:jst)]

Boris, can you dig in a bit more here and see what might be causing this?

Comment 16

[Boris Zbarsky [:bzbarsky]]

I can try, but see comment 12.

Comment 17

[Boris Zbarsky [:bzbarsky]]

Alright, so the "mjit-code" allocations here actually come from the regexp jit, which apparently allocates out of the same place as the mjit.  All the allocations coming through JSC::ExecutableAllocator::alloc seem to be n==389, and come from the same place: line 2810 of the attached file.  That line is:

  event.namespace_re = 
    new RegExp("(^|\\.)" + namespaces.join("\\.(?:.*\\.)?") + "(\\.|$)");

I added a counter to count RegExp objects and print the number whenever we're allocating a RegExp and the number is 0 mod 100.  When I first load the page, I see numbers in the 1600 range being printed.  After running the page for about 5 minutes, and then bonking the "minimize memory" button in about:memory a few times, I see numbers printed in the 20,000 range.  And if I breakpoint in ~RegExp, I do in fact see a bunch of regexps being deallocated.  So the page is creating more regexps than that.

In fact, I added separate counters in RegExp() and ~RegExp() and ran the testcase for about 3 minutes.  At the end of that time, I'm seeing numbers like this:

  Regexp alloc count: 31000
  Regexp delete count: 17400

I do also see some executable pools deleted, but not many compared to how many are allocated.  So there seem to be two main effects here: fragmentation in the regexp executable pools due to some regexps but not others sticking around (if I understand this pool correctly) and the fact that we're ending up with lots of regexp objects not going away.

Now presumably they're not going away because the |event| object above is not going away.  Next step is to try to figure out why that is, I guess...

Comment 18

[Boris Zbarsky [:bzbarsky]]

Oh, and if about:memory could separate regexp code and actual mjit code, that might be really nice.... not sure how doable that is.

Comment 19

[Boris Zbarsky [:bzbarsky]]

So at line 2810 there, |event| is a native Object.  It was that way before it ever got passed into the function.  It got there via the click() method on line 9064 making this call on line 9099:

  trigger.trigger(e, [i]);

which lands us on line 3469, then through the guts of forEach on line 3470, which calls the function line 2810 is in.

click() is called on line 8285 from speed() with no arguments.  So this |event| object comes from line 9089:

  e = e || $.Event();

where the latter ends up allocating the object with |new jQuery.Event|.

Comment 20

[Boris Zbarsky [:bzbarsky]]

OK, so I ran this for a bit, then did a JS heap dump right after minimizing and looked for "(^|\\.)" in there.  Here's what I get:

0x23a79de0 string (^|\\.)(\\.|$)  via ...(0x16d52a60 Object).5(0x16d94ca0 Object).jQuery16109070024718758194(0x16d94ce8 Object).fxqueue(0x16daaa50 Array).element[16](0x23a81938 Function).parent(0x23a83298 Call).optall(0x23a7ddc0 Object).old(0x23a81778 Function).parent(0x23a83160 Call).e(0x23a7dd30 Object).namespace_re(0x23a83230 RegExp).source

Lots and lots of stuff like that, with slightly different array addresses for .fxqueue, and each array having several hundred element.

Now that has some stuff trimmed off the front, but if I then look for that RegExp directly:

0x23a83230 RegExp 2309a0c0        via ...(0x16d570b0 Function).cache(0x16d52a60 Object).5(0x16d94ca0 Object).jQuery16109070024718758194(0x16d94ce8 Object).fxqueue(0x16daaa50 Array).element[16](0x23a81938 Function).parent(0x23a83298 Call).optall(0x23a7ddc0 Object).old(0x23a81778 Function).parent(0x23a83160 Call).e(0x23a7dd30 Object).namespace_re

The "jQuery16109070024718758194" thing comes from the "expando" prop in the jQuery.extend call on line 1395.  The "fxqueue" comes from the queue() function on line 1758.

So for some reason we have lots of very long event queues here.  Are things not being dequeued for some reason? ccing John, because he may actually know this queue stuff.

Comment 21

[Boris Zbarsky [:bzbarsky]]

To quantify "lots" and "very long", when I have 1500 or so live regexps for that particular |new RegExp| call, there are 4 different fxqueue arrays, each containing about 380 elements.  They account for all but one of those regexps.  The remaining regexp is reachable via this path:

  nsXPCWrappedJS[nsIAnimationFrameListener,0x2257fac0].mJSObj(0x177a2238 Function).parent(0x17792808 Call).self(0x177a30d0 Object).options(0x17794fb8 Object).old(0x1779edd0 Function).parent(0x1779d438 Call).e(0x17794c58 Object).namespace_re(0x177dfd28 RegExp).source

which is the only sane part here: this is actually hanging off the upcoming callback function that Gecko is holding on to.

So to be clear, what's happening here is that the page JS just creates lots of regexp objects and holds on to many of them.  This may be a bug in jQuery (most likely) or in the consumer, but that's what the page does.  Hence the Chrome behavior here.

The best we can do on our end pending a fix to jQuery or the page is to try to reduce the fragmentation in the regexp code pools if possible... and even that would only help a bit, because the page holds on to about half the regexps it creates.

Perhaps if we move to lazy regexp compilation (which we have wanted elsewhere anyway, I think) plus expiring compiled regexps that haven't been used in a while, we could limit the damage to just the GC heap for the actual RegExp objects...

Comment 22

[Andrew McCreight [:mccr8]]

(In reply to comment #18)
> Oh, and if about:memory could separate regexp code and actual mjit code,
> that might be really nice.... not sure how doable that is.

I filed Bug 673158 for this.

Comment 23

[Boris Zbarsky [:bzbarsky]]

And by the way, I'm guessing that in this case the remaining unclassified stuff is also somewhere in the js engine.  Might be worth it to look up where.

Comment 24

[Johnny Stenback (:jst)]

Thanks for digging in bz! I think this one's in jquery's court now. Over to nobody on our end until we hear back, but it's looking like this is invalid as far as Firefox bugs go.

Comment 25

[Boris Zbarsky [:bzbarsky]]

I filed bug 673188 on lazily compiling regexps and bug 673189 on discarding cold regexp jitcode.

Comment 26

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

We have the mitigation strategies filed, the underlying bug here is in jquery, so moving over to Tech Evangelism.

Comment 27

[Nicholas Nethercote [inactive]]

(In reply to comment #26)
> We have the mitigation strategies filed, the underlying bug here is in
> jquery, so moving over to Tech Evangelism.

Tech evangelists:  see comment 21 for details.

Comment 28

[Karl Dubost💡 :karlcow]

→ http HEAD http://samuelsidler.com/2011/03/09/quote/
HTTP/1.1 404 Not Found
Cache-Control: no-cache, must-revalidate, max-age=0
Content-Encoding: gzip
Content-Length: 20
Content-Type: text/html; charset=UTF-8
Date: Fri, 26 Sep 2014 00:02:59 GMT
Expires: Wed, 11 Jan 1984 05:00:00 GMT
Pragma: no-cache
Server: Apache
Set-Cookie: PHPSESSID=V6Q6JUP58zmHYAH6lgNO03; path=/
Vary: Accept-Encoding,User-Agent
X-Pingback: http://samuelsidler.com/xmlrpc.php


Not valid anymore.