Thinker Li [:sinker] Reporter
	Description • 10 years ago

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.

	Julien Wajsberg [:julienw]
	Comment 1 • 10 years ago

Should the component be Core::DOM:Contacts ?

	Ting-Yu Chou [:ting] (away)
	Comment 2 • 10 years ago

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

	Ting-Yuan Huang
	Comment 3 • 10 years ago

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.

	Ting-Yuan Huang
	Comment 4 • 10 years ago

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.

	Wesley Huang [:wesley_huang] (EPM) (NI me)
	Comment 5 • 10 years ago

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

	Thinker Li [:sinker] Reporter
	Comment 6 • 10 years ago

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

	Ting-Yuan Huang
	Comment 7 • 10 years ago

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?

	Julien Wajsberg [:julienw]
	Comment 8 • 10 years ago

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

	Ken Chang[:kenkai]
	Comment 9 • 10 years ago

Performance improvement is one of 2.2 features.

	Blake Kaplan (:mrbkap) (inactive)
	Comment 10 • 10 years ago

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.

	Blake Kaplan (:mrbkap) (inactive)
	Comment 11 • 10 years ago

Hopefully, this is useful.

	Ting-Yuan Huang
	Comment 12 • 10 years ago

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 :)

	Julien Wajsberg [:julienw]
	Comment 13 • 10 years ago

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

	Ting-Yuan Huang
	Comment 14 • 10 years ago

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.

	Blake Kaplan (:mrbkap) (inactive)
	Comment 15 • 10 years ago

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.

	Ben Turner (not reading bugmail, use the needinfo flag!) Assignee
	Comment 16 • 10 years ago

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

	Kan-Ru Chen [:kanru] (UTC+9)
	Comment 17 • 10 years ago

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

	Ben Turner (not reading bugmail, use the needinfo flag!) Assignee
	Comment 18 • 10 years ago

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?

	Kan-Ru Chen [:kanru] (UTC+9)
	Comment 19 • 10 years ago

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.

	Kan-Ru Chen [:kanru] (UTC+9)
	Comment 20 • 10 years ago

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>

	Kan-Ru Chen [:kanru] (UTC+9)
	Comment 21 • 10 years ago

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

	Ben Turner (not reading bugmail, use the needinfo flag!) Assignee
	Comment 22 • 10 years ago

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

	Bobby Holley (:bholley)
	Comment 23 • 10 years ago

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

	Ben Turner (not reading bugmail, use the needinfo flag!) Assignee
	Comment 24 • 10 years ago

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?

	Kan-Ru Chen [:kanru] (UTC+9)
	Comment 25 • 10 years ago

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

	Ben Turner (not reading bugmail, use the needinfo flag!) Assignee
	Comment 26 • 10 years ago

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

	Kan-Ru Chen [:kanru] (UTC+9)
	Comment 27 • 10 years ago

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.

	Kan-Ru Chen [:kanru] (UTC+9)
	Comment 28 • 10 years ago

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.

	Kan-Ru Chen [:kanru] (UTC+9)
	Comment 29 • 10 years ago

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

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

bholley could you r+ this patch?

	Bobby Holley (:bholley)
	Comment 30 • 10 years ago

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.

	Kan-Ru Chen [:kanru] (UTC+9)
	Comment 31 • 10 years ago

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

	Kan-Ru Chen [:kanru] (UTC+9)
	Comment 32 • 10 years ago

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

	Carsten Book [:Tomcat]
	Comment 33 • 10 years ago

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

	Ryan VanderMeulen [:RyanVM]
	Comment 34 • 10 years ago

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

	bhavana bajaj [:bajaj]
	Comment 35 • 10 years ago

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]:"

	Ben Turner (not reading bugmail, use the needinfo flag!) Assignee
	Comment 36 • 10 years ago

[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

	bhavana bajaj [:bajaj]
	Comment 37 • 10 years ago

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

	Ryan VanderMeulen [:RyanVM]
	Comment 38 • 10 years ago

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