Bug 316541

I have this one too, on my employer's exchange server (imap connector) with a quite poor connectivity (connection regularly reset, sometime huge network lag).

When I strace the akonadi_imap_resource, I see that the process is stuck in a loop:
poll([{fd=3, events=POLLIN}, {fd=7, events=POLLIN}, {fd=8, events=POLLIN}, {fd=6, events=POLLIN}, {fd=9, events=POLLIN}], 5, 4294967295) = 1 ([{fd=3, revents=POLLIN}])
read(3, "\1\0\0\0\0\0\0\0", 16)         = 8
recvfrom(6, 0x13f76e4, 4096, 0, 0, 0)   = -1 EAGAIN (Resource temporarily unavailable)
recvfrom(6, 0x13f76e4, 4096, 0, 0, 0)   = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=3, events=POLLIN}, {fd=7, events=POLLIN}, {fd=8, events=POLLIN}, {fd=6, events=POLLIN}, {fd=9, events=POLLIN}], 5, 4294967295) = 1 ([{fd=3, revents=POLLIN}])
read(3, "\1\0\0\0\0\0\0\0", 16)         = 8
recvfrom(6, 0x13f76e4, 4096, 0, 0, 0)   = -1 EAGAIN (Resource temporarily unavailable)
recvfrom(6, 0x13f76e4, 4096, 0, 0, 0)   = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=3, events=POLLIN}, {fd=7, events=POLLIN}, {fd=8, events=POLLIN}, {fd=6, events=POLLIN}, {fd=9, events=POLLIN}], 5, 4294967295) = 1 ([{fd=3, revents=POLLIN}])
read(3, "\1\0\0\0\0\0\0\0", 16)         = 8
recvfrom(6, 0x13f76e4, 4096, 0, 0, 0)   = -1 EAGAIN (Resource temporarily unavailable)
recvfrom(6, 0x13f76e4, 4096, 0, 0, 0)   = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=3, events=POLLIN}, {fd=7, events=POLLIN}, {fd=8, events=POLLIN}, {fd=6, events=POLLIN}, {fd=9, events=POLLIN}], 5, 4294967295) = 1 ([{fd=3, revents=POLLIN}])
read(3, "\1\0\0\0\0\0\0\0", 16)         = 8
recvfrom(6, 0x13f76e4, 4096, 0, 0, 0)   = -1 EAGAIN (Resource temporarily unavailable)
recvfrom(6, 0x13f76e4, 4096, 0, 0, 0)   = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=3, events=POLLIN}, {fd=7, events=POLLIN}, {fd=8, events=POLLIN}, {fd=6, events=POLLIN}, {fd=9, events=POLLIN}], 5, 4294967295) = 1 ([{fd=3, revents=POLLIN}])


Looking at .xsession-errors file, there is no significant error.  Some messages like this, but nothing more:
akonadi_imap_resource_0(6697)/kdepimlibs (kimap) KIMAP::StoreJob::handleResponse: We asked for UID but the server didn't give it back, resultingFlags not stored. 
akonadi_imap_resource_0(6697)/kdecore (KConfigSkeleton) KCoreConfigSkeleton::writeConfig:


Please tell what informations you need !

Oops, did forgot this: for me, this happens only since kde 4.10.1. kde 4.10.0 and older were not affected

Moreover, the process is also slowly leaking memory :
I get this after some hours:
casta     9911 76.4 12.1 963212 476116 ?       Sl   Mar14 716:16  \_ /usr/bin/akonadi_imap_resource --identifier akonadi_imap_resource_0

476Mo RSS

I'm experiencing similar issues with akonadi 1.9.1, and kmail 4.10.1.
akonadi_imap_resource runs even when kmail is not, and often takes up ~20% CPU per imap thread.
When calling akonadictl stop i get the following:

QProcess: Destroyed while process is still running.
ProcessControl: Application /usr/bin/akonadi_imap_resource stopped unexpectedly ( "Process crashed" )
Application '/usr/bin/akonadi_imap_resource' crashed. No restart!
QProcess: Destroyed while process is still running.
ProcessControl: Application /usr/bin/akonadi_imap_resource stopped unexpectedly ( "Process crashed" )
Application '/usr/bin/akonadi_imap_resource' crashed. No restart!

This is rendering my system close to useless, so a rollback or a fix should happen soon. Also, how could this ever be released into the wild? it's 100% reproducible, and should have been catched by performance tests...

Created attachment 78355 [details]
network traffic when akonadi_imap_resource CPU usage is high

I noticed that the CPU usage seems to be bounded to bandwidth usage.

In my case (connection to an imap4 exchange connector with poor quality because the exchange server is not very stable), when the CPU starts to grow, it's in sync with significant bandwidth usage. I get around 120kB/s both direction of IMAP traffic (it's on my employer's local network), see the rrd screenshot attached. All the traffic shown is IMAP related. When the network taffic drops down, it's because I restarted akonadi...
You can relink this with the strace I reported earlier. All of those events are coming in sync.
And It's quite systematically reproducible. CPU/Network usage is always growing around half an hour after I restart akonadi server.

I confirm this problem:
$ strace -p 1879 -q -i -t
21:28:25 [      32896e998d] restart_syscall(<... resuming interrupted call ...>) = 1
21:28:25 [      3289a0e12d] read(3, "\1\0\0\0\0\0\0\0", 16) = 8
21:28:25 [      3289a0e4b7] recvfrom(6, 0x1e3a1a4, 4096, 0, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
21:28:25 [      3289a0e4b7] recvfrom(6, 0x1e3a1a4, 4096, 0, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
21:28:25 [      32896e998d] poll([{fd=3, events=POLLIN}, {fd=7, events=POLLIN}, {fd=8, events=POLLIN}, {fd=6, events=POLLIN}, {fd=9, events=POLLIN}], 5, 4294967295) = 1 ([{fd=3, revents=POLLIN}])
21:28:25 [      3289a0e12d] read(3, "\1\0\0\0\0\0\0\0", 16) = 8
21:28:25 [      3289a0e4b7] recvfrom(6, 0x1e3a1a4, 4096, 0, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
21:28:25 [      3289a0e4b7] recvfrom(6, 0x1e3a1a4, 4096, 0, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
21:28:25 [      32896e998d] poll([{fd=3, events=POLLIN}, {fd=7, events=POLLIN}, {fd=8, events=POLLIN}, {fd=6, events=POLLIN}, {fd=9, events=POLLIN}], 5, 4294967295) = 1 ([{fd=3, revents=POLLIN}])
21:28:25 [      3289a0e12d] read(3, "\1\0\0\0\0\0\0\0", 16) = 8
21:28:25 [      3289a0e4b7] recvfrom(6, 0x1e3a1a4, 4096, 0, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
21:28:25 [      3289a0e4b7] recvfrom(6, 0x1e3a1a4, 4096, 0, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
21:28:25 [      32896e998d] poll([{fd=3, events=POLLIN}, {fd=7, events=POLLIN}, {fd=8, events=POLLIN}, {fd=6, events=POLLIN}, {fd=9, events=POLLIN}], 5, 4294967295) = 1 ([{fd=3, revents=POLLIN}])
21:28:25 [      3289a0e12d] read(3, "\1\0\0\0\0\0\0\0", 16) = 8
21:28:25 [      3289a0e4b7] recvfrom(6, 0x1e3a1a4, 4096, 0, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
21:28:25 [      3289a0e4b7] recvfrom(6, 0x1e3a1a4, 4096, 0, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
21:28:25 [      32896e998d] poll([{fd=3, events=POLLIN}, {fd=7, events=POLLIN}, {fd=8, events=POLLIN}, {fd=6, events=POLLIN}, {fd=9, events=POLLIN}], 5, 4294967295) = 1 ([{fd=3, revents=POLLIN}])

On the server side I see:
Mar 26 18:05:25 rut last message repeated 203 times
Mar 26 18:05:25 rut kernel: Limiting open port RST response from 228 to 200 packets/sec
Mar 26 18:05:25 rut inetd[993]: imaps from 10.84.12.122 exceeded counts/min (limit 60/min)
Mar 26 18:05:25 rut last message repeated 65 times
Mar 26 21:16:16 rut inetd[993]: imaps from 10.84.12.122 exceeded counts/min (limit 60/min)
Mar 26 21:26:17 rut last message repeated 59378 times

Mar 26 21:16:16 rut imapd[66678]: Unexpected client disconnect, while reading line user=??? host=[10.84.12.122]
Mar 26 21:16:16 rut imapd[66679]: Unexpected client disconnect, while reading line user=??? host=[10.84.12.122]
Mar 26 21:16:16 rut imapd[66680]: Unexpected client disconnect, while reading line user=??? host=[10.84.12.122]
Mar 26 21:16:16 rut imapd[66681]: Unexpected client disconnect, while reading line user=??? host=[10.84.12.122]
Mar 26 21:16:16 rut imapd[66682]: Unexpected client disconnect, while reading line user=??? host=[10.84.12.122]
Mar 26 21:16:16 rut imapd[66683]: Unexpected client disconnect, while reading line user=??? host=[10.84.12.122]
Mar 26 21:16:16 rut imapd[66684]: Unexpected client disconnect, while reading line user=??? host=[10.84.12.122]
Mar 26 21:16:16 rut imapd[66685]: Unexpected client disconnect, while reading line user=??? host=[10.84.12.122]
Mar 26 21:16:16 rut imapd[66686]: Unexpected client disconnect, while reading line user=??? host=[10.84.12.122]

Some more factors:
Using self signed cert.
Imap-uw via inetd as a mail server.
There is no difference if I'll use mysql or sqlite backend.
Problem doesn't appear for other mail accounts like Gmail or MS Exchange.
PID          PENDING          BLOCKED          IGNORED           CAUGHT STAT TTY        TIME COMMAND
3883  7.5  0.6 609084 23156 ?        Sl   21:34   0:34 /usr/bin/akonadi_imap_resource --identifier akonadi_imap_resource_0
3884  0.2  0.7 685920 26912 ?        Sl   21:34   0:01 /usr/bin/akonadi_imap_resource --identifier akonadi_imap_resource_1

I also forgot to add that setting imap log is not very helpful in that case:
$ echo $KIMAP_LOGFILE
/tmp/imap.log
$ wc -l /tmp/imap.log.3883.1 
0 /tmp/imap.log.3883.1
$ wc -l /tmp/imap.log.3884.1 
3436 /tmp/imap.log.3884.1

Problem disappears iff you turn off akonadi - akonadictl stop.

I've had this problem since I can remember. I'm not sure if I had it with KDE 3.x, but I'm SURE i've had it with EVERY version along KDE 4.x

The problem only happens with one specific IMAP account, which only accepts one connection at a time. I've searched all over for a way to limit the number of IMAP connections KMail/Akonadi initiates to a specific server, but it seems there's no way to do it. I can't even delete email, or mark it as read, as all changes are lost when then connection goes down. I have to do it all via webmail.

Every once in a while, after a connection drop, the Akonadi process related to this specific IMAP account starts consuming 100% of the CPU and, like someone else already said, the only way to stop it is to restart Akonadi.

The server dropping the connection CAN lead to this problem, but not always. Sometimes I just get all my deleted mail back, and my read mail marked as unread. However, I also had a WiFi router problem where the connection appeared to be up, but there was no connection to the network. If this happens overnight, it triggers the Akonadi CPU usage bug 100% of the time.



My strace right now shows basically nothing although is has been running for about 10 minutes now, but Akonadi is consuming 100% CPU:

[root@roadrunner ~]# strace -fp 16902
Process 16902 attached with 4 threads
[pid 12245] restart_syscall(<... resuming interrupted call ...> <unfinished ...>
[pid 17968] restart_syscall(<... resuming interrupted call ...> <unfinished ...>
[pid 16902] futex(0xcdea0c, FUTEX_WAIT_PRIVATE, 3, NULL

Git commit a4299dbabf37e692f4355ed4871fc0e3681d765b by David Faure.
Committed on 26/06/2013 at 10:13.
Pushed by dfaure into branch 'KDE/4.10'.

Cancel session request if the task is deleted early.

E.g. due to losing the connection to the server.
Otherwise the request is processed later on, with no task to use that
session, and we end up with a session in m_reservedSession for ever, and
soon afterwards an infinite stream of
"Cancelling this request. Probably there is no more session available."

Might be related to:
Related: bug 318098
(but for lack of debug output in these reports, I can't tell for sure)

FIXED-IN: 4.10.5
Reviewed-by: Kévin Ottens

M  +5    -2    resources/imap/resourcetask.cpp
M  +6    -0    resources/imap/sessionpool.cpp
M  +1    -0    resources/imap/sessionpool.h
M  +43   -0    resources/imap/tests/testsessionpool.cpp

http://commits.kde.org/kdepim-runtime/a4299dbabf37e692f4355ed4871fc0e3681d765b

I applied this patchset against my current gentoo 4.10.4 install and restarted akonadiserver. After some minutes, The problem is back:
- I see the same loop in strace as in comment #1
- I see the same bandwith consumption as in my attachement

There is nothing special in .xsession-errors
What sort of debug output do you want ? Is there something to enable to gather some useful output ?

Git commit 00784dd1a92cb00069df9e5f296e02f268fab6ed by David Faure.
Committed on 04/07/2013 at 21:00.
Pushed by dfaure into branch 'KDE/4.10'.

Cancel session request if imap idle manager is deleted before getting a session.

Same logic as commit a4299dbabf37e692f4355ed4871fc0e3681d765b, but for
the idle manager.
Same possible symptom later on, an infinite number of:
"Cancelling this request. Probably there is no more session available."
Related: bug 318098
FIXED-IN: 4.11

CCMAIL: ervin@kde.org

M  +7    -2    resources/imap/imapidlemanager.cpp

http://commits.kde.org/kdepim-runtime/00784dd1a92cb00069df9e5f296e02f268fab6ed

(In reply to comment #5)
Same effect on KMail 4.10.4, 50% one core of the cpu and 135kbyte Network Traffic between imap server also after closing kmail! :-/
Is there any workarround out there?

The traffic (and related CPU use) is caused by bug #316840. It usually starts after some time (~30 minutes). Known workaround is to set automatic mail check interval to be less than the go-crazy interval, or to disable SSL completely.

*** This bug has been confirmed by popular vote. ***

Thank you disable SSL worked :)

(In reply to comment #13)
> The traffic (and related CPU use) is caused by bug #316840. It usually
> starts after some time (~30 minutes). Known workaround is to set automatic
> mail check interval to be less than the go-crazy interval, or to disable SSL
> completely.

Yes indeed !
Thanks for pointing this.

This bug has only been reported for versions before 4.14, which have been unsupported for at least two years now. Can anyone tell if this bug still present?

If noone confirms this bug for a Framework-based version of kmail2 (version 5.0 or later, as part of KDE Applications 15.12 or later), it gets closed in about three months.

Just as announced in my last comment, I close this bug. If you encounter it again in a recent version (at least 5.0 aka 15.08), please open a new one unless it already exists. Thank you for all your input.