[Dovecot] POP3 Dovecot Auth CPU usage 75%+
Root Kev
root.kev at gmail.com
Mon Apr 16 17:55:54 EEST 2012
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
More information about the dovecot
mailing list