[Akonadi] [Bug 332684] New: [Maildir] lots of stats calls to /etc/localtime on synchronizing folders
Martin Steigerwald
Martin at Lichtvoll.de
Thu Mar 27 13:37:55 GMT 2014
https://bugs.kde.org/show_bug.cgi?id=332684
Bug ID: 332684
Summary: [Maildir] lots of stats calls to /etc/localtime on
synchronizing folders
Classification: Unclassified
Product: Akonadi
Version: 4.12
Platform: Debian unstable
OS: Linux
Status: UNCONFIRMED
Severity: normal
Priority: NOR
Component: Maildir Resource
Assignee: kdepim-bugs at kde.org
Reporter: Martin at Lichtvoll.de
I think I found a cause for slowness of KMail after downloading and filtern
mails when it synchronizes folders: For Maildir file it stats it does two stat
calls to /etc/localtime.
Reproducible: Always
Steps to Reproduce:
1. Have a large POP 3 account with some mailing list folders of several 10000
mails
2. Wait a while for lots of new mails to arrive
3. Download mails
4. Filter mails
Actual Results:
merkaba:~> ps aux | grep 10350 | grep -v grep
martin 10350 18.2 4.1 633212 329004 ? Rl 13:08 15:52
/usr/bin/akonadi_agent_launcher akonadi_maildir_resource
akonadi_maildir_resource_0
10350 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
10350 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
10350
stat("/home/martin/.local/share/local-mail/.Lichtvoll.directory/.Linux.directory/kernel-ml/new/1368623610.R679.merkaba",
{st_mode=S_IFREG|0644, st_size=9688, ...}) = 0
10350 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
10350 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
10350
stat("/home/martin/.local/share/local-mail/.Lichtvoll.directory/.Linux.directory/kernel-ml/new/1368623610.R724.merkaba",
{st_mode=S_IFREG|0644, st_size=3832, ...}) = 0
10350 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
10350 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
10350
stat("/home/martin/.local/share/local-mail/.Lichtvoll.directory/.Linux.directory/kernel-ml/new/1368623610.R818.merkaba",
{st_mode=S_IFREG|0644, st_size=2909, ...}) = 0
10350 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
10350 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
10350
stat("/home/martin/.local/share/local-mail/.Lichtvoll.directory/.Linux.directory/kernel-ml/new/1368623610.R90.merkaba",
{st_mode=S_IFREG|0644, st_size=2754, ...}) = 0
10350 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
10350 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
10350
stat("/home/martin/.local/share/local-mail/.Lichtvoll.directory/.Linux.directory/kernel-ml/new/1368623611.R182.merkaba",
{st_mode=S_IFREG|0644, st_size=2984, ...}) = 0
10350 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
10350 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
10350
stat("/home/martin/.local/share/local-mail/.Lichtvoll.directory/.Linux.directory/kernel-ml/new/1368623611.R187.merkaba:2,S",
{st_mode=S_IFREG|0644, st_size=4869, ...}) = 0
10350 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
10350 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
10350
stat("/home/martin/.local/share/local-mail/.Lichtvoll.directory/.Linux.directory/kernel-ml/new/1368623611.R297.merkaba",
{st_mode=S_IFREG|0644, st_size=3520, ...}) = 0
10350 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
10350 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
merkaba:~> grep -c "stat(" strace-bla.txt
108244
merkaba:~> grep -c "stat(\"/etc/localtime" strace-bla.txt
72058
>From a different period during maildir resource being busy with itself (not
possible to attach strace twice to the maildir resource):
merkaba:~> strace -c -f -p 10350
Process 10350 attached with 2 threads - interrupt to quit
10350^CProcess 10350 detached
Process 10391 detached
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
45.33 0.220536 457 483 getdents
39.64 0.192880 6 31360 stat
3.99 0.019400 6 2994 2883 recvmsg
3.08 0.014972 11 1394 51 read
2.38 0.011592 8 1392 poll
1.56 0.007571 11 663 write
1.12 0.005430 21 256 brk
1.10 0.005375 5 1123 ioctl
0.59 0.002865 17 164 sendmsg
0.49 0.002398 8 304 access
0.30 0.001443 722 2 rename
0.14 0.000682 85 8 open
0.08 0.000401 40 10 statfs
0.06 0.000280 140 2 2 lstat
0.05 0.000257 14 18 close
0.04 0.000192 19 10 openat
0.02 0.000107 7 15 fstat
0.01 0.000060 8 8 fcntl
0.01 0.000059 4 16 uname
0.00 0.000014 14 1 mmap
0.00 0.000014 14 1 munmap
------ ----------- ----------- --------- --------- ----------------
100.00 0.486528 40224 2936 total
Expected Results:
A sane amount of calls to stat("/etc/localtime"). This is the time zone
description and I won´t expect it to change every second :). So I think it
makes sense to cache the result of the call to it for a while.
That kernel-ml folder is a bit insane (220000) mails, but it will cause the
slow down for smaller folders as well.
I have the complete strace log available, but I´d first need to sanitize it for
private data. In anyway, this should be easy to reproduce.
--
You are receiving this mail because:
You are the assignee for the bug.
More information about the Kdepim-bugs
mailing list