Slow reading of large dovecot-uidlist files

Wed Apr 13 05:03:22 UTC 2016

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On Tue, 12 Apr 2016, Bostjan Skufca wrote:
> On 12 April 2016 at 14:04, Steffen Kaiser <skdovecot at 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
>> 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.
>
>
> 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.

The SELECT starts 13:07:35.305074 and ends 13:07:35.555618, that's 0.25 
seconds.

>
> 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 at 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,
>

- -- 
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-----