Bug 64838

Created attachment 79641 [details]
5000 Contats log using synceval dbus APIs.

Created attachment 79642 [details]
5000 Contats log using synceval dbus APIs.

Created attachment 79643 [details]
5000 Contats testing vCards

Hi,

I made the following test over an empty DB:

time syncevolution --daemon=no  database=pim-manager-test backend=evolution-contacts --import ./5000vCard.txt
...
real	7m6.102s
user	0m55.495s
sys	0m7.416s

I noticed that during the import at regular time slots the printout stuck.
Since our HW does not allow fast r/w operations I'm just wondering if during the import/sync a r/w operation is performed for any contact.

(In reply to comment #4)
> I made the following test over an empty DB:
> 
> time syncevolution --daemon=no  database=pim-manager-test
> backend=evolution-contacts --import ./5000vCard.txt
> ...
> real	7m6.102s
> user	0m55.495s
> sys	0m7.416s
> 
> I noticed that during the import at regular time slots the printout stuck.
> Since our HW does not allow fast r/w operations I'm just wondering if during
> the import/sync a r/w operation is performed for any contact.

For every contact, there are potentially multiple writes. I'm less sure about sync() calls, those might get batched together.

Benchmarks done by Openismus showed submitting contacts in batches is orders of magnitude faster than writing one at a time. So addressing bug #52669 should help a lot, as writing seems to be the primary bottleneck for initial imports.

I also have a bug open upstream about sync() handling in EDS which needs more work - see https://bugzilla.gnome.org/show_bug.cgi?id=697278

Created attachment 80727 [details]
1000.vcf with the same PHOTO for each contact

I've added batch inserts (bug #52669) and removed one redundant EDS operation per insert. Importing became 4 times faster.

I also noticed and fixed that matching involved unnecessary DB writes:

commit c88ebbb9164281c012078761ec577607e7e75f30
Author: Patrick Ohly <patrick.ohly@intel.com>
Date:   Wed Jun 12 08:25:48 2013 +0200

    EDS contacts: avoid unnecessary DB writes during slow sync
    
    Traditionally, contacts were modified shortly before writing into EDS
    to match with Evolution expectations (must have N, only one CELL TEL,
    VOICE flag must be set). During a slow sync, the engine compare the
    modified contacts with the unmodified, incoming one. This led to
    mismatches and/or merge operations which end up not changing anything
    in the DB because the only difference would be removed again before
    writing.
    
    To avoid this, define datatypes which include the EDS modifications in
    its <incomingscript>. Then the engine works with an item as it would
    be written to EDS and correctly determines that the incoming and DB
    items are identical.
    
    Found in testpim.py's testSync when applied to the test cases
    generated by the Openismus test case generator.

Now performance is like this (still not involving PBAP!):

(In reply to comment #0)
> 1000:
> 
> import: 32.273505s
> match: 15.500893s
> remove: 23.965385s
> 
> 5000:
> 
> import: 173.671093s
> match: 135.620294s
> remove: 111.923021s
> 
> 10000:
> 
> import: 395.876979s
> match: 563.556571s
> remove: 227.145546s

1000:
import: 8.6s
match: 9.8s
remove: 19.0s

5000:
import: 56.5s
match: 96.7s
remove: 88.3s

10000:
import: 171s
match: 353s
remove: 179s

I also measured the PBAP transfer from a Samsung Galaxy SIII. obexd took 150s to download 9994 contacts. I had sent the 10000.vcf file via Bluetooth, but the phone dropped some contacts when importing.

Note that this is without photo data, because the Openismus test case generator has no option to generate photo data.

My personal address book has 845 contacts. 41 of those have a PHOTO, thanks to Google Contacts, which inserts photos of my contacts after getting them from somewhere. In terms of bytes, 35% of the vCard data is in PHOTO. On average, a photo is 4000 bytes large when uuencoded.

I ran tests earlier: excluding that photo data from the transfer had very little impact on PBAP transfer time. That's why bug #59551, the incremental PHOTO download, is not that important.

For the sake of worst case analysis, let's assume that every contact has a photo of roughly 4000 bytes. I've used my own photo, because that is what I can publish here, and inserted that photo into each of the 1000 contacts. See the attached 1000-with-photos.vcf.

Here some more PBAP transfer stats:
- 1000.vcf (240KB): 25s
- 1000-with-photos.vcf (3.65MB): 109s
- 1000-with-photos.vcf excluding the PHOTO data: 16s

It's unintuitive that the last duration is smaller than the first one. Perhaps there were some caching effects in the phone.

I consider this issue resolved and plan no further work.