GNOME Bugzilla – Bug 643498
e-calendar-factory causes 100 % CPU load
Last modified: 2018-09-07 10:09:15 UTC
Dear Evolution developers, upgrading from 2.30.5 to 2.32.2 switching to the calendar and navigating to another day stalls for over a minute or sometimes indefinitely. 3641 joe 20 0 300m 261m 7748 R 98 6.8 8:51.78 e-calendar-fact May calendar directories take up 37 MB as a hole. $ du -sh ~/.local/share/evolution/calendar/ 37M /home/paul/.local/share/evolution/calendar/ Please advise me on how to debug this. Thanks, Paul
The following error messages are printed to the terminal I executed `evolution` from. (evolution:3989): libecal-WARNING **: Cannot start cal view: Zeitüberschreitung wurde erreicht (evolution:3989): calendar-gui-WARNING **: gnome-cal.c:826: Query did not successfully complete, code: 17 (Zeitüberschreitung wurde erreicht) (evolution:3989): calendar-gui-WARNING **: gnome-cal.c:1111: Could not create the query: Zeitüberschreitung wurde erreicht (evolution:3989): libecal-WARNING **: Cannot start cal view: Zeitüberschreitung wurde erreicht (evolution:3989): calendar-gui-WARNING **: e-cal-model.c:2085: Unable to get query, Zeitüberschreitung wurde erreicht (evolution:3989): calendar-gui-WARNING **: e-cal-model.c:2085: Unable to get query, Zeitüberschreitung wurde erreicht (evolution:3989): libecal-WARNING **: Cannot start cal view: Zeitüberschreitung wurde erreicht (evolution:3989): libecal-WARNING **: Cannot start cal view: Zeitüberschreitung wurde erreicht (evolution:3989): calendar-gui-WARNING **: gnome-cal.c:826: Query did not successfully complete, code: 17 (Zeitüberschreitung wurde erreicht) (evolution:3989): calendar-gui-WARNING **: e-cal-model.c:2085: Unable to get query, Zeitüberschreitung wurde erreicht (evolution:3989): calendar-gui-WARNING **: gnome-cal.c:1111: Could not create the query: Zeitüberschreitung wurde erreicht (evolution:3989): calendar-gui-WARNING **: e-cal-model.c:2085: Unable to get query, Zeitüberschreitung wurde erreicht (evolution:3989): calendar-gui-WARNING **: gnome-cal.c:1111: Could not create the query: Zeitüberschreitung wurde erreicht (evolution:3989): calendar-gui-WARNING **: gnome-cal.c:1111: Could not create the query: Zeitüberschreitung wurde erreicht (evolution:3989): calendar-gui-WARNING **: e-cal-model.c:2085: Unable to get query, Zeitüberschreitung wurde erreicht evolution-mail-Message: Error occurred while existing dialogue active: Die Verbindung wurde vom Kommunikationspartner zurückgesetzt evolution-mail-Message: Error occurred while existing dialogue active: Server-Verbindung unerwartet getrennt:Die Verbindung wurde vom Kommunikationspartner zurückgesetzt
I switched to the calendar and started OProfile afterward. $ sudo opcontrol --no-vmlinux $ sudo opcontrol --reset Signalling daemon... done $ sudo opcontrol --start Profiler running. $ sudo opcontrol --stop Stopping profiling. $ sudo opcontrol --dump $ opreport CPU: AMD64 processors, speed 2100 MHz (estimated) Counted CPU_CLK_UNHALTED events (Cycles outside of halt state) with a unit mask of 0x00 (No unit mask) count 100000 CPU_CLK_UNHALT...| samples| %| ------------------ 1728344 81.8994 libglib-2.0.so.0.2800.1 162458 7.6982 no-vmlinux 47994 2.2742 oprofiled CPU_CLK_UNHALT...| samples| %| ------------------ […] I do not know OProfile, so please tell me what options I can use to make this useful for you.
Are there any tests to check if my local calendars are sane/formatted correctly? They should be as I have only used Evolution to create/edit them.
$ opreport -c CPU: AMD64 processors, speed 2100 MHz (estimated) Counted CPU_CLK_UNHALTED events (Cycles outside of halt state) with a unit mask of 0x00 (No unit mask) count 100000 samples % image name app name symbol name ------------------------------------------------------------------------------- 1674598 86.0383 libglib-2.0.so.0.2800.1 libglib-2.0.so.0.2800.1 g_list_last 1674598 100.000 libglib-2.0.so.0.2800.1 libglib-2.0.so.0.2800.1 g_list_last [self] ------------------------------------------------------------------------------- 47955 2.4639 oprofiled oprofiled /usr/bin/oprofiled 47955 100.000 oprofiled oprofiled /usr/bin/oprofiled [self] ------------------------------------------------------------------------------- 19352 0.9943 libpixman-1.so.0.21.4 libpixman-1.so.0.21.4 /usr/lib/libpixman-1.so.0.21.4 19352 100.000 libpixman-1.so.0.21.4 libpixman-1.so.0.21.4 /usr/lib/libpixman-1.so.0.21.4 [self] ------------------------------------------------------------------------------- 8897 0.4571 libdbus-1.so.3.5.4 libdbus-1.so.3.5.4 /lib/libdbus-1.so.3.5.4 8897 100.000 libdbus-1.so.3.5.4 libdbus-1.so.3.5.4 /lib/libdbus-1.so.3.5.4 [self] ------------------------------------------------------------------------------- 8850 0.4547 libpthread-2.11.2.so libpthread-2.11.2.so pthread_mutex_lock 8850 100.000 libpthread-2.11.2.so libpthread-2.11.2.so pthread_mutex_lock [self] ------------------------------------------------------------------------------- 7636 0.3923 dbus-daemon dbus-daemon /usr/bin/dbus-daemon 7636 100.000 dbus-daemon dbus-daemon /usr/bin/dbus-daemon [self] ------------------------------------------------------------------------------- 5883 0.3023 libglib-2.0.so.0.2800.1 libglib-2.0.so.0.2800.1 g_main_context_check 5883 100.000 libglib-2.0.so.0.2800.1 libglib-2.0.so.0.2800.1 g_main_context_check [self] ------------------------------------------------------------------------------- 5354 0.2751 libglib-2.0.so.0.2800.1 libglib-2.0.so.0.2800.1 g_main_context_prepare 5354 100.000 libglib-2.0.so.0.2800.1 libglib-2.0.so.0.2800.1 g_main_context_prepare [self] ------------------------------------------------------------------------------- 4528 0.2326 libpthread-2.11.2.so libpthread-2.11.2.so __pthread_mutex_unlock_usercnt 4528 100.000 libpthread-2.11.2.so libpthread-2.11.2.so __pthread_mutex_unlock_usercnt [self] ------------------------------------------------------------------------------- 4236 0.2176 Xorg Xorg /usr/bin/Xorg 4236 100.000 Xorg Xorg /usr/bin/Xorg [self] ------------------------------------------------------------------------------- 4059 0.2085 libc-2.11.2.so libc-2.11.2.so _int_malloc 4059 100.000 libc-2.11.2.so libc-2.11.2.so _int_malloc [self] ------------------------------------------------------------------------------- 3506 0.1801 perl perl /usr/bin/perl 3506 100.000 perl perl /usr/bin/perl [self] ------------------------------------------------------------------------------- 3163 0.1625 libc-2.11.2.so libc-2.11.2.so memcpy 3163 100.000 libc-2.11.2.so libc-2.11.2.so memcpy [self] ------------------------------------------------------------------------------- 2911 0.1496 libcairo.so.2.11000.2 libcairo.so.2.11000.2 /usr/lib/libcairo.so.2.11000.2 2911 100.000 libcairo.so.2.11000.2 libcairo.so.2.11000.2 /usr/lib/libcairo.so.2.11000.2 [self] ------------------------------------------------------------------------------- 2868 0.1474 libc-2.11.2.so libc-2.11.2.so _IO_vfscanf 2868 100.000 libc-2.11.2.so libc-2.11.2.so _IO_vfscanf [self] ------------------------------------------------------------------------------- 2701 0.1388 libglib-2.0.so.0.2800.1 libglib-2.0.so.0.2800.1 g_variant_type_string_scan 2701 100.000 libglib-2.0.so.0.2800.1 libglib-2.0.so.0.2800.1 g_variant_type_string_scan [self] ------------------------------------------------------------------------------- 2685 0.1380 libpthread-2.11.2.so libpthread-2.11.2.so pthread_mutex_unlock 2685 100.000 libpthread-2.11.2.so libpthread-2.11.2.so pthread_mutex_unlock [self] ------------------------------------------------------------------------------- 2315 0.1189 libpthread-2.11.2.so libpthread-2.11.2.so __i686.get_pc_thunk.bx 2315 100.000 libpthread-2.11.2.so libpthread-2.11.2.so __i686.get_pc_thunk.bx [self] ------------------------------------------------------------------------------- 2262 0.1162 libglib-2.0.so.0.2800.1 libglib-2.0.so.0.2800.1 __i686.get_pc_thunk.bx 2262 100.000 libglib-2.0.so.0.2800.1 libglib-2.0.so.0.2800.1 __i686.get_pc_thunk.bx [self] […]
Thanks for a bug report. Could you install debug-info packages for evolution-data-server and evolution and get backtrace of running e-calendar-factory, when it gets to the busy state, please? That may shed a bit of light what it is actually doing. Thanks in advance. To get a backtrace just get a process ID (PID) of the running e-calendar-factory and then invoke this on a console: $ gdb --batch --ex "t a a bt" -pid=PID &>bt.txt and attach the bt.txt here. (make sure it doesn't contain any private information, like server names, email addresses or passwords).
Created attachment 182462 [details] backtrace when e-calendar-factory is in busy state As asked 643498:5 here is the backtrace created by `gdb -batch -ex "t a a bt" -pid=3463 &> /tmp/bt`. I executes this command every three seconds and the backtraces look exactly the same besides some changes in the `list` and `callback` values, e. g. `#0 0xf7424a35 in g_list_last (list=0xed3b1030)`.
Thanks for the update. So it's checking for events from your local calendar. Is the calendar so large? I do not see from the backtrace whether it's a calendar or tasks/memos list.
(In reply to comment #7) > Thanks for the update. So it's checking for events from your local calendar. Is > the calendar so large? $ du -sh .local/share/evolution/calendar/ 37M .local/share/evolution/calendar/ > I do not see from the backtrace whether it's a calendar or tasks/memos list. It is a calendar.
Oh, I see you wrote it in the comment #0 too, I'm sorry for asking the same. Well, processing 37MB of data, not talking how many events it can produce (with instances of recurring events), then it makes sense it takes some time to do it. The UI, when it finished the query, may show you how many events it found at the left-top corner, though it doesn't tell how many events it processed in total to filter out only those visible.
(In reply to comment #9) > Well, processing 37MB of data, not talking how many events it can produce (with > instances of recurring events), then it makes sense it takes some time to do > it. The UI, when it finished the query, may show you how many events it found > at the left-top corner, though it doesn't tell how many events it processed in > total to filter out only those visible. Well using 2.30.3 I did not notice any problems and it took maybe some seconds. Now it takes over a minute and that every time dealing with the calendar.
Additionally the entries are still not shown and I still get the following on the console. (evolution:4090): libecal-WARNING **: Cannot start cal view: Zeitüberschreitung wurde erreicht (evolution:4090): calendar-gui-WARNING **: e-cal-model.c:2085: Unable to get query, Zeitüberschreitung wurde erreicht (evolution:4090): libecal-WARNING **: gdbus_cal_disconnect: Failed to close calendar, Zeitüberschreitung wurde erreicht (evolution:4090): calendar-gui-WARNING **: e-cal-model.c:2085: Unable to get query, Zeitüberschreitung wurde erreicht (evolution:4090): libecal-WARNING **: Cannot start cal view: Zeitüberschreitung wurde erreicht (evolution:4090): calendar-gui-WARNING **: gnome-cal.c:826: Query did not successfully complete, code: 17 (Zeitüberschreitung wurde erreicht) (evolution:4090): libecal-WARNING **: Cannot start cal view: Zeitüberschreitung wurde erreicht (evolution:4090): calendar-gui-WARNING **: gnome-cal.c:1111: Could not create the query: Zeitüberschreitung wurde erreicht evolution-mail-Message: Error occurred while existing dialogue active: Die Verbindung wurde vom Kommunikationspartner zurückgesetzt (evolution:4090): calendar-gui-WARNING **: gnome-cal.c:1111: Could not create the query: Zeitüberschreitung wurde erreicht (evolution:4090): libecal-WARNING **: Cannot start cal view: Zeitüberschreitung wurde erreicht (evolution:4090): calendar-gui-WARNING **: gnome-cal.c:826: Query did not successfully complete, code: 17 (Zeitüberschreitung wurde erreicht) I can see existing entries in the month overview since the number is bold. But selecting that day it again takes a while and entries of that day are not shown and the pasted messages above are printed to the console.
Sorry to adding another seperate comment. How can I check if caching is working?
> Well using 2.30.3 I did not notice any problems and it took maybe some > seconds. Now it takes over a minute and that every time dealing with > the calendar. I see, the EIntervalTree (the new thing in 2.32.0) is meant to help, to "index" events based on the time of its occurrence, but it doesn't seem to do the right thing for you. > (evolution:4090): libecal-WARNING **: Cannot start cal view: > Zeitüberschreitung wurde erreicht Could you translate the above, please? (In reply to comment #12) > Sorry to adding another seperate comment. How can I check if caching is > working? There is no file caching for local calendars, it's a plain text file, which is read on start and everything is kept in memory. The interval tree may not work the best for recurring events set to recur for ever, as they have no time frame, so they should be shown/considered in all times. Is your local calendar having recurring events with for-ever type?
(In reply to comment #13) > > Well using 2.30.3 I did not notice any problems and it took maybe some > > seconds. Now it takes over a minute and that every time dealing with > > the calendar. > > I see, the EIntervalTree (the new thing in 2.32.0) is meant to help, to "index" > events based on the time of its occurrence, but it doesn't seem to do the right > thing for you. > > > (evolution:4090): libecal-WARNING **: Cannot start cal view: > > Zeitüberschreitung wurde erreicht > > Could you translate the above, please? I would translate it as »Timed out« or timeout was reached. > (In reply to comment #12) > > Sorry to adding another seperate comment. How can I check if caching is > > working? > > There is no file caching for local calendars, it's a plain text file, which is > read on start and everything is kept in memory. The interval tree may not work > the best for recurring events set to recur for ever, as they have no time > frame, so they should be shown/considered in all times. Is your local calendar > having recurring events with for-ever type? I think it has one or two such events. How can I check for sure?
(In reply to comment #14) > > > (evolution:4090): libecal-WARNING **: Cannot start cal view: > > > Zeitüberschreitung wurde erreicht > > > > Could you translate the above, please? > > I would translate it as »Timed out« or timeout was reached. Ah, thanks, it makes sense, the e-calendar-factory didn't send a reply to evolution over DBus in time, so it throws this error. It means, like when getting this on a query for certain time period, that it behaves like nothing was returned - just the results you are facing. > > Is your local calendar having recurring events with for-ever type? > > I think it has one or two such events. How can I check for sure? Because your UI is tricking you, open the raw ~/.local/share/evolution/calendar/system/calendar.ics file (it's for the On This Computer/Personal calendar, if you've more local calendars, then it can be in a different folder than "system") and search for RRULE lines. It's doable with this command too: $ cat ~/.local/share/evolution/calendar/system/calendar.ics | grep RRULE It'll give us an overview how many recurring events you have and what recurrence type they have set. (Mine has only 9 - added "| wc -l" at the end of the command.)
(In reply to comment #15) > (In reply to comment #14) […] > > > Is your local calendar having recurring events with for-ever type? > > > > I think it has one or two such events. How can I check for sure? > > Because your UI is tricking you, open the raw > ~/.local/share/evolution/calendar/system/calendar.ics > file (it's for the On This Computer/Personal calendar, if you've more local > calendars, then it can be in a different folder than "system") and search for > RRULE lines. It's doable with this command too: > $ cat ~/.local/share/evolution/calendar/system/calendar.ics | grep RRULE No need to use pipe with `grep`. grep RRULE ~/.local/share/evolution/calendar/system/calendar.ics > It'll give us an overview how many recurring events you have > and what recurrence type they have set. (Mine has only 9 - added "| wc -l" at the end of > the command.) I have these two RRULE:FREQ=YEARLY;BYDAY=-1SU;BYMONTH=9 RRULE:FREQ=YEARLY;BYDAY=-1SU;BYMONTH=2 and six with `FREQ=WEEKLY;COUNT=13;`, one with `FREQ=WEEKLY;COUNT=18;` and one with `FREQ=DAILY;COUNT=5`.
ok, those first two are set "for ever", the rest is limited. Could you check how many events is stored in your calendar, please? It's basically count of lines containing "BEGIN:VEVENT". How many events do you expect to see in your calendar for the actual month, please? The only thing I want to know this for is to have a raw overview for possible test data generation.
(In reply to comment #17) > ok, those first two are set "for ever", the rest is limited. Could you check > how many events is stored in your calendar, please? It's basically count of > lines containing "BEGIN:VEVENT". $ grep 'BEGIN:VEVENT' ~/.local/share/evolution/calendar/system/calendar.ics | wc -l gives around 54000. > How many events do you expect to see in your calendar for the actual month, please? March has around 13 entries and February has 1900. I used `grep '^\ 201102'` and `grep '^\ 201103'` and divided it by 2.
Oh, I'm sorry, I lost track on this. Many things changed meanwhile, did anything change for you too? I'm specifically thinking of 3.20.x or newer (3.24.x is the current stable version).