11:13 a.m.
https://bugs.freedesktop.org/show_bug.cgi?id=60851
Priority: highest
Bug ID: 60851
CC: syncevolution-issues(a)syncevolution.org
Assignee: patrick.ohly(a)intel.com
Blocks: 55918
Summary: server must always be responsive, in particular after
SetActiveAddressBooks
Severity: major
Classification: Unclassified
OS: All
Reporter: patrick.ohly(a)gmx.de
Hardware: Other
Status: ASSIGNED
Version: unspecified
Component: SyncEvolution
Product: SyncEvolution
Need to write a test which regularly pings the server while reconfiguration of
the active address books is running. Also enhance performance of that.
The question related to this is whether SetActiveAddressBooks() should return
before the work is done (currently it does) and what the result of queries
should be while the reconfiguration runs (currently it may return data that
belongs to disabled address books - that data will be removed shortly, for some
definition of "short").
--
You are receiving this mail because:
You are on the CC list for the bug.
8:31 a.m.
New subject: [Bug 60851] server must always be responsive, in particular after SetActiveAddressBooks
https://bugs.freedesktop.org/show_bug.cgi?id=60851
--- Comment #1 from Patrick Ohly <patrick.ohly(a)gmx.de> ---
I've written a test and can reproduce the problem:
mkdir /tmp/testing
cd /tmp/testing
export XDG_CONFIG_HOME=/tmp/testing/temp-testpim/config
XDG_DATA_HOME=/tmp/testing/temp-testpim/local/cache
~pohly/src/syncevolution/test/dbus-session.sh bash
TEST_DBUS_QUIET=1 PATH=/home/pohly/work/syncevolution/src:$PATH
TESTPIM_TEST_ACTIVE_NUM=1000
~pohly/src/syncevolution/src/dbus/server/pim/testpim.py -v
TestContacts.testActive
======================================================================
FAIL: testActive (__main__.TestContacts)
TestContacts.testActive - reconfigure active address books several times
----------------------------------------------------------------------
Traceback (most recent call last):
File "/home/pohly/src/syncevolution/src/dbus/server/pim/testpim.py", line
1647, in testActive
w.checkpoint('full view')
File "/home/pohly/src/syncevolution/src/dbus/server/pim/testpim.py", line
248, in checkpoint
self.check()
File "/home/pohly/src/syncevolution/src/dbus/server/pim/testpim.py", line
239, in check
self.test.assertEqual([], tooslow)
File "/home/pohly/src/syncevolution/test/testdbus.py", line 1321, in
assertEqualCustom
unittest.TestCase.assertEqual(self, self.stripDBus(a, sortLists),
self.stripDBus(b, sortLists), msg)
AssertionError: Lists differ: [] != [(1360937032.086724, 78.482029...
Second list contains 1 additional elements.
First extra element 0:
(1360937032.086724, 78.48202991485596)
- []
+ [(1360937032.086724, 78.48202991485596)]
^^^^^^ ^^^^
start time duration of GetAllPeers call
What I see in the dbus.log of that test are many "new contact data" messages
from evolution-addressbook-factory to syncevo-dbus-server, followed by a
GetAllPeers message (the ping) and directly afterwards the reply:
signal sender=:1.1011 -> dest=(null destination) serial=1036
path=/test/dbus/py; interface=t.d.p; member=log2
string "87.300s: waiting for view with contacts"
method call sender=:1.1011 -> dest=:1.1013 serial=1037
path=/org/01/pim/contacts; interface=org._01.pim.contacts.Manager;
member=GetAllPeers
method return sender=:1.1013 -> dest=:1.1011 reply_serial=1037
array [
dict entry(
string "test-dbus-a"
array [
dict entry(
string "address"
string "xxx"
)
dict entry(
string "protocol"
string "PBAP"
)
]
)
dict entry(
string "test-dbus-b"
array [
dict entry(
string "address"
string "xxx"
)
dict entry(
string "protocol"
string "PBAP"
)
]
)
dict entry(
string "test-dbus-c"
array [
dict entry(
string "address"
string "xxx"
)
dict entry(
string "protocol"
string "PBAP"
)
]
)
]
signal sender=:1.1011 -> dest=(null destination) serial=1038
path=/test/dbus/py; interface=t.d.p; member=log2
string "165.982s: ping failure: duration 78.482030s, error None"
The dbus.log does not contain time stamps; checking with "dbus-monitor
--profile" while the test runs confirms that the reply is sent quite a bit
later (over a minute). Attaching with gdb shows that the process is busy inside
folks code during that time and only rarely serves new method calls in the main
event loop.
My theory is that when receiving many contacts from EDS, folks inside
syncevo-dbus-server can't keep up with evolution-addressbook-factory and lets
contact data pile up in its incoming D-Bus channel. The D-Bus method call then
gets tacked onto the end of that pile and only gets seen by syncevo-dbus-server
when all data is processed.
What makes the situation worse is that the test adds contacts one-by-one
quickly, so there is one notification message being sent by
evolution-addressbook-factory for every contact. This is not the normal startup
situation, although it might happen when importing straight from a phone during
syncing. When allowing folks to read after all test contacts are already in EDS
cuts down the duration of GetAllPeers from 78 to 2 seconds - but that's still
too much.
I am not sure yet what the right solution will be. Using direct reading inside
folks will change the timing aspect, but might still lead to a long period of
time where no other events are processed. Ultimately loading data and
processing changes must become a lower priority task inside syncevo-dbus-server
which must not interfere with other, more important work.
--
You are receiving this mail because:
You are on the CC list for the bug.
8:58 a.m.
New subject: [Bug 60851] server must always be responsive, in particular after SetActiveAddressBooks
https://bugs.freedesktop.org/show_bug.cgi?id=60851
--- Comment #2 from Patrick Ohly <patrick.ohly(a)gmx.de> ---
I also found that a ReadContacts() call with a large number of ids can lock up
the server for a while, because *that* call is implemented synchronously. I
looked briefly into what it would take to make it asynchronous, but stopped
after thinking about some of the consequence.
By design, the call has to return all results at once. That implies assembling
the response in memory and returning it when done. When interleaving other
event processing with that data gathering, the result might become inconsistent
(contact prepared, stored, then modified before sending result). Preventing
that is much harder than letting the application break up large ReadContacts()
calls into multiple smaller ones. This is what I am now doing in testpim.py.
--
You are receiving this mail because:
You are on the CC list for the bug.
4:17 a.m.
New subject: [Bug 60851] server must always be responsive, in particular after SetActiveAddressBooks
https://bugs.freedesktop.org/show_bug.cgi?id=60851
--- Comment #3 from Michael Hasselmann <michael(a)taschenorakel.de> ---
Isn't that something one could improve by adding Direct Read Access to
libfolks? I don't know of any method (in D-Bus) to prioritize messages that
are sent to the same bus.
Also, do I read correctly that SetActiveAddressBooks() should be turned into a
sync call and only return when reading of new address book data is complete?
--
You are receiving this mail because:
You are on the CC list for the bug.
5:07 a.m.
New subject: [Bug 60851] server must always be responsive, in particular after SetActiveAddressBooks
https://bugs.freedesktop.org/show_bug.cgi?id=60851
--- Comment #4 from Patrick Ohly <patrick.ohly(a)gmx.de> ---
(In reply to comment #3)
Isn't that something one could improve by adding Direct Read
Access to
libfolks?
No, I don't think so. The actual work would still need to be chopped up into
pieces which gets processed after dealing with the higher priority D-Bus
events.
I don't know of any method (in D-Bus) to prioritize messages
that
are sent to the same bus.
Right, which is why all messages must be taken out of the bus and queued for
later processing, if necessary. The obvious downside is that memory in the
recipient will baloon if it cannot keep up.
It may be easier to avoid that with DRA (because the producer of the data is
local and can be told to slow down), but that'll involve further API changes.
Also, do I read correctly that SetActiveAddressBooks() should be
turned into
a sync call and only return when reading of new address book data is
complete?
That was indeed tossed around as an idea, but it is hard to implement (folks
doesn't signal when the change is complete) and thus I'd prefer to keep the
call semantic as it is right now (doesn't wait).
Again, these are orthogonal problems. Even if the call was waiting, D-Bus event
processing must continue while it waits.
--
You are receiving this mail because:
You are on the CC list for the bug.
2:15 a.m.
New subject: [Bug 60851] server must always be responsive, in particular after SetActiveAddressBooks
https://bugs.freedesktop.org/show_bug.cgi?id=60851
--- Comment #5 from Patrick Ohly <patrick.ohly(a)gmx.de> ---
A bug step towards solving this problem was posted in folks for review. See
https://bugzilla.gnome.org/show_bug.cgi?id=694385 and patch
https://bugzilla.gnome.org/review?bug=694385&attachment=237091 in particular.
The TEST_DBUS_QUIET=1 TESTPIM_TEST_ACTIVE_NUM=1000 test now passes with D-Bus
messages replied to within 0.3 seconds or less - not perfect, but considerably
better than before.
--
You are receiving this mail because:
You are on the CC list for the bug.
8:45 a.m.
New subject: [Bug 60851] server must always be responsive, in particular after SetActiveAddressBooks
https://bugs.freedesktop.org/show_bug.cgi?id=60851
--- Comment #6 from Patrick Ohly <patrick.ohly(a)gmx.de> ---
Collabora enhanced performance in recent folks. While re-doing benchmarks I
noticed that the worst-case performance for 1000 contacts isn't as bad as I
remember it. However, I have not done an exact comparison.
The patch in https://bugzilla.gnome.org/show_bug.cgi?id=694385 is still
relevant, though. Here's a comparison with TEST_DBUS_QUIET=1
TESTPIM_TEST_ACTIVE_NUM=2000 TESTPIM_TEST_ACTIVE_RESPONSE=-1 and filling the
address books one-by-one while folks processes the changes.
I used an updated testpim.py which prints all samples instead of checking them.
TESTPIM_TEST_ACTIVE_RESPONSE=-1 enables that mode.
stats (https://github.com/rustyrussell/stats) is used to calculate
min-max(avg) for each phase. Full files will be attached.
Without patch:
$ stats folks-master-unpatched-2000.log
testActive (__main__.TestContacts)
TestContacts.testActive - reconfigure active address books several times ...
Pinging server at intervals of 0.200000s.
full view: ping duration: 0.012624-137.164563(45.7348+/-65)
contact data: ping duration: 0.005966-0.030444(0.0161076+/-0.0069)
['', 'a', 'b', 'c'] -> []: ping duration:
0.008605-0.763513(0.386059+/-0.38)
[] -> ['c']: ping duration: 0.008072-1.226016(0.149534+/-0.38)
['c'] -> ['b']: ping duration: 0.004165-0.836381(0.106718+/-0.26)
['b'] -> ['b', 'c']: ping duration:
0.005579-1.218825(0.145583+/-0.38)
['b', 'c'] -> ['a']: ping duration:
0.008640-1.261694(0.158903+/-0.36)
['a'] -> ['a', 'c']: ping duration:
0.005384-1.210349(0.143487+/-0.38)
['a', 'c'] -> ['a', 'b']: ping duration:
0.004604-0.328148(0.0475674+/-0.099)
['a', 'b'] -> ['a', 'b', 'c']: ping duration:
0.006383-1.224438(0.150367+/-0.38)
['a', 'b', 'c'] -> ['']: ping duration:
0.011664-1.227834(0.198583+/-0.38)
[''] -> ['', 'c']: ping duration:
0.005088-1.201952(0.143017+/-0.37)
['', 'c'] -> ['', 'b']: ping duration:
0.004293-0.313067(0.045124+/-0.095)
['', 'b'] -> ['', 'b', 'c']: ping duration:
0.011554-1.373705(0.27695+/-0.52)
['', 'b', 'c'] -> ['', 'a']: ping duration:
0.004793-1.213316(0.158278+/-0.35)
['', 'a'] -> ['', 'a', 'c']: ping duration:
0.005222-1.234311(0.149249+/-0.38)
['', 'a', 'c'] -> ['', 'a', 'b']: ping
duration:
0.004743-0.122250(0.0208045+/-0.034)
['', 'a', 'b'] -> ['', 'a', 'b',
'c']: ping duration:
0.005526-1.225899(0.146111+/-0.38)
ok
----------------------------------------------------------------------
Ran 1 test in 905.721s
OK
Note the 137s maximum response time during populating the data ("full view").
With patch:
$ stats folks-master-patched-2000.log
testActive (__main__.TestContacts)
TestContacts.testActive - reconfigure active address books several times ...
Pinging server at intervals of 0.200000s.
full view: ping duration: 0.004023-0.103919(0.0433612+/-0.025)
contact data: ping duration: 0.005415-0.037208(0.0193849+/-0.0088)
['', 'a', 'b', 'c'] -> []: ping duration:
0.011281-0.751190(0.381236+/-0.37)
[] -> ['c']: ping duration: 0.004249-0.028754(0.0124643+/-0.0061)
['c'] -> ['b']: ping duration: 0.003715-0.207745(0.0281574+/-0.046)
['b'] -> ['b', 'c']: ping duration:
0.006746-0.032266(0.0171924+/-0.0075)
['b', 'c'] -> ['a']: ping duration:
0.005372-0.378336(0.0332488+/-0.076)
['a'] -> ['a', 'c']: ping duration:
0.003991-0.034730(0.0185342+/-0.0083)
['a', 'c'] -> ['a', 'b']: ping duration:
0.004354-0.205181(0.0245261+/-0.04)
['a', 'b'] -> ['a', 'b', 'c']: ping duration:
0.004429-0.053523(0.0222038+/-0.013)
['a', 'b', 'c'] -> ['']: ping duration:
0.007220-0.567568(0.0461981+/-0.13)
[''] -> ['', 'c']: ping duration:
0.004500-0.031244(0.0149976+/-0.0077)
['', 'c'] -> ['', 'b']: ping duration:
0.005897-0.218556(0.0247215+/-0.043)
['', 'b'] -> ['', 'b', 'c']: ping duration:
0.004165-0.045688(0.0226147+/-0.011)
['', 'b', 'c'] -> ['', 'a']: ping duration:
0.004427-0.572938(0.0389641+/-0.1)
['', 'a'] -> ['', 'a', 'c']: ping duration:
0.004139-0.041826(0.021645+/-0.011)
['', 'a', 'c'] -> ['', 'a', 'b']: ping
duration:
0.007139-0.221841(0.0326704+/-0.039)
['', 'a', 'b'] -> ['', 'a', 'b',
'c']: ping duration:
0.004101-0.060816(0.0274812+/-0.017)
ok
----------------------------------------------------------------------
Ran 1 test in 946.532s
OK
The maximum response time during loading gets reduced to 0.1s.
On the downside, total runtime increases by 4%.
When running the test so that all data is already in EDS when folks starts,
then the "full view" max response time is 2.3s without patch and 0.2s with.
Total runtime goes up from 797s to 848s (6%) - this cannot be compared directly
with the other setup, because loading no longer overlaps with generating the
data.
--
You are receiving this mail because:
You are on the CC list for the bug.
8:47 a.m.
New subject: [Bug 60851] server must always be responsive, in particular after SetActiveAddressBooks
https://bugs.freedesktop.org/show_bug.cgi?id=60851
--- Comment #7 from Patrick Ohly <patrick.ohly(a)gmx.de> ---
Created attachment 77050
--> https://bugs.freedesktop.org/attachment.cgi?id=77050&action=edit
2000 contacts, folks 7f1fd0dd0, generating contacts one-by-one while folks runs
--
You are receiving this mail because:
You are on the CC list for the bug.
8:48 a.m.
New subject: [Bug 60851] server must always be responsive, in particular after SetActiveAddressBooks
https://bugs.freedesktop.org/show_bug.cgi?id=60851
--- Comment #8 from Patrick Ohly <patrick.ohly(a)gmx.de> ---
Created attachment 77051
--> https://bugs.freedesktop.org/attachment.cgi?id=77051&action=edit
2000 contacts, folks with patch, generating contacts one-by-one while folks
runs
--
You are receiving this mail because:
You are on the CC list for the bug.
8:48 a.m.
New subject: [Bug 60851] server must always be responsive, in particular after SetActiveAddressBooks
https://bugs.freedesktop.org/show_bug.cgi?id=60851
--- Comment #9 from Patrick Ohly <patrick.ohly(a)gmx.de> ---
Created attachment 77052
--> https://bugs.freedesktop.org/attachment.cgi?id=77052&action=edit
2000 contacts, folks 7f1fd0dd0, generating contacts before folks runs
--
You are receiving this mail because:
You are on the CC list for the bug.
8:49 a.m.
New subject: [Bug 60851] server must always be responsive, in particular after SetActiveAddressBooks
https://bugs.freedesktop.org/show_bug.cgi?id=60851
--- Comment #10 from Patrick Ohly <patrick.ohly(a)gmx.de> ---
Created attachment 77053
--> https://bugs.freedesktop.org/attachment.cgi?id=77053&action=edit
2000 contacts, folks with patch, generating contacts before folks runs
--
You are receiving this mail because:
You are on the CC list for the bug.
2:28 p.m.
New subject: [Bug 60851] server must always be responsive, in particular after SetActiveAddressBooks
https://bugs.freedesktop.org/show_bug.cgi?id=60851
--- Comment #11 from Patrick Ohly <patrick.ohly(a)gmx.de> ---
All relevant patches in folks were accepted, see
https://bugzilla.gnome.org/show_bug.cgi?id=694385
TODO:
- try out DRA in combination with testActive; blocked by not being able to call
e_book_client_open_direct_sync from Vala (not tracked upstream yet)
--
You are receiving this mail because:
You are on the CC list for the bug.
10:12 a.m.
New subject: [Bug 60851] server must always be responsive, in particular after SetActiveAddressBooks
https://bugs.freedesktop.org/show_bug.cgi?id=60851
Patrick Ohly <patrick.ohly(a)gmx.de> changed:
What |Removed |Added
----------------------------------------------------------------------------
Assignee|patrick.ohly(a)intel.com |syncevolution-issues@syncev
| |olution.org
Component|SyncEvolution |PIM Manager
--
You are receiving this mail because:
You are on the CC list for the bug.
You are the assignee for the bug.
7:42 a.m.
New subject: [Bug 60851] server must always be responsive, in particular after SetActiveAddressBooks
https://bugs.freedesktop.org/show_bug.cgi?id=60851
GitLab Migration User <gitlab-migration(a)fdo.invalid> changed:
What |Removed |Added
----------------------------------------------------------------------------
Status|ASSIGNED |RESOLVED
Resolution|--- |MOVED
--- Comment #12 from GitLab Migration User <gitlab-migration(a)fdo.invalid> ---
-- GitLab Migration Automatic Message --
This bug has been migrated to freedesktop.org's GitLab instance and has been
closed from further activity.
You can subscribe and participate further through the new bug through this link
to our GitLab instance:
https://gitlab.freedesktop.org/SyncEvolution/syncevolution/issues/89.
--
You are receiving this mail because:
You are the assignee for the bug.
You are on the CC list for the bug.
838
days inactive
2905
days old
syncevolution-issues@syncevolution.org
13 comments
1 participants
participants (1)
-
bugzilla-daemon＠freedesktop.org