[Dovecot] POP3 Dovecot Auth CPU usage 75%+
Hello all,
I hope someone can help me, I have been testing out Dovecot to switch from popa3d which I use at the moment. When I get several users connecting and disconnection multiple times, the Dovecot process with command Auth uses 50-90% of the CPU for the period which they are connecting. I am wondering if there is something that I may have misconfigured, or if there is something that I can change so that this spike doesn't occur.
If anyone could shed some light on the issue, I would appreciate it,
Kevin
/var/mail# dovecot -n # 2.1.4: /usr/local/etc/dovecot/dovecot.conf # OS: Linux 2.6.32-33-generic-pae i686 Ubuntu 10.04.4 LTS ext4 auth_cache_size = 10 M auth_verbose = yes disable_plaintext_auth = no instance_name = Mail Popper 1 listen = 172.20.20.222 login_greeting = Mail Popper 1 Ready mail_location = mbox:/var/empty:INBOX=/var/mail/%u:INDEX=MEMORY mail_privileged_group = mail namespace inbox { inbox = yes location = mailbox Drafts { special_use = \Drafts } mailbox Junk { special_use = \Junk } mailbox Sent { special_use = \Sent } mailbox "Sent Messages" { special_use = \Sent } mailbox Trash { special_use = \Trash } prefix = } passdb { driver = shadow } protocols = pop3 service pop3-login { service_count = 0 } ssl = no userdb { driver = passwd } protocol pop3 { pop3_uidl_format = %08Xu%08Xv }
Hello all,
I hope someone can help me, I have been testing out Dovecot to switch from popa3d which I use at the moment. When I get several users connecting and disconnection multiple times, the Dovecot process with command Auth uses 50-90% of the CPU for the period which they are connecting. I am wondering if there is something that I may have misconfigured, or if there is something that I can change so that this spike doesn't occur.
If anyone could shed some light on the issue, I would appreciate it,
Kevin
/var/mail# dovecot -n # 2.1.4: /usr/local/etc/dovecot/dovecot.conf # OS: Linux 2.6.32-33-generic-pae i686 Ubuntu 10.04.4 LTS ext4 auth_cache_size = 10 M auth_verbose = yes disable_plaintext_auth = no instance_name = Mail Popper 1 listen = 172.20.20.222 login_greeting = Mail Popper 1 Ready mail_location = mbox:/var/empty:INBOX=/var/mail/%u:INDEX=MEMORY mail_privileged_group = mail namespace inbox { inbox = yes location = mailbox Drafts { special_use = \Drafts } mailbox Junk { special_use = \Junk } mailbox Sent { special_use = \Sent } mailbox "Sent Messages" { special_use = \Sent } mailbox Trash { special_use = \Trash } prefix = } passdb { driver = shadow } protocols = pop3 service pop3-login { service_count = 0 } ssl = no userdb { driver = passwd } protocol pop3 { pop3_uidl_format = %08Xu%08Xv }
On 12.4.2012, at 23.46, Root Kev wrote:
I hope someone can help me, I have been testing out Dovecot to switch from popa3d which I use at the moment. When I get several users connecting and disconnection multiple times, the Dovecot process with command Auth uses 50-90% of the CPU for the period which they are connecting. I am wondering if there is something that I may have misconfigured, or if there is something that I can change so that this spike doesn't occur.
So is it the "auth" process or "auth worker" process? What if you add:
passdb { driver = shadow } userdb { driver = passwd args = blocking=yes }
does that move the CPU usage from "auth" to "auth worker" process? Is it using /etc/shadow and /etc/passwd files? Are they large? Do you have enabled other weird stuff in /etc/nsswitch.conf (and were there some other files related to them as well?)
I tried making the changes that you suggested but it didn't seem to make a
noticeable difference. It should be using the shadow file directly. The
shadow file has the default Ubuntu system accounts and 16 user accounts, so
overall fairly small. The nsswitch.conf file is set as default:
# /etc/nsswitch.conf
#
# Example configuration of GNU Name Service Switch functionality.
# If you have the glibc-doc-reference' and info' packages installed, try:
# `info libc "Name Service Switch"' for information about this file.
passwd: compat group: compat shadow: compat
hosts: files dns networks: files
protocols: db files services: db files ethers: db files rpc: db files
netgroup: nis
An example of users connecting and the Auth process using alot of CPU (from top):
Cpu(s): 87.4%us, 8.0%sy, 0.0%ni, 2.3%id, 0.0%wa, 0.7%hi, 1.7%si, 0.0%st Mem: 1026096k total, 533924k used, 492172k free, 60340k buffers Swap: 1757176k total, 0k used, 1757176k free, 414212k cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
643 dovecot 20 0 3096 1616 1208 S 50.7 0.2 0:01.76 auth
644 root 20 0 3096 1524 1140 S 1.3 0.1 0:00.08 auth
642 dovenull 20 0 4276 1612 1256 S 1.0 0.2 0:00.03 pop3-login
623 root 20 0 2704 1020 772 S 0.7 0.1 0:00.02 dovecot
627 root 20 0 4344 2808 1056 S 0.7 0.3 0:00.03 config
631 syslog 20 0 33916 1924 1036 S 0.3 0.2 0:01.61 rsyslogd
696 serverma 20 0 5464 2564 2040 R 0.3 0.2 0:00.01 pop3
1 root 20 0 2652 1604 1216 S 0.0 0.2 0:01.59init
2 root 20 0 0 0 0 S 0.0 0.0 0:00.00kthreadd
Thanks for any other ideas....
Kevin
On Fri, Apr 13, 2012 at 7:55 AM, Timo Sirainen tss@iki.fi wrote:
On 12.4.2012, at 23.46, Root Kev wrote:
So is it the "auth" process or "auth worker" process? What if you add:
passdb { driver = shadow } userdb { driver = passwd args = blocking=yes }
does that move the CPU usage from "auth" to "auth worker" process? Is it using /etc/shadow and /etc/passwd files? Are they large? Do you have enabled other weird stuff in /etc/nsswitch.conf (and were there some other files related to them as well?)
On 13.4.2012, at 17.32, Root Kev wrote:
643 dovecot 20 0 3096 1616 1208 S 50.7 0.2 0:01.76 auth
Well, I can't think of any good reason for this. Try strace -p 643 (or whatever pid of the process eating CPU) for a few seconds and send its output? Also maybe get a couple of gdb backtraces to see where it's doing stuff:
gdb -p 643 bt quit
and repeat it a few times
I think my last email may have been bounced due to attachment size, I have put a snippet of the captures below. The CPU is still going to high percent of usage when my test mailboxes are used. An ideas on how to bring down the Auth CPU usage would be greatly appreciated!
Thanks,
Kevin
Stace on the Auth process:
epoll_wait(13, {{EPOLLIN, {u32=150109008, u64=150109008}}}, 29, 149958) = 1 gettimeofday({1334328634, 21072}, NULL) = 0 read(29, "VERSION\t1\t1\nREQUEST\t1011351553\t3"..., 1024) = 72 time(NULL) = 1334328634 writev(29, [{"USER\t1011351553\tservermailbox1\ts"..., 108}, {"\n", 1}], 2) = 109 gettimeofday({1334328634, 27993}, NULL) = 0 epoll_wait(13, {{EPOLLIN, {u32=149927248, u64=149927248}}}, 29, 149992) = 1 gettimeofday({1334328634, 32215}, NULL) = 0 accept(11, {sa_family=AF_FILE, NULL}, [2]) = 30 fcntl64(30, F_GETFL) = 0x2 (flags O_RDWR) fcntl64(30, F_SETFL, O_RDWR|O_NONBLOCK) = 0 gettimeofday({1334328634, 32342}, NULL) = 0 fstat64(30, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0 _llseek(30, 0, 0xbffd24c0, SEEK_CUR) = -1 ESPIPE (Illegal seek) getsockname(30, {sa_family=AF_FILE, path="/usr/local/var/run/dovecot"}, [41]) = 0 epoll_ctl(13, EPOLL_CTL_ADD, 30, {EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP, {u32=150123496, u64=150123496}}) = 0 write(30, "VERSION\t1\t1\nSPID\t2093\n", 22) = 22 gettimeofday({1334328634, 32625}, NULL) = 0 epoll_wait(13, {{EPOLLIN, {u32=150123496, u64=150123496}}}, 29, 1000) = 1 gettimeofday({1334328634, 32721}, NULL) = 0 read(30, "VERSION\t1\t1\n", 1024) = 12 gettimeofday({1334328634, 32792}, NULL) = 0 epoll_wait(13, {{EPOLLIN, {u32=150123496, u64=150123496}}}, 29, 1000) = 1 gettimeofday({1334328634, 32883}, NULL) = 0 read(30, "REQUEST\t3624009729\t3062\t16\tbe004"..., 1012) = 60 time(NULL) = 1334328634 writev(30, [{"USER\t3624009729\tservermailbox\tsy"..., 105}, {"\n", 1}], 2) = 106 gettimeofday({1334328634, 33062}, NULL) = 0 epoll_wait(13, {{EPOLLIN|EPOLLHUP, {u32=150094520, u64=150094520}}}, 29, 999) = 1 gettimeofday({1334328634, 33766}, NULL) = 0 read(28, "", 6243) = 0 epoll_ctl(13, EPOLL_CTL_DEL, 28, {0, {u32=150094520, u64=150094520}}) = 0 close(28) = 0 epoll_wait(13, {{EPOLLIN|EPOLLHUP, {u32=150109008, u64=150109008}}}, 29, -1) = 1 gettimeofday({1334328634, 40036}, NULL) = 0 read(29, "", 952) = 0 epoll_ctl(13, EPOLL_CTL_DEL, 29, {0, {u32=150109008, u64=150109008}}) = 0 close(29) = 0 gettimeofday({1334328634, 40163}, NULL) = 0 gettimeofday({1334328634, 40197}, NULL) = 0 epoll_wait(13, {{EPOLLIN|EPOLLHUP, {u32=150123496, u64=150123496}}}, 29, 1000) = 1 gettimeofday({1334328634, 44007}, NULL) = 0 read(30, "", 952) = 0 epoll_ctl(13, EPOLL_CTL_DEL, 30, {0, {u32=150123496, u64=150123496}}) = 0 close(30) = 0 gettimeofday({1334328634, 44148}, NULL) = 0 gettimeofday({1334328634, 44184}, NULL) = 0 epoll_wait(13, {{EPOLLIN, {u32=150065544, u64=150065544}}}, 29, 1000) = 1 gettimeofday({1334328634, 52466}, NULL) = 0 read(26, "AUTH\t1\tPLAIN\tservice=pop3\tlip=17"..., 8170) = 122 gettimeofday({1334328634, 52582}, NULL) = 0 writev(12, [{"PENALTY-GET\t172.20.20.110", 25}, {"\n", 1}], 2) = 26 gettimeofday({1334328634, 52698}, NULL) = 0 epoll_wait(13, {{EPOLLIN, {u32=149924840, u64=149924840}}}, 29, 992) = 1 gettimeofday({1334328634, 52760}, NULL) = 0 read(12, "0 0\n", 424) = 4 time(NULL) = 1334328634 gettimeofday({1334328634, 93200}, NULL) = 0 writev(26, [{"OK\t1\tuser=servermailbox1", 24}, {"\n", 1}], 2) = 25 read(12, 0x8f36c14, 420) = -1 EAGAIN (Resource temporarily unavailable) gettimeofday({1334328634, 93651}, NULL) = 0 epoll_wait(13, {{EPOLLIN, {u32=150065544, u64=150065544}}}, 29, 951) = 1 gettimeofday({1334328634, 93715}, NULL) = 0 read(26, "AUTH\t2\tPLAIN\tservice=pop3\tlip=17"..., 8048) = 118 gettimeofday({1334328634, 93808}, NULL) = 0 writev(12, [{"PENALTY-GET\t172.20.20.110", 25}, {"\n", 1}], 2) = 26 gettimeofday({1334328634, 93919}, NULL) = 0 epoll_wait(13, {{EPOLLIN, {u32=149924840, u64=149924840}}}, 29, 951) = 1 gettimeofday({1334328634, 93980}, NULL) = 0 read(12, "0 0\n", 420) = 4 time(NULL) = 1334328634 gettimeofday({1334328634, 133578}, NULL) = 0 writev(26, [{"OK\t2\tuser=servermailbox", 23}, {"\n", 1}], 2) = 24 read(12, 0x8f36c18, 416) = -1 EAGAIN (Resource temporarily unavailable) gettimeofday({1334328634, 133998}, NULL) = 0 epoll_wait(13, {{EPOLLIN, {u32=149927248, u64=149927248}}}, 29, 911) = 1 gettimeofday({1334328634, 134064}, NULL) = 0 accept(11, {sa_family=AF_FILE, NULL}, [2]) = 28 fcntl64(28, F_GETFL) = 0x2 (flags O_RDWR) fcntl64(28, F_SETFL, O_RDWR|O_NONBLOCK) = 0 gettimeofday({1334328634, 134200}, NULL) = 0 fstat64(28, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0 _llseek(28, 0, 0xbffd24c0, SEEK_CUR) = -1 ESPIPE (Illegal seek) getsockname(28, {sa_family=AF_FILE, path="/usr/local/var/run/dovecot"}, [41]) = 0 epoll_ctl(13, EPOLL_CTL_ADD, 28, {EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP, {u32=150094520, u64=150094520}}) = 0
Debug on the auth process: Apr 13 11:01:58 devsmtp dovecot: auth: Debug: cache(qamailbox,172.20.20.222): miss Apr 13 11:01:58 devsmtp dovecot: auth-worker(3432): Debug: Loading modules from directory: /usr/local/lib/dovecot/auth Apr 13 11:01:58 devsmtp dovecot: auth-worker(3432): Debug: shadow(qamailbox,172.20.20.222): lookup Apr 13 11:01:58 devsmtp dovecot: auth: Debug: client out: OK#0111#011user=qamailbox Apr 13 11:01:58 devsmtp dovecot: auth: Debug: master in: REQUEST#0111220673537#0113397#0111#0115609887f745a84903ce3699d23e7b886 Apr 13 11:01:58 devsmtp dovecot: auth: Debug: userdb-cache(qamailbox,172.20.20.222): miss Apr 13 11:01:58 devsmtp dovecot: auth-worker(3432): Debug: passwd(qamailbox,172.20.20.222): lookup Apr 13 11:01:58 devsmtp dovecot: auth: Debug: master out: USER#0111220673537#011qamailbox#011system_groups_user=qamailbox#011uid=1002#011gid=1002#011home=/home/qamailbox Apr 13 11:01:58 devsmtp dovecot: pop3-login: Login: user=<qamailbox>, method=PLAIN, rip=172.20.20.222, lip=172.20.20.222, mpid=3433, secured Apr 13 11:02:05 devsmtp dovecot: pop3(qamailbox): Disconnected: Logged out top=0/0, retr=1/15637, del=0/50, size=779917 Apr 13 11:05:31 devsmtp dovecot: auth: Debug: auth client connected (pid=3397) Apr 13 11:05:31 devsmtp dovecot: auth: Debug: client in: AUTH#0112#011PLAIN#011service=pop3#011lip=172.20.20.222#011rip=172.20.20.110#011lport=110#011rport=53254#011resp=AHNlcnZlcm1haWxib3gxADEyMzQ1Ng== Apr 13 11:05:31 devsmtp dovecot: auth: Debug: cache(servermailbox1,172.20.20.110): miss Apr 13 11:05:31 devsmtp dovecot: auth-worker(3459): Debug: Loading modules from directory: /usr/local/lib/dovecot/auth Apr 13 11:05:31 devsmtp dovecot: auth-worker(3459): Debug: shadow(servermailbox1,172.20.20.110): lookup Apr 13 11:05:31 devsmtp dovecot: auth: Debug: client out: OK#0112#011user=servermailbox1 Apr 13 11:05:31 devsmtp dovecot: auth: Debug: master in: REQUEST#011358219777#0113397#0112#01132ecf6b93729a90ece98bbb643446ea6 Apr 13 11:05:31 devsmtp dovecot: auth: Debug: userdb-cache(servermailbox1,172.20.20.110): miss Apr 13 11:05:31 devsmtp dovecot: auth-worker(3459): Debug: passwd(servermailbox1,172.20.20.110): lookup Apr 13 11:05:31 devsmtp dovecot: auth: Debug: master out: USER#011358219777#011servermailbox1#011system_groups_user=servermailbox1#011uid=1007#011gid=1007#011home=/home/servermailbox1 Apr 13 11:05:31 devsmtp dovecot: pop3-login: Login: user=<servermailbox1>, method=PLAIN, rip=172.20.20.110, lip=172.20.20.222, mpid=3460 Apr 13 11:05:31 devsmtp dovecot: pop3(servermailbox1): Disconnected: Logged out top=5/6281, retr=5/77906, del=0/50, size=778637 Apr 13 11:05:31 devsmtp dovecot: auth: Debug: client in: AUTH#0113#011PLAIN#011service=pop3#011lip=172.20.20.222#011rip=172.20.20.110#011lport=110#011rport=53255#011resp=AHNlcnZlcm1haWxib3gxADEyMzQ1Ng== Apr 13 11:05:31 devsmtp dovecot: auth: Debug: cache(servermailbox1,172.20.20.110): hit: {CRYPT}$6$bpFXtlOP$zczdubFhGyRjJA0PD9lr/QbWAdweg3jThwkxkfCEGgxPxFpualm1ea.8rECmM1UZ0YuTNKWpiGPHwLhys1luy0#011user=servermailbox1#011user=servermailbox1 Apr 13 11:05:31 devsmtp dovecot: auth: Debug: client out: OK#0113#011user=servermailbox1 Apr 13 11:05:31 devsmtp dovecot: auth: Debug: master in: REQUEST#0112057699329#0113397#0113#01132ecf6b93729a90ece98bbb643446ea6 Apr 13 11:05:31 devsmtp dovecot: auth: Debug: userdb-cache(servermailbox1,172.20.20.110): hit: servermailbox1#011system_groups_user=servermailbox1#011uid=1007#011gid=1007#011home=/home/servermailbox1 Apr 13 11:05:31 devsmtp dovecot: auth: Debug: master out: USER#0112057699329#011servermailbox1#011system_groups_user=servermailbox1#011uid=1007#011gid=1007#011home=/home/servermailbox1 Apr 13 11:05:31 devsmtp dovecot: pop3-login: Login: user=<servermailbox1>, method=PLAIN, rip=172.20.20.110, lip=172.20.20.222, mpid=3461 Apr 13 11:05:31 devsmtp dovecot: pop3(servermailbox1): Disconnected: Logged out top=0/0, retr=0/0, del=0/50, size=778637 Apr 13 11:05:33 devsmtp dovecot: auth: Debug: client in: AUTH#0111#011PLAIN#011service=pop3#011lip=172.20.20.222#011rip=172.20.20.110#011lport=110#011rport=53261#011resp=AHNlcnZlcm1haWxib3gxADEyMzQ1Ng== Apr 13 11:05:33 devsmtp dovecot: auth: Debug: cache(servermailbox1,172.20.20.110): hit: {CRYPT}$6$bpFXtlOP$zczdubFhGyRjJA0PD9lr/QbWAdweg3jThwkxkfCEGgxPxFpualm1ea.8rECmM1UZ0YuTNKWpiGPHwLhys1luy0#011user=servermailbox1#011user=servermailbox1 Apr 13 11:05:33 devsmtp dovecot: auth: Debug: client out: OK#0111#011user=servermailbox1 Apr 13 11:05:33 devsmtp dovecot: auth: Debug: master in: REQUEST#0113081109505#0113386#0111#01146c7d95e8b31022008fef693a1ef018c Apr 13 11:05:33 devsmtp dovecot: auth: Debug: userdb-cache(servermailbox1,172.20.20.110): hit: servermailbox1#011system_groups_user=servermailbox1#011uid=1007#011gid=1007#011home=/home/servermailbox1 Apr 13 11:05:33 devsmtp dovecot: auth: Debug: master out: USER#0113081109505#011servermailbox1#011system_groups_user=servermailbox1#011uid=1007#011gid=1007#011home=/home/servermailbox1 Apr 13 11:05:33 devsmtp dovecot: pop3-login: Login: user=<servermailbox1>, method=PLAIN, rip=172.20.20.110, lip=172.20.20.222, mpid=3462 Apr 13 11:05:33 devsmtp dovecot: pop3(servermailbox1): Disconnected: Logged out top=0/0, retr=0/0, del=1/50, size=778637 Apr 13 11:05:33 devsmtp dovecot: auth: Debug: client in: AUTH#0114#011PLAIN#011service=pop3#011lip=172.20.20.222#011rip=172.20.20.110#011lport=110#011rport=53262#011resp=AHNlcnZlcm1haWxib3gxADEyMzQ1Ng== Apr 13 11:05:33 devsmtp dovecot: auth: Debug: cache(servermailbox1,172.20.20.110): hit: {CRYPT}$6$bpFXtlOP$zczdubFhGyRjJA0PD9lr/QbWAdweg3jThwkxkfCEGgxPxFpualm1ea.8rECmM1UZ0YuTNKWpiGPHwLhys1luy0#011user=servermailbox1#011user=servermailbox1 Apr 13 11:05:33 devsmtp dovecot: auth: Debug: client out: OK#0114#011user=servermailbox1 Apr 13 11:05:33 devsmtp dovecot: auth: Debug: master in: REQUEST#0112632187905#0113397#0114#01132ecf6b93729a90ece98bbb643446ea6 Apr 13 11:05:33 devsmtp dovecot: auth: Debug: userdb-cache(servermailbox1,172.20.20.110): hit: servermailbox1#011system_groups_user=servermailbox1#011uid=1007#011gid=1007#011home=/home/servermailbox1 Apr 13 11:05:33 devsmtp dovecot: auth: Debug: master out: USER#0112632187905#011servermailbox1#011system_groups_user=servermailbox1#011uid=1007#011gid=1007#011home=/home/servermailbox1 Apr 13 11:05:33 devsmtp dovecot: pop3-login: Login: user=<servermailbox1>, method=PLAIN, rip=172.20.20.110, lip=172.20.20.222, mpid=3463 Apr 13 11:05:33 devsmtp dovecot: pop3(servermailbox1): Disconnected: Logged out top=0/0, retr=0/0, del=0/49, size=763044 Apr 13 11:05:33 devsmtp dovecot: auth: Debug: client in: AUTH#0115#011PLAIN#011service=pop3#011lip=172.20.20.222#011rip=172.20.20.110#011lport=110#011rport=53263#011resp=AHNlcnZlcm1haWxib3gxADEyMzQ1Ng== Apr 13 11:05:33 devsmtp dovecot: auth: Debug: cache(servermailbox1,172.20.20.110): hit: {CRYPT}$6$bpFXtlOP$zczdubFhGyRjJA0PD9lr/QbWAdweg3jThwkxkfCEGgxPxFpualm1ea.8rECmM1UZ0YuTNKWpiGPHwLhys1luy0#011user=servermailbox1#011user=servermailbox1
participants (2)
-
Root Kev
-
Timo Sirainen