https://bugs.freedesktop.org/show_bug.cgi?id=60851
--- Comment #1 from Patrick Ohly <[email protected]> --- 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.
_______________________________________________ Syncevolution-issues mailing list [email protected] http://lists.syncevolution.org/listinfo/syncevolution-issues
