Dovecot 2.3.0 imap-login using 100% CPU

[Jason Kiniry]

When in the process of testing out the 2.3.0 version of Dovecot, we noticed that on a busy server, imap-login can sometimes take 100% CPU and remain there indefinitely. We grabbed a gdb trace while it was happening:

dovenull 36053 31.2  0.0  60460 17316 ?        R    04:38  11:55 dovecot/imap-login
root at server [~]# strace -p 36053
Process 36053 attached
^CProcess 36053 detached
root at server [~]# gdb 
atGNU gdb (GDB) Red Hat Enterprise Linux (7.2-92.el6)
Copyright (C) 2010 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-redhat-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
(gdb) attach 36053
Attaching to process 36053
Reading symbols from /usr/libexec/dovecot/imap-login...done.
Reading symbols from /usr/lib64/dovecot/libdovecot-login.so.0...done.
Loaded symbols for /usr/lib64/dovecot/libdovecot-login.so.0
Reading symbols from /usr/lib64/dovecot/libdovecot.so.0...done.
Loaded symbols for /usr/lib64/dovecot/libdovecot.so.0
Reading symbols from /lib64/libc.so.6...(no debugging symbols found)...done.
Loaded symbols for /lib64/libc.so.6
Reading symbols from /usr/lib64/libssl.so.10...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libssl.so.10
Reading symbols from /usr/lib64/libcrypto.so.10...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libcrypto.so.10
Reading symbols from /lib64/librt.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib64/librt.so.1
Reading symbols from /lib64/libdl.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/libdl.so.2
Reading symbols from /lib64/ld-linux-x86-64.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/ld-linux-x86-64.so.2
Reading symbols from /lib64/libgssapi_krb5.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/libgssapi_krb5.so.2
Reading symbols from /lib64/libkrb5.so.3...(no debugging symbols found)...done.
Loaded symbols for /lib64/libkrb5.so.3
Reading symbols from /lib64/libcom_err.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/libcom_err.so.2
Reading symbols from /lib64/libk5crypto.so.3...(no debugging symbols found)...done.
Loaded symbols for /lib64/libk5crypto.so.3
Reading symbols from /lib64/libz.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib64/libz.so.1
Reading symbols from /lib64/libpthread.so.0...(no debugging symbols found)...done.
[Thread debugging using libthread_db enabled]
Loaded symbols for /lib64/libpthread.so.0
Reading symbols from /lib64/libkrb5support.so.0...(no debugging symbols found)...done.
Loaded symbols for /lib64/libkrb5support.so.0
Reading symbols from /lib64/libkeyutils.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib64/libkeyutils.so.1
Reading symbols from /lib64/libresolv.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/libresolv.so.2
Reading symbols from /lib64/libselinux.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib64/libselinux.so.1
Reading symbols from /usr/lib64/dovecot/libssl_iostream_openssl.so...done.
Loaded symbols for /usr/lib64/dovecot/libssl_iostream_openssl.so
0x00007f758fb8dd18 in client_notify_auth_ready at plt () from /usr/lib64/dovecot/libdovecot-login.so.0
Missing separate debuginfos, use: debuginfo-install dovecot-2.3.0-4.cp1162.x86_64
(gdb) back
#0  0x00007f758fb8dd18 in client_notify_auth_ready at plt () from /usr/lib64/dovecot/libdovecot-login.so.0
#1  0x00007f758fb90af0 in clients_notify_auth_connected () at client-common-auth.c:837
#2  0x00007f758f8cfc04 in auth_server_input_done (conn=0x7f7591911838) at auth-server-connection.c:127
#3  auth_server_connection_input_line (conn=0x7f7591911838) at auth-server-connection.c:229
#4  auth_server_connection_input (conn=0x7f7591911838) at auth-server-connection.c:281
#5  0x00007f758f8f5e35 in io_loop_call_io (io=0x7f759277e2a0) at ioloop.c:614
#6  0x00007f758f8f7d3f in io_loop_handler_run_internal (ioloop=<value optimized out>) at ioloop-epoll.c:222
#7  0x00007f758f8f5f25 in io_loop_handler_run (ioloop=0x7f75918e4d00) at ioloop.c:666
#8  0x00007f758f8f6148 in io_loop_run (ioloop=0x7f75918e4d00) at ioloop.c:639
#9  0x00007f758f875ab3 in master_service_run (service=0x7f75918e4b90, callback=<value optimized out>) at master-service.c:767
#10 0x00007f758fb96156 in login_binary_run (binary=<value optimized out>, argc=1, argv=0x7f75918e4890) at main.c:549
#11 0x00007f758f4a2d1d in __libc_start_main () from /lib64/libc.so.6
#12 0x00007f758ffc4469 in _start ()
(gdb) run
The program being debugged has been started already.
Start it from the beginning? (y or n) n
Program not restarted.
(gdb) continue
Continuing.
^C
Program received signal SIGINT, Interrupt.
client_notify_auth_ready (client=0x7f7592775140) at client-common.c:1031
1031	client-common.c: No such file or directory.
	in client-common.c
(gdb) back
#0  client_notify_auth_ready (client=0x7f7592775140) at client-common.c:1031
#1  0x00007f758fb90af0 in clients_notify_auth_connected () at client-common-auth.c:837
#2  0x00007f758f8cfc04 in auth_server_input_done (conn=0x7f7591911838) at auth-server-connection.c:127
#3  auth_server_connection_input_line (conn=0x7f7591911838) at auth-server-connection.c:229
#4  auth_server_connection_input (conn=0x7f7591911838) at auth-server-connection.c:281
#5  0x00007f758f8f5e35 in io_loop_call_io (io=0x7f759277e2a0) at ioloop.c:614
#6  0x00007f758f8f7d3f in io_loop_handler_run_internal (ioloop=<value optimized out>) at ioloop-epoll.c:222
#7  0x00007f758f8f5f25 in io_loop_handler_run (ioloop=0x7f75918e4d00) at ioloop.c:666
#8  0x00007f758f8f6148 in io_loop_run (ioloop=0x7f75918e4d00) at ioloop.c:639
#9  0x00007f758f875ab3 in master_service_run (service=0x7f75918e4b90, callback=<value optimized out>) at master-service.c:767
#10 0x00007f758fb96156 in login_binary_run (binary=<value optimized out>, argc=1, argv=0x7f75918e4890) at main.c:549
#11 0x00007f758f4a2d1d in __libc_start_main () from /lib64/libc.so.6
#12 0x00007f758ffc4469 in _start ()
(gdb) 

Anyone have any thoughts?

Regards,

Jason Kiniry