7.3 + kqueue + apache/php + DNS lookup problem

[Jeremy Chadwick]

On Fri, Sep 30, 2011 at 04:31:18PM -0700, Doug Barton wrote:
> Howdy,
> 
> So, this is a bit of an odd one .... I've got a web server running
> apache 2.2.17 and php 5.3.5. The host itself is running 7.3-RELEASE,
> i386, and is not busy. I can do DNS queries on the command line all day
> long and they are very snappy. Using nslookup, dig, whatever.
> 
> The weirdness comes in when the httpd process needs to do a DNS lookup.
> With a local cache I'm getting the following:
> 
> 97625 httpd    0.031139 CALL  connect(0x55,0x284fd590,0x10)
> 97625 httpd    0.031142 STRU  struct sockaddr { AF_INET, 127.0.0.1:53 }
> 97625 httpd    0.031150 RET   connect 0
> 97625 httpd    0.031153 CALL  sendto(0x55,0x2a7d1000,0x1e,0,0,0)
> 97625 httpd    0.031169 GIO   fd 85 wrote 30 bytes
> 97625 httpd    0.031173 RET   sendto 30/0x1e
> 97625 httpd    0.031179 CALL  clock_gettime(0,0xbfbfb58c)
> 97625 httpd    0.031184 RET   clock_gettime 0
> 97625 httpd    0.031188 CALL
> kevent(0x54,0xbfbfb678,0x1,0xbfbfb678,0x1,0xbfbfb68c)
> 97625 httpd    3.064266 GIO   fd 84 wrote 20 bytes
> 
> .... note the 3 second delay here.
> 
> 97625 httpd    3.064277 GIO   fd 84 read 20 bytes
> 97625 httpd    3.064281 RET   kevent 1
> 97625 httpd    3.064287 CALL
> recvfrom(0x55,0x2a6c4000,0x10000,0,0xbfbfb5f8,0xbfbfb694)
> 97625 httpd    3.064293 GIO   fd 85 read 30 bytes
> 97625 httpd    3.064296 STRU  struct sockaddr { AF_INET, 127.0.0.1:53 }
> 97625 httpd    3.064299 RET   recvfrom 30/0x1e
> 97625 httpd    3.064308 CALL  close(0x55)
> 
> I'm open to suggestions on where to look to improve this situation.

I'm not familiar with the kqueue event mechanism in BSD.  I know it's
great, but I'm just not familiar with how to use it/etc..  If I'm
reading the syscall trace correctly, it looks like the daemon opens up a
socket to 127.0.0.1:53 (named) on fd 0x55/85, writes 30 bytes of data to
it, initiates a kernel event that writes 20 bytes of data to a different
descriptor 0x54/84, reads 20 bytes back from that fd, then reads 30
bytes from descriptor 0x55/85.

I wonder what the kevent() is actually accomplishing here.  I wish I
could see within the kevent structs at 0xbfbfb678 and 0xbfbfb678, and
the timespec struct at 0xbfbfb68c.

There's also a part of me that remembers some sort of kevent/kqueue
problem on older FreeBSD that got fixed at one point.  The problem is
that I can't remember what that problem was, nor what release fixed it.
As such I don't want to resort to a "upgrade your OS!" response.

Does this happen when httpd tries to do DNS resolution for, say, an
incoming connection to the web server (e.g. trying to resolve the
incoming IP address of the client to an FQDN), or is it happening within
some PHP code (assuming PHP is installed/used as an Apache module)
that's trying to do DNS resolution of some kind?

Are the delays always 3 seconds?  If so, that almost sounds like a
timeout of some kind.  That's the thing about the kevent() call: I wish
I could see what's in the timespec struct, since that's what defines the
timeout values.

-- 
| Jeremy Chadwick                                jdc at parodius.com |
| Parodius Networking                       http://www.parodius.com/ |
| UNIX Systems Administrator                   Mountain View, CA, US |
| Making life hard for others since 1977.               PGP 4BD6C0CB |