Initial Lookup Slowness BIND 9.2.4
David Porsche'
david at from525.com
Tue Dec 30 21:44:29 UTC 2008
FYI,
Here is the snoop data I forgot to post before.
**NOTE** This snoop data is from a different lookup than the BIND debug
data I posted earlier. If expanded snoop data is needed to help
troubleshoot please let me know and I will be happy to provide it.
Snoop Data
No. Time Source Destination
Protocol Info
26 13:05:01.576841 192.168.1.136 192.228.79.201 DNS
Standard query A digg.com
27 13:05:01.577330 192.168.1.136 192.228.79.201 DNS
Standard query NS <Root>
29 13:05:01.672651 192.228.79.201 192.168.1.136 DNS
Standard query response
30 13:05:01.674168 192.168.1.136 192.52.178.30 DNS
Standard query A digg.com
44 13:05:03.578357 192.168.1.136 192.112.36.4 DNS
Standard query NS <Root>
45 13:05:03.629167 192.112.36.4 192.168.1.136 DNS
Standard query response NS A.ROOT-SERVERS.NET NS E.ROOT-SERVERS.NET
NS M.ROOT-SERVERS.NET NS I.ROOT-SERVERS.NET NS L.ROOT-SERVERS.NET NS
K.ROOT-SERVERS.NET NS C.ROOT-SERVERS.NET NS H.ROOT-SERVERS.NET NS
D.ROOT-SERVERS.NET NS J.ROOT-SERVERS.NET NS B.ROOT-SERVERS.NET NS
G.ROOT-SERVERS.NET NS F.ROOT-SERVERS.NET
46 13:05:03.675242 192.168.1.136 192.5.6.30 DNS
Standard query A digg.com
55 13:05:05.676885 192.168.1.136 192.42.93.30 DNS
Standard query A digg.com
56 13:05:05.773642 192.42.93.30 192.168.1.136 DNS
Standard query response
57 13:05:05.775441 192.168.1.136 192.36.148.17 DNS
Standard query A udns1.ultradns.net
58 13:05:05.775844 192.168.1.136 192.36.148.17 DNS
Standard query A6 udns1.ultradns.net
59 13:05:05.776277 192.168.1.136 192.36.148.17 DNS
Standard query A udns2.ultradns.net
60 13:05:05.776701 192.168.1.136 192.36.148.17 DNS
Standard query A6 udns2.ultradns.net
65 13:05:05.896455 192.36.148.17 192.168.1.136 DNS
Standard query response
66 13:05:05.897853 192.168.1.136 192.5.6.30 DNS
Standard query A udns1.ultradns.net
67 13:05:05.900602 192.36.148.17 192.168.1.136 DNS
Standard query response
68 13:05:05.900609 192.36.148.17 192.168.1.136 DNS
Standard query response
69 13:05:05.901768 192.168.1.136 192.5.6.30 DNS
Standard query A udns2.ultradns.net
70 13:05:05.901881 192.36.148.17 192.168.1.136 DNS
Standard query response
71 13:05:05.902630 192.168.1.136 192.5.6.30 DNS
Standard query A6 udns1.ultradns.net
72 13:05:05.903701 192.168.1.136 192.5.6.30 DNS
Standard query A6 udns2.ultradns.net
73 13:05:06.063030 192.5.6.30 192.168.1.136 DNS
Standard query response A 204.69.234.1
74 13:05:06.064088 192.168.1.136 204.69.234.1 DNS
Standard query A digg.com
75 13:05:06.068817 192.5.6.30 192.168.1.136 DNS
Standard query response A 204.74.101.1
76 13:05:06.069384 192.5.6.30 192.168.1.136 DNS
Standard query response
77 13:05:06.069390 192.5.6.30 192.168.1.136 DNS
Standard query response
78 13:05:06.071696 192.168.1.136 204.74.109.1 DNS
Standard query A6 udns1.ultradns.net
79 13:05:06.072396 192.168.1.136 204.74.109.1 DNS
Standard query A6 udns2.ultradns.net
80 13:05:06.072841 192.168.1.136 192.33.4.12 DNS
Standard query A pdns3.ultradns.org
81 13:05:06.073217 192.168.1.136 192.33.4.12 DNS
Standard query A6 pdns3.ultradns.org
82 13:05:06.073649 192.168.1.136 192.33.4.12 DNS
Standard query A pdns4.ultradns.org
83 13:05:06.074044 192.168.1.136 192.33.4.12 DNS
Standard query A6 pdns4.ultradns.org
84 13:05:06.074470 192.168.1.136 192.33.4.12 DNS
Standard query A pdns5.ultradns.info
85 13:05:06.074874 192.168.1.136 192.33.4.12 DNS
Standard query A6 pdns5.ultradns.info
86 13:05:06.075345 192.168.1.136 192.33.4.12 DNS
Standard query A pdns6.ultradns.co.uk
87 13:05:06.075752 192.168.1.136 192.33.4.12 DNS
Standard query A6 pdns6.ultradns.co.uk
88 13:05:06.088138 204.74.109.1 192.168.1.136 DNS
Standard query response
89 13:05:06.089304 192.168.1.136 204.74.108.1 DNS
Standard query AAAA udns1.ultradns.net
90 13:05:06.092343 204.74.109.1 192.168.1.136 DNS
Standard query response
91 13:05:06.092415 192.33.4.12 192.168.1.136 DNS
Standard query response
92 13:05:06.093735 192.168.1.136 199.19.57.1 DNS
Standard query A pdns3.ultradns.org
93 13:05:06.094471 192.168.1.136 204.74.108.1 DNS
Standard query AAAA udns2.ultradns.net
94 13:05:06.095224 192.33.4.12 192.168.1.136 DNS
Standard query response
95 13:05:06.095947 192.168.1.136 199.19.57.1 DNS
Standard query A6 pdns3.ultradns.org
96 13:05:06.096055 192.33.4.12 192.168.1.136 DNS
Standard query response
97 13:05:06.096781 192.168.1.136 199.19.57.1 DNS
Standard query A pdns4.ultradns.org
98 13:05:06.098855 192.33.4.12 192.168.1.136 DNS
Standard query response
99 13:05:06.098861 192.33.4.12 192.168.1.136 DNS
Standard query response
100 13:05:06.099973 192.168.1.136 199.249.113.1 DNS
Standard query A6 pdns5.ultradns.info
101 13:05:06.100126 204.69.234.1 192.168.1.136 DNS
Standard query response A 64.191.203.30
102 13:05:06.100993 192.168.1.136 204.74.113.44 DNS
Standard query A pdns6.ultradns.co.uk
106 13:05:06.121429 204.74.113.44 192.168.1.136 DNS
Standard query response A 204.74.115.1
107 13:05:06.121448 204.74.108.1 192.168.1.136 DNS
Standard query response
111 13:05:06.132240 204.74.108.1 192.168.1.136 DNS
Standard query response
112 13:05:06.142383 199.19.57.1 192.168.1.136 DNS
Standard query response
113 13:05:06.143226 192.168.1.136 199.7.69.1 DNS
Standard query A pdns3.ultradns.org
114 13:05:06.146285 199.19.57.1 192.168.1.136 DNS
Standard query response
115 13:05:06.146291 199.19.57.1 192.168.1.136 DNS
Standard query response
116 13:05:06.147175 192.168.1.136 199.7.69.1 DNS
Standard query A6 pdns3.ultradns.org
117 13:05:06.147802 192.168.1.136 199.7.69.1 DNS
Standard query A pdns4.ultradns.org
118 13:05:06.162990 199.7.69.1 192.168.1.136 DNS
Standard query response A 199.7.68.1
119 13:05:06.168279 199.7.69.1 192.168.1.136 DNS
Standard query response
120 13:05:06.169386 192.168.1.136 199.7.68.1 DNS
Standard query AAAA pdns3.ultradns.org
123 13:05:06.171642 199.7.69.1 192.168.1.136 DNS
Standard query response A 199.7.69.1
126 13:05:06.205035 199.7.68.1 192.168.1.136 DNS
Standard query response
127 13:05:06.365001 199.249.113.1 192.168.1.136 DNS
Standard query response
128 13:05:06.365952 192.168.1.136 204.74.114.1 DNS
Standard query A6 pdns5.ultradns.info
129 13:05:06.399487 204.74.114.1 192.168.1.136 DNS
Standard query response
130 13:05:06.400732 192.168.1.136 204.74.115.1 DNS
Standard query AAAA pdns5.ultradns.info
131 13:05:06.414880 204.74.115.1 192.168.1.136 DNS
Standard query response
> 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
>
More information about the bind-users
mailing list