Dovecot 2.3.0 imap-login using 100% CPU

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
5 messages Options
Reply | Threaded
Open this post in threaded view
|

Dovecot 2.3.0 imap-login using 100% CPU

Jason Kiniry-2
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@server [~]# strace -p 36053
Process 36053 attached
^CProcess 36053 detached
root@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@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@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
Reply | Threaded
Open this post in threaded view
|

Re: Dovecot 2.3.0 imap-login using 100% CPU

Jason Kiniry-2
We were able to obtain a better backtrace:

0x00007f4b303b5af5 in clients_notify_auth_connected () at client-common-auth.c:839
839                     if (!client_does_custom_io(client) && client->input_blocked) {
(gdb) run

Thank you!

Regards,

Jason Kiniry

> On Jan 10, 2018, at 4:28 PM, Jason Kiniry <[hidden email]> wrote:
>
> 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@server [~]# strace -p 36053
> Process 36053 attached
> ^CProcess 36053 detached
> root@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@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@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

Reply | Threaded
Open this post in threaded view
|

Re: Dovecot 2.3.0 imap-login using 100% CPU

Aki Tuomi-2
Thank you for this, we'll look into it.

Aki


On 11.01.2018 01:29, Jason Kiniry wrote:

> We were able to obtain a better backtrace:
>
> 0x00007f4b303b5af5 in clients_notify_auth_connected () at client-common-auth.c:839
> 839                     if (!client_does_custom_io(client) && client->input_blocked) {
> (gdb) run
>
> Thank you!
>
> Regards,
>
> Jason Kiniry
>
>> On Jan 10, 2018, at 4:28 PM, Jason Kiniry <[hidden email]> wrote:
>>
>> 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@server [~]# strace -p 36053
>> Process 36053 attached
>> ^CProcess 36053 detached
>> root@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@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@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

Reply | Threaded
Open this post in threaded view
|

Re: Dovecot 2.3.0 imap-login using 100% CPU

Aki Tuomi-2
In reply to this post by Jason Kiniry-2
Is it possible for you to provide output of

p *client
p *client->next
p *client->next->next

until it hits NULL?

Aki


On 11.01.2018 01:29, Jason Kiniry wrote:

> We were able to obtain a better backtrace:
>
> 0x00007f4b303b5af5 in clients_notify_auth_connected () at client-common-auth.c:839
> 839                     if (!client_does_custom_io(client) && client->input_blocked) {
> (gdb) run
>
> Thank you!
>
> Regards,
>
> Jason Kiniry
>
>> On Jan 10, 2018, at 4:28 PM, Jason Kiniry <[hidden email]> wrote:
>>
>> 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@server [~]# strace -p 36053
>> Process 36053 attached
>> ^CProcess 36053 detached
>> root@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@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@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

Reply | Threaded
Open this post in threaded view
|

Re: Dovecot 2.3.0 imap-login using 100% CPU

Timo Sirainen
In reply to this post by Jason Kiniry-2
On 10 Jan 2018, at 17.28, Jason Kiniry <[hidden email]> wrote:
>
> 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@server [~]# strace -p 36053
> Process 36053 attached
> ^CProcess 36053 detached

So it's not doing any syscalls. What about ltrace -tt -e '*' -p <pid>?

Also what's your doveconf -n? Mainly wondering about service imap-login { .. } settings. Probably service_count=1 (default)? This somehow hangs here when there's a client with pending input, but auth process wasn't yet connected to. It's not very obvious though how it could have gotten stuck in there.