Bug 332684 - [Maildir] lots of stats calls to /etc/localtime on synchronizing folders
Summary: [Maildir] lots of stats calls to /etc/localtime on synchronizing folders
Status: REOPENED
Alias: None
Product: Akonadi
Classification: Frameworks and Libraries
Component: Maildir Resource (show other bugs)
Version: 5.2.3
Platform: Debian unstable Linux
: NOR normal
Target Milestone: ---
Assignee: kdepim bugs
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2014-03-27 13:37 UTC by Martin Steigerwald
Modified: 2017-01-08 12:30 UTC (History)
0 users

See Also:
Latest Commit:
Version Fixed In:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Martin Steigerwald 2014-03-27 13:37:55 UTC
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.
Comment 1 Martin Steigerwald 2014-03-27 13:42:10 UTC
akonadi maildir resource is CPU bound on one core (100%) for minutes during that case. KMail is blocked.
Comment 2 Martin Steigerwald 2014-05-02 11:23:24 UTC
I don´t know where that went to but Dan asked me whether setting TZ to something will get rid of the stat()´s on /etc/localtime. Yes it does. Still folder synchronisation is slow:

Bug 334218 - synchronizations of large folders with filesystem contents hogs a Sandybridge core for minutes stat()ing every file in it
Comment 3 Denis Kurz 2016-09-24 20:31:12 UTC
This bug has only been reported for versions older than KDEPIM 4.14 (at most akonadi-1.3). Can anyone tell if this bug still present?

If noone confirms this bug for a recent version of akonadi (part of KDE Applications 15.08 or later), it gets closed in about three months.
Comment 4 Denis Kurz 2017-01-07 22:04:03 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.
Comment 5 Martin Steigerwald 2017-01-08 12:30:59 UTC
This still is happening with KMail 5.2.3 (Debian unstable has no newer package unfortunately and currently I don´t self-compile KDEPIM).

How to reproduce?

1. Start KMail with TZ variable unset.
2. Trace it like this: strace -f -o strace-kmail-stat-localtime.txt -p 16925
3. Click between some (larger) folders.

# Actual Results

~> strace -f -o strace-kmail-stat-localtime.txt -p 16925
strace: Process 16925 attached with 22 threads

~> grep -c "stat(\"/etc/localtime" strace-kmail-stat-localtime.txt 
5496

in just a few seconds of KMail runtime.

# Expected results
Cache what KMail needs from /etc/localtime at least for a while to reduce the number of calls to that syscall.