Initial Lookup Slowness BIND 9.2.4

David Porsche' david at from525.com
Fri Jan 2 04:48:37 UTC 2009 

Thanks All!

I upgraded to 9.6 and the slowness issue seems to of disappeared!  This is
a good thing anyway since I wanted to test out some of the new xml stats
features.  Thanks to all who have replied.











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

More information about the bind-users mailing list