Bug 316541 - akonadi_imap_resource uses 50% of one core even while KMail is shut down
Summary: akonadi_imap_resource uses 50% of one core even while KMail is shut down
Status: RESOLVED UNMAINTAINED
Alias: None
Product: kmail2
Classification: Applications
Component: general (show other bugs)
Version: 4.10.1
Platform: Other Linux
: NOR grave
Target Milestone: ---
Assignee: kdepim bugs
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2013-03-11 14:43 UTC by Edward
Modified: 2017-01-07 21:28 UTC (History)
10 users (show)

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


Attachments
network traffic when akonadi_imap_resource CPU usage is high (15.15 KB, image/png)
2013-03-24 23:53 UTC, Guillaume Castagnino
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Edward 2013-03-11 14:43:48 UTC
I have one account set up in KMail: it is IMAP with a self-signed certificate.  Even when I shut down KMail, akonadi_imap_resource process runs in the background and consumes 50% of one CPU core.  If I kill the process, it eventually starts itself up again.

Reproducible: Always

Steps to Reproduce:
1. Set up an IMAP account in KMail (not sure if it has to be with a self-signed certificate on the server, but mine is)
2. Shut down KMail
3. top shows akonadi_imap_resource using the CPU continuously
Comment 1 Guillaume Castagnino 2013-03-12 15:23:47 UTC
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 !
Comment 2 Guillaume Castagnino 2013-03-12 15:24:53 UTC
Oops, did forgot this: for me, this happens only since kde 4.10.1. kde 4.10.0 and older were not affected
Comment 3 Guillaume Castagnino 2013-03-15 07:53:51 UTC
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
Comment 4 Henrik Juul Pedersen 2013-03-20 09:37:23 UTC
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...
Comment 5 Guillaume Castagnino 2013-03-24 23:53:14 UTC
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.
Comment 6 Łukasz 2013-03-26 20:43:55 UTC
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
Comment 7 Łukasz 2013-03-26 20:48:43 UTC
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.
Comment 8 Gamblit 2013-05-14 15:02:34 UTC
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
Comment 9 David Faure 2013-06-26 10:48:25 UTC
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
Comment 10 Guillaume Castagnino 2013-06-27 19:28:27 UTC
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 ?
Comment 11 David Faure 2013-07-04 21:02:11 UTC
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
Comment 12 Axel Schmidt 2013-07-08 16:44:01 UTC
(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?
Comment 13 Daniel Vrátil 2013-07-09 11:42:29 UTC
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.
Comment 14 Axel Schmidt 2013-07-09 12:33:15 UTC
*** This bug has been confirmed by popular vote. ***
Comment 15 Axel Schmidt 2013-07-09 13:06:19 UTC
Thank you disable SSL worked :)
Comment 16 Guillaume Castagnino 2013-07-30 18:19:27 UTC
(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.
Comment 17 Denis Kurz 2016-09-24 17:53:19 UTC
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.
Comment 18 Denis Kurz 2017-01-07 21:28:16 UTC
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.