1103446 - Improve ContactManager to make the conversion of contacts faster (200+ms).

Status: RESOLVED FIXED

(Firefox OS Graveyard :: Performance, defect)

Description

[Thinker Li [:sinker]]

ContactManager spend quite a lot of time to wrap/convert Contacts.

The possible solutions that I know are
 - a faster way to convert data.
 - be multi-threading to wrap/convert Contact objects.

Maybe, there is a better solution.  Let's discuss here.

Comment 1

[Julien Wajsberg [:julienw]]

Should the component be Core::DOM:Contacts ?

Comment 2

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

ContactManager._convertContact() news mozContact which is a JS implemented WebIDL.

Comment 3

[Ting-Yuan Huang]

No wrappedJSObject is used nor __exposedProps__ is needed now. The class in question is redefined in WebIDL. Anyway, bug 783057 has nothing to do with this bug.

Comment 4

[Ting-Yuan Huang]

The time spent here (1020ms) is much higher than Thinker's estimation (200+ms).

With reference-workload-light (200 contacts), it takes ~4.6 sec / 3866 1-ms samples to stabilize on Flame. There are 936 samples (~1.02 sec) in the callees of _convertContacts and 772 samples (~0.85 sec) of this:

> let newContact = new this._window.mozContact(contact.properties);

Namely, it takes ~4.25ms to new a mozContact.

Comment 5

[Wesley Huang [:wesley_huang] (EPM) (NI me)]

We should consider making it a feature blocker if this improves launch time.

Comment 6

[Thinker Li [:sinker]]

assign to Ting-Yuan for temporary since he is studying.  Assign to others if he think there is better candidate for this bug.

Comment 7

[Ting-Yuan Huang]

Attachment: Return Contact instead of mozContact.

It seems that argument passing to the constructor of mozContact takes most of the time. By returning Contact (which implements mozContact) rather than mozContact, the _convertContact() and launch time become much faster. The improvement roughly match what described in comment 4, which is ~0.85 sec.

Before:
http://people.mozilla.org/~bgirard/cleopatra/#report=842f0c00e65b531ff1ebc281a17c6522012d034a
After:
http://people.mozilla.org/~bgirard/cleopatra/#report=8716fa7833c8ba11e19e4966ca66817fde8eb761

I'm still trying to catch up the knowledge here and not sure if doing so is OK or not. Gregor, may I know your opinion?

Comment 8

[Julien Wajsberg [:julienw]]

I just want to note that this definitely could make the SMS app startup faster as well.

Comment 9

[Ken Chang[:kenkai]]

Performance improvement is one of 2.2 features.

Comment 10

[Blake Kaplan (:mrbkap) (inactive)]

Gregor asked me to look into this. I don't think the patch can land as is, unfortunately, because even though all of the properties will exist properly on the Contact object (instead of a mozContact object), it won't have the correct prototype and things like |contact instanceof window.mozContact| will return false.

Ting-Yuan, would you mind testing that?

It seems like the easiest way to fix this would be to have getters for all of the properties listed in the mozContact webidl interface and to simply store their values on a sub-object hanging off of the webidl object.

I have a sketch of a patch that bent and I cooked up that I'll attach here. I haven't run it at all, so it might not work at all; however, I think it's the right approach at least.

Comment 11

[Blake Kaplan (:mrbkap) (inactive)]

Attachment: sketch

Hopefully, this is useful.

Comment 12

[Ting-Yuan Huang]

http://people.mozilla.org/~bgirard/cleopatra/#report=417802cc8c33d4a1c922b4350daae66688a23aa7

It's roughly 613ms faster than the unmodified codes in terms of convertContacts: the number of samples filtered by convertContacts are 956 and 399 respectively.

The improvement to the overall running time is 5080 - 4765 = 315ms, measured by the first and last call-stack pikes.

I'm still catching up the knowledge here so I can't comment on the result. Perhaps this should be a need-info rather than a feedback :)

Comment 13

[Julien Wajsberg [:julienw]]

Ting-Yuan, do you see an improvement with the SMS launch time as well?

Comment 14

[Ting-Yuan Huang]

w/o mrbkap's patch
http://people.mozilla.org/~bgirard/cleopatra/#report=197474f417f2508c63c56da5e1ebb34fbf3db354

w/ mrbkap's patch
http://people.mozilla.org/~bgirard/cleopatra/#report=75ade316f94877c1c2cef4c9da254d646e0afdf6

There are 178/59 samples of convertContacts and the sample size is roughly 1.17ms. The improvement is 140ms.

The overall running time is 4465ms/4172ms and the improvement is larger than 140ms, but the outlines/shapes of the stack-depths looked a little bit different. In the contacts case they looked quite similar; The patch just made the histogram more compact. Maybe we should first define a deterministic way to measure the start-up times.

Comment 15

[Blake Kaplan (:mrbkap) (inactive)]

Hi Ting-Yuan,

I don't have time to drive this patch into the tree myself. I requested feedback from you basically as a needinfo :)

The idea behind the patch is that in the current code, we're iterating, in chrome code, over an object that's already been cloned into content. Unfortunately, due to the way our wrappers work, each iteration is very expensive because we have to continually switch security contexts between chrome and content. I think this is what you found when you wrote your first patch.

Unfortunately, the way that we create the DOM object is important, so we can't avoid the round-trip in order to create that object. My patch fixes this by doing as much of the work as possible in C++ (which doesn't have the same performance bottlenecks). I don't know enough about this bug to know if the 613ms is enough, but I guess it's a start. I'm happy to answer any questions you have about this patch or anything else here.

Comment 16

[Ben Turner (not reading bugmail, use the needinfo flag!)]

Attachment: Better idea

How about this? This should remove all the X-Ray wrappers and cloning.

Comment 17

[Kan-Ru Chen [:kanru] (UTC+9)]

(In reply to ben turner [:bent] (use the needinfo? flag!) from comment #16)
> Created attachment 8549042 [details] [diff] [review]
> Better idea
> 
> How about this? This should remove all the X-Ray wrappers and cloning.

Before:
https://people.mozilla.org/~bgirard/cleopatra/#report=9895482ee79f718ff9d3b26fd0a1ed2a03abba89&selection=0,1,871,63,63,875,154,876
After:
https://people.mozilla.org/~bgirard/cleopatra/#report=6c324bafe551534036817cc3c0b0f965e6605366&selection=0,1,818,24,24,823,132,824


This patch reduced the total time of _convertContacts() from 1087ms to 348ms which is a 700ms+ win! However the total time seems only reduced 200ms+. Maybe the time is distributed to later property access through Xray?

Comment 18

[Ben Turner (not reading bugmail, use the needinfo flag!)]

The "after" profile there doesn't really show a whole lot of time spent in contacts now... It looks ore like we're triggering a bunch of layout flushes from some mutationHandler() function?

Comment 19

[Kan-Ru Chen [:kanru] (UTC+9)]

I profiled again.

Timing before patch

https://people.mozilla.org/~bgirard/cleopatra/#report=4b1a1c34d1bcd6081faa92e598654228fdc144c2&selection=0,1,829,48,48,832,141,833

I/Communications: Content JS LOG: Performance Entry: mark|navigationLoaded|532.1532129999999|0|1421730699919 
I/Communications: Content JS LOG: Performance Entry: mark|navigationInteractive|568.716619|0|1421730699955 
I/Communications: Content JS LOG: Performance Entry: mark|visuallyLoaded|737.555319|0|1421730700123 
I/Communications: Content JS LOG: Performance Entry: mark|contentInteractive|1221.3032210000001|0|1421730700607 
I/Communications: Content JS LOG: Performance Entry: mark|fullyLoaded|6787.150922999999|0|1421730706173 

After patch

https://people.mozilla.org/~bgirard/cleopatra/#report=fb16142e0a015e9fd3c5851eb16b4fbf2e67afc1&selection=0,1,847,55,55,851,143,852

I/Communications( 1074): Content JS LOG: Performance Entry: mark|navigationLoaded|542.2859759999999|0|1421731546806 
I/Communications( 1074): Content JS LOG: Performance Entry: mark|navigationInteractive|578.574699|0|1421731546842 
I/Communications( 1074): Content JS LOG: Performance Entry: mark|visuallyLoaded|737.4027159999999|0|1421731547000 
I/Communications( 1074): Content JS LOG: Performance Entry: mark|contentInteractive|1098.611324|0|1421731547362 
I/Communications( 1074): Content JS LOG: Performance Entry: mark|fullyLoaded|4661.193346|0|1421731550924 

The time to visuallyLoaded is about the same. The contentInteractive is 123ms faster. fullyLoaded is 2126ms faster.

However I noticed there is a JS error after patch.

W/Communications( 1174): renderPhoto@app://communications.gaiamobile.org/contacts/js/views/list.js:1040:5
W/Communications( 1174): onscreen@app://communications.gaiamobile.org/contacts/js/views/list.js:116:5
W/Communications( 1174): safeOnscreenCallback@app://communications.gaiamobile.org/shared/js/tag_visibility_monitor.js:527:7
W/Communications( 1174): notifyInRange@app://communications.gaiamobile.org/shared/js/tag_visibility_monitor.js:521:7
W/Communications( 1174): notifyOnscreenInRange@app://communications.gaiamobile.org/shared/js/tag_visibility_monitor.js:512:5
W/Communications( 1174): callCallbacks@app://communications.gaiamobile.org/shared/js/tag_visibility_monitor.js:428:7
W/Communications( 1174): updateVisibility@app://communications.gaiamobile.org/shared/js/tag_visibility_monitor.js:172:7
W/Communications( 1174): init@app://communications.gaiamobile.org/shared/js/tag_visibility_monitor.js:133:5
W/Communications( 1174): monitorTagVisibility@app://communications.gaiamobile.org/shared/js/tag_visibility_monitor.js:578:3
W/Communications( 1174): n
W/Communications( 1174): Content JS WARN: monitorTagVisiblity: Exception in onscreenCallback: Error: Permission denied to access property 'valueOf' setImageURL@app://communications.gaiamobile.org/contacts/js/views/list.js:1008:9

I think it's because the Contact returned from DOMRequest is type |any| so it's properly wrapped. The cross-compartment wrapper on Contact.photo[0] does not allow us to call methods from content.

Comment 20

[Kan-Ru Chen [:kanru] (UTC+9)]

10          mov     r7, ip
(gdb) b Proxy.cpp:47
Breakpoint 1 at 0xb5f2daf8: file ../../../gecko/js/src/proxy/Proxy.cpp, line 47.
(gdb) c
Continuing.
[New Thread 5715.5731]

Breakpoint 1, js::AutoEnterPolicy::reportErrorIfExceptionIsNotPending (this=this@entry=0xbeda7220, cx=cx@entry=0xb6a31b70, id=...) at ../../../gecko/js/src/proxy/Proxy.cpp:48
48                                     prop);
(gdb) bt
#0  js::AutoEnterPolicy::reportErrorIfExceptionIsNotPending (this=this@entry=0xbeda7220, cx=cx@entry=0xb6a31b70, id=...) at ../../../gecko/js/src/proxy/Proxy.cpp:48
#1  0xb5f2e514 in AutoEnterPolicy (act=1, id=..., wrapper=..., handler=0xb66124d0 <xpc::FilteringWrapper<js::SecurityWrapper<js::CrossCompartmentWrapper>, xpc::Opaque>::singleton>, cx=0xb6a31b70, 
    this=0xbeda7220, mayThrow=<optimized out>) at ../../../gecko/js/src/jsproxy.h:599
#2  js::Proxy::get (cx=0xb6a31b70, proxy=..., receiver=..., id=..., vp=...) at ../../../gecko/js/src/proxy/Proxy.cpp:288
#3  0xb5d7350e in JSObject::getGeneric (cx=<optimized out>, obj=..., receiver=..., id=..., vp=...) at ../../../gecko/js/src/vm/NativeObject.h:1358
#4  0xb5f8fbf0 in GetPropertyOperation (vp=..., lval=..., pc=<optimized out>, script=..., fp=<optimized out>, cx=<optimized out>) at ../../../gecko/js/src/vm/Interpreter.cpp:251
#5  Interpret (cx=0xb6a31b70, state=...) at ../../../gecko/js/src/vm/Interpreter.cpp:2372
#6  0xb5f9588c in js::RunScript (cx=cx@entry=0xb6a31b70, state=...) at ../../../gecko/js/src/vm/Interpreter.cpp:448
#7  0xb5f95ac2 in js::Invoke (cx=cx@entry=0xb6a31b70, args=..., construct=construct@entry=js::NO_CONSTRUCT) at ../../../gecko/js/src/vm/Interpreter.cpp:517
#8  0xb5f96118 in js::Invoke (cx=cx@entry=0xb6a31b70, thisv=..., fval=..., argc=argc@entry=1, argv=0xbeda7d38, rval=rval@entry=...) at ../../../gecko/js/src/vm/Interpreter.cpp:554
#9  0xb5e4cdba in js::jit::DoCallFallback (cx=0xb6a31b70, frame=0xbeda7d80, stub_=<optimized out>, argc=1, vp=0xbeda7d28, res=...) at ../../../gecko/js/src/jit/BaselineIC.cpp:9496
#10 0xb37b58a4 in ?? ()
#11 0xb37b58a4 in ?? ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
(gdb) p handler
$12 = (const xpc::FilteringWrapper<js::SecurityWrapper<js::CrossCompartmentWrapper>, xpc::Opaque> *) 0xb66124d0 <xpc::FilteringWrapper<js::SecurityWrapper<js::CrossCompartmentWrapper>, xpc::Opaque>::singleton>

Comment 21

[Kan-Ru Chen [:kanru] (UTC+9)]

Attachment: Better idea 2?

This patch works but I don't know why photo[] needs clone.

https://people.mozilla.org/~bgirard/cleopatra/#report=3e5dbdd9ce76e15bcb4a8d7dfa16cbc2abf6b37d&selection=0,1,792,33,33,795,121,796

I/Communications: Content JS LOG: Performance Entry: mark|navigationLoaded|575.5531820000001|0|1421744120297 
I/Communications: Content JS LOG: Performance Entry: mark|navigationInteractive|611.689304|0|1421744120332 
I/Communications: Content JS LOG: Performance Entry: mark|visuallyLoaded|788.280177|0|1421744120509 
I/Communications: Content JS LOG: Performance Entry: mark|contentInteractive|1053.502214|0|1421744120774 
I/Communications: Content JS LOG: Performance Entry: mark|fullyLoaded|4890.920189|0|1421744124612

Comment 22

[Ben Turner (not reading bugmail, use the needinfo flag!)]

Unfortunately I think we need to ask bholley here...

Comment 23

[Bobby Holley (:bholley)]

(In reply to ben turner [:bent] (use the needinfo? flag!) from comment #22)
> Unfortunately I think we need to ask bholley here...

We're going to look at this in-person when I'm in SF tomorrow.

Comment 24

[Ben Turner (not reading bugmail, use the needinfo flag!)]

Attachment: Better idea 3!

Hi Kan-Ru, your approach works too, but bholley and I think that this might be more correct. Basically the way you were doing this before uses an advanced function that shouldn't be necessary in this case (though it is still fine and supported). Please give this patch a try and see how it performs?

Comment 25

[Kan-Ru Chen [:kanru] (UTC+9)]

(In reply to ben turner [:bent] (use the needinfo? flag!) from comment #24)
> Created attachment 8552558 [details] [diff] [review]
> Better idea 3!
> 
> Hi Kan-Ru, your approach works too, but bholley and I think that this might
> be more correct. Basically the way you were doing this before uses an
> advanced function that shouldn't be necessary in this case (though it is
> still fine and supported). Please give this patch a try and see how it
> performs?

Yes, this should work. I was hoping the advanced function would save some createInstance time after reading https://developer.mozilla.org/en-US/docs/Mozilla/WebIDL_bindings#Using_the_WebIDL_constructor

So do you think only clone photo is fine?

Comment 26

[Ben Turner (not reading bugmail, use the needinfo flag!)]

Hm, have we seen createInstance showing up in profiles? But yeah, that's fine too. And I think the "photo" property is the only thing you have to worry about (we only need special cloning for DOM objects, not normal binding object types, dictionaries, or JS object types).

Comment 27

[Kan-Ru Chen [:kanru] (UTC+9)]

I see. Since Blob is already a DOM object so it wont be WebIDL wrapped again so we have to clone it. I'll try the patch today.

Comment 28

[Kan-Ru Chen [:kanru] (UTC+9)]

with new patch

https://people.mozilla.org/~bgirard/cleopatra/#report=3e5dbdd9ce76e15bcb4a8d7dfa16cbc2abf6b37d&selection=0,1,792,33,33,795,121,796

I/Communications( 1184): Content JS LOG: Performance Entry: mark|navigationLoaded|549.5803460000001|0|1421895623363 
I/Communications( 1184): Content JS LOG: Performance Entry: mark|navigationInteractive|586.4489550000001|0|1421895623399 
I/Communications( 1184): Content JS LOG: Performance Entry: mark|visuallyLoaded|744.1171989999999|0|1421895623557 
I/Communications( 1184): Content JS LOG: Performance Entry: mark|contentInteractive|1047.184496|0|1421895623860 
I/Communications( 1184): Content JS LOG: Performance Entry: mark|fullyLoaded|4617.305052|0|1421895627430 

Looks good.

Comment 29

[Kan-Ru Chen [:kanru] (UTC+9)]

Comment on attachment 8552558 [details] [diff] [review]
Better idea 3!

Review of attachment 8552558 [details] [diff] [review]:
-----------------------------------------------------------------

bholley could you r+ this patch?

Comment 30

[Bobby Holley (:bholley)]

Comment on attachment 8552558 [details] [diff] [review]
Better idea 3!

Review of attachment 8552558 [details] [diff] [review]:
-----------------------------------------------------------------

Looks good. Did you verify that the performance characteristics are the same as with the _create approach (i.e. the createInstance overhead is negligible)? I agree with your logic for that, but it depends whether it's a problem in practice.

Comment 31

[Kan-Ru Chen [:kanru] (UTC+9)]

(In reply to Bobby Holley (Busy with media, don't ask for DOM/JS/XPConnect things) from comment #30)
> Comment on attachment 8552558 [details] [diff] [review]
> Better idea 3!
> 
> Review of attachment 8552558 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Looks good. Did you verify that the performance characteristics are the same
> as with the _create approach (i.e. the createInstance overhead is
> negligible)? I agree with your logic for that, but it depends whether it's a
> problem in practice.

Yes, the overhead is totally negligible. Thanks for the review!

Comment 32

[Kan-Ru Chen [:kanru] (UTC+9)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/aa2ab2b3f01b

Comment 33

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/aa2ab2b3f01b

Comment 34

[Ryan VanderMeulen [:RyanVM]]

Please request b2g37 approval on this when you get a chance.

Comment 35

[bhavana bajaj [:bajaj]]

bent can you please fill in the approval request comment form to mainly know risk here ?

"[Approval Request Comment]
[Bug caused by] (feature/regressing bug #):
[User impact] if declined:
[Testing completed]:
[Risk to taking this patch] (and alternatives if risky):
[String changes made]:"

Comment 36

[Ben Turner (not reading bugmail, use the needinfo flag!)]

[Approval Request Comment]
[Bug caused by] (feature/regressing bug #): This has been around forever I think
[User impact] if declined: Slower contacts
[Testing completed]: There's a bunch of contacts tests running everywhere I think
[Risk to taking this patch] (and alternatives if risky): Anything that could be wrong here would be immediately obvious, so given green tests I don't think there's much risk here.
[String changes made]: None

Comment 37

[bhavana bajaj [:bajaj]]

CC'ing geo/edward chen to see if they are seeing any improvements in datazilla data around this.

Comment 38

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-b2g37_v2_2/rev/67c2d7718b47