| Summary: | [Maildir] lots of stats calls to /etc/localtime on synchronizing folders | ||
|---|---|---|---|
| Product: | [Frameworks and Libraries] Akonadi | Reporter: | Martin Steigerwald <Martin> |
| Component: | Maildir Resource | Assignee: | kdepim bugs <kdepim-bugs> |
| Status: | REOPENED --- | ||
| Severity: | normal | ||
| Priority: | NOR | ||
| Version: | 5.2.3 | ||
| Target Milestone: | --- | ||
| Platform: | Debian unstable | ||
| OS: | Linux | ||
| Latest Commit: | Version Fixed In: | ||
| Sentry Crash Report: | |||
akonadi maildir resource is CPU bound on one core (100%) for minutes during that case. KMail is blocked. 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 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. 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. 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. |
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.