Slow reading of large dovecot-uidlist files

Tue Apr 12 13:31:10 UTC 2016

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.

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