7.3 + kqueue + apache/php + DNS lookup problem

[Doug Barton]

Thanks Jeremy and Chuck. Answers below.

On 09/30/2011 17:37, Jeremy Chadwick wrote:
> 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.

That's not necessarily off the table, but doing that would have to be
because we're sure it would fix the problem.

> 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?

It's a php module doing a lookup for the hostname of the back-end mysql
server.

> Are the delays always 3 seconds? 

Pretty much.

> If so, that almost sounds like a timeout of some kind.  

That was my first thought, but the answer always comes eventually.

To answer Chuck's questions, no threading is involved, and it's not
apache doing the lookups.


Doug

-- 

	Nothin' ever doesn't change, but nothin' changes much.
			-- OK Go

	Breadth of IT experience, and depth of knowledge in the DNS.
	Yours for the right price.  :)  http://SupersetSolutions.com/