Initial Lookup Slowness BIND 9.2.4

Fri Jan 2 00:20:18 UTC 2009

Upgrade:
1773.   [bug]           Fast retry on host / net unreachable. [RT #13153]

In message <20522.170.149.100.10.1230669064.squirrel at from525.com>, "David Porsc
he'" writes:
> 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
> _______________________________________________
> bind-users mailing list
> bind-users at lists.isc.org
> https://lists.isc.org/mailman/listinfo/bind-users
-- 
Mark Andrews, ISC
1 Seymour St., Dundas Valley, NSW 2117, Australia
PHONE: +61 2 9871 4742                 INTERNET: Mark_Andrews at isc.org