Very odd epoll_ctl calls in mail proxy

[Igor Sysoev]

On Tue, Nov 08, 2011 at 12:04:01PM +1100, Robert Mueller wrote:
> I'm using nginx 1.0.8 in mail proxy mode and when trying to track down a
> particular issue I happened to do an strace of a process and found
> something very odd.
> 
> Our config looks pretty straight forward.
> 
> mail {
>     auth_http unix:/var/state/saslauthd/nginx:/;
>     imap_client_buffer  16k;
> 
>     pop3_capabilities "SASL OTP" "EXPIRE NEVER" "LOGIN-DELAY 0" ... ;
>     imap_capabilities "IMAP4" "IMAP4rev1" "LITERAL+" ... ;
> 
>     server {
>       listen 66.111.4.61:110;
>       ... a number of other ips
> 
>       protocol pop3;
>       proxy on;
>       proxy_timeout  5m;
>       proxy_pass_error_message on;
>       auth_http_header "ServerHostname" "mail.messagingengine.com";
>     }
> 
>     server {
>       listen 66.111.4.61:143;
>       ... a number of other ips
> 
>       protocol imap;
>       proxy on;
>       proxy_timeout  1h;
>       auth_http_header "ServerHostname" "mail.messagingengine.com";
>     }
> 
>     ... a number of other similar server blocks including ssl ones
> }
> 
> Here's what the strace of the nginx process on our server looked like
> (20k concurrent connections across 8 procs).
> 
> 17:55:00.682440 read(599, 0xac4ba60, 34821) = -1 EAGAIN (Resource
> temporarily unavailable)
> 17:55:00.682551 sendto(4128, "cick SELECT \"INBOX."..., 68, 0, NULL, 0)
> = 68
> 17:55:00.682674 epoll_ctl(203, EPOLL_CTL_DEL, 7, {0, {u32=0, u64=0}}) =
> 0
> 17:55:00.682770 epoll_ctl(203, EPOLL_CTL_DEL, 8, {0, {u32=0, u64=0}}) =
> 0
> 
> ... 170 lines or so of the same thing deleted ...
> 
> 17:55:00.710905 epoll_ctl(203, EPOLL_CTL_DEL, 177, {0, {u32=0, u64=0}})
> = 0
> 17:55:00.710997 epoll_ctl(203, EPOLL_CTL_DEL, 178, {0, {u32=0, u64=0}})
> = 0
> 17:55:00.711092 epoll_ctl(203, EPOLL_CTL_DEL, 179, {0, {u32=0, u64=0}})
> = 0
> 17:55:00.711184 epoll_wait(203, {{EPOLLIN|EPOLLOUT, {u32=2113145168,
> u64=139674449611088}}, ...
> 17:55:00.711327 recvfrom(4128, "* OK [CLOSED] Ok\r\n* 37
> EXISTS\r\n*"..., 4096, 0, NULL, NULL) = 344
> 
> ... lots more read/write/recvfrom/sendto/epoll_wait calls
> 
> 17:55:00.815683 sendto(3271, "6 EXPUNGE\r\n", 11, 0, NULL, 0) = 11
> 17:55:00.815820 epoll_ctl(203, EPOLL_CTL_ADD, 7, {EPOLLIN,
> {u32=2112495632, u64=139674448961552}}) = 0
> 17:55:00.815947 epoll_ctl(203, EPOLL_CTL_ADD, 8, {EPOLLIN,
> {u32=2112495824, u64=139674448961744}}) = 0
> 
> ... 170 lines or so of the same thing deleted ...
> 
> 17:55:00.849680 epoll_ctl(203, EPOLL_CTL_ADD, 178, {EPOLLIN,
> {u32=2112528464, u64=139674448994384}}) = 0
> 17:55:00.850305 epoll_ctl(203, EPOLL_CTL_ADD, 179, {EPOLLIN,
> {u32=2112528656, u64=139674448994576}}) = 0
> 17:55:00.850466 epoll_wait(203, {{EPOLLIN|EPOLLOUT, {u32=2113156497,
> u64=139674449622417}}, ...
> 17:55:00.850638 accept4(105, {sa_family=AF_INET, sin_port=htons(4899),
> sin_addr=inet_addr("a.a.a.a")}, [16], SOCK_NONBLOCK) = 4356
> 17:55:00.850784 write(5, "2011/11/07 17:55:00 [info] 24092"..., 94) = 94
> 
> ... lots more read/write/recvfrom/sendto/epoll_wait calls
> 
> 17:55:00.861272 recvfrom(3471, 0x8653b70, 4096, 0, 0, 0) = -1 EAGAIN
> (Resource temporarily unavailable)
> 17:55:00.861404 epoll_ctl(203, EPOLL_CTL_DEL, 7, {0, {u32=0, u64=0}}) =
> 0
> 17:55:00.861514 epoll_ctl(203, EPOLL_CTL_DEL, 8, {0, {u32=0, u64=0}}) =
> 0
> 
> ... 170 lines or so again just like above ...
> 
> I see this over and over, the same fd's (7-179) added and removed over
> and over again quite rapidly.
> 
> So why would nginx be adding 170 fd's to it's epoll descriptor, then
> deleting those 170 fd's a fraction later, and repeating that over and
> over?

It seems you have about 170 listen directives.
This is probably caused by accept_mutex. Try

events {
     accept_mutex  off;
     ...
}

Probably it's better to disable accept_mutex by default.


-- 
Igor Sysoev