thr3ads.net - dovecot - Slow reading of large dovecot-uidlist files [Apr 2016]

If this information is useful, please help other people find it:
Share via:

Steffen Kaiser

2016-Apr-12 12:04 UTC

Slow reading of large dovecot-uidlist files

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

On Tue, 12 Apr 2016, Bostjan Skufca wrote:> On 12 April 2016 at 10:23, A.L.E.C <alec at alec.pl> wrote:
>
>> 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.
>>
>
> (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.
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.
> 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
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.
> - 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.
>
>
>
>>
>> --
>> 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
>>
>
- -- 
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-----

Bostjan Skufca

2016-Apr-12 13:31 UTC

head link

Slow reading of large dovecot-uidlist files

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,

Steffen Kaiser

2016-Apr-13 05:03 UTC

head link

Slow reading of large dovecot-uidlist files

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

dovecot - Apr 2016 - Slow reading of large dovecot-uidlist files

Slow reading of large dovecot-uidlist files

Slow reading of large dovecot-uidlist files

Slow reading of large dovecot-uidlist files