680784 - lots of cpu time spent in FindInJSObjectScope with large amount of tabs

Status: RESOLVED WORKSFORME

(Core :: XPConnect, defect)

Description

[ohsix]

in a session that >2000 (estimated) tabs on this machine, a lot of time is spent in FindInJSObjectScope when new tabs are opened. for profiling, about 50 new tabs are opened by ctrl clicking a link in an existing page and then closing the tabs one by one, it took about 5 minutes total.

here's the top of that report:

    32.21%  firefox-bin  libxul.so                   [.] XPCWrappedNativeScope::FindInJSObjectScope(JSContext*, JSObject*, int, XPCJSRuntime*)
            |
            --- XPCWrappedNativeScope::FindInJSObjectScope(JSContext*, JSObject*, int, XPCJSRuntime*)
               |          
               |--33.16%-- 0x7fff1ba3ce90
               |          
               |--17.60%-- (nil)
               |          
               |--16.42%-- 0x7fff1ba3d120
               |          
               |--8.29%-- 0x7fff1ba372d0
               |          
               |--8.27%-- 0x7fff1ba3da10
               |          
               |--8.26%-- 0x7fff1ba3b6a0
               |          
                --7.99%-- 0x7fff1ba3ad30

    10.01%  firefox-bin  libxul.so                   [.] JS_GetCompartmentPrivate
            |
            --- JS_GetCompartmentPrivate

     5.35%  firefox-bin  libxul.so                   [.] TraverseExpandoObjects(xpc::PtrAndPrincipalHashKey*, JSCompartment*, void*)
            |
            --- TraverseExpandoObjects(xpc::PtrAndPrincipalHashKey*, JSCompartment*, void*)

     1.61%  firefox-bin  libxul.so                   [.] SearchTable
            |
            --- SearchTable
               |          
                --100.00%-- (nil)
                          |          
                           --100.00%-- PL_DHashFreeTable
                                     0xc3a4f3d78948144f

     1.43%  firefox-bin  libxul.so                   [.] js::Interpret(JSContext*, js::StackFrame*, unsigned int, js::InterpMode)
            |
            --- js::Interpret(JSContext*, js::StackFrame*, unsigned int, js::InterpMode)
               |          
               |--8.93%-- 0x7f08a30a9d77
               |          
               |--8.90%-- 0x7f08a1d3eb19
               |          
               |--8.90%-- 0x7f08827a71ec
               |          
               |--8.88%-- 0x7f08adb403d4
               |          
               |--5.93%-- 0x7f08a1d48a42
               |          
               |--5.93%-- 0x7f08a1fd94bf
               |          
               |--5.86%-- 0x7f08a1fba9de
               |          
               |--5.81%-- 0x7f08a1d489d2
               |          
               |--5.73%-- 0x7f08a30a9d86
               |          
               |--2.98%-- 0x7f08827a72eb
               |          
               |--2.97%-- 0x7f08a1d3ece8
               |          
               |--2.97%-- 0x7f08a1d489d5
               |          
               |--2.97%-- 0x7f08a1f13966
               |          
               |--2.97%-- 0x7f08a1d3ebf9
               |          
               |--2.96%-- 0x7f08a1d48a03
               |          
               |--2.96%-- 0x7f08adb403d8
               |          
               |--2.96%-- 0x7f08a1f1397f
               |          
               |--2.90%-- 0x7f08827f4615
               |          
               |--2.88%-- 0x7f08a1d2e009
               |          
               |--2.87%-- 0x7f08adbfd53e
               |          
                --2.77%-- 0x7f08a1d3eb33

     1.23%  firefox-bin  libpthread-2.13.so          [.] pthread_mutex_lock
            |
            --- pthread_mutex_lock
               |          
               |--28.21%-- 0x7f08b92b2288
               |          
               |--28.06%-- 0x7f08b92b2368
               |          
               |--12.97%-- 0x7f08b92b22f8
               |          
               |--7.40%-- 0x7f088dd00938
               |          
               |--2.59%-- 0x7f08b92b2218
               |          
               |--2.56%-- 0x7f0879fa02e0
               |          0x7f0800000007
               |          
               |--1.12%-- 0x7f0818901808
               |          
               |--0.82%-- 0x7f0867900b30
               |          
               |--0.74%-- 0x7f086cd01808
               |          
               |--0.74%-- 0x1001100000006
               |          nsAttrAndChildArray::GetAttr(nsIAtom*, int) const
               |          
               |--0.74%-- 0x7f08a21edae0
               |          |          
               |          |--50.11%-- 0x7f0800000007
               |          |          
               |           --49.89%-- 0x7fff00000007
               |          
               |--0.73%-- 0x7f08a21edaa0
               |          0x7f0800000007
               |          
               |--0.72%-- 0x7f08b92b21a8
               |          
               |--0.72%-- 0x7f08b92b2138
               |          
               |--0.56%-- 0x7fff1ba39d90
               |          
               |--0.55%-- 0x7fff1ba3b530
                --10.76%-- [...]

Comment 1

[Andreas Gal :gal]

This is a great bug report. Thanks.

Comment 2

[Dão Gottwald [:dao]]

Is this a regression? Did you not see this issue in Firefox 5, 4, 3.6?

Comment 3

[Andreas Gal :gal]

This might have regressed slightly between 3.6 and 4 when we added compartments (we enter a compartment), but I am pretty sure the real issue here is that we are doing a linear search across all scopes. mrbkap and I have discussed this before as being potentially slow. I am glad we have actually proof now it is.

Comment 4

[ohsix]

slightly related to last comment, and initial bug, the profile looks like this and stays this way (profiled almost a half hour) when tab candy is open in one of the windows, takes a few seconds to do anything, lots of seconds to type in search queries in the tab candy view.

    27.29%  firefox-bin  libxul.so                   [.] JS_GetCompartmentPrivate
            |
            --- JS_GetCompartmentPrivate

    20.15%  firefox-bin  libxul.so                   [.] TraverseExpandoObjects(xpc::PtrAndPrincipalHashKey*, JSCompartment*, void*)
            |
            --- TraverseExpandoObjects(xpc::PtrAndPrincipalHashKey*, JSCompartment*, void*)

    10.54%  firefox-bin  libxul.so                   [.] XPCWrappedNativeScope::FindInJSObjectScope(JSContext*, JSObject*, int, XPCJSRuntime*)
            |
            --- XPCWrappedNativeScope::FindInJSObjectScope(JSContext*, JSObject*, int, XPCJSRuntime*)
               |          
               |--43.03%-- (nil)
               |          
               |--29.56%-- 0x7fff68edab50
               |          
               |--14.60%-- 0x7fff68edaed0
               |          
                --12.81%-- 0x7fff68edab10

Comment 5

[ohsix]

anything going on with this? other profiles i've sharded off my main profile have started to do the same thing

Mozilla/5.0 (Ubuntu; X11; Linux x86_64; rv:9.0.1) Gecko/20100101 Firefox/9.0.1

              2 -- js-compartments-system
            692 -- js-compartments-user

Comment 6

[ohsix]

sorry for not putting this all in one message;

the memory usage is actually quite good considering

1,958,678,528 B (100.0%) -- resident
├──1,941,463,040 B (99.12%) -- anonymous
│  ├──1,930,919,936 B (98.58%) -- anonymous, outside brk() [rw-p] [681]
│  └─────10,543,104 B (00.54%) -- anonymous, outside brk() [rwxp] [86]
└─────16,461,824 B (00.84%) -- shared-libraries

              4 -- js-compartments-system
          1,798 -- js-compartments-user

are the numbers from the profile i created the original report with/for

the linear slowdown with ff3, or basically pre-compartments was manageable, and i could migrate stuff if needed; but with ff4+ there's just huge long pauses, and i don't know why but it seems there's a situation where you have just a handful more tabs and get huge pauses, close them and it acts normally, so it's not all the compartment count and the linear walk, maybe visiting every compartment to collect things?

Comment 7

[Bobby Holley (:bholley)]

Hm. So this should be constant time for global objects with the special XPConnect magic in them:

http://mxr.mozilla.org/mozilla-central/source/js/xpconnect/src/XPCWrappedNativeScope.cpp#760

I'd always assumed that that was the common case. Andreas or blake - do you guys know why we'd want a global without JSCLASS_XPCONNECT_GLOBAL? What are the situations where we don't have it? Can we just make sure we always have it?

Comment 8

[Bobby Holley (:bholley)]

I just realized this will actually be fixed entirely by compartment-per-global, which Luke and I are going to be doing this quarter. So keep an eye on bug 650353!

Comment 9

[Olli Pettay [:smaug][[e-mail]]]

I haven't seen this lately, and since bug 650353 is fixed, I assume also this one is.