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