Initial Lookup Slowness BIND 9.2.4

Wed Dec 31 14:25:39 UTC 2008

In article <gjdv84$5id$1 at sf1.isc.org>,
David Porsche'  <david at from525.com> wrote:
>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.

I used to notice the same thing when I was running earlier versions of
bind than I am now.  I can't remember at which version the slowness
disappeared, but I think that bind 9.4.* did not show the slowness.
9.2.4 is an ancient version considering that 9.6.0 was just released.
I am running 9.5.1 here.

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

-- 
Tom Schulz
schulz at adi.com