Initial Lookup Slowness BIND 9.2.4

[David Porsche']

All,

I have installed a caching only instance of BIND (9.2.4) on a CentOS
machine on my internal network.  I have noticed that initial DNS requests
against the server take a rather large amount of time (usually around 7
seconds).  I have done some basic troubleshooting and I am coming up at a
loss.  I think my ISP might be doing something "funny" but I am not sure
how to test any further.

I have captured BIND debug info at a trace level of 3 (posted bellow).  I
have also captured snoop data via tcpdump.  From what I can tell; it seems
as if responses are taking a "long" time to come back.  The same behavior
is exhibited for any domain or host I attempt to lookup.

To be clear, everything is working, just much slower than it should for
initial queries.  Any help troubleshooting would be greatly appreciated.


BIND DEBUG DATA

Dec 29 18:14:32.772 client: debug 3: client 192.168.1.136#48327: UDP request
Dec 29 18:14:32.772 security: debug 3: client 192.168.1.136#48327: request
is not signed
Dec 29 18:14:32.772 security: debug 3: client 192.168.1.136#48327:
recursion available: approved
Dec 29 18:14:32.772 client: debug 3: client 192.168.1.136#48327: query
Dec 29 18:14:32.772 security: debug 3: client 192.168.1.136#48327: query
(cache) approved
Dec 29 18:14:32.772 client: debug 3: client 192.168.1.136#48327: replace
Dec 29 18:14:32.772 general: debug 3: clientmgr @0x9b68380: createclients
Dec 29 18:14:32.772 general: debug 3: clientmgr @0x9b68380: recycle
Dec 29 18:14:32.772 resolver: debug 1: createfetch: speedr.com A
Dec 29 18:14:32.772 resolver: debug 3: fctx 0xb609e8a0: create
Dec 29 18:14:32.772 resolver: debug 3: fctx 0xb609e8a0: join
Dec 29 18:14:32.772 resolver: debug 3: fetch 0xb60368b8 (fctx 0xb609e8a0):
created
Dec 29 18:14:32.772 client: debug 3: client @0xb60710f8: udprecv
Dec 29 18:14:32.772 resolver: debug 3: fctx 0xb609e8a0: start
Dec 29 18:14:32.772 resolver: debug 3: fctx 0xb609e8a0: try
Dec 29 18:14:32.772 resolver: debug 3: fctx 0xb609e8a0: cancelqueries
Dec 29 18:14:32.772 resolver: debug 3: fctx 0xb609e8a0: getaddresses
Dec 29 18:14:32.773 resolver: debug 3: fctx 0xb609e8a0: query
Dec 29 18:14:32.773 resolver: debug 3: resquery 0xb6094940 (fctx
0xb609e8a0): send
Dec 29 18:14:32.773 resolver: debug 3: resquery 0xb6094940 (fctx
0xb609e8a0): sent
Dec 29 18:14:32.773 resolver: debug 3: resquery 0xb6094940 (fctx
0xb609e8a0): senddone
Dec 29 18:14:32.773 resolver: debug 3: fctx 0xb609e8a0: cancelquery
Dec 29 18:14:34.775 resolver: debug 3: fctx 0xb609e8a0: timeout
Dec 29 18:14:34.775 resolver: debug 3: fctx 0xb609e8a0: try
Dec 29 18:14:34.775 resolver: debug 3: fctx 0xb609e8a0: query
Dec 29 18:14:34.775 resolver: debug 3: resquery 0xb6094940 (fctx
0xb609e8a0): send
Dec 29 18:14:34.775 resolver: debug 3: resquery 0xb6094940 (fctx
0xb609e8a0): sent
Dec 29 18:14:34.775 resolver: debug 3: resquery 0xb6094940 (fctx
0xb609e8a0): senddone
Dec 29 18:14:34.775 resolver: debug 3: fctx 0xb609e8a0: cancelquery
Dec 29 18:14:36.776 resolver: debug 3: fctx 0xb609e8a0: timeout
Dec 29 18:14:36.776 resolver: debug 3: fctx 0xb609e8a0: try
Dec 29 18:14:36.776 resolver: debug 3: fctx 0xb609e8a0: query
Dec 29 18:14:36.776 resolver: debug 3: resquery 0xb6094940 (fctx
0xb609e8a0): send
Dec 29 18:14:36.776 resolver: debug 3: resquery 0xb6094940 (fctx
0xb609e8a0): sent
Dec 29 18:14:36.776 resolver: debug 3: resquery 0xb6094940 (fctx
0xb609e8a0): senddone
Dec 29 18:14:36.791 client: debug 3: client 192.26.92.30#53: UDP request
Dec 29 18:14:36.792 client: debug 3: client 192.26.92.30#53: next
Dec 29 18:14:36.792 client: debug 3: client 192.26.92.30#53: endrequest
Dec 29 18:14:36.792 client: debug 3: client @0xb60710f8: udprecv
Dec 29 18:14:36.792 resolver: debug 3: resquery 0xb6094940 (fctx
0xb609e8a0): response
Dec 29 18:14:36.792 resolver: debug 3: fctx 0xb609e8a0: noanswer_response
Dec 29 18:14:36.792 resolver: debug 3: fctx 0xb609e8a0: cache_message
Dec 29 18:14:36.792 resolver: debug 3: fctx 0xb609e8a0: cancelquery
Dec 29 18:14:36.792 resolver: debug 3: fctx 0xb609e8a0: cancelqueries
Dec 29 18:14:36.792 resolver: debug 3: fctx 0xb609e8a0: try
Dec 29 18:14:36.792 resolver: debug 3: fctx 0xb609e8a0: cancelqueries
Dec 29 18:14:36.792 resolver: debug 3: fctx 0xb609e8a0: getaddresses
Dec 29 18:14:36.792 resolver: debug 3: fctx 0xb609e8a0: query
Dec 29 18:14:36.792 resolver: debug 3: resquery 0xb6094940 (fctx
0xb609e8a0): send
Dec 29 18:14:36.792 resolver: debug 3: resquery 0xb6094940 (fctx
0xb609e8a0): sent
Dec 29 18:14:36.792 resolver: debug 3: resquery 0xb6094940 (fctx
0xb609e8a0): senddone
Dec 29 18:14:37.773 client: debug 3: client 192.168.1.136#48327: UDP request
Dec 29 18:14:37.773 security: debug 3: client 192.168.1.136#48327: request
is not signed
Dec 29 18:14:37.773 security: debug 3: client 192.168.1.136#48327:
recursion available: approved
Dec 29 18:14:37.773 client: debug 3: client 192.168.1.136#48327: query
Dec 29 18:14:37.773 security: debug 3: client 192.168.1.136#48327: query
(cache) approved
Dec 29 18:14:37.773 client: debug 3: client 192.168.1.136#48327: replace
Dec 29 18:14:37.773 general: debug 3: clientmgr @0x9b68380: createclients
Dec 29 18:14:37.773 general: debug 3: clientmgr @0x9b68380: recycle
Dec 29 18:14:37.773 resolver: debug 1: createfetch: speedr.com A
Dec 29 18:14:37.773 resolver: debug 3: fctx 0xb609e8a0: join
Dec 29 18:14:37.773 resolver: debug 3: fetch 0xb608e830 (fctx 0xb609e8a0):
created
Dec 29 18:14:37.773 client: debug 3: client @0xb6060ea0: udprecv
Dec 29 18:14:38.794 resolver: debug 3: fctx 0xb609e8a0: timeout
Dec 29 18:14:38.794 resolver: debug 3: fctx 0xb609e8a0: try
Dec 29 18:14:38.794 resolver: debug 3: fctx 0xb609e8a0: query
Dec 29 18:14:38.794 resolver: debug 3: resquery 0xb60e4298 (fctx
0xb609e8a0): send
Dec 29 18:14:38.794 resolver: debug 3: resquery 0xb60e4298 (fctx
0xb609e8a0): sent
Dec 29 18:14:38.794 resolver: debug 3: resquery 0xb60e4298 (fctx
0xb609e8a0): senddone
Dec 29 18:14:38.817 client: debug 3: client 128.121.3.72#53: UDP request
Dec 29 18:14:38.817 client: debug 3: client 128.121.3.72#53: next
Dec 29 18:14:38.817 client: debug 3: client 128.121.3.72#53: endrequest
Dec 29 18:14:38.817 client: debug 3: client @0xb6060ea0: udprecv
Dec 29 18:14:38.817 resolver: debug 3: resquery 0xb60e4298 (fctx
0xb609e8a0): response
Dec 29 18:14:38.817 resolver: debug 3: fctx 0xb609e8a0: answer_response
Dec 29 18:14:38.817 resolver: debug 3: fctx 0xb609e8a0: cache_message
Dec 29 18:14:38.817 resolver: debug 3: fctx 0xb609e8a0: cancelquery
Dec 29 18:14:38.817 resolver: debug 3: fctx 0xb609e8a0: done
Dec 29 18:14:38.817 resolver: debug 3: fctx 0xb609e8a0: stopeverything
Dec 29 18:14:38.817 resolver: debug 3: fctx 0xb609e8a0: cancelqueries
Dec 29 18:14:38.817 resolver: debug 3: fctx 0xb609e8a0: cancelquery
Dec 29 18:14:38.817 resolver: debug 3: fctx 0xb609e8a0: sendevents
Dec 29 18:14:38.817 resolver: debug 3: fetch 0xb60368b8 (fctx 0xb609e8a0):
destroyfetch
Dec 29 18:14:38.817 client: debug 3: client 192.168.1.136#48327: send
Dec 29 18:14:38.817 client: debug 3: client 192.168.1.136#48327: sendto
Dec 29 18:14:38.817 client: debug 3: client 192.168.1.136#48327: senddone
Dec 29 18:14:38.817 client: debug 3: client 192.168.1.136#48327: next
Dec 29 18:14:38.817 client: debug 3: client 192.168.1.136#48327: endrequest
Dec 29 18:14:38.817 resolver: debug 3: fetch 0xb608e830 (fctx 0xb609e8a0):
destroyfetch
Dec 29 18:14:38.817 resolver: debug 3: fctx 0xb609e8a0: shutdown
Dec 29 18:14:38.817 client: debug 3: client 192.168.1.136#48327: send
Dec 29 18:14:38.818 client: debug 3: client 192.168.1.136#48327: sendto
Dec 29 18:14:38.818 client: debug 3: client 192.168.1.136#48327: senddone
Dec 29 18:14:38.818 client: debug 3: client 192.168.1.136#48327: next
Dec 29 18:14:38.818 client: debug 3: client 192.168.1.136#48327: endrequest
Dec 29 18:14:38.818 resolver: debug 3: fctx 0xb609e8a0: doshutdown
Dec 29 18:14:38.818 resolver: debug 3: fctx 0xb609e8a0: stopeverything
Dec 29 18:14:38.818 resolver: debug 3: fctx 0xb609e8a0: cancelqueries
Dec 29 18:14:38.818 resolver: debug 3: fctx 0xb609e8a0: destroy