Slow reading of large dovecot-uidlist files
Hi there,
(context: I was optimizing Roundcube mailbox list server response, and in that 300-400ms response time, around 170ms is spent on single fgets() call which is waiting IMAP repsonse to "SELECT MyMailbox" command)
I straced dovecot and of the whole request/response process, around 30ms is spent for everything else, and overwhelming majority of time (150-170ms) is spent for reading dovecot-uidlist file for given mailbox.
I skimmed over src/lib-storage/index/maildir/maildir-uidlist.c and src/src/lib/istream.c, but I am out of ideas on how to optimize mentioned file reading elegantly to make it faster.
Is there any way to cache parsed content of uidlist file(s) or some other obvious quicktrick I am missing to speed this process up?
Does anyone have any other ideas, how to speed this up?
b.
It will be nice if the "SELECT MyMailbox" command will be "SELECT mymailbox LIMIT 100" or something, to get the first files since only the last messages are shown to the user. I don't know if "Limit" clause is available over IMAP.
On 04/09/2016 09:04 PM, Bostjan Skufca wrote:
-- Best regards, Adrian Minta
I tested this by timestamping tcpdump output while issuing this command directly to dovecot (limit 100 works, but does nothing) and there is no difference, it keeps taking ~160ms to respond.
b.
On 10 April 2016 at 10:27, Adrian Minta <adrian.minta@gmail.com> wrote:
On 04/10/2016 10:27 AM, Adrian Minta wrote:
SELECTing a mailbox has nothing to do with FETCHing messages, so above does not make much sense. I don't know dovecot's code, but I suppose it uses uidlist file to get mailbox statistics that it returns as EXISTS, RECENT, UNSEEN, UIDNEXT, UIDVALIDITY, etc, which are required by IMAP standard. I don't know, maybe they could be stored in more optimized way, but I think in most cases this data is also needed for SORT/THREAD/FETCH which is sent after SELECT in many cases - so it will be needed anyway. There are cases (e.g. mailbox synchronization) when you indeed do only SELECT. -- Aleksander 'A.L.E.C' Machniak Kolab Groupware Developer [http://kolab.org] Roundcube Webmail Developer [http://roundcube.net] --------------------------------------------------- PGP: 19359DC1 @@ GG: 2275252 @@ WWW: http://alec.pl
On 12 April 2016 at 10:23, A.L.E.C <alec@alec.pl> wrote:
(Oh, Alec, hi :) Can someone (who is more intimate with Dovecot's internals) comment on what dovecot is actually doing, where this time is being spent? That would be awesome:) My uidfile is 4MB "large" and reading it takes about 3ms on my system, so there is still ~160ms (98%) of dovecot's delay that is unaccounted for. BTW: I would have thought that the whole process goes like this: - user logs in, dovecot imap process starts - "SELECT MyMailbox" is issued for the first time - dovecot reads uidlist file for that mailbox and caches it along with timestamp metadata - on subsequent requests, uidlist file is stat-ed to detect any changes (changed by i.e. another process that handles same user's connection, from another device) and trigger rereading when needed, otherwise cache is used - I would imagine having certain (fairly low) TTL on the cache to prevent too much memory consumption would be nice, too. Would that make sense? (I am just trying to figure out the way how to optimize response time to SELECT and thus make rendering mailbox listing in Roundcube faster, or, better, acceptable.) Best, b.
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 On Tue, 12 Apr 2016, Bostjan Skufca wrote:
You could try to trace Dovecot and see if there are a lot of syscalls when a new connection starts up, e.g. with strace or dtruss.
does your mailboxes change without Dovecot? Do you have some script or something like that that causes the mtime of the directory change? If Dovecot thinks an external program changed the mailbox, it validates all messages in cache and from store.
- -- Steffen Kaiser -----BEGIN PGP SIGNATURE----- Version: GnuPG v1 iQEVAwUBVwzkWnz1H7kL/d9rAQLxzgf/VYvyXO2AhhpMO96EWHekgUZAFx8f+Wn+ UKJcVcbRVUvabo+8CDHyqClLbBugGDJfYDVMTOLplIJ3ZrExRqbh3sENmoRYnk8q nlWoKuwoskUYYM30Ax9yYuVxDzhGOdrI7TDrojsnJgyV1w8u8jMW6iCi1ziYvcIc u34DvOBLL16biP/rqziCouTbOZcsy9wL/T7RgBE/27ph651I7A8kQ3udfKWMW0gn +EIaDWquVnHmgozP93Ln0TpN5tMi9GW50zNmT8tWUnr07aYc3E5vaS3uYLvwxVx9 P5WIVgEObF4+BrZVCFfVRpkp51hxngk2k70RdmjgzD1dOSGGLELZkw== =j6AD -----END PGP SIGNATURE-----
On 12 April 2016 at 14:04, Steffen Kaiser <skdovecot@smail.inf.fh-brs.de> wrote:
You could try to trace Dovecot and see if there are a lot of syscalls when a new connection starts up, e.g. with strace or dtruss.
Not that many, if I exclude reading the uidlist file contents. See the trace below.
does your mailboxes change without Dovecot? Do you have some script or
Are you talking about main directory of mailbox, where /cur, /new etc reside? Nothing external touches it, we migrated postfix LDA to dovecot LDA for this very reason.
What I observed now: dovecot creates a dovecot-uidlist.lock file on average once every minute. The reason is Roundcube's minutely refresh configuration. However, even with that disabled and dir mtime not updated, if I issue SELECT, it rereads uidlist file entirely. I can see in strace there is no .lock file manipulation and no change in dir mtime.
b.
strace output:
{{EPOLLIN, {u32=22457424, u64=22457424}}}, 5, 1780008) = 1 13:07:35.305074 read(7, "A0002 SELECT Gmail\r\n", 5336) = 20 13:07:35.305180 stat("/var/mail/virtual/ stage.mail.teon.si/bostjan/.Gmail/tmp", {st_mode=S_IFDIR|0700, st_size=4096, ...}) = 0 13:07:35.305261 stat("/var/mail/virtual/stage.mail.teon.si/bostjan/.Gmail", {st_mode=S_IFDIR|0700, st_size=4096, ...}) = 0 13:07:35.305305 stat("/var/mail/virtual/stage.mail.teon.si/bostjan/.Gmail", {st_mode=S_IFDIR|0700, st_size=4096, ...}) = 0 13:07:35.305343 open("/var/mail/virtual/ stage.mail.teon.si/bostjan/.Gmail/dovecot.index.log", O_RDWR|O_APPEND) = 13 13:07:35.305379 fstat(13, {st_mode=S_IFREG|0600, st_size=14264, ...}) = 0 13:07:35.305409 pread(13, "\1\2(\0\330\22\0W\\\0\0\0[\0\0\0(\251\1\0\314\270\1Wp\22\1\0\0\0\0\0"..., 40, 0) = 40 13:07:35.305445 open("/var/mail/virtual/ stage.mail.teon.si/bostjan/.Gmail/dovecot.index", O_RDWR) = 14 13:07:35.305476 fstat(14, {st_mode=S_IFREG|0600, st_size=1686936, ...}) = 0 13:07:35.305507 mmap(NULL, 1686936, PROT_READ|PROT_WRITE, MAP_PRIVATE, 14, 0) = 0x7f9540451000 13:07:35.305562 fstat(13, {st_mode=S_IFREG|0600, st_size=14264, ...}) = 0 13:07:35.305596 pread(13, "\200\200\200\205\4\0\0\0\204\22\1\0\204\22\1\0\10\0\0\0\200\200\200\203\0\0\10\20X\0\0\0"..., 8192, 10284) = 3980 13:07:35.305626 pread(13, "", 8192, 14264) = 0 13:07:35.305657 fstat(13, {st_mode=S_IFREG|0600, st_size=14264, ...}) = 0 13:07:35.305684 mmap(NULL, 14264, PROT_READ, MAP_SHARED, 13, 0) = 0x7f95405fc000 13:07:35.305712 madvise(0x7f95405fc000, 14264, MADV_SEQUENTIAL) = 0 13:07:35.305738 fstat(13, {st_mode=S_IFREG|0600, st_size=14264, ...}) = 0 13:07:35.306249 munmap(0x7f9540451000, 1686936) = 0 13:07:35.306387 stat("/var/mail/virtual/ stage.mail.teon.si/bostjan/.Gmail/new", {st_mode=S_IFDIR|0700, st_size=4096, ...}) = 0 13:07:35.306429 stat("/var/mail/virtual/ stage.mail.teon.si/bostjan/.Gmail/cur", {st_mode=S_IFDIR|0700, st_size=6311936, ...}) = 0 13:07:35.306482 umask(0177) = 077 13:07:35.306512 lstat("/var/mail/virtual/ stage.mail.teon.si/bostjan/.Gmail/dovecot-uidlist.lock", 0x7ffea1ef7bd0) = -1 ENOENT (No such file or directory) 13:07:35.306553 open("/var/mail/virtual/ stage.mail.teon.si/bostjan/.Gmail/dovecot-uidlist.lock", O_RDWR|O_CREAT|O_EXCL, 0666) = 15 13:07:35.306618 write(15, "9815:labrat-1", 13) = 13 13:07:35.306662 fstat(15, {st_mode=S_IFREG|0600, st_size=13, ...}) = 0 13:07:35.306690 close(15) = 0 13:07:35.306716 lstat("/var/mail/virtual/ stage.mail.teon.si/bostjan/.Gmail/dovecot-uidlist.lock", {st_mode=S_IFREG|0600, st_size=13, ...}) = 0 13:07:35.306747 umask(077) = 0177 13:07:35.306772 open("/var/mail/virtual/ stage.mail.teon.si/bostjan/.Gmail/dovecot-uidlist", O_RDWR) = 15 13:07:35.306802 lseek(15, 0, SEEK_SET) = 0 13:07:35.306827 fstat(15, {st_mode=S_IFREG|0600, st_size=3875867, ...}) = 0 13:07:35.306856 brk(0x1bec000) = 0x1bec000 13:07:35.306918 fstat(15, {st_mode=S_IFREG|0600, st_size=3875867, ...}) = 0 13:07:35.306955 pread(15, "3 V1459433542 N1 G8cfaa815851200"..., 8192, 0) = 8192 13:07:35.307183 pread(15, "-1,S=14182,W=14669\n156 :14596233"..., 8156, 8192) = 8156 13:07:35.307404 pread(15, "89.M700263P26773.labrat-1,S=805,"..., 8179, 16348) = 8179 13:07:35.307621 pread(15, "4.M540099P26773.labrat-1,S=11962"..., 8178, 24527) = 8178 13:07:35.307840 pread(15, "W=4891\n612 :1459624371.M994429P2"..., 8146, 32705) = 8146 13:07:35.308056 pread(15, "73.labrat-1,S=15387,W=15911\n764 "..., 8165, 40851) = 8165 ... ... ... 13:07:35.537511 pread(15, "3283P31774.labrat-1,S=9466,W=968"..., 8171, 3837511) = 8171 13:07:35.537878 pread(15, "52\n69737 :1459730261.M163039P317"..., 8140, 3845682) = 8140 13:07:35.538242 pread(15, "774.labrat-1,S=1394,W=1431\n69883"..., 8164, 3853822) = 8164 13:07:35.538607 pread(15, "rat-1,S=12084,W=12326\n70030 :145"..., 8157, 3861986) = 8157 13:07:35.538962 pread(15, "2882,W=2928\n70176 :1459730412.M3"..., 8149, 3870143) = 5724 13:07:35.539232 pread(15, "", 2425, 3875867) = 0 13:07:35.540551 stat("/var/mail/virtual/ stage.mail.teon.si/bostjan/.Gmail/dovecot.index.log.2", 0x7ffea1ef7dd0) = -1 ENOENT (No such file or directory) 13:07:35.540712 alarm(180) = 0 13:07:35.540778 fcntl(13, F_SETLKW, {type=F_WRLCK, whence=SEEK_SET, start=0, len=0}) = 0 13:07:35.540856 alarm(0) = 180 13:07:35.540929 stat("/var/mail/virtual/ stage.mail.teon.si/bostjan/.Gmail/dovecot.index.log", {st_mode=S_IFREG|0600, st_size=14264, ...}) = 0 13:07:35.541015 fstat(13, {st_mode=S_IFREG|0600, st_size=14264, ...}) = 0 13:07:35.541127 access("/var/mail/virtual/ stage.mail.teon.si/bostjan/.Gmail/cur", W_OK) = 0 13:07:35.553975 stat("/var/mail/virtual/ stage.mail.teon.si/bostjan/.Gmail/cur", {st_mode=S_IFDIR|0700, st_size=6311936, ...}) = 0 13:07:35.554155 fcntl(13, F_SETLK, {type=F_UNLCK, whence=SEEK_SET, start=0, len=0}) = 0 13:07:35.554906 lstat("/var/mail/virtual/ stage.mail.teon.si/bostjan/.Gmail/dovecot-uidlist.lock", {st_mode=S_IFREG|0600, st_size=13, ...}) = 0 13:07:35.555088 unlink("/var/mail/virtual/ stage.mail.teon.si/bostjan/.Gmail/dovecot-uidlist.lock") = 0 13:07:35.555238 stat("/var/mail/virtual/ stage.mail.teon.si/bostjan/.Gmail/dovecot.index.log", {st_mode=S_IFREG|0600, st_size=14264, ...}) = 0 13:07:35.555321 fstat(13, {st_mode=S_IFREG|0600, st_size=14264, ...}) = 0 13:07:35.555396 fstat(13, {st_mode=S_IFREG|0600, st_size=14264, ...}) = 0 13:07:35.555455 stat("/var/mail/virtual/ stage.mail.teon.si/bostjan/dovecot.list.index.log", {st_mode=S_IFREG|0600, st_size=2916, ...}) = 0 13:07:35.555495 fstat(4, {st_mode=S_IFREG|0600, st_size=2916, ...}) = 0 13:07:35.555585 setsockopt(7, SOL_TCP, TCP_CORK, [1], 4) = 0 13:07:35.555618 write(7, "* FLAGS (\\Answered \\Flagged \\Del"..., 382) = 382 13:07:35.555656 setsockopt(7, SOL_TCP, TCP_CORK, [0], 4) = 0 13:07:35.555774 epoll_wait(12, {{EPOLLIN, {u32=22457424, u64=22457424}}}, 5, 1800000) = 1 13:07:35.556355 read(7, "A0003 UID SEARCH 70231\r\n", 5316) = 24 13:07:35.556499 stat("/var/mail/virtual/ stage.mail.teon.si/bostjan/dovecot.list.index.log", {st_mode=S_IFREG|0600, st_size=2916, ...}) = 0 13:07:35.556543 fstat(4, {st_mode=S_IFREG|0600, st_size=2916, ...}) = 0 13:07:35.556603 stat("/var/mail/virtual/ stage.mail.teon.si/bostjan/.Gmail/dovecot.index.log", {st_mode=S_IFREG|0600, st_size=14264, ...}) = 0 13:07:35.556641 fstat(13, {st_mode=S_IFREG|0600, st_size=14264, ...}) = 0 13:07:35.556676 fstat(13, {st_mode=S_IFREG|0600, st_size=14264, ...}) = 0 13:07:35.556734 stat("/var/mail/virtual/ stage.mail.teon.si/bostjan/dovecot.list.index.log", {st_mode=S_IFREG|0600, st_size=2916, ...}) = 0 13:07:35.556771 fstat(4, {st_mode=S_IFREG|0600, st_size=2916, ...}) = 0 13:07:35.556819 stat("/var/mail/virtual/ stage.mail.teon.si/bostjan/.Gmail/dovecot.index.log", {st_mode=S_IFREG|0600, st_size=14264, ...}) = 0 13:07:35.556855 fstat(13, {st_mode=S_IFREG|0600, st_size=14264, ...}) = 0 13:07:35.556889 fstat(13, {st_mode=S_IFREG|0600, st_size=14264, ...}) = 0 13:07:35.556944 setsockopt(7, SOL_TCP, TCP_CORK, [1], 4) = 0 13:07:35.556976 write(7, "* SEARCH 70278\r\nA0003 OK Search "..., 65) = 65 13:07:35.557011 setsockopt(7, SOL_TCP, TCP_CORK, [0], 4) = 0 13:07:35.557061 epoll_wait(12, {{EPOLLIN, {u32=22457424, u64=22457424}}}, 5, 1799999) = 1 13:07:35.576027 read(7, "A0004 STATUS Gmail (MESSAGES UNS"..., 5292) = 38 13:07:35.576142 setsockopt(7, SOL_TCP, TCP_CORK, [1], 4) = 0 13:07:35.576185 write(7, "* STATUS Gmail (MESSAGES 70231 U"..., 125) = 125 13:07:35.576225 setsockopt(7, SOL_TCP, TCP_CORK, [0], 4) = 0 13:07:35.576299 epoll_wait(12, {{EPOLLIN, {u32=22457424, u64=22457424}}}, 5, 1800000) = 1 13:07:35.612494 read(7, "A0005 GETQUOTAROOT Gmail\r\n", 5254) = 26 13:07:35.612654 socket(PF_LOCAL, SOCK_STREAM, 0) = 16 13:07:35.612741 fcntl(16, F_GETFL) = 0x2 (flags O_RDWR) 13:07:35.612817 fcntl(16, F_SETFL, O_RDWR|O_NONBLOCK) = 0 13:07:35.612888 connect(16, {sa_family=AF_LOCAL, sun_path="/var/run/dovecot/dict"}, 110) = 0 13:07:35.612959 fcntl(16, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK) 13:07:35.612994 fcntl(16, F_SETFL, O_RDWR) = 0 13:07:35.613028 fstat(16, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0 13:07:35.613068 lseek(16, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek) 13:07:35.613149 getsockname(16, {sa_family=AF_LOCAL, NULL}, [2]) = 0 13:07:35.613229 write(16, "H2\t0\t0\tbostjan@stage.mail.teon.s"..., 40) = 40 13:07:35.613285 write(16, "Lpriv/quota/storage\n", 20) = 20 13:07:35.613337 alarm(30) = 0 13:07:35.613389 read(16, "O2960032661\n", 8192) = 12 13:07:35.621249 alarm(0) = 30 13:07:35.621330 write(16, "Lpriv/quota/messages\n", 21) = 21 13:07:35.621392 alarm(30) = 0 13:07:35.621431 read(16, "O70251\n", 8180) = 7 13:07:35.621508 alarm(0) = 30 13:07:35.621585 setsockopt(7, SOL_TCP, TCP_CORK, [1], 4) = 0 13:07:35.621640 write(7, "* QUOTAROOT Gmail \"User quota\"\r\n"..., 136) = 136 13:07:35.621694 setsockopt(7, SOL_TCP, TCP_CORK, [0], 4) = 0 13:07:35.621788 epoll_wait(12, {}, 5, 0) = 0 13:07:35.621830 close(16) = 0 13:07:35.621893 epoll_wait(12, {{EPOLLIN, {u32=22457424, u64=22457424}}}, 5, 1800000) = 1 13:07:35.626137 read(7, "C64 EXAMINE \"\"\r\n", 5228) = 16 13:07:35.626210 close(15) = 0 13:07:35.628537 brk(0x17ec000) = 0x17ec000 13:07:35.629407 setsockopt(7, SOL_TCP, TCP_CORK, [1], 4) = 0 13:07:35.629448 write(7, "* OK [CLOSED] Previous mailbox c"..., 115) = 115 13:07:35.629481 setsockopt(7, SOL_TCP, TCP_CORK, [0], 4) = 0 13:07:35.629560 epoll_wait(12,
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1
On Tue, 12 Apr 2016, Bostjan Skufca wrote:
The SELECT starts 13:07:35.305074 and ends 13:07:35.555618, that's 0.25 seconds.
Steffen Kaiser -----BEGIN PGP SIGNATURE----- Version: GnuPG v1
iQEVAwUBVw3TGnz1H7kL/d9rAQK1jgf/aYR+zFswuXsKn2Vm19J+r0ATI1e2x1bS ukv+evXN6FZHnDUAuR/Ay2GHVE76TBdcCkxWPVfBnbGgQ1DG/zV+6CWYts+O6b/4 D5TPhMILMhwokiFv1NjpgHDz+u8vV2+6Gv69/Qr5I1l0NhMYrx8f1qdk2QYlfND4 01aBomKPEkK2mNhVpoRTDp/jks27Ji3or2NbAW7HToEuB00FjVSSTkZACRGtwtty /qb648it3STSy4re+2Mej0lI6ByFkhSDgZnJE3dIt/3iZedON8ILJvpato74mmr4 Sx72Mic/pzr6mu+kaYv9EWwS71kSAoKVXH6tgCub7CKfCnZZR5FB6g== =3KMD -----END PGP SIGNATURE-----
participants (5)
-
A.L.E.C
-
Adrian Minta
-
Bostjan Skufca
-
Steffen Kaiser
-
Timo Sirainen