vdirsyncer single file calendar sync's growth of running time is quadratic or higher (it takes "forever") #818
Comments
bernhardreiter
changed the title
|
Removing .vdirsyncer and doing a new discover and sync works, but the next sync hangs again. |
bernhardreiter
changed the title
|
Meanwhile I can reproduce this just with install vdirsyncer "The clean, easy way"set base /home/bernhardreiter/vtest
PIPX_HOME=$base PIPX_BIN_DIR=$base/bin pipx install vdirsyncer
# gets me package vdirsyncer 0.16.7, Python 3.7.3
pushd $basesetup singlefile -> singlefile one way configmkdir problem-1
echo '[general]
status_path = "$base/problem-1"
[pair my_calendar]
a = "my_calendar_a"
b = "my_calendar_b"
collections = null
conflict_resolution = "a wins"
[storage my_calendar_a]
type = "singlefile"
path = "$base/problem-1/my_calendar_a.ics"
[storage my_calendar_b]
type = "singlefile"
path = "$base/problem-1/my_calendar_b.ics"
' | sed -e "s|\$base|$base|" >problem-1/configtesting a calendarrm problem-1/my*
cp my_calendar_bad.ics problem-1/my_calendar_a.ics
touch problem-1/my_calendar_b.ics
./bin/vdirsyncer -v DEBUG -c problem-1/config discover
./bin/vdirsyncer -v DEBUG -c problem-1/config sync |
bernhardreiter
changed the title
bernhardreiter
changed the title
|
Doing more tests, even applying delta debugging I found that it is not a hang but a more then linearithmic grows of running time for the number of calendar items synced in a single file. A calendar with 1822 items needed 4:26 (4 hours and 26 minutes) to sync. That can easily be be mistaked for a "hang". :) Conclusion: something about the implemented algorithm is not good, as this is a high order of growth on the input files. DetailsAs it was a calendar with personal data, I cannot publish it. As I expected something in the contents itself, I've tried to reduce the problem case first. Below is the code that worked from a vdir directory of the original data #!/usr/bin/env python3
"""Test if vdirsyncer fails to sync on a list of iCalender files.
File names are hardcoded.
This can be used as script to test if a set is interesting when applying
deltadebugging. Used with https://github.com/dsw/delta
./delta-release-2020-06-22/delta -test=tryentries4.py -in_place entries
SPDX-License-Identifier: Apache-2.0
SPDX-FileCopyrightText: 2021 Intevation GmbH <https://intevation.de>
Author: <bernhard.reiter@intevation.de>
"""
import os
from pathlib import Path
import shutil
import subprocess
import sys
import time
import tempfile
entries = []
for line in open("entries", "rt"):
entries.append(line[:-1])
# print(len(entries))
# print(repr(entries[-1]))
def write_config(target_dir):
template = """
[general]
status_path = "{target_dir}/status/"
[pair my_calendar]
a = "my_calendar_a"
b = "my_calendar_local"
collections = null
conflict_resolution = "a wins"
[storage my_calendar_a]
type = "filesystem"
fileext = ""
read_only = true
path = "{target_dir}/vdir"
[storage my_calendar_local]
type = "singlefile"
path = "{target_dir}/my_calendar_b.ics"
"""
# print(template.format(target_dir=target_dir.resolve()))
(target_dir / "config").write_text(
template.format(target_dir=target_dir.resolve()))
# create an empty iCalender file
(target_dir / "my_calendar_b.ics").touch()
def runtest(original_dir, target_dir, entries):
org_path = original_dir / "vdir"
vdir_path = target_dir / "vdir"
vdir_path.mkdir(parents=True)
for entry in entries:
shutil.copy(org_path / entry, vdir_path)
write_config(target_dir)
cmd_basic =["/home/bern/vdirsyncer/venv/bin/vdirsyncer",
"-c", (target_dir / "config").resolve()]
p = subprocess.Popen(cmd_basic + ["discover"])
print(f"Running {p.args}")
p.wait(3)
p = subprocess.Popen(cmd_basic +["-v", "WARNING", "sync"])
print(f"Running {p.args}")
p.wait(8)
p = subprocess.Popen(cmd_basic +["sync"])
starttime = time.perf_counter()
print(f"Running {p.args}")
try:
p.wait(36000)
except subprocess.TimeoutExpired:
stoptime = time.perf_counter()
elapsed = int(stoptime - starttime)
print("Killing {!r} after {:d} seconds".format(p, elapsed))
p.kill()
return False
stoptime = time.perf_counter()
elapsed = int(stoptime - starttime)
print("Sync completed after {:d} seconds".format(elapsed))
return True
#result = runtest(Path("./fetch-private2"), Path("./testall"), entries)
with tempfile.TemporaryDirectory() as tempdir_name:
print("Testing in {}".format(tempdir_name))
result = runtest(Path("./fetch-private2"), Path(tempdir_name), entries)
if result: # we've failed to find an error, as "delta" expects it.
sys.exit(1)Here are some numbers to show the increase of runtime:
|
|
Can you check if |
|
Thanks for the hint. I will. |
|
Let me know how that goes, I have some theories on what’s going on.
|
Letting the big test (t1822m1.py) run for 10 minutes: not terminated. 10 minutes is too long for this simple sync (as there is no change in this test it only needs to compare 1822 iCal objects). So unfortunately: no, not solved by |
|
Can you share the test? I can try and profile it and see if that yields anything useful. There's clearly a bug here, but I've no idea where. |
Unfortunately not, as it is a personal calendar with private data. (This is why I've went with delta debugging first, my hypothesis then was that it would be related to the contents of some iCalender objects.) liberally licensed calender data setDo you know any liberarlly licenced larger iCalender data sets? I've tried to find some, but was not successful? Best candidates after search
|
|
I used Icalendar-generator to generate an icalender-file with 2000 items, and tested it with config: testing calendar: cp ~/icalendar-generator/calendar.ics ~/vtest/calendar-a/my_calendar_a.ics
touch ~/vtest/calendar-b/my_calendar_a.ics
vdirsyncer -v debug -c /vtest/config discover
vdirsyncer -v debug -c /vtest/config sync
|
|
Hi, I have the same problem, I'm syncing two calendars from my private Nextcloud instance. After removing all contents of the Stracing the process I can see that |
|
Attaching a debugger (something that will be much harder to do for users if you move to Rust, btw, because of compiler optimizations and potential lack of debug symbols :D ), I see that we never get out of this loop: vdirsyncer/vdirsyncer/sync/__init__.py Lines 62 to 67 in 3bf9a3d and in particular we spend a lot of time (many seconds) for each iteration of the inner loop at the bottom of this callstack: |
|
And here is a flamegraph that clearly shows where time is spent. If you download the SVG and open the downloaded file in a browser it's actually interactive.
|
|
I don't know vdirsyncer internals well enough to judge whether we could completely avoid the hashing, or at least provide a faster (compiled?) implementation. Since |
For the For However, if we're hashing any item one more than once per run, that's a bug a can be optimized away. That aside, cheaper hashing for this use-case might make sense. There's also a lot of string copying/concat going on in conversions. That can probably be improved, but I've no concretes ideas on how. |
|
Mmh ok I see three suspicious things happening that together might explain the sync taking forever. @WhyNotHugo please let me know what you think.
for href in uniq(hrefs): # there are 756 hrefs in my case
item, etag = await self.get(href)
yield href, item, etagThis in turn calls async for _ in self.list(): # also 756 elements!
pass
async def get(self, href):
if self._items is None or not self._at_once:
async for _ in self.list():
pass
try:
return self._items[href]I waited until the which it really shouldn't do because there is nothing to update: those events had just been copied from the calendar during the first |
Check closely: it only does the iteration if These lines: if self._items is None or not self._at_once:
async for _ in self.list():
passAre an ugly way of forcing the cache to get populated. |
|
it's really executed every time in my case, because EDIT: vdirsyncer/vdirsyncer/sync/__init__.py Lines 143 to 146 in 54a90aa A few lines later, when actions are run, vdirsyncer/vdirsyncer/sync/__init__.py Lines 155 to 158 in 54a90aa |
|
I think we can override the |
|
Basically, this bit should be wrapped in for href in uniq(hrefs): # there are 756 hrefs in my case
item, etag = await self.get(href)
yield href, item, etag |
|
Alright, I'll give it a go after I create another calendar for this purpose, because problem number 3. here makes me wary of running |
It would be useful to see both versions and see what changed. It might be that the server normalised into a semantically-equivalent format. Do any of your entries have more than one |
For single file storage we wrap the logic of get_multi with the at_once context manager so that `self.list()` (which is called by `self.get()`) actually caches the items rather than re-computing them at every call. This should largely mitigate the performance issue describe at pimutils#818 . The issue discussion also contains more background about this patch.
|
The patch proposed at #1051 seems to fix points 1. and 2. |
This seems to be triggered by events that I add to the calendar from my phone caldav client, not with events that I create directly from the Nextcloud web interface. Here is the diff before and after ~/Downloads diff -u 67cbcb15-d064-4f63-aa9b-38ccf7ef50c2.ics 67cbcb15-d064-4f63-aa9b-38ccf7ef50c2\(1\).ics
--- 67cbcb15-d064-4f63-aa9b-38ccf7ef50c2.ics 2023-03-09 18:35:23.560070893 -0600
+++ 67cbcb15-d064-4f63-aa9b-38ccf7ef50c2(1).ics 2023-03-09 18:36:15.013387075 -0600
@@ -1,19 +1,9 @@
BEGIN:VCALENDAR
VERSION:2.0
+PRODID:-//IDN nextcloud.com//Calendar app 3.4.2//EN
PRODID:DAVx5/4.3-ose ical4j/3.2.7 (ws.xsoh.etar)
-BEGIN:VEVENT
-DTSTAMP:20230310T003500Z
-UID:67cbcb15-d064-4f63-aa9b-38ccf7ef50c2
-SUMMARY:Test event 3
-DTSTART;TZID=America/Guatemala:20230311T000000
-DTEND;TZID=America/Guatemala:20230311T010000
-STATUS:CONFIRMED
-BEGIN:VALARM
-TRIGGER:-PT10M
-ACTION:DISPLAY
-DESCRIPTION:Test event 3
-END:VALARM
-END:VEVENT
+PRODID:-//Sabre//Sabre VObject 4.4.1//EN
+CALSCALE:GREGORIAN
BEGIN:VTIMEZONE
TZID:America/Guatemala
LAST-MODIFIED:20221105T024526Z
@@ -27,4 +17,17 @@
RDATE:20061001T000000
END:STANDARD
END:VTIMEZONE
+BEGIN:VEVENT
+DTSTAMP:20230310T003500Z
+UID:67cbcb15-d064-4f63-aa9b-38ccf7ef50c2
+SUMMARY:Test event 3
+DTSTART;TZID=America/Guatemala:20230311T000000
+DTEND;TZID=America/Guatemala:20230311T010000
+STATUS:CONFIRMED
+BEGIN:VALARM
+TRIGGER:-PT10M
+ACTION:DISPLAY
+DESCRIPTION:Test event 3
+END:VALARM
+END:VEVENT
END:VCALENDARMaybe interestingly |
|
So you created this on the phone, vdirsyncer downloaded it, and the next sync it was trying to create it? Looks like it's mostly shuffling the order of the items. This is due to how singlefile works. vtimezones are shared across ALL events in the file, so they're in another order, and when "splitting" to sync, they end up in another order. itś mostly harmless. I can only think of extremely complicated fixes right now. The PRODID duplication is a bug of the singlefile storage and needs to be fixed. |
yes, the next sync it updated it as above. for some reason, events created via the web interface are already like vdirsyncer wants them, so they are left alone. the problem with the mostly harmless update is that it takes forever if the calendar has hundreds or thousands of such events. |
|
Thanks for looking into the issue. I've skimmed your new messages. Just one remark, about my old findings:
(from #818 (comment)) At least I could prove by delta debugging that there haven't been a bad calender entry in my test data triggering a defect and all tests terminated (but some only after hours). HTH |
|
#1051 has been merged. Can you check how performance is when using current |
Testing Growth of running time seems to be more linear then before. Thanks again for maintaining vdirsyncer and for all that have helped to fix the issue. details of testingUsing an old version of https://cantonbecker.com/astronomy-calendar/ with 411 entries: grep SUMM astrocal-20210525.ics | wc -l
411/home/ber/.local/bin/vdirsyncer --version
vdirsyncer, version 0.19.1
time /home/ber/.local/bin/vdirsyncer -v DEBUG -c problem-1/config sync
real 0m21,845s
git clone https://github.com/pimutils/vdirsyncer.git vdirsyncer-git
cd vdirsyncer-git/
pip install -e .
/home/ber/.local/bin/vdirsyncer --version
vdirsyncer, version 0.19.2.dev6+g079a156
time /home/ber/.local/bin/vdirsyncer -v DEBUG -c problem-1/config sync
real 0m0,780sUsing https://gitlab.com/FadiAbb/icalendar-generator to generate from 2023-04-01 with number of entries, v0.19.1. and main branch timings: |
|
Thanks for confirming! |
Observed:
running
/usr/bin/vdirsyncer -v debug syncand the process hangs in one thread.Expected: Sync completes. It did before the move to Debian buster and switch of vdirsyncer version. Or a diagnostic message that help finding the problem, if there is one.
Further observations:
an strace shows
futex(0x7f387429e890, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANYand a py-bt with gdb showsThe text was updated successfully, but these errors were encountered: