Bug 422336 - kmail: the access and reading of the received messages is often very slow
Summary: kmail: the access and reading of the received messages is often very slow
Status: RESOLVED WORKSFORME
Alias: None
Product: Akonadi
Classification: Frameworks and Libraries
Component: Maildir Resource (show other bugs)
Version: 5.14.1
Platform: Debian unstable Linux
: NOR major
Target Milestone: ---
Assignee: kdepim bugs
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2020-06-01 17:15 UTC by phil-deb1.merlin@laposte.net
Modified: 2022-02-11 07:07 UTC (History)
9 users (show)

See Also:
Latest Commit:
Version Fixed In:
Sentry Crash Report:


Attachments
message (2.66 KB, text/plain)
2020-06-03 17:15 UTC, Marc Mezzarobba
Details
Patch for akonadi (2.95 KB, patch)
2021-03-07 10:40 UTC, Fabian Vogt
Details

Note You need to log in before you can comment on or make changes to this bug.
Description phil-deb1.merlin@laposte.net 2020-06-01 17:15:08 UTC
I open a Debian Bug Number :Bug#961913 who describe the problem
https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=961913
The messages are fetched with Pop3 and store with local maildir


OBSERVED RESULT


EXPECTED RESULT


SOFTWARE/OS VERSIONS
Windows: 
macOS: 
Linux/KDE Plasma: 
(available in About System)
KDE Plasma Version: 
KDE Frameworks Version: 
Qt Version: 

ADDITIONAL INFORMATION
Comment 1 phil-deb1.merlin@laposte.net 2020-06-02 10:19:12 UTC
All informations SOFTWARE/OS VERSIONS are included in the Debian Bug 96193
when i open a mail in an other Folder that its currently open
i have an windows KDE
The Kde messaging client
Reception of file contents
Please wait
When le problem arrived a TOP command show akonadi_maildir CPU 102% mem 0,5%
akonadi show:
org.kde.pim.akonadiserver: ItemRetrievalJob for request 0x7f7838a76830 finished
org.kde.pim.akonadiserver.search: Executing search "kontact-48271-SearchSession"
org.kde.pim.akonadiserver.search: Search  "kontact-48271-SearchSession" done (without remote search)
org.kde.pim.akonadiserver.search: Executing search "kontact-48271-SearchSession"
org.kde.pim.akonadiserver.search: Search  "kontact-48271-SearchSession" done (without remote search)
org.kde.pim.akonadiserver.search: Executing search "searchUpdate-1591091823"
org.kde.pim.akonadiserver.search: Search  "searchUpdate-1591091823" done (without remote search)
each Folders contains about 10000 mails
this problem occurred after updating kmail from 4: 19.08.3-1 to 4: 20.04.1-1
Comment 2 phil-deb1.merlin@laposte.net 2020-06-02 18:35:00 UTC
Average time to wait before being able to access a message in a folder one minute or more
Comment 3 Marc Mezzarobba 2020-06-03 17:15:19 UTC
Created attachment 129030 [details]
message
Comment 4 Marc Mezzarobba 2020-06-03 17:19:33 UTC
Dear kdepim developers,

I'm seeing a similar issue with kmail on debian. My setup is close to that of the original reporter: I also just upgraded from kmail (+ dependencies) 19.08.3 to 20.04.1, and I'm using POP3 with a few dozens local maildir folders.

My attempt to post more details was blocked by a spam filter. Please see the attachment above for the full version of this message.
Comment 5 Martin Steigerwald 2020-06-05 16:05:03 UTC
Reassigning to Akonadi. I can not select maildir resource at the moment, I bet I first need to save the comment and then I will reassign to maildir resource. That is what I believe where the issue happens.

I confirm this. I am using KDEPIM 20.04 with KMail and Akonadi 5.14.1 on Debian Sid with PostgreSQL database.

OBSERVED RESULT

Compared to KDEPIM / Akonadi 19.08 synchronizing a mail folder even with just a few thousand mails takes much, much longer. It easily takes a minute or more during which Akonadi does not respond to KMail requesting the payload of a mail anymore. This needs to the "Retrieving folder contents" when clicking on a mail Akonadi did not retrieve recently before.

During the synchronization it consumes 100% of one Intel Sandybridge Mobile i5 CPU core for a minute or longer. I checked once with strace and it was polling several dozens if not more times a second on an eventfd. If you have some instructions I can try to find out more about what the maildir resource is doing at during those slow synchronization operations.

EXPECTED RESULT

1. Akonadi maildir resource works as fast as with KDEPIM / Akonadi 19.08 before.

2. Akonadi never ever blocks an immediate user request for displaying a mail while performing a background task but this I already reported in:

[Akonadi] [Bug 367892] New: During folder synchronization Akonadi blocks out other operations like deleting or viewing mails.

3. It does not needlessly synchronize local folders. For local mails during runtime Akonadi as already an inotify watch on every folder. Yet it synchronizes the same folders several times during Akonadi session even *tough* Akonadi is *the only* one writing to it. I also reported this one already in:

[Akonadi] [Bug 334216] New: synchronizes folder with filesystem after downloading and filtering mails needlessly
Comment 6 Martin Steigerwald 2020-06-09 07:53:41 UTC
- Open a folder with just about 13000 mails
- Click on it for the first time in a KMail/Akonadi session or after a while you used it last again
- Wait for one minute for Akonadi to deliver the payload of a mail I like to reply to to KMail

This is unbearable. I do not remember it ever having been that bad.
Comment 7 Martin Steigerwald 2020-06-09 08:45:58 UTC
With a folder with about 30500 it just got that back that KMail gave up waiting after some minutes:

"Unable to fetch item from backend (collection -1): Unable to contact resource."

Why "-1"? I have no clue. So or so… this is an error message an user should never ever see, cause its incomprehensible and the user also cannot do anything about it.
Comment 8 Martin Steigerwald 2020-06-09 08:46:31 UTC
(In reply to Martin Steigerwald from comment #7)
> With a folder with about 30500 it just got that back that KMail gave up
> waiting after some minutes:

it just got that bad
Comment 9 Martin Steigerwald 2020-06-09 08:53:09 UTC
An awkward work-around demonstrates that it really is Akonadi maildir resource. If I terminate the akonadi_maildir_resource process KMail almost immediately becomes responsive again. But if I do this for more than three times then Akonadi considers the resource to be broken and would not start it anymore.
Comment 10 Martin Steigerwald 2020-06-09 09:07:31 UTC
Marc, thank you a lot for your analysis in comment #2. I just noticed it now. I bet it can be valuable help for the developers to pinpoint the issue.
Comment 11 Martin Steigerwald 2020-06-09 09:10:55 UTC
(In reply to Martin Steigerwald from comment #10)
> Marc, thank you a lot for your analysis in comment #2. I just noticed it
> now. I bet it can be valuable help for the developers to pinpoint the issue.

I can confirm your finding with perf top:

Samples
Overhead  Shared Object                         Symbol
  65,66%  libQt5Core.so.5.12.5                  [.] QMetaObjectPrivate::disconnect
   5,87%  [kernel]                              [k] 0xffffffff81737191
   2,07%  libQt5Core.so.5.12.5                  [.] QMetaObject::activate
   1,58%  i965_dri.so                           [.] linear_to_ytiled_faster
   0,66%  libKF5MessageList.so.5.14.1.abi1      [.] MessageList::Core::Item::parent
   0,59%  libQt5WebEngineCore.so.5.12.5         [.] exec_ops
   0,48%  libQt5Gui.so.5.12.5                   [.] qt_alphamapblit_argb32
   0,39%  libKF5MessageList.so.5.14.1.abi1      [.] MessageList::Core::Item::indexOfChildItem
   0,35%  libQt5Gui.so.5.12.5                   [.] qt_memfill32
   0,31%  libKF5MessageList.so.5.14.1.abi1      [.] MessageList::Core::Item::type
   0,25%  libc-2.30.so                          [.] _int_malloc

Samples
Overhead  Shared Object                         Symbol
  72,54%  libQt5Core.so.5.12.5                           [.] QMetaObjectPrivate::disconnect
   4,87%  [kernel]                                       [k] 0xffffffff81737191
   1,72%  libQt5Core.so.5.12.5                           [.] QMetaObject::activate
   0,74%  libKF5MessageList.so.5.14.1.abi1               [.] MessageList::Core::Item::parent
   0,56%  libKF5MessageList.so.5.14.1.abi1               [.] MessageList::Core::Item::indexOfChildItem
   0,52%  perf_5.6                                       [.] 0x000000000033fe21
   0,48%  perf_5.6                                       [.] 0x0000000000275703
   0,36%  i965_dri.so                                    [.] linear_to_ytiled_faster
   0,30%  libQt5Core.so.5.12.5                           [.] QAbstractItemModelPrivate::rowsAboutToBeInserted
   0,30%  libQt5Core.so.5.12.5                           [.] QAbstractItemModelPrivate::rowsAboutToBeRemoved
   0,23%  libQt5Core.so.5.12.5                           [.] bm_find
Comment 12 Martin Steigerwald 2020-06-09 09:26:01 UTC
See also:

Bug 422624 - Akonadi does full rescan on every change in maildir

as well as reopened

Bug 334209 - synchronizes folder contents during runtime needlessly when switching between different folders
Comment 13 Martin Steigerwald 2020-06-09 11:58:42 UTC
Strace output when maildir resources takes ages to complete a synchronization:

[pid  7806] poll([{fd=5, events=POLLIN}, {fd=13, events=POLLIN}], 2, 55 <unfinished ...>
[pid  7815] write(5, "\1\0\0\0\0\0\0\0", 8) = 8
[pid  7806] <... poll resumed>)         = 1 ([{fd=5, revents=POLLIN}])
[pid  7806] read(5, "\1\0\0\0\0\0\0\0", 16) = 8
[pid  7806] poll([{fd=5, events=POLLIN}, {fd=13, events=POLLIN}], 2, 50 <unfinished ...>
[pid  7815] write(5, "\1\0\0\0\0\0\0\0", 8) = 8
[pid  7806] <... poll resumed>)         = 1 ([{fd=5, revents=POLLIN}])
[pid  7806] read(5, "\1\0\0\0\0\0\0\0", 16) = 8
[pid  7806] poll([{fd=5, events=POLLIN}, {fd=13, events=POLLIN}], 2, 46 <unfinished ...>
[pid  7815] write(5, "\1\0\0\0\0\0\0\0", 8) = 8
[pid  7806] <... poll resumed>)         = 1 ([{fd=5, revents=POLLIN}])
[pid  7806] read(5, "\1\0\0\0\0\0\0\0", 16) = 8
[pid  7806] poll([{fd=5, events=POLLIN}, {fd=13, events=POLLIN}], 2, 41 <unfinished ...>
[pid  7815] write(5, "\1\0\0\0\0\0\0\0", 8) = 8
[pid  7806] <... poll resumed>)         = 1 ([{fd=5, revents=POLLIN}])
[pid  7806] read(5, "\1\0\0\0\0\0\0\0", 16) = 8
[pid  7806] poll([{fd=5, events=POLLIN}, {fd=13, events=POLLIN}], 2, 37 <unfinished ...>
[pid  7815] write(5, "\1\0\0\0\0\0\0\0", 8) = 8
[pid  7806] <... poll resumed>)         = 1 ([{fd=5, revents=POLLIN}])
[pid  7806] read(5, "\1\0\0\0\0\0\0\0", 16) = 8
[pid  7806] poll([{fd=5, events=POLLIN}, {fd=13, events=POLLIN}], 2, 31 <unfinished ...>
[pid  7815] write(5, "\1\0\0\0\0\0\0\0", 8) = 8
[pid  7806] <... poll resumed>)         = 1 ([{fd=5, revents=POLLIN}])
[pid  7806] read(5, "\1\0\0\0\0\0\0\0", 16) = 8
[pid  7806] poll([{fd=5, events=POLLIN}, {fd=13, events=POLLIN}], 2, 26^Cstrace: Process 7806 detached
 <detached ...>

It goes on like that in rapid succession. 10 second statistic:

% timeout 10 strace -cp 7806
strace: Process 7806 attached
strace: Process 7806 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 75,59    0,052635          32      1618           poll
 24,25    0,016883          11      1531           read
  0,16    0,000111           4        24           futex
  0,00    0,000000           0         1           restart_syscall
------ ----------- ----------- --------- --------- ----------------
100.00    0,069629                  3174           total

[…]/proc/7806> ls -l fd/5
lrwx------ 1 martin martin 64 Jun  9 13:57 fd/5 -> 'anon_inode:[eventfd]'
[…]/proc/7806> ls -l fd/13
lr-x------ 1 martin martin 64 Jun  9 13:57 fd/13 -> anon_inode:inotify
Comment 14 Marc Mezzarobba 2020-06-10 17:27:12 UTC
Another, possibly more informative, perf report on the akonadi_maildir_resource process. (I don't understand why perf no longer manages to resolve the symbols are those from libQt5Core; I tried purging the buildid cache, to no avail.)

    99.62%    99.11%  SessionThread    libQt5Core.so.5.12.5               
            |          
            |--92.11%--QApplication::notify
            |          QApplicationPrivate::notify_helper
            |          QReadNotifier::event
            |          QAbstractSocketPrivate::canReadNotification
            |          QAbstractSocketPrivate::emitReadyRead
            |          0x7effbccc1385
            |          0x7effbccc14e3
            |          Akonadi::Connection::handleIncomingData
            |          |          
            |           --92.05%--0x7effbccc3bd2
            |                     |          
            |                      --92.05%--0x7effbccc3240
            |          
            |--2.16%--0x7effbcc956d6
            |          0x7effbccec7bc
            |          g_main_context_iteration
            |          |          
            |           --2.16%--0x7effbb02519b
            |                     g_main_context_dispatch
            |                     0x7effbcced3c0
            |                     0x7effbcc96a50
            |                     QApplication::notify
            |                     QApplicationPrivate::notify_helper
            |                     QReadNotifier::event
            |                     QAbstractSocketPrivate::canReadNotification
            |                     |          
            |                      --2.15%--QAbstractSocketPrivate::emitReadyRead
            |                                0x7effbccc1385
            |                                |          
            |                                 --2.15%--0x7effbcbd9560
            |          
            |--1.99%--g_main_context_iteration
            |          0x7effbb02519b
            |          g_main_context_dispatch
            |          0x7effbcced3c0
            |          0x7effbcc96a50
            |          QApplication::notify
            |          QApplicationPrivate::notify_helper
            |          QReadNotifier::event
            |          QAbstractSocketPrivate::canReadNotification
            |          QAbstractSocketPrivate::emitReadyRead
            |          0x7effbccc1385
            |          0x7effbccc14e3
            |          Akonadi::Connection::handleIncomingData
            |          0x7effbccc3bd2
            |          0x7effbccc3240
            |          
            |--1.77%--Akonadi::Connection::handleIncomingData
            |          0x7effbccc3bd2
            |          0x7effbccc3240
            |          
             --1.08%--0x7effbcc96a50
                       QApplication::notify
                       QApplicationPrivate::notify_helper
                       QReadNotifier::event
                       QAbstractSocketPrivate::canReadNotification
                       QAbstractSocketPrivate::emitReadyRead
                       0x7effbccc1385
                       0x7effbccc14e3
                       Akonadi::Connection::handleIncomingData
                       |          
                        --1.08%--0x7effbccc3bd2
                                  0x7effbccc3240

    97.82%     0.00%  SessionThread    libQt5Widgets.so.5.12.5            
            |
            ---QApplication::notify
               QApplicationPrivate::notify_helper
               QReadNotifier::event
               QAbstractSocketPrivate::canReadNotification
               |          
                --97.82%--QAbstractSocketPrivate::emitReadyRead
                          0x7effbccc1385
                          |          
                          |--95.66%--0x7effbccc14e3
                          |          |          
                          |           --95.66%--Akonadi::Connection::handleIncomingData
                          |                     |          
                          |                      --95.45%--0x7effbccc3bd2
                          |                                |          
                          |                                 --95.44%--0x7effbccc3240
                          |          
                           --2.15%--0x7effbcbd9560

    97.82%     0.00%  SessionThread    libQt5Network.so.5.12.5            
            |          
             --97.82%--QReadNotifier::event
                       QAbstractSocketPrivate::canReadNotification
                       |          
                        --97.81%--QAbstractSocketPrivate::emitReadyRead
                                  0x7effbccc1385
                                  |          
                                  |--95.66%--0x7effbccc14e3
                                  |          |          
                                  |           --95.66%--Akonadi::Connection::handleIncomingData
                                  |                     |          
                                  |                      --95.45%--0x7effbccc3bd2
                                  |                                |          
                                  |                                 --95.44%--0x7effbccc3240
                                  |          
                                   --2.15%--0x7effbcbd9560

    97.44%     0.01%  SessionThread    libKF5AkonadiCore.so.5.14.1.abi2   
            |          
             --97.43%--Akonadi::Connection::handleIncomingData
                       |          
                        --97.22%--0x7effbccc3bd2
                                  |          
                                   --97.21%--0x7effbccc3240

     4.23%     0.01%  SessionThread    libglib-2.0.so.0.6200.4            
            |          
             --4.15%--g_main_context_iteration
                       |          
                        --4.15%--0x7effbb02519b
                                  g_main_context_dispatch
                                  0x7effbcced3c0
                                  0x7effbcc96a50
                                  QApplication::notify
                                  QApplicationPrivate::notify_helper
                                  QReadNotifier::event
                                  QAbstractSocketPrivate::canReadNotification
                                  |          
                                   --4.15%--QAbstractSocketPrivate::emitReadyRead
                                             0x7effbccc1385
                                             |          
                                             |--2.15%--0x7effbcbd9560
                                             |          
                                              --1.99%--0x7effbccc14e3
                                                        |          
                                                         --1.99%--Akonadi::Connection::handleIncomingData
                                                                   0x7effbccc3bd2
                                                                   0x7effbccc3240
Comment 15 Sander van Grieken 2020-06-26 06:05:36 UTC
I'm not so sure the root cause is the maildir resource. I'm experiencing major slowdowns using imap resource as well.
Comment 16 Martin Steigerwald 2020-06-26 08:56:27 UTC
(In reply to Sander van Grieken from comment #15)
> I'm not so sure the root cause is the maildir resource. I'm experiencing
> major slowdowns using imap resource as well.

Maybe. However for now I suggest you open a different bug report about that, unless you can verify the following: Does akonadi_imap_resource also produce 100% cpu usage, does it spin in the same areas (see perf output in the comments)? If not, please open a separate bug report.

Feel free to add a link to your new bug report in a comment here.
Comment 17 Jonas Schäfer 2020-07-01 15:31:48 UTC
I would like to confirm the imap resource problem being similar, but I don’t know which specific perf invocation produces output like the one shown above.

The symptoms seem very similar and I can see it spinning on an fd like the maildir resource here in strace.

If you could hand me the perf command lines, I’d try to confirm and if it matches, post here or create a new bugreport if it doesn’t match.

(I never used perf before, came up with perf report -g but that didn’t look structurally similar; but maybe I’m missing something else.)
Comment 18 Martin Steigerwald 2020-07-01 18:32:06 UTC
(In reply to Jonas Schäfer from comment #17)
> I would like to confirm the imap resource problem being similar, but I don’t
> know which specific perf invocation produces output like the one shown above.

Marc, could you post the perf command line you used for the analysis in comment #14? It is more detailed than what I used (and do not remember right now).
Comment 19 phil-deb1.merlin@laposte.net 2020-07-01 18:51:44 UTC
Since Qt 5.14.2 arrived in the unstable version of Debian with a modification of Akonadi the problem has disappeared. Thank you so much. For me I consider that the Bug is resolved.
Comment 20 Martin Steigerwald 2020-07-01 22:06:14 UTC
(In reply to phil-deb1.merlin@laposte.net from comment #19)
> Since Qt 5.14.2 arrived in the unstable version of Debian with a
> modification of Akonadi the problem has disappeared. Thank you so much. For
> me I consider that the Bug is resolved.

I can confirm that akonadi_maildir_resource is much faster again as well. I wasn't sure initial, but I just tested switching between folders and it is much faster again. I don't know that fixed it but it maybe that Akonadi 20.04 and Qt 5.12 did not like each other.

Jonas, can you confirm that IMAP resource is still slow with Qt 5.14? If so, I suggest this to be a different bug.

Anyway I am closing as RESOLVED / WORKSFORME now as… I have no idea what fixed it. If anyone still has this issue, with maildir resource, please speak up and I open it again. Confirm that you are running on Qt 5.14 though.
Comment 21 Jonas Schäfer 2020-07-04 08:27:56 UTC
Hi Martin,

I followed the idea to upgrade to 5.14, and everything has improved a lot back to the previous level!

Thanks!
Comment 22 Toni 2020-07-06 12:08:53 UTC
Could someone please identify the commit(s) which resolved this problem?

The issue may be fixed on Debian after an update to Qt 5.14, but that is not the only affected platform. OpenSUSE Leap 15.2 was just released with Kmail 20.04 and Qt 5.12 and it suffers this same problem. Leap 15.2 will remain on Qt 5.12 (LTS) for its lifetime (12-18 months).

The fix for this issue needs to be backported from Qt 5.14 to Qt 5.12 LTS, which is supported until end of next year. It would be helpful to know which fix it is that needs to be backported in order to ask upstream for that to be done.
Comment 23 Martin Steigerwald 2020-07-08 07:10:42 UTC
Toni, I am not going to do a git bisect between Qt 5.12 and Qt 5.14 – it would take a long, long, long time on this quite a bit older laptop. But maybe someone else is willing to or… has an idea what commit it might be.

But I reopened the bug and set it to "NEEDSINFO". So if someone is willing to identify the git commit or has an idea which one it could be already… go ahead.
Comment 24 Toni 2020-07-09 09:07:10 UTC
I wasn't asking for a bisect necessarily, I could do the brute force search myself if required. I was hoping someone already had some idea which commit(s) it is that fixes it. Phil's comment about a specific version of Qt with changes for akonadi suggested there was some specific change to fix this issue. I can confirm the problem did not occur on another distro which updated Qt to 5.15 at the same time kde-pim was updated to 20.04.
Comment 25 Fabian Vogt 2021-03-07 10:40:50 UTC
Created attachment 136452 [details]
Patch for akonadi

This is most likely https://bugreports.qt.io/browse/QTBUG-72649. The commit(s) upstream which improve this in Qt itself depend on heavy refactoring, so doesn't (easily) apply to 5.12. I attached a patch to akonadi which works around the Qt issue. It reportedly fixes high CPU use of akonadi resources.