613498 - Very slow chrome to content DOM access

Status: NEW

(Core :: XPConnect, defect)

Description

[Boris Zbarsky [:bzbarsky]]

The steps are in bug 613487.

Profile says:

  4% in js_Interpret
  4% GC
 89% under js::proxy_GetProperty

The property get time is about half XrayWrapper::getPropertyDescriptor and half JSCrossCompartmentWrapper::call.

Under getPropertyDescriptor we have:

 4% entering cross-compatment calls
 4% resolveOwnProperty on the wrapper
 9% JS_WrapValue
 8% JS_DefinePropertyById
 3% auto-entering compartments
 3% XPCCallContext ctors
 3% XPCNativeMember::resolve
 2% leaving cross-compartment calls

and some minor stuff.

Under call we have:

 4% self time in XPCWrappedNative::CallMethod
 2% XPCCallContext ctors
 8% NativeData2JS
 4% calling actual DOM methods (previousSibling, nextSibling, etc)
 4% nsScriptSecurityManager::CanAccess (from CallMethod).  Can we remove this
    yet?
 1% XPCCallContext::CanCallNow.
 1% ~CallMethodHelper.
 1% NS_IsMainThread_P
 1% various xptInterfaceEntry stuff.

Comment 1

[Boris Zbarsky [:bzbarsky]]

So summary:

1)  Under call() this is all xpconnect suck.  No fast-path for wrapping, looks
    like, and probably useless security checks, plus general silliness.  Any way
    we could call quickstubs from the proxy code somehow?  ;)
2)  Under getPropertyDescriptor, about 10% of the total runtime is managing our
    compartment.  
3)  JS_WrapValue is mostly JSCompatment::wrap self time and JSWrapper::New.
4)  JS_DefinePropertyById is ending up in newShape, changeProperty,
    lookupProperty, putProperty, etc.

Comment 2

[Boris Zbarsky [:bzbarsky]]

Attachment: Zip of testcase that can be used, since the other one is gone

Comment 4

[Ting-Yu Chou [:ting] (away)]

UncheckedUnwrap is now the top symbol on the reversed callstack after bug 1363963 landed, https://perfht.ml/2rrY3S3.

Comment 5

[Boris Zbarsky [:bzbarsky]]

I suspect that bug 1355109 would help here more than anything else.

Comment 6

[Ting-Yu Chou [:ting] (away)]

If so, do I still need to work on bug 1348099? The numbers in bug 1348099 comment 27 and 29 look worthy though.

Comment 7

[Boris Zbarsky [:bzbarsky]]

The patch in bug 1355109 should help with getters, but so far not with method calls or indexed access on lists.  So improving those cases would still be a good idea; I expect the patches in bug 1348099 do help with method calls.

Comment 8

[Ting-Yu Chou [:ting] (away)]

Replace the empty if [1] by MOZ_ASSERT_IF doesn't get better numbers for the micro benchmark (bug 1348095 comment 3).

[1] http://searchfox.org/mozilla-central/rev/f1472e5b57fea8d4a7bbdd81c44e46958fe3c1ce/js/src/proxy/Wrapper.cpp#344-345

Comment 9

[Ting-Yu Chou [:ting] (away)]

From VTune, I see:

(a) accessing object scope in XrayResolveOwnProperty() [1] and getExpandoObject() [2] is expensive
(b) the if clause for ExposeObjectToActiveJS() [3] is the reason why Wrapper::wrappedObject() stays on the top of profile

Now we have two calls to getExpandoObject() and two calls to getTargetObject() in a single Proxy::get(), one pair in hasOwn() [4][5] and one pair in GetProtoType() [6]. I am thinking something like CreateProtoWalkingContext() and pass the context to hasOwn() and GetProtoType(), so we can call getExpandoObject() and getTargetObject() just once. It'd also be good if we improve (a) and (b).

[1] http://searchfox.org/mozilla-central/rev/3a3af33f513071ea829debdfbc628caebcdf6996/dom/bindings/BindingUtils.cpp#1721
[2] http://searchfox.org/mozilla-central/rev/3a3af33f513071ea829debdfbc628caebcdf6996/js/xpconnect/wrappers/XrayWrapper.cpp#1153
[3] http://searchfox.org/mozilla-central/rev/3a3af33f513071ea829debdfbc628caebcdf6996/js/src/proxy/Wrapper.cpp#346-347
[4] http://searchfox.org/mozilla-central/rev/3a3af33f513071ea829debdfbc628caebcdf6996/js/xpconnect/wrappers/XrayWrapper.cpp#2100
[5] http://searchfox.org/mozilla-central/rev/3a3af33f513071ea829debdfbc628caebcdf6996/js/xpconnect/wrappers/XrayWrapper.cpp#1513
[6] http://searchfox.org/mozilla-central/rev/3a3af33f513071ea829debdfbc628caebcdf6996/js/xpconnect/wrappers/XrayWrapper.cpp#2412,2414

Comment 10

[Ting-Yu Chou [:ting] (away)]

Running the test case is a lot better as of bug 1355109 landed. Reducing the number of times calling getExpandoObject() and getTargetObject() that I mentioned in comment 9 will help, but probably doesn't block this bug? Are there anything else that you think we should do?

Comment 11

[Boris Zbarsky [:bzbarsky]]

So I just tried re-profiling both the testcase from bug 1348095 comment 3 and the testcase from bug 613487.

On the latter, we're no longer a long pole: Xray time is less than 1/3 the time spent in xpath evaluation, for example....

On the former, a profile is at https://perfht.ml/2w0yrv2 but note that it's not running in a sandbox and hence does not benefit from bug 1355109 afaict.

The main thing that would help here would probably be extending the caching to more cases, but that may depend on the compartments work jorendorff is doing.

The other thing that would be useful here are "real life" testcases instead of microbenchmarks (e.g. actual extension content scripts where this is a problem).

Comment 12

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

I thought sandboxes were the only cases that we expected bug 1355109 to help.

Comment 13

[Boris Zbarsky [:bzbarsky]]

> I thought sandboxes were the only cases that we expected bug 1355109 to help.

For now, yes, until we merge chrome compartments and rework Xray expandos.

Comment 14

[Edouard Oger [:eoger]]

(In reply to Boris Zbarsky [:bz] (vacation Aug 14-27) from comment #11)
> The other thing that would be useful here are "real life" testcases instead
> of microbenchmarks (e.g. actual extension content scripts where this is a
> problem).

Bug 1369274 might be what you are looking for.

Comment 15

[Boris Zbarsky [:bzbarsky]]

Yep, thank you!  And thank you for the profiles in there!

Comment 16

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

bz, do you think this should be still p1 from QF point of view?

Comment 17

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

(64, p1 for now)

Comment 18

[Boris Zbarsky [:bzbarsky]]

I think so, because of webextensions....

Comment 19

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

A profile from recent Nightly
http://bit.ly/2KfV5pQ

Comment 20

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

The particular testcase might become a lot faster with bug 1474130 fixed.
A bit wrong to add dependency, since that bug won't fix this one at all, but at least it would fix a common performance bottleneck.

Comment 21

[Daniel Holbert [:dholbert]]

[qf:p1] is now reserved for pageload, so let's call this p2.

Comment 22

[Kris Maglione [:kmag]]

Alas, this almost certainly affects page load in a lot of cases.

Comment 23

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

Kris, do you happen to have any profiles showing that? Since if this affects page load badly, we should probably re-triage.

Comment 24

[Kris Maglione [:kmag]]

(In reply to Olli Pettay [:smaug] from comment #23)

Kris, do you happen to have any profiles showing that? Since if this affects page load badly, we should probably re-triage.

I don't, but I know this tends to show up in extensions that walk the entire DOM for one reason or other (e.g., form fill extensions looking for fields to fill), and they tend to do that during page load.

Comment 25

[Daniel Holbert [:dholbert]]

OK, thanks for the heads up. A profile for demonstration/investigation of pageload impact would be nice, but for now let's call it [qf:p1:pageload] then.

Comment 27

[Randell Jesup [:jesup] (needinfo me)]

Can we get a profile on this from someone? And Peter, can you prioritize? Thanks!

Comment 28

[Peter Van der Beken [:peterv]]

The original testcase attached to this bug seems to perform ok for me. But maybe it doesn't show the underlying issues that this bug was supposed to be about?

Comment 29

[Boris Zbarsky [:bzbarsky]]

Sessionstore got moved into C++, so the original testcase is no longer exercising "chrome to content DOM access" case, right?

This bug could probably benefit from actual extension testcases showing these problems...

Comment 30

[(no longer active)]

I remember that around 2017 one of the extensions that ran into performance problems because of this bug was Grammarly. Sadly I don't remember any exact STRs, but I just captured this profile from Nightly by pasting the text of Tom Sawyer into a Bugzilla text box with Grammarly installed, in case it would be helpful.

Comment 31

[Mayank Bansal]

Profile from Nightly (doesnt finish loading): https://share.firefox.dev/4fZlAzz (this is all nsINode::ComputeIndexOf )
Chrome: Almost instant

Comment 32

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

That profile doesn't seem to have much to do with this bug.
Also, see https://bugzilla.mozilla.org/show_bug.cgi?id=613498#c29