Closed Bug 746439 Opened 12 years ago Closed 6 years ago

Contacts API: profile performance

Categories

(Core Graveyard :: DOM: Contacts, defect, P2)

Product:
Core Graveyard
Component:
DOM: Contacts
Type:
defect

Tracking

(blocking-kilimanjaro:+, blocking-basecamp:-)

Status:
RESOLVED WONTFIX
Project Flags:
blocking-kilimanjaro +
blocking-basecamp -

People

(Reporter: gwagner, Assigned: jrmuizel)

References

Details

(Whiteboard: [LOE:M])

Attachments

(1 file)

DB with 350 contacts
3.00 MB, application/octet-stream
Details 
We want to be able to retrieve contacts in chunks.
Blocks: b2g-contact
OS: Mac OS X → All
Hardware: x86 → All
Version: unspecified → Trunk
blocking-basecamp: --- → ?
We still have to figure out how much of an improvement we can get with such a patch. The problem is that in order to return a sorted list of contacts, we still have to retrieve all contacts from the DB and sort them.
The only performance improvement that this bug solves is the transfer of contacts from the parent to the child process. So we can transfer them in chunks instead of one list.
We might want to set it blocking-basecamp if we find out that the transfer is a bottleneck.
Alberto feel free to post some performance numbers if you already did some measurements.
Assignee: nobody → anygregor
After some tests:

It takes an average of 3500ms load the contacts app:

Avg of 1700ms for getting the contacts from the DB. Here the request:

var options = {
      sortBy: 'familyName',
      sortOrder: 'ascending'
    };
var request = navigator.mozContacts.find(options);

It takes a while also painting the results, but after some improvements, I think I can reduce the time to 500ms (Avg of 1500ms right now).

Not sure getting them in chuncks is going to help or not. Could you take a look where is the bottleneck in your side?

Thanks.
How many contacts are those figures?
Sorry, forgot that: 500 contacts imported with UI test app
Nice catch JM :)

Regards
Blocking. And re-summarized to be non-proscriptive.
blocking-basecamp: ? → +
blocking-kilimanjaro: --- → +
Summary: Contacts API: Add pagination → Contacts API: improve performance
Step 1 here should be that we should profile the API calls and start figuring out where time is spent. We should do that before starting to guess at what the solution is.
I looked at the API side on otoro:
It seems we spend most of the time transferring the contacts from the parent to the child process. I even see 1800msec for 500 contacts.
Sorting takes about 180 msec.
I forgot to mention the total time for 500 contacts on otoro:
Transfer from Parent to Child: 1923msec
Total round-trip time: 2758msec
Jonas also asked for the time the getAll call takes: ca 300msec.
That almost defies belief!  We could memcpy() 100MB in that time!

Where's the 2.7s going?
Also, how much data are we transferring.
The DB with some overhead is 3670016 bytes.
100mb for 500 contacts without photo? Is that correct?
(In reply to Alberto Pastor from comment #15)
> 100mb for 500 contacts without photo? Is that correct?

no. I hope not. otherwise bent has to fix it :)
Depends on: 754142
I did some more measurements on the otoro device with 350 contacts.

Timeline (in msec) starts when I send async find. Then I measure time to
1) receive message on parent side
2) before sorting (success callback of DB)
3) after sorting
4) receive in child
5) after success callback in JS


empty DB, first call (opening the DB)
1) 24
2) 653  
3) 653
4) 656
5) 657

empty DB, 2nd call after killing contacts app
1) 42
2) 427
3) 427
4) 434
5) 436

370 contacts, first call
1) 28 - 47
2) 1068
3) 1198
4) 1375
5) 2799

370 after killing contacts app
1) 21
2) 749
3) 882
4) 1071
5) 2505
Thanks!

So it seems like we have two bottlenecks here. One is loading the data from IndexedDB, the other is that sending data from the child to the API takes a *huge* amount of time.

What are we doing between 4 and 5? Are we just parsing the data from a string to an object graph using JSON.parse()? Or I guess we are having to create DOM objects for each contact and fill that with the appropriate data.
(In reply to Jonas Sicking (:sicking) from comment #18)
> 
> What are we doing between 4 and 5? Are we just parsing the data from a
> string to an object graph using JSON.parse()? Or I guess we are having to
> create DOM objects for each contact and fill that with the appropriate data.

That also includes the time we spend in the callback.
Ugh, ok, so then the last number does say that much regarding the performance of the API :(.

So it seems that we then have one unknown, which is how much time we spend in the API between 4 and 5, and then the IndexedDB performance.

So likely we should start profiling the IndexedDB implementation as well.
Jeff may be able to help here with his mad profiling skillz.
I'm profiling on a Mac now and so don't have working leaf symbols but this profile should give a bit of an idea of what's going on (at least for the last 3 seconds):

http://people.mozilla.com/~bgirard/cleopatra/?report=3d9474d4a82e5351b8879b01d7f06457c9ccce13
I will still try to get something more useful.
(In reply to Jeff Muizelaar [:jrmuizel] from comment #22)
> I'm profiling on a Mac now and so don't have working leaf symbols but this
> profile should give a bit of an idea of what's going on (at least for the
> last 3 seconds):
> 
> http://people.mozilla.com/~bgirard/cleopatra/
> ?report=3d9474d4a82e5351b8879b01d7f06457c9ccce13

Are you profiling a b2g desktop build or a FF desktop build?
Two things are important when we're measuring here:

1. That we measure on an actual B2G device. IO performance is very different there than on desktop, so it'll matter a lot more than on desktop.

2. That we profile a testcase which doesn't do anything in the success callback. The main question in this bug is if we need to completely rewrite the API because it requires too much IO before delivering any results. So the first question is if we can make the actual API fast enough for what we need. What the app does is a secondary concern and easier to fix.
(In reply to Jeff Muizelaar [:jrmuizel] from comment #22)
> I'm profiling on a Mac now and so don't have working leaf symbols but this
> profile should give a bit of an idea of what's going on (at least for the
> last 3 seconds):
> 
> http://people.mozilla.com/~bgirard/cleopatra/
> ?report=3d9474d4a82e5351b8879b01d7f06457c9ccce13

Sorry this wasn't clear: This is a profile of b2g on a Nexus S using a Mac instead of my usual desktop Linux machine.
(In reply to Jonas Sicking (:sicking) from comment #25)
> 2. That we profile a testcase which doesn't do anything in the success
> callback. The main question in this bug is if we need to completely rewrite
> the API because it requires too much IO before delivering any results. So
> the first question is if we can make the actual API fast enough for what we
> need. What the app does is a secondary concern and easier to fix.

It would be lovely if someone could write that test case.
Attached file DB with 350 contacts — 
Contacts DB with 350 entries.
Hi Jeff,

I created a testcase in gaia.
You can just download https://github.com/gregorwagner/gaia/tree/perfTest
I added a button to UI Tests->Contacts tests->Get all contacts.

You can download the DB with 350 contacts and push it to 
/data/local/indexedDB/chrome on your device
Here's a proper profile of Contacts startup on the b2g device:
http://people.mozilla.com/~bgirard/cleopatra/?report=bcab890025670003ebb41473801b1dffbccdbf78

I'll profile the testcase next.
Almost all the time is spent in "syscall". Any ideas what that is? Could that be the IO caused by IndexedDB? But if so I'm surprised that various sqlite signatures aren't showing up. Note that all IndexedDB IO happens on background threads in the parent process.
(In reply to Jonas Sicking (:sicking) from comment #32)
> Almost all the time is spent in "syscall". Any ideas what that is? Could
> that be the IO caused by IndexedDB? But if so I'm surprised that various
> sqlite signatures aren't showing up. Note that all IndexedDB IO happens on
> background threads in the parent process.

syscall is just us waiting for events. This is only profile of the main thread.
(In reply to Jeff Muizelaar [:jrmuizel] from comment #33)
> (In reply to Jonas Sicking (:sicking) from comment #32)
> > Almost all the time is spent in "syscall". Any ideas what that is? Could
> > that be the IO caused by IndexedDB? But if so I'm surprised that various
> > sqlite signatures aren't showing up. Note that all IndexedDB IO happens on
> > background threads in the parent process.
> 
> syscall is just us waiting for events. This is only profile of the main
> thread.

In this case that was probably the time before I clicked the button. This profile has that cleaned up and is perhaps more clear:
http://people.mozilla.com/~bgirard/cleopatra/?report=a54ae8205a8da05e0ff2b6dd9ed3cd3865de1fce

Here's a bit of interpretation:
At the beginning it looks like there's some runnable that's calling JSStructuredCloneReader::read() among other things.
- 182ms in <Anonymous> - ContactDB.jsm:379 which calls makeExport()
- 316ms in ContactService.jsm:117
 -  150ms in sortfunction()
- something that calls JSONParser:parse()
- 297ms in ContactManager.js:345
- 1374ms in BrowserElementPromptService.jsm:30 which is showing the prompt for me.
Whats the status here?
Priority: -- → P2
Renom if you think we can't ship a v1 without this.
blocking-basecamp: + → ---
Per IRC conversations with a few other folks, I think the best course of action if there is disagreement on whether this blocks or not is to do the following:

- Move the blocking-basecamp flag to ? for re-evaluation
- Indicate a rationale for why you disagree
blocking-basecamp: --- → ?
We can't block on this until we get some actionable data ... but we'd really like to fix this!  If we get some data, let's re-nom.
blocking-basecamp: ? → -
Depends on: 783645
Requesting 500 contacts with a real OOP contacts app takes not 8-10 sec. This doesn't include the frontend rendering. I created a button in the gaia contacts tests that requests all contacts without the rendering part: https://github.com/gregorwagner/gaia/tree/perfTest

There are several moving parts here:

Bug 783057 increased the loading time for 500 contacts from around 2 sec to 4 sec for in-process. I will fix this in Bug 783645.

Changing the nice value (http://mxr.mozilla.org/mozilla-central/source/b2g/app/b2g.js#509) to 0 decreases the loading time from 10 sec to around 8 sec.

We would need a profile for the real OOP situation. 
Jeff, do you think you could help here?
The time until we see the 500 contacts with an OOP contacts app is around 16 sec.
9 sec until we get the contacts and 7 sec for the success CB.
blocking-basecamp: - → ?
Gregor, can you post a dump of a single contact now, with all the data and search strings, etc.? Just curious how big each contact is now.
blocking-basecamp: ? → +
Jeff, would you be able to bring this bug forward to the point of having actionable profile data?
Assignee: anygregor → jmuizelaar
Whiteboard: [LOE:M]
Morphing this bug to just cover profiling what's going on here since all the discussion and the assignment and time estimate is just for the profiling part.
Summary: Contacts API: improve performance → Contacts API: profile performance
(In reply to ben turner [:bent] from comment #41)
> Gregor, can you post a dump of a single contact now, with all the data and
> search strings, etc.? Just curious how big each contact is now.

Basically it's just the contacts data + searchable fields that are stored lowercase + tel lookup fields:

For example:
contact: {
  "properties": {
    "name":["Testname1"],
    "honorificPrefix":null,
    "givenName":["Test1","Test2"],
    "additionalName":null,
    "familyName":["TestFamilyName","Wagner"],
    "honorificSuffix":null,
    "nickname":["nicktest"],
    "email":[{"type":["work"],"value":"x@y.com"}],
    "photo":null,
    "url":null,
    "category":null,
    "adr":[{
      "type":"work",
      "streetAddress":"street 1",
      "locality":"locality 1",
      "region":"region 1",
      "postalCode":"postal code 1",
      "countryName":"country 1"
    }],
    "tel":[ {
      "type":["work"],"value":"123456","carrier":"testCarrier"},{"type":["home","fax"],"value":"+9-876-5432","carrier":null
    }],
    "org":null,
    "jobTitle":null,
    "bday":null,
    "note":null,
    "impp":null,
    "anniversary":null
  },
  "search": {
    "name":["testname1"],
    "honorificPrefix":[],
    "givenName":["test1","test2"],
    "additionalName":[],
    "familyName":["testfamilyname","wagner"],
    "honorificSuffix":[],"nickname":["nicktest"],
    "email":["x@y.com"],
    "category":[],
    "tel":["123456","23456","3456","456","56","6","+9-876-5432","9-876-5432","-876-5432","876-5432","76-5432","6-5432","-5432","5432","432","32","2","98765432","8765432","765432","65432","5432","432","32","2"],
    "org":[],
    "jobTitle":[],
    "note":[],
    "impp":[]
  }
}
I'm a bit confused about what else needs profiling here. The latest profiles I linked to are of the perf test. I believe those profiles are of the b2g process, do you also want a profile of plugin-container?
(In reply to Jeff Muizelaar [:jrmuizel] from comment #45)
> I'm a bit confused about what else needs profiling here. The latest profiles
> I linked to are of the perf test. I believe those profiles are of the b2g
> process, do you also want a profile of plugin-container?

AFAIK, the contacts app is now running OOP.  We've also apparently gotten about 10x worse in terms of performance as a result of the OOP move :/
And the regression is 2-5x.
(In reply to Jeff Muizelaar [:jrmuizel] from comment #45)
> I'm a bit confused about what else needs profiling here. The latest profiles
> I linked to are of the perf test. I believe those profiles are of the b2g
> process, do you also want a profile of plugin-container?

Well, Gregor posted a link to a new test that will avoid the rendering overhead, so I think we need new profiles. One of each process would be awesome.

Gregor, also, cjones noticed that we have a bunch of |debug(JSON.stringify(contact))| stuff. Even if debug() is disabled (e.g. defined to { }) then we'll still be creating these strings in release builds. We should remove this somehow (preprocessor?).
(In reply to ben turner [:bent] from comment #49)
> Gregor, also, cjones noticed that we have a bunch of
> |debug(JSON.stringify(contact))| stuff. Even if debug() is disabled (e.g.
> defined to { }) then we'll still be creating these strings in release
> builds. We should remove this somehow (preprocessor?).

+1 to that. Or do what we do in the RIL:

  if (DEBUG) debug(...);

Not pretty but effective.
(In reply to Philipp von Weitershausen [:philikon] from comment #50)
> (In reply to ben turner [:bent] from comment #49)
> > Gregor, also, cjones noticed that we have a bunch of
> > |debug(JSON.stringify(contact))| stuff. Even if debug() is disabled (e.g.
> > defined to { }) then we'll still be creating these strings in release
> > builds. We should remove this somehow (preprocessor?).
> 
> +1 to that. Or do what we do in the RIL:
> 
>   if (DEBUG) debug(...);
> 
> Not pretty but effective.

I will change this real quick in bug 784746.
Depends on: 784746
With the patches from bug 784746 and bug 784099 I see now a reduction from 9 sec to 1.5 - 2 sec (500 contacts, OOP with UI tests-> contacts tests -> get all contacts).
We should re-evaluate with the new performance numbers.
blocking-basecamp: + → ?
The one remaining bit of data I want to see is in-process vs. OOP numbers with debugging removed.
(In reply to Chris Jones [:cjones] [:warhammer] from comment #54)
> The one remaining bit of data I want to see is in-process vs. OOP numbers
> with debugging removed.

In process has the same performance as OOP. For 500 contacts around 1.5 sec. (It's hard to say exactly because I usually get +- 200 msec)
(In reply to Gregor Wagner [:gwagner] from comment #55)
> In process has the same performance as OOP. For 500 contacts around 1.5 sec.
> (It's hard to say exactly because I usually get +- 200 msec)

/me dances a little!
blocking-basecamp: ? → -
Component: DOM: Device Interfaces → DOM: Contacts
DOM: Contacts isn't used anymore. 
Closing all remaining bugs.
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → WONTFIX
Product: Core → Core Graveyard
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: