Open Bug 613498 Opened 14 years ago Updated 2 years ago

Very slow chrome to content DOM access

Categories

(Core :: XPConnect, defect)

x86
macOS
defect

Tracking

()

Performance Impact low

People

(Reporter: bzbarsky, Unassigned)

References

(Depends on 2 open bugs, Blocks 1 open bug)

Details

(Keywords: perf, perf:pageload)

Attachments

(1 file)

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.
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.
Depends on: 1348095
Depends on: 1348099
Blocks: QuantumFlow
Whiteboard: [qf]
Whiteboard: [qf] → [qf:p1]
Blocks: 1258946
Depends on: 1363956
Assignee: nobody → janus926
Depends on: 1363959
Depends on: 1363963
UncheckedUnwrap is now the top symbol on the reversed callstack after bug 1363963 landed, https://perfht.ml/2rrY3S3.
I suspect that bug 1355109 would help here more than anything else.
If so, do I still need to work on bug 1348099? The numbers in bug 1348099 comment 27 and 29 look worthy though.
Depends on: 1355109
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.
Depends on: 1377815
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
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
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?
Flags: needinfo?(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).
Flags: needinfo?(bzbarsky)
I thought sandboxes were the only cases that we expected bug 1355109 to help.
> 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.
Depends on: 1384790
(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.
Depends on: 1369274
Yep, thank you!  And thank you for the profiles in there!
Depends on: 1388538
Assignee: janus926 → nobody
Whiteboard: [qf:p1] → [qf:p2]
Keywords: perf
Whiteboard: [qf:p2] → [perf:p1]
Whiteboard: [perf:p1] → [qf:p1]
Whiteboard: [qf:p1] → [qf:i60][qf:p1]
Whiteboard: [qf:i60][qf:p1] → [qf:f60][qf:p1]
Whiteboard: [qf:f60][qf:p1] → [qf:f61][qf:p1]
bz, do you think this should be still p1 from QF point of view?
Flags: needinfo?(bzbarsky)
(64, p1 for now)
Whiteboard: [qf:f61][qf:p1] → [qf:f64][qf:p1]
I think so, because of webextensions....
Flags: needinfo?(bzbarsky)
Whiteboard: [qf:f64][qf:p1] → [qf:p1:f64]
A profile from recent Nightly
http://bit.ly/2KfV5pQ
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.
Depends on: 1474130

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

Whiteboard: [qf:p1:f64] → [qf:p2:responsiveness]

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

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

Flags: needinfo?(kmaglione+bmo)

(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.

Flags: needinfo?(kmaglione+bmo)

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.

Whiteboard: [qf:p2:responsiveness] → [qf:p1:pageload]
Blocks: 1486303
Blocks: 1487465

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

Flags: needinfo?(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?

Flags: needinfo?(peterv) → needinfo?(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...

Flags: needinfo?(bzbarsky)

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.

Whiteboard: [qf:p1:pageload] → [qf:p3:pageload]
Performance Impact: --- → P3
Keywords: perf:pageload
Whiteboard: [qf:p3:pageload]
Severity: normal → S3
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: