Bug 422336

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

Average time to wait before being able to access a message in a folder one minute or more

Created attachment 129030 [details]
message

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.

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

- 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.

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.

(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

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.

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.

(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

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

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

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

I'm not so sure the root cause is the maildir resource. I'm experiencing major slowdowns using imap resource as well.

(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.

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.)

(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).

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.

(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.

Hi Martin,

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

Thanks!

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.

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.

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.

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.