more lags with kmail 4.11

Martin Steigerwald <[email protected]> Wed, 16 Oct 2013 12:46:47 +0200
Newsgroups	gmane.comp.kde.users.pim
Message-ID	<4060747.FJHSdGt55d@merkaba>
Hi!

Filed as bug

Bug 326089 - accessing mail contents lags for minutes and then sending mail 
does as well
https://bugs.kde.org/326089

And downgraded to KDEPIM 4.10 again as kmail 4.11 simply does not want to send 
this mail within *any reasonable* amount of time.



Today I upgraded kdepim to 4.11 as well after kdelibs/base stuff and kdepimlibs 
and akonadi are already updated. Debian Experimental that is.

With kmail 4.11 I get much worse latencies when accessing mails. I get 
"retrieving folder contents" for minutes before mail is displayed even when 
without kmail being started Akonadi appears to be idle.

CPU wise I usually get something like this:

  PID SYSCPU USRCPU  VGROW  RGROW  RDDSK   WRDSK ST EXC S  CPU  CMD
 3949  1.40s  3.35s     0K     0K     4K    448K --   - S  48%  mysqld
 6450  0.22s  3.69s     0K     0K     0K      0K --   - R  40%  kmail
 3946  1.27s  2.60s     0K     0K     0K      0K --   - S  39%  akonadiserver

But what on earth is KMail doing here when it *waits* for Akonadi to retrieve 
the mail?



In strace -fF -p pid-of-kmail I get stuff like this

[pid  6097] recvfrom(7, 0x2469ca4, 4096, 0, 0, 0) = -1 EAGAIN (Resource 
temporarily unavailable)
[pid  6097] ioctl(10, FIONREAD, [255])  = 0
[pid  6097] read(10, "* 81 22 (NAME \"Spam\" MIMETYPE (m"..., 255) = 255
[pid  6097] recvfrom(7, 0x2469ca4, 4096, 0, 0, 0) = -1 EAGAIN (Resource 
temporarily unavailable)
[pid  6097] poll([{fd=3, events=POLLIN}, {fd=8, events=POLLIN}, {fd=7, 
events=POLLIN}, {fd=9, events=POLLIN}, {fd=10, events=POLLIN}, {fd=5, 
events=POLLIN}, {fd=13, events=POLLIN}, {fd=15, events=POLLIN}, {fd=22, 
events=POLLIN}, {fd=24, events=POLLIN}], 10, 20) = 1 ([{fd=10, 
revents=POLLIN}])
[pid  6097] recvfrom(7, 0x2469ca4, 4096, 0, 0, 0) = -1 EAGAIN (Resource 
temporarily unavailable)
[pid  6097] ioctl(10, FIONREAD, [251])  = 0
[pid  6097] read(10, "* 82 22 (NAME \"Unsicher\" MIMETYP"..., 251) = 251
[pid  6097] recvfrom(7, 0x2469ca4, 4096, 0, 0, 0) = -1 EAGAIN (Resource 
temporarily unavailable)
[pid  6097] poll([{fd=3, events=POLLIN}, {fd=8, events=POLLIN}, {fd=7, 
events=POLLIN}, {fd=9, events=POLLIN}, {fd=10, events=POLLIN}, {fd=5, 
events=POLLIN}, {fd=13, events=POLLIN}, {fd=15, events=POLLIN}, {fd=22, 
events=POLLIN}, {fd=24, events=POLLIN}], 10, 19) = 1 ([{fd=10, 
revents=POLLIN}])
[pid  6097] recvfrom(7, 0x2469ca4, 4096, 0, 0, 0) = -1 EAGAIN (Resource 
temporarily unavailable)
[pid  6097] ioctl(10, FIONREAD, [347])  = 0
[pid  6097] read(10, "* 22 10 (NAME \"trash\" MIMETYPE ("..., 347) = 347
[pid  6097] recvfrom(7, 0x2469ca4, 4096, 0, 0, 0) = -1 EAGAIN (Resource 
temporarily unavailable)
[pid  6097] poll([{fd=3, events=POLLIN}, {fd=8, events=POLLIN}, {fd=7, 
events=POLLIN}, {fd=9, events=POLLIN}, {fd=10, events=POLLIN}, {fd=5, 
events=POLLIN}, {fd=13, events=POLLIN}, {fd=15, events=POLLIN}, {fd=22, 
events=POLLIN}, {fd=24, events=POLLIN}], 10, 19) = 1 ([{fd=10, 
revents=POLLIN}])
[pid  6097] recvfrom(7, 0x2469ca4, 4096, 0, 0, 0) = -1 EAGAIN (Resource 
temporarily unavailable)
[pid  6097] ioctl(10, FIONREAD, [394])  = 0
[pid  6097] read(10, "* 10 0 (NAME \"Lokale Ordner\" MIM"..., 394) = 394
[pid  6097] recvfrom(7, 0x2469ca4, 4096, 0, 0, 0) = -1 EAGAIN (Resource 
temporarily unavailable)
[pid  6097] poll([{fd=3, events=POLLIN}, {fd=8, events=POLLIN}, {fd=7, 
events=POLLIN}, {fd=9, events=POLLIN}, {fd=10, events=POLLIN}, {fd=5, 
events=POLLIN}, {fd=13, events=POLLIN}, {fd=15, events=POLLIN}, {fd=22, 
events=POLLIN}, {fd=24, events=POLLIN}], 10, 18) = 1 ([{fd=10, 
revents=POLLIN}])
[pid  6097] recvfrom(7, 0x2469ca4, 4096, 0, 0, 0) = -1 EAGAIN (Resource 
temporarily unavailable)
[pid  6097] ioctl(10, FIONREAD, [24])   = 0
[pid  6097] read(10, "1351 OK List completed\r\n", 24) = 24
[pid  6097] write(3, "\1\0\0\0\0\0\0\0", 8) = 8
[pid  6097] recvfrom(7, 0x2469ca4, 4096, 0, 0, 0) = -1 EAGAIN (Resource 
temporarily unavailable)
[pid  6097] poll([{fd=3, events=POLLIN}, {fd=8, events=POLLIN}, {fd=7, 
events=POLLIN}, {fd=9, events=POLLIN}, {fd=10, events=POLLIN}, {fd=5, 
events=POLLIN}, {fd=13, events=POLLIN}, {fd=15, events=POLLIN}, {fd=22, 
events=POLLIN}, {fd=24, events=POLLIN}], 10, 0) = 1 ([{fd=3, revents=POLLIN}])
[pid  6097] recvfrom(7, 0x2469ca4, 4096, 0, 0, 0) = -1 EAGAIN (Resource 
temporarily unavailable)
[pid  6097] write(3, "\1\0\0\0\0\0\0\0", 8) = 8
[pid  6097] write(3, "\1\0\0\0\0\0\0\0", 8) = 8
[pid  6097] write(3, "\1\0\0\0\0\0\0\0", 8) = 8
[pid  6097] write(3, "\1\0\0\0\0\0\0\0", 8) = 8
[pid  6097] write(3, "\1\0\0\0\0\0\0\0", 8) = 8
[pid  6097] write(3, "\1\0\0\0\0\0\0\0", 8) = 8
[pid  6097] write(3, "\1\0\0\0\0\0\0\0", 8) = 8
[pid  6097] write(3, "\1\0\0\0\0\0\0\0", 8) = 8
[pid  6097] recvfrom(7, 0x2469ca4, 4096, 0, 0, 0) = -1 EAGAIN (Resource 
temporarily unavailable)
[pid  6097] poll([{fd=3, events=POLLIN}, {fd=8, events=POLLIN}, {fd=7, 
events=POLLIN}, {fd=9, events=POLLIN}, {fd=10, events=POLLIN}, {fd=5, 
events=POLLIN}, {fd=13, events=POLLIN}, {fd=15, events=POLLIN}, {fd=22, 
events=POLLIN}, {fd=24, events=POLLIN}], 10, 0) = 1 ([{fd=3, revents=POLLIN}])
[pid  6097] read(3, "\t\0\0\0\0\0\0\0", 16) = 8
[pid  6097] recvfrom(7, 0x2469ca4, 4096, 0, 0, 0) = -1 EAGAIN (Resource 
temporarily unavailable)
[pid  6097] write(3, "\1\0\0\0\0\0\0\0", 8) = 8
[pid  6097] write(3, "\1\0\0\0\0\0\0\0", 8) = 8
[pid  6097] write(3, "\1\0\0\0\0\0\0\0", 8) = 8
[pid  6097] sendmsg(5, {msg_name(0)=NULL, 
msg_iov(2)=[{"l\1\1\1`\0\0\0\335\27\0\0\213\0\0\0\1\1o\0\v\0\0\0/jobtrac"..., 
160}, {"\20\0\0\0kmail2-542439653\0\0\0\0\7\0\0\0005484"..., 96}], 
msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 256
[pid  6097] sendmsg(5, {msg_name(0)=NULL, 
msg_iov(2)=[{"l\1\1\1`\0\0\0\336\27\0\0\213\0\0\0\1\1o\0\v\0\0\0/jobtrac"..., 
160}, {"\20\0\0\0kmail2-542439653\0\0\0\0\7\0\0\00053c5"..., 96}], 
msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 256
[pid  6097] sendmsg(5, {msg_name(0)=NULL, 
msg_iov(2)=[{"l\1\1\1\21\0\0\0\337\27\0\0\210\0\0\0\1\1o\0\v\0\0\0/jobtrac"..., 
152}, {"\7\0\0\000545e230\0\0\0\0\0\0", 17}], msg_controllen=0, msg_flags=0}, 
MSG_NOSIGNAL) = 169
[pid  6097] write(3, "\1\0\0\0\0\0\0\0", 8) = 8
[pid  6097] write(3, "\1\0\0\0\0\0\0\0", 8) = 8
[pid  6097] recvfrom(7, 0x2469ca4, 4096, 0, 0, 0) = -1 EAGAIN (Resource 
temporarily unavailable)
[pid  6097] poll([{fd=3, events=POLLIN}, {fd=8, events=POLLIN}, {fd=7, 
events=POLLIN}, {fd=9, events=POLLIN}, {fd=10, events=POLLIN}, {fd=5, 
events=POLLIN}, {fd=13, events=POLLIN}, {fd=15, events=POLLIN}, {fd=22, 
events=POLLIN}, {fd=24, events=POLLIN}, {fd=10, events=POLLOUT}], 11, 0) = 2 
([{fd=3, revents=POLLIN}, {fd=10, revents=POLLOUT}])
[pid  6097] read(3, "\5\0\0\0\0\0\0\0", 16) = 8
[pid  6097] recvfrom(7, 0x2469ca4, 4096, 0, 0, 0) = -1 EAGAIN (Resource 
temporarily unavailable)
[pid  6097] sendmsg(5, {msg_name(0)=NULL, 
msg_iov(2)=[{"l\1\1\1\f\0\0\0\340\27\0\0\207\0\0\0\1\1o\0\v\0\0\0/jobtrac"..., 
152}, {"\7\0\0\000545e110\0", 12}], msg_controllen=0, msg_flags=0}, 
MSG_NOSIGNAL) = 164
[pid  6097] poll([{fd=7, events=POLLIN|POLLOUT}], 1, 4294967295) = 1 ([{fd=7, 
revents=POLLOUT}])
[pid  6097] writev(7, [{"+\3\1\0", 4}, {NULL, 0}, {"", 0}], 3) = 4
[pid  6097] poll([{fd=7, events=POLLIN}], 1, 4294967295) = 1 ([{fd=7, 
revents=POLLIN}])
[pid  6097] recvfrom(7, 
"\1\1IK\0\0\0\0\32\0\0\5\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 4096, 0, 
NULL, NULL) = 32
[pid  6097] recvfrom(7, 0x2469ca4, 4096, 0, 0, 0) = -1 EAGAIN (Resource 
temporarily unavailable)
[pid  6097] poll([{fd=7, events=POLLIN|POLLOUT}], 1, 4294967295) = 1 ([{fd=7, 
revents=POLLOUT}])
[pid  6097] writev(7, [{"&\3\2\0\241\0\0\0", 8}, {NULL, 0}, {"", 0}], 3) = 8
[pid  6097] poll([{fd=7, events=POLLIN}], 1, 4294967295) = 1 ([{fd=7, 
revents=POLLIN}])
[pid  6097] recvfrom(7, 
"\1\1JK\0\0\0\0\241\0\0\0h\3\300\1\374\0\256\3\374\0\256\3\4\0\0\0\0\0\0\0", 
4096, 0, NULL, NULL) = 32
[pid  6097] recvfrom(7, 0x2469ca4, 4096, 0, 0, 0) = -1 EAGAIN (Resource 
temporarily unavailable)
[pid  6097] recvfrom(7, 0x2469ca4, 4096, 0, 0, 0) = -1 EAGAIN (Resource 
temporarily unavailable)
[pid  6097] poll([{fd=7, events=POLLIN|POLLOUT}], 1, 4294967295) = 1 ([{fd=7, 
revents=POLLOUT}])
[pid  6097] writev(7, [{"(\3\4\0\241\0\0\0U\0\340\6\374\0\256\3", 16}, {NULL, 
0}, {"", 0}], 3) = 16
[pid  6097] poll([{fd=7, events=POLLIN}], 1, 4294967295) = 1 ([{fd=7, 
revents=POLLIN}])
[pid  6097] recvfrom(7, 
"\1\1KK\0\0\0\0\0\0\0\0\374\0O\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 4096, 0, 
NULL, NULL) = 32
[pid  6097] recvfrom(7, 0x2469ca4, 4096, 0, 0, 0) = -1 EAGAIN (Resource 
temporarily unavailable)
[pid  6097] recvfrom(7, 0x2469ca4, 4096, 0, 0, 0) = -1 EAGAIN (Resource 
temporarily unavailable)
[pid  6097] write(3, "\1\0\0\0\0\0\0\0", 8) = 8

So basically KMail seems to be polling something endlessly.


Whats going on there?

Its 1, in words: one, mail I try to access in kmail.


While this activity happens I can still change folders and get updates mail 
lists quickly, it is just accessing the mail contents that is so slow that 
KMail is currently unusable for me and I am considering downgrading to 4.10 
again.


According to akonadiconsole Akonadi is basically idling during that time which 
is basically a lie above atop CPU usage information above.


I used up 10 minutes or so in writing this mail and I still get: 

  PID SYSCPU USRCPU  VGROW  RGROW  RDDSK  WRDSK ST EXC S  CPU CMD        1/3
 3949  1.45s  3.44s     0K     0K     4K   480K --   - S  50% mysqld
 3946  1.31s  2.65s     0K     0K     0K     0K --   - S  40% akonadiserver
 6450  0.21s  3.60s   296K   252K     0K     0K --   - S  39% kmail


Ciao,
-- 
Martin 'Helios' Steigerwald - http://www.Lichtvoll.de
GPG: 03B0 0D6C 0040 0710 4AFA  B82F 991B EAAC A599 84C7
_______________________________________________
KDE PIM users mailing list
Subscription management: https://mail.kde.org/mailman/listinfo/kdepim-users