dovecot - Sep 2013 - Dovecot extremely slow!

Please help,

Dovecot is running extremely slow for the last couple of weeks and it 
seems to be getting worse (or my patience running short).

I attach the 10-master configuration and the log file after running 
strace according to: http://wiki.dovecot.org/Debugging/ProcessTracing

I can click on an email and wait for a minute or more before receiving a 
connection dropped or no error at all.  I use many clients (thunderbird, 
windows 8 mail, maildroid for android, squirrelmail) and they all have 
similar behavior.  It happens both in the inbox and on imap subfolders. 
Sometimes it helps changing subfolders back and forth.

I have many imap folders organized in up to 3 levels of subfolders and 
use postfix for delivery.

Let me know any other info you require. Thanks!

      Patricio
-------------- next part --------------
#default_process_limit = 100
#default_client_limit = 1000

# Default VSZ (virtual memory size) limit for service processes. This is mainly
# intended to catch and kill processes that leak memory before they eat up
# everything.
#default_vsz_limit = 256M

# Login user is internally used by login processes. This is the most untrusted
# user in Dovecot system. It shouldn't have access to anything at all.
#default_login_user = dovenull

# Internal user is used by unprivileged processes. It should be separate from
# login user, so that login processes can't disturb other processes.
#default_internal_user = dovecot

service imap-login {
  inet_listener imap {
    #port = 143
  }
  inet_listener imaps {
    #port = 993
    #ssl = yes
  }

  # Number of connections to handle before starting a new process. Typically
  # the only useful values are 0 (unlimited) or 1. 1 is more secure, but 0
  # is faster. <doc/wiki/LoginProcess.txt>
  #service_count = 1

  # Number of processes to always keep waiting for more connections.
  #process_min_avail = 0

  # If you set service_count=0, you probably need to grow this.
  #vsz_limit = $default_vsz_limit
}

service pop3-login {
  inet_listener pop3 {
    #port = 110
  }
  inet_listener pop3s {
    #port = 995
    #ssl = yes
  }
}

service lmtp {
  unix_listener lmtp {
    #mode = 0666
  }

  # Create inet listener only if you can't use the above UNIX socket
  #inet_listener lmtp {
    # Avoid making LMTP visible for the entire internet
    #address     #port = 
  #}
}

service imap {
  # Most of the memory goes to mmap()ing files. You may need to increase this
  # limit if you have huge mailboxes.
  #vsz_limit = $default_vsz_limit

  # Max. number of IMAP processes (connections)
  #process_limit = 1024
}

service pop3 {
  # Max. number of POP3 processes (connections)
  #process_limit = 1024
}

service auth {
  # auth_socket_path points to this userdb socket by default. It's typically
  # used by dovecot-lda, doveadm, possibly imap process, etc. Users that have
  # full permissions to this socket are able to get a list of all usernames and
  # get the results of everyone's userdb lookups.
  #
  # The default 0666 mode allows anyone to connect to the socket, but the
  # userdb lookups will succeed only if the userdb returns an "uid"
field that
  # matches the caller process's UID. Also if caller's uid or gid
matches the
  # socket's uid or gid the lookup succeeds. Anything else causes a failure.
  #
  # To give the caller full permissions to lookup all users, set the mode to
  # something else than 0666 and Dovecot lets the kernel enforce the
  # permissions (e.g. 0777 allows everyone full permissions).
  unix_listener auth-userdb {
    #mode = 0666
    #user = 
    #group = 
  }

  # Postfix smtp-auth
  unix_listener /var/spool/postfix/private/auth {
    user = postfix
    group = postfix
    mode = 0666
  }
  inet_listener {
    port = 12345
  }


  # Auth process is run as this user.
  #user = $default_internal_user
}

service auth-worker {
  # Auth worker process is run as root by default, so that it can access
  # /etc/shadow. If this isn't necessary, the user should be changed to
  # $default_internal_user.
  #user = root
}

service dict {
  # If dict proxy is used, mail processes should have access to its socket.
  # For example: mode=0660, group=vmail and global mail_access_groups=vmail
  unix_listener dict {
    #mode = 0600
    #user = 
    #group = 
  }
}
-------------- next part --------------
18:29:13.833120 epoll_wait(9, {}, 6, 23980) = 0
18:29:37.837451 stat("/home/pato/mail/Astro/conferences",
{st_mode=S_IFREG|0644, st_size=112122083, ...}) = 0
18:29:37.838261 epoll_wait(9, {}, 6, 29999) = 0
18:30:07.867721 stat("/home/pato/mail/Astro/conferences",
{st_mode=S_IFREG|0644, st_size=112122083, ...}) = 0
18:30:07.868340 epoll_wait(9, {}, 6, 28917) = 0
18:30:36.814608 write(11, "* OK Still here\r\n", 17) = 17
18:30:36.832177 time(NULL)              = 1380144636
18:30:36.833279 epoll_wait(9, {{EPOLLIN, {u32=1413012688,
u64=139759648824528}}}, 6, 1034) = 1
18:30:37.065994 read(11, "DONE\r\n", 8030) = 6
18:30:37.066289 epoll_ctl(9, EPOLL_CTL_DEL, 11, {0, {u32=1413012688,
u64=139759648824528}}) = 0
18:30:37.066574 inotify_rm_watch(13, 2) = 0
18:30:37.066795 epoll_ctl(9, EPOLL_CTL_DEL, 13, {0, {u32=1413125552,
u64=139759648937392}}) = 0
18:30:37.067053 write(11, "8 OK Idle completed.\r\n", 22) = 22
18:30:37.067185 epoll_ctl(9, EPOLL_CTL_ADD, 11,
{EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP, {u32=1413012688, u64=139759648824528}}) = 0
18:30:37.067301 epoll_wait(9, {{EPOLLIN, {u32=1413012688,
u64=139759648824528}}}, 6, 1800000) = 1
18:30:37.291601 read(11, "9 noop\r\n", 8024) = 8
18:30:37.291914 stat("/home/pato/mail/Astro/conferences",
{st_mode=S_IFREG|0644, st_size=112122083, ...}) = 0
18:30:37.292250
stat("/home/pato/mail/Astro/.imap/conferences/dovecot.index.log",
{st_mode=S_IFREG|0644, st_size=11400, ...}) = 0
18:30:37.305654 fstat(10, {st_mode=S_IFREG|0644, st_size=11400, ...}) = 0
18:30:37.305786 fstat(10, {st_mode=S_IFREG|0644, st_size=11400, ...}) = 0
18:30:37.305964 alarm(180)              = 0
18:30:37.306051 fcntl(10, F_SETLKW, {type=F_WRLCK, whence=SEEK_SET, start=0,
len=0}) = 0
18:30:37.306458 alarm(0)                = 180
18:30:37.306555 time(NULL)              = 1380144637
18:30:37.306619
stat("/home/pato/mail/Astro/.imap/conferences/dovecot.index.log",
{st_mode=S_IFREG|0644, st_size=11400, ...}) = 0
18:30:37.306971 fstat(10, {st_mode=S_IFREG|0644, st_size=11400, ...}) = 0
18:30:37.307141 time(NULL)              = 1380144637
18:30:37.307226 fcntl(10, F_SETLK, {type=F_UNLCK, whence=SEEK_SET, start=0,
len=0}) = 0
18:30:37.307707 write(11, "9 OK NOOP completed.\r\n", 22) = 22
18:30:37.307986 epoll_wait(9, {{EPOLLIN, {u32=1413012688,
u64=139759648824528}}}, 6, 1800000) = 1
18:30:37.535951 read(11, "10 UID fetch 191:* (FLAGS)\r\n", 8016) = 28
18:30:37.536285
stat("/home/pato/mail/Astro/.imap/conferences/dovecot.index.log",
{st_mode=S_IFREG|0644, st_size=11400, ...}) = 0
18:30:37.536613 fstat(10, {st_mode=S_IFREG|0644, st_size=11400, ...}) = 0
18:30:37.536904 fstat(10, {st_mode=S_IFREG|0644, st_size=11400, ...}) = 0
18:30:37.537254 write(11, "* 189 FETCH (UID 190 FLAGS (\\See"..., 61)
= 61
18:30:37.537349 epoll_wait(9, {{EPOLLIN, {u32=1413012688,
u64=139759648824528}}}, 6, 1800000) = 1
18:30:37.763416 read(11, "11 IDLE\r\n", 7988) = 9
18:30:37.763715 time(NULL)              = 1380144637
18:30:37.763994 inotify_add_watch(13,
"/home/pato/mail/Astro/conferences",
IN_MODIFY|IN_CLOSE_WRITE|IN_CLOSE_NOWRITE|IN_MOVED_FROM|IN_MOVED_TO|IN_CREATE|IN_DELETE|IN_DELETE_SELF)
= 3
18:30:37.764617 epoll_ctl(9, EPOLL_CTL_ADD, 13,
{EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP, {u32=1413125552, u64=139759648937392}}) = 0
18:30:37.764825 stat("/home/pato/mail/Astro/conferences",
{st_mode=S_IFREG|0644, st_size=112122083, ...}) = 0
18:30:37.765039 epoll_ctl(9, EPOLL_CTL_DEL, 11, {0, {u32=1413012688,
u64=139759648824528}}) = 0
18:30:37.765160 epoll_ctl(9, EPOLL_CTL_ADD, 11,
{EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP, {u32=1413012688, u64=139759648824528}}) = 0
18:30:37.765233 stat("/home/pato/mail/Astro/conferences",
{st_mode=S_IFREG|0644, st_size=112122083, ...}) = 0
18:30:37.765337
stat("/home/pato/mail/Astro/.imap/conferences/dovecot.index.log",
{st_mode=S_IFREG|0644, st_size=11400, ...}) = 0
18:30:37.765430 fstat(10, {st_mode=S_IFREG|0644, st_size=11400, ...}) = 0
18:30:37.765502 fstat(10, {st_mode=S_IFREG|0644, st_size=11400, ...}) = 0
18:30:37.765588 alarm(180)              = 0
18:30:37.765643 fcntl(10, F_SETLKW, {type=F_WRLCK, whence=SEEK_SET, start=0,
len=0}) = 0
18:30:37.765983 alarm(0)                = 180
18:30:37.766041 time(NULL)              = 1380144637
18:30:37.766092
stat("/home/pato/mail/Astro/.imap/conferences/dovecot.index.log",
{st_mode=S_IFREG|0644, st_size=11400, ...}) = 0
18:30:37.766367 fstat(10, {st_mode=S_IFREG|0644, st_size=11400, ...}) = 0
18:30:37.766466 time(NULL)              = 1380144637
18:30:37.766518 fcntl(10, F_SETLK, {type=F_UNLCK, whence=SEEK_SET, start=0,
len=0}) = 0
18:30:37.766923 write(11, "+ idling\r\n", 10) = 10
18:30:37.767054 epoll_wait(9, {{EPOLLIN, {u32=1413125552,
u64=139759648937392}}}, 6, 29998) = 1
18:30:37.767136 read(13, "\2\0\0\0\0\200\0\0\0\0\0\0\0\0\0\0", 32768)
= 16
18:30:37.767211 epoll_wait(9, {}, 6, 29998) = 0
18:31:07.794079 stat("/home/pato/mail/Astro/conferences",
{st_mode=S_IFREG|0644, st_size=112122083, ...}) = 0
18:31:07.794611 epoll_wait(9, {}, 6, 30000) = 0
18:31:37.821166 stat("/home/pato/mail/Astro/conferences",
{st_mode=S_IFREG|0644, st_size=112122083, ...}) = 0
18:31:37.821778 epoll_wait(9, {}, 6, 30000) = 0
18:32:07.852108 stat("/home/pato/mail/Astro/conferences",
{st_mode=S_IFREG|0644, st_size=112122083, ...}) = 0
18:32:07.852770 epoll_wait(9, {}, 6, 28911) = 0
18:32:36.793076 write(11, "* OK Still here\r\n", 17) = 17
18:32:36.793376 time(NULL)              = 1380144756
18:32:36.793646 epoll_wait(9, {{EPOLLIN, {u32=1413012688,
u64=139759648824528}}}, 6, 1059) = 1
18:32:37.029815 read(11, "DONE\r\n", 7979) = 6
18:32:37.030105 epoll_ctl(9, EPOLL_CTL_DEL, 11, {0, {u32=1413012688,
u64=139759648824528}}) = 0
18:32:37.030390 inotify_rm_watch(13, 3) = 0
18:32:37.030676 epoll_ctl(9, EPOLL_CTL_DEL, 13, {0, {u32=1413125552,
u64=139759648937392}}) = 0
18:32:37.030874 write(11, "11 OK Idle completed.\r\n", 23) = 23
18:32:37.030977 epoll_ctl(9, EPOLL_CTL_ADD, 11,
{EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP, {u32=1413012688, u64=139759648824528}}) = 0
18:32:37.031101 epoll_wait(9, {{EPOLLIN, {u32=1413012688,
u64=139759648824528}}}, 6, 1799999) = 1
18:32:37.280529 read(11, "12 noop\r\n", 7973) = 9
18:32:37.280754 stat("/home/pato/mail/Astro/conferences",
{st_mode=S_IFREG|0644, st_size=112122083, ...}) = 0
18:32:37.281073
stat("/home/pato/mail/Astro/.imap/conferences/dovecot.index.log",
{st_mode=S_IFREG|0644, st_size=11400, ...}) = 0
18:32:37.281914 fstat(10, {st_mode=S_IFREG|0644, st_size=11400, ...}) = 0
18:32:37.282202 fstat(10, {st_mode=S_IFREG|0644, st_size=11400, ...}) = 0
18:32:37.282417 alarm(180)              = 0
18:32:37.282503 fcntl(10, F_SETLKW, {type=F_WRLCK, whence=SEEK_SET, start=0,
len=0}) = 0
18:32:37.282815 alarm(0)                = 180
18:32:37.282867 time(NULL)              = 1380144757
18:32:37.282917
stat("/home/pato/mail/Astro/.imap/conferences/dovecot.index.log",
{st_mode=S_IFREG|0644, st_size=11400, ...}) = 0
18:32:37.283174 fstat(10, {st_mode=S_IFREG|0644, st_size=11400, ...}) = 0
18:32:37.283272 time(NULL)              = 1380144757
18:32:37.283321 fcntl(10, F_SETLK, {type=F_UNLCK, whence=SEEK_SET, start=0,
len=0}) = 0
18:32:37.283760 write(11, "12 OK NOOP completed.\r\n", 23) = 23
18:32:37.283886 epoll_wait(9, {{EPOLLIN, {u32=1413012688,
u64=139759648824528}}}, 6, 1800000) = 1
18:32:37.508552 read(11, "13 UID fetch 191:* (FLAGS)\r\n", 7964) = 28
18:32:37.508868
stat("/home/pato/mail/Astro/.imap/conferences/dovecot.index.log",
{st_mode=S_IFREG|0644, st_size=11400, ...}) = 0
18:32:37.509183 fstat(10, {st_mode=S_IFREG|0644, st_size=11400, ...}) = 0
18:32:37.509412 fstat(10, {st_mode=S_IFREG|0644, st_size=11400, ...}) = 0
18:32:37.509645 write(11, "* 189 FETCH (UID 190 FLAGS (\\See"..., 61)
= 61
18:32:37.509719 epoll_wait(9, {{EPOLLIN, {u32=1413012688,
u64=139759648824528}}}, 6, 1800000) = 1
18:32:37.735149 read(11, "14 IDLE\r\n", 7936) = 9
18:32:37.735437 time(NULL)              = 1380144757
18:32:37.735713 inotify_add_watch(13,
"/home/pato/mail/Astro/conferences",
IN_MODIFY|IN_CLOSE_WRITE|IN_CLOSE_NOWRITE|IN_MOVED_FROM|IN_MOVED_TO|IN_CREATE|IN_DELETE|IN_DELETE_SELF)
= 4
18:32:37.736237 epoll_ctl(9, EPOLL_CTL_ADD, 13,
{EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP, {u32=1413125552, u64=139759648937392}}) = 0
18:32:37.736487 stat("/home/pato/mail/Astro/conferences",
{st_mode=S_IFREG|0644, st_size=112122083, ...}) = 0
18:32:37.736719 epoll_ctl(9, EPOLL_CTL_DEL, 11, {0, {u32=1413012688,
u64=139759648824528}}) = 0
18:32:37.736845 epoll_ctl(9, EPOLL_CTL_ADD, 11,
{EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP, {u32=1413012688, u64=139759648824528}}) = 0
18:32:37.736965 stat("/home/pato/mail/Astro/conferences",
{st_mode=S_IFREG|0644, st_size=112122083, ...}) = 0
18:32:37.737068
stat("/home/pato/mail/Astro/.imap/conferences/dovecot.index.log",
{st_mode=S_IFREG|0644, st_size=11400, ...}) = 0
18:32:37.737159 fstat(10, {st_mode=S_IFREG|0644, st_size=11400, ...}) = 0
18:32:37.737229 fstat(10, {st_mode=S_IFREG|0644, st_size=11400, ...}) = 0
18:32:37.737313 alarm(180)              = 0
18:32:37.737365 fcntl(10, F_SETLKW, {type=F_WRLCK, whence=SEEK_SET, start=0,
len=0}) = 0
18:32:37.737693 alarm(0)                = 180
18:32:37.737748 time(NULL)              = 1380144757
18:32:37.737802
stat("/home/pato/mail/Astro/.imap/conferences/dovecot.index.log",
{st_mode=S_IFREG|0644, st_size=11400, ...}) = 0
18:32:37.738075 fstat(10, {st_mode=S_IFREG|0644, st_size=11400, ...}) = 0
18:32:37.738173 time(NULL)              = 1380144757
18:32:37.738224 fcntl(10, F_SETLK, {type=F_UNLCK, whence=SEEK_SET, start=0,
len=0}) = 0
18:32:37.738653 write(11, "+ idling\r\n", 10) = 10
18:32:37.738784 epoll_wait(9, {{EPOLLIN, {u32=1413125552,
u64=139759648937392}}}, 6, 29998) = 1
18:32:37.738867 read(13, "\3\0\0\0\0\200\0\0\0\0\0\0\0\0\0\0", 32768)
= 16
18:32:37.738962 epoll_wait(9, {}, 6, 29998) = 0
18:33:07.767247 stat("/home/pato/mail/Astro/conferences",
{st_mode=S_IFREG|0644, st_size=112122083, ...}) = 0
18:33:07.767582 epoll_wait(9, {}, 6, 30000) = 0
18:33:37.797914 stat("/home/pato/mail/Astro/conferences",
{st_mode=S_IFREG|0644, st_size=112122083, ...}) = 0
18:33:37.798562 epoll_wait(9, {}, 6, 29999) = 0
18:34:07.827911 stat("/home/pato/mail/Astro/conferences",
{st_mode=S_IFREG|0644, st_size=112122083, ...}) = 0
18:34:07.828547 epoll_wait(9,  <unfinished ...>

On 25 Sep 2013, at 16:05 , Patricio Rojo <pato at oan.cl> wrote:
> I attach the 10-master configuration 
That?s not that useful.

doveconf -n is useful

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

On Wed, 25 Sep 2013, Patricio Rojo wrote:
> I can click on an email and wait for a minute or more before receiving a 
> connection dropped or no error at all.  I use many clients (thunderbird, 
> windows 8 mail, maildroid for android, squirrelmail) and they all have 
> similar behavior.  It happens both in the inbox and on imap subfolders. 
> Sometimes it helps changing subfolders back and forth.
>
> I have many imap folders organized in up to 3 levels of subfolders and use 
> postfix for delivery.
What about I/O load on the server? Something in kernel log? Do you use 
FTS? Do you get many messages at once?

Then, as Lukreme and Bob already said, provide doveconf -n and check out 
Dovecot logs, for "Error" and "Warning".

- -- 
Steffen Kaiser
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.11 (GNU/Linux)

iQEVAwUBUkP1Ol3r2wJMiz2NAQJ+ewf/ZcGWyYnAx50iZZ8/jkO9c9BU5WmRmMA3
AaBx8fM8IrSXnWtCUY+WcaIvn2wl9MnCFQn2Onigqv52wwdUXppuBKBqKlPKRl0b
MF8MkqUh1hrM8gIqBNHNiMWhGJXKcMRF5+fk2JtgFtDzew5x2bvsd+g1WlAf5cPo
8W5gsEP8wfpYxNgsnMW4yzokJdoXUa9laqUKgOqArtXVsbRE/sJ5Kh8c71tj+YY3
J4G5aenCxunjjs6caJbKN4YuvLptI2vSw2WhAc2c5WnVtXvRsTARsAlsQAJo+kLU
+aDTbaW1ChldCHzUkRSBEEH5cU8ij3yD2p0TRaYMdakeNxaf8MdYfw==zrAV
-----END PGP SIGNATURE-----

On 9/25/2013 5:05 PM, Patricio Rojo wrote:
> Please help,
> 
> Dovecot is running extremely slow for the last couple of weeks and it
> seems to be getting worse (or my patience running short).
Progressive degradation of mail server performance, whether an IMAP
mailbox server, or an MTA, is almost always caused by the storage
subsystem, usually due to filesystem free space fragmentation.

If you have a parity RAID array, have lost a disk and are running in
degraded mode, this can also cause large IO latency, slowing Dovecot.

Another common cause is heavy swap usage.  If you have a runaway process
or one with a memory leak, this will eat up physical RAM, causing heavy
swap usage.  If swap resides on the same spindles as your mailboxes,
this will degrade Dovecot performance.

If your box is hosted at a colo facility, or is in fact a VPS, it's
always possible a network problem or a clogged shared segment at the
provider is causing packet loss, which can also cause the client delay
behavior you have described.  If this server resides behind consumer
ADSL there could be a problem with your DSL provider's network.

In other words, if you didn't change the Dovecot configuration on the
day the performance first dropped, or very shortly before, then the
performance problem has nothing to do with Dovecot.  And this is almost
always the case with performance degradation.  The source of the problem
lie outside Dovecot, again, usually in the storage stack.  Start your
troubleshooting there.

-- 
Stan