bind 9.2.4 --new queries take > 4 seconds

Fri Nov 5 23:59:29 UTC 2004

This is on SuSE 9.2, though it happened on 9.1, too.

   # dig +stats iii.com

   ; <<>> DiG 9.2.4 <<>> +stats iii.com
   ;; global options:  printcmd
   ;; Got answer:
   ;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 25596
   ;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 4, ADDITIONAL:
0

   ;; QUESTION SECTION:
   ;iii.com.			IN	A

   ;; ANSWER SECTION:
   iii.com.		43200	IN	A	205.227.88.2

   ;; AUTHORITY SECTION:
   iii.com.		43200	IN	NS	dnsauth1.sys.gtei.net.
   iii.com.		43200	IN	NS	dnsauth2.sys.gtei.net.
   iii.com.		43200	IN	NS	dnsauth3.sys.gtei.net.
   iii.com.		43200	IN	NS	vega.iii.com.

>>>;; Query time: 4592 msec
   ;; SERVER: 67.121.255.169#53(67.121.255.169)
   ;; WHEN: Fri Nov  5 15:43:48 2004
   ;; MSG SIZE  rcvd: 141

   # 

Almost 4.6 seconds.  After the first time, it's fast (a few ms).

stracing (-f) of named is below.  Notice the two 1.99 second delays at
lines 37 and 76:

 1 [pid 1202] 0.001989 futex(0x8093fb0, FUTEX_WAKE, 1 <unfinished ...>
 2 [pid 1200] 0.002018 <... futex resumed> ) = 0
 3 [pid 1202] 0.000013 <... futex resumed> ) = 1
 4 [pid 1200] 0.001969 futex(0x8093fac, FUTEX_WAIT, 2, NULL
<unfinished ...>
 5 [pid 1202] 0.000018 futex(0x8093fac, FUTEX_WAKE, 1 <unfinished ...>
 6 [pid 1200] 0.001977 <... futex resumed> ) = -1 EAGAIN (Resource
temporarily unavailable)
 7 [pid 1202] 0.000020 <... futex resumed> ) = 0
 8 [pid 1200] 0.001982 futex(0x8093fac, FUTEX_WAKE, 1 <unfinished ...>
 9 [pid 1202] 0.000016 select(39, [5 20 21 22 23 25 26 27 28 29 30 31
32 33 34 35 36 37], [], NULL, NULL <unfinished ...>
10 [pid 1200] 0.001988 <... futex resumed> ) = 0
11 [pid 1200] 0.001993 futex(0x8093f78, FUTEX_WAKE, 1) = 0
12 [pid 1200] 0.004008 recvmsg(24, {msg_name(16)={sa_family=AF_INET,
sin_port=htons(32811), sin_addr=inet_addr("67.121.255.169")},
msg_iov(1)=[{""..., 4096}], msg_controllen=20, msg_control=0x80d0578,
, msg_flags=0}, 0) = 25
13 [pid 1200] 0.003996 gettimeofday({1099698223, 980864}, NULL) = 0
14 [pid 1200] 0.003090 gettimeofday({1099698223, 983864}, NULL) = 0
15 [pid 1200] 0.001953 gettimeofday({1099698223, 985866}, NULL) = 0
16 [pid 1200] 0.001996 recvmsg(24, 0xb7bee940, 0) = -1 EAGAIN
(Resource temporarily unavailable)
17 [pid 1200] 0.001957 write(6, "\30\0\0\0\375\377\377\377", 8
<unfinished ...>
18 [pid 1202] 0.001026 <... select resumed> ) = 1 (in [5])
19 [pid 1200] 0.000057 <... write resumed> ) = 8
20 [pid 1202] 0.000018 read(5, "\30\0\0\0\375\377\377\377", 8) = 8
21 [pid 1202] 0.000064 read(5, 0xb6bec878, 8) = -1 EAGAIN (Resource
temporarily unavailable)
22 [pid 1202] 0.000035 select(39, [5 20 21 22 23 24 25 26 27 28 29 30
31 32 33 34 35 36 37], [], NULL, NULL <unfinished ...>
23 [pid 1200] 0.000810 gettimeofday({1099698223, 991860}, NULL) = 0
24 [pid 1200] 0.002003 gettimeofday({1099698223, 993886}, NULL) = 0
25 [pid 1200] 0.002456 gettimeofday({1099698223, 995860}, NULL) = 0
26 [pid 1200] 0.001585 futex(0x809415c, FUTEX_WAKE, 1) = 1
27 [pid 1201] 0.001945 <... futex resumed> ) = 0
28 [pid 1200] 0.000033 gettimeofday( <unfinished ...>
29 [pid 1201] 0.000969 gettimeofday( <unfinished ...>
30 [pid 1200] 0.000018 <... gettimeofday resumed> {1099698223,
999882}, NULL) = 0
31 [pid 1200] 0.000092 sendmsg(35, {msg_name(28)={sa_family=AF_INET6,
sin6_port=htons(53), inet_pton(AF_INET6, "2001:503:a83e::2:30",
&sin6_addr), sin6_flowinfo=0, sin6_scope_id=0},
msg_iov(1)=[{"\364\372\0\20\0\1\0\0\0\0\0\1\3iii\3com\0\0\1\0\1\0\0)"...,
36}], msg_controllen=0, msg_flags=0}, 0) = -1 ENETUNREACH (Network is
unreachable)
32 [pid 1200] 0.000106 futex(0x8093fb0, FUTEX_WAIT, 2011, NULL
<unfinished ...>
33 [pid 1201] 0.000783 <... gettimeofday resumed> {1099698224, 860},
NULL) = 0
34 [pid 1201] 0.001009 futex(0x8094128, FUTEX_WAKE, 1) = 0
35 [pid 1201] 0.001985 clock_gettime(CLOCK_REALTIME, {1099698224,
4859000}) = 0
36 [pid 1201] 0.002009 futex(0x809415c, FUTEX_WAIT, 1691, {1,
991001000}) = -1 ETIMEDOUT (Connection timed out)
37 [pid 1201] 1.996417 gettimeofday({1099698226, 2469}, NULL) = 0
38 [pid 1201] 0.002184 futex(0x8093fb0, FUTEX_WAKE, 1 <unfinished ...>
39 [pid 1200] 0.002008 <... futex resumed> ) = 0
40 [pid 1201] 0.000012 <... futex resumed> ) = 1
41 [pid 1200] 0.001981 futex(0x8093fac, FUTEX_WAIT, 2, NULL
<unfinished ...>
42 [pid 1201] 0.000018 futex(0x8093fac, FUTEX_WAKE, 1 <unfinished ...>
43 [pid 1200] 0.002035 <... futex resumed> ) = -1 EAGAIN (Resource
temporarily unavailable)
44 [pid 1201] 0.000020 <... futex resumed> ) = 0
45 [pid 1200] 0.001924 futex(0x8093fac, FUTEX_WAKE, 1 <unfinished ...>
46 [pid 1201] 0.000016 futex(0x8094128, FUTEX_WAKE, 1 <unfinished ...>
47 [pid 1200] 0.001990 <... futex resumed> ) = 0
48 [pid 1201] 0.000012 <... futex resumed> ) = 0
49 [pid 1200] 0.002036 futex(0x8093f78, FUTEX_WAKE, 1 <unfinished ...>
50 [pid 1201] 0.000018 clock_gettime(CLOCK_REALTIME,  <unfinished ...>
51 [pid 1200] 0.001928 <... futex resumed> ) = 0
52 [pid 1201] 0.000012 <... clock_gettime resumed> {1099698226,
17498000}) = 0
53 [pid 1200] 0.002035 gettimeofday( <unfinished ...>
54 [pid 1201] 0.000016 futex(0x809415c, FUTEX_WAIT, 1693, {18,
699694000} <unfinished ...>
55 [pid 1200] 0.001951 <... gettimeofday resumed> {1099698226, 21465},
NULL) = 0
56 [pid 1200] 0.001985 gettimeofday({1099698226, 25478}, NULL) = 0
57 [pid 1200] 0.002023 futex(0x809415c, FUTEX_WAKE, 1 <unfinished ...>
58 [pid 1201] 0.000982 <... futex resumed> ) = 0
59 [pid 1200] 0.000011 <... futex resumed> ) = 1
60 [pid 1201] 0.000016 futex(0x8094158, FUTEX_WAIT, 2, NULL
<unfinished ...>
61 [pid 1200] 0.000971 futex(0x8094158, FUTEX_WAKE, 1 <unfinished ...>
62 [pid 1201] 0.001003 <... futex resumed> ) = 0
63 [pid 1200] 0.000012 <... futex resumed> ) = 1
64 [pid 1201] 0.000015 futex(0x8094158, FUTEX_WAKE, 1) = 0
65 [pid 1201] 0.000024 futex(0x8094128, FUTEX_WAIT, 2, NULL
<unfinished ...>
66 [pid 1200] 0.000947 futex(0x8094128, FUTEX_WAKE, 1 <unfinished ...>
67 [pid 1201] 0.000996 <... futex resumed> ) = 0
68 [pid 1200] 0.000011 <... futex resumed> ) = 1
69 [pid 1201] 0.000016 gettimeofday({1099698226, 31509}, NULL) = 0
70 [pid 1201] 0.000036 futex(0x8094128, FUTEX_WAKE, 1) = 0
71 [pid 1201] 0.000022 clock_gettime(CLOCK_REALTIME, {1099698226,
31567000}) = 0
72 [pid 1201] 0.000029 futex(0x809415c, FUTEX_WAIT, 1695, {1,
993911000} <unfinished ...>
73 [pid 1200] 0.000900 gettimeofday({1099698226, 33462}, NULL) = 0
74 [pid 1200] 0.002051 sendmsg(35, {msg_name(28)={sa_family=AF_INET6,
sin6_port=htons(53), inet_pton(AF_INET6, "2001:503:231d::2:30",
&sin6_addr), sin6_flowinfo=0, sin6_scope_id=0},
msg_iov(1)=[{"\372}\0\20\0\1\0\0\0\0\0\1\3iii\3com\0\0\1\0\1\0\0)\10"...,
36}], msg_controllen=0, msg_flags=0}, 0) = -1 ENETUNREACH (Network is
unreachable)
75 [pid 1200] 0.001959 futex(0x8093fb0, FUTEX_WAIT, 2013, NULL
<unfinished ...>
76 [pid 1201] 1.992584 <... futex resumed> ) = -1 ETIMEDOUT
(Connection timed out)
77 [pid 1201] 0.002051 gettimeofday({1099698228, 32072}, NULL) = 0
78 [pid 1201] 0.003950 futex(0x8093fb0, FUTEX_WAKE, 1 <unfinished ...>
79 [pid 1200] 0.002006 <... futex resumed> ) = 0
80 [pid 1201] 0.000012 <... futex resumed> ) = 1
81 [pid 1200] 0.001983 futex(0x8093fac, FUTEX_WAIT, 2, NULL
<unfinished ...>
82 [pid 1201] 0.000019 futex(0x8093fac, FUTEX_WAKE, 1 <unfinished ...>

Here's what I've tried:

1. rebuilt named with --disable-ipv6, made no difference -- the ipv6
   address made me suspicious, but it's in a different process
2. options in named.conf:

  options {
	directory "/var/lib/named";
	 query-source port 53;
  };
3. have up-to-date root hints file
  (ie, mine is the same as ftp://ftp.internic.net/domain/named.root)

Ideas, anyone?  I'm at wits end on this...
thanks.

Kevin Layer