Re: Slow reading of large dovecot-uidlist files

13 Apr 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@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@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-----