thr3ads.net - dovecot - [Dovecot] 2.0.beta3 imapd running hot [Mar 2010]

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

Bernhard Schmidt

2010-Mar-21 01:20 UTC

[Dovecot] 2.0.beta3 imapd running hot

Hi,

since a couple of weeks I occasionally have an imapd going crazy on me,
using up 100% CPU. Current revision is 10962

29865 vmail     20   0 47820 3296 1708 R 99.7  0.9 131:07.85 imap

vmail    29865 86.1  0.8  47820  3296 ?        R    Mar20 131:20
dovecot/imap [berni 2001:a60:f001:1:219:66ff:fe8b:a6e IDLE

strace -p <pid> shows a repeating pattern of

epoll_wait(8, {{EPOLLOUT, {u32=36560672, u64=36560672}}}, 5, 4872) = 1
gettimeofday({1269133967, 495298}, NULL) = 0
gettimeofday({1269133967, 495333}, NULL) = 0
gettimeofday({1269133967, 495370}, NULL) = 0

with the last argument of epoll_wait (4872) slowly decrementing and then
wrapping around to ~30k.

Attaching gdb shows the following backtrace:

(gdb) bt full
#0  array_idx_i (ioloop=0x22bd5f0) at array.h:189
No locals.
#1  io_loop_handler_run (ioloop=0x22bd5f0) at ioloop-epoll.c:188
        ctx = 0x22bd800
        event = <value optimized out>
        list = <value optimized out>
        io = <value optimized out>
        tv = {tv_sec = 26, tv_usec = 307176}
        t_id = 2
        msecs = 26308
        ret = 1
        i = <value optimized out>
        call = <value optimized out>
#2  0x00007f8f682bc8e8 in io_loop_run (ioloop=0x22bd5f0) at ioloop.c:350
No locals.
#3  0x00007f8f682acd63 in master_service_run (service=0x22bd4c0,
callback=0x6590) at master-service.c:486
No locals.
#4  0x0000000000418551 in main (argc=1, argv=0x22bd3a0) at main.c:313
        set_roots = {0x41b840, 0x0}
        service_flags = <value optimized out>
        storage_service_flags = MAIL_STORAGE_SERVICE_FLAG_DISALLOW_ROOT
        postlogin_socket_path = 0x0
(gdb) c
Continuing.
^C
Program received signal SIGINT, Interrupt.
0x00007fffed1ff9ad in gettimeofday ()
(gdb) bt full
#0  0x00007fffed1ff9ad in gettimeofday ()
No symbol table info available.
#1  0x00007f8f6795f02a in gettimeofday () from /lib/libc.so.6
No symbol table info available.
#2  0x00007f8f682bcb39 in io_loop_handle_timeouts_real
(ioloop=0x22bd5f0) at ioloop.c:291
        item = <value optimized out>
        tv = {tv_sec = 0, tv_usec = 36427248}
        tv_call = {tv_sec = 0, tv_usec = 140737170938560}
        t_id = <value optimized out>
#3  io_loop_handle_timeouts (ioloop=0x22bd5f0) at ioloop.c:339
        _data_stack_cur_id = 0
#4  0x00007f8f682bd70e in io_loop_handler_run (ioloop=0x22bd5f0) at
ioloop-epoll.c:180
        ctx = 0x22bd800
        event = <value optimized out>
        list = <value optimized out>
        io = <value optimized out>
        tv = {tv_sec = 28, tv_usec = 267997}
        t_id = 2
        msecs = 28268
        ret = 1
        i = <value optimized out>
        call = <value optimized out>
#5  0x00007f8f682bc8e8 in io_loop_run (ioloop=0x22bd5f0) at ioloop.c:350
No locals.
#6  0x00007f8f682acd63 in master_service_run (service=0x22bd4c0,
callback=0) at master-service.c:486
No locals.
#7  0x0000000000418551 in main (argc=1, argv=0x22bd3a0) at main.c:313
        set_roots = {0x41b840, 0x0}
        service_flags = <value optimized out>
        storage_service_flags = MAIL_STORAGE_SERVICE_FLAG_DISALLOW_ROOT
        postlogin_socket_path = 0x0

doveconf -n:

mail.svr02.mucip.net:~# doveconf -n
# 2.0.beta3: /etc/dovecot/dovecot.conf
# OS: Linux 2.6.33 x86_64 Debian squeeze/sid 
auth_mechanisms = plain login
disable_plaintext_auth = no
listen = 83.170.6.69, 2001:1b10:1000::110:1:1
mail_gid = 5000
mail_location = maildir:%h/:INDEX=/var/cache/dovecot/%1n/%n
mail_uid = 5000
maildir_stat_dirs = yes
maildir_very_dirty_syncs = yes
passdb {
  args = /etc/dovecot/dovecot-ldap.conf
  driver = ldap
}
plugin {
  quota = dict:user::file:%h/dovecot-quota
  quota_rule = *:storage=500M
  sieve = ~/.dovecot.sieve
  sieve_dir = ~/sieve
}
postmaster_address = postmaster at birkenwald.de
protocols = imap pop3 lmtp managesieve
quota_full_tempfail = yes
service auth {
  unix_listener /var/spool/postfix-mailout/private/auth {
    group = postfix
    mode = 0660
    user = postfix
  }
  unix_listener /var/spool/postfix/private/auth {
    group = postfix
    mode = 0660
    user = postfix
  }
  unix_listener auth-userdb {
    group = vmail
    mode = 0660
  }
}
service imap-login {
  inet_listener imap {
    port = 143
  }
  inet_listener imaps {
    port = 993
    ssl = yes
  }
}
service lmtp {
  inet_listener {
    port = 24
  }
}
service managesieve-login {
  inet_listener sieve_deprecated {
    port = 2000
  }
  process_min_avail = 1
}
service pop3-login {
  inet_listener pop3 {
    port = 110
  }
  inet_listener pop3s {
    port = 995
    ssl = yes
  }
}
ssl_cert = </etc/ssl/private/pop3.mucip.net.crt
ssl_key = </etc/ssl/private/pop3.mucip.net.key
userdb {
  args = /etc/dovecot/dovecot-ldap.conf
  driver = ldap
}
verbose_proctitle = yes
protocol pop3 {
  mail_plugins = quota
  pop3_uidl_format = %08Xu%08Xv
}
protocol lmtp {
  mail_plugins = sieve quota
}
protocol lda {
  mail_plugins = sieve quota
}
protocol imap {
  imap_idle_notify_interval = 600 s
  mail_plugins = quota imap_quota zlib imap_zlib
}

At the moment I have two suspects, the imap_zlib plugin and CONDSTORE
(which I recently reenabled in Thunderbird after the fixed version got
deployed). The client is always Thunderbird 3.0.3+, but from different
systems. It does terminate without any error message in the logs when I
exit Thunderbird.

Now testing without zlib...

Bernhard

Timo Sirainen

2010-Mar-21 14:17 UTC

head link

[Dovecot] 2.0.beta3 imapd running hot

On Sun, 2010-03-21 at 01:20 +0000, Bernhard Schmidt
wrote:> strace -p <pid> shows a repeating pattern of
> 
> epoll_wait(8, {{EPOLLOUT, {u32=36560672, u64=36560672}}}, 5, 4872) = 1
> gettimeofday({1269133967, 495298}, NULL) = 0
> gettimeofday({1269133967, 495333}, NULL) = 0
> gettimeofday({1269133967, 495370}, NULL) = 0
So nothing else? It looks like some function is being called over and
over again that "you can write more data to client", but the function
then does nothing.
> Attaching gdb shows the following backtrace:
It would be helpful to find out what the I/O function is that is being
called. For example:

b ioloop-epoll.c:208
p *io
cont
p *io
cont
..etc..

What is the *io output? If it's client_output() or something else as
generic.. Use "step" to get into the function then then:

p *client
p *client.output_lock
p client.command_queue[0]
p client.command_queue[1]
p client.command_queue[2]

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 198 bytes
Desc: This is a digitally signed message part
URL:
<http://dovecot.org/pipermail/dovecot/attachments/20100321/12779b54/attachment-0002.bin>

Bernhard Schmidt

2010-Mar-22 17:13 UTC

head link

[Dovecot] 2.0.beta3 imapd running hot

On 21.03.2010 15:17, Timo Sirainen wrote:

Hi,
>> strace -p<pid>  shows a repeating pattern of
>>
>> epoll_wait(8, {{EPOLLOUT, {u32=36560672, u64=36560672}}}, 5, 4872) = 1
>> gettimeofday({1269133967, 495298}, NULL) = 0
>> gettimeofday({1269133967, 495333}, NULL) = 0
>> gettimeofday({1269133967, 495370}, NULL) = 0
>
> So nothing else? It looks like some function is being called over and
> over again that "you can write more data to client", but the
function
> then does nothing.
No, nothing else (I could see).
>> Attaching gdb shows the following backtrace:
> It would be helpful to find out what the I/O function is that is being
> called. For example:
I'll try to get your debug output.

I'm pretty sure it's related to the imap_zlib plugin, I haven't had
one
single problem since I disabled it. I'll reenable and go tracing.

Bernhard

Bernhard Schmidt

2010-Mar-28 19:34 UTC

head link

[Dovecot] 2.0.beta3 imapd running hot

On 21.03.2010 15:17, Timo Sirainen wrote:

Hi Timo,
> It would be helpful to find out what the I/O function is that is being
> called. For example:
>
> b ioloop-epoll.c:208
> p *io
> cont
> p *io
> cont
> ..etc..
>
> What is the *io output? If it's client_output() or something else as
> generic.. Use "step" to get into the function then then:
>
> p *client
> p *client.output_lock
> p client.command_queue[0]
> p client.command_queue[1]
> p client.command_queue[2]
(gdb) bt
#0  stream_send_io (fstream=0x179a570) at ostream-file.c:464
#1  0x00007fbaa9a69775 in io_loop_handler_run (ioloop=<value optimized 
out>) at ioloop-epoll.c:208
#2  0x00007fbaa9a688f8 in io_loop_run (ioloop=0x177e5f0) at ioloop.c:350
#3  0x00007fbaa9a58d63 in master_service_run (service=0x177e4c0, 
callback=0) at master-service.c:486
#4  0x00000000004186c1 in main (argc=1, argv=0x177e3a0) at main.c:323
(gdb) b ioloop-epoll.c:208
Breakpoint 1 at 0x7fbaa9a69767: file ioloop-epoll.c, line 208.
(gdb) p *io
No symbol "io" in current context.
(gdb) cont
Continuing.

Breakpoint 1, io_loop_handler_run (ioloop=<value optimized out>) at 
ioloop-epoll.c:208
208	ioloop-epoll.c: Datei oder Verzeichnis nicht gefunden.
	in ioloop-epoll.c
(gdb) p *io
$1 = {io = {condition = IO_WRITE, callback = 0x7fbaa9a715c0 
<stream_send_io>, context = 0x179a570, ioloop = 0x177e5f0},
   prev = 0x182a460, next = 0x177f350, refcount = 1, fd = 10}
(gdb)

(gdb) cont
Continuing.

Breakpoint 1, io_loop_handler_run (ioloop=<value optimized out>) at 
ioloop-epoll.c:208
208	in ioloop-epoll.c
(gdb) p *io
$2 = {io = {condition = IO_WRITE, callback = 0x7fbaa9a715c0 
<stream_send_io>, context = 0x179a570, ioloop = 0x177e5f0},
   prev = 0x182a460, next = 0x177f350, refcount = 1, fd = 10}
(gdb) step
207	in ioloop-epoll.c
(gdb) p *client
No symbol "client" in current context.

I am pretty sure it is related to imap_zlib ... at least this did not 
happen when I disabled the plugin.

I'm on revision 10993 at the moment.

Bernhard

Possibly Parallel Threads

Search for more possibly parallel threads

dovecot - Mar 2010 - 2.0.beta3 imapd running hot

[Dovecot] 2.0.beta3 imapd running hot

[Dovecot] 2.0.beta3 imapd running hot

[Dovecot] 2.0.beta3 imapd running hot

[Dovecot] 2.0.beta3 imapd running hot

Possibly Parallel Threads