Very odd epoll_ctl calls in mail proxy

[Robert Mueller]

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?

Rob
Rob Mueller
robm at fastmail.fm