[Bug-wget] Slow DNS resolve (5 seconds)

[Adrian Grajdeanu]

Hi,
I've noticed that wget 1.11.4 is very slow resolving hostnames via DNS. 
Here is what I mean:
>time wget www.google.com
--2008-11-30 09:27:07--  http://www.google.com/
Resolving www.google.com... 64.233.169.103, 64.233.169.104, 
64.233.169.147, ...
Connecting to www.google.com|64.233.169.103|:80... connected.
HTTP request sent, awaiting response... 200 OK
Length: unspecified [text/html]
Saving to: `index.html.6'

    [ <=> 

               ] 5,848       --.-K/s   in 0.01s

2008-11-30 09:27:12 (399 KB/s) - `index.html.6' saved [5848]


real    0m5.047s
user    0m0.002s
sys     0m0.002s

Notice realtime is 5 seconds and change. Five seconds are spent at the 
Resolving www.google.com...
line before answers are provided.

Similar request using curl is 5 seconds faster:

>time curl www.google.com >index.html
  % Total    % Received % Xferd  Average Speed   Time    Time     Time 
 Current
                                 Dload  Upload   Total   Spent    Left 
 Speed
100  5848    0  5848    0     0  83808      0 --:--:-- --:--:-- --:--:-- 
 311k

real    0m0.073s
user    0m0.001s
sys     0m0.002s
>

I've gone and strace the wget and found out a weird thing. Here are the 
calls relevant to DNS request:

socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 3
connect(3, {sa_family=AF_INET, sin_port=htons(53), 
sin_addr=inet_addr("68.105.28.12")}, 28) = 0
fcntl(3, F_GETFL)                       = 0x2 (flags O_RDWR)
fcntl(3, F_SETFL, O_RDWR|O_NONBLOCK)    = 0
poll([{fd=3, events=POLLOUT}], 1, 0)    = 1 ([{fd=3, revents=POLLOUT}])
sendto(3, "\374\346\1\0\0\1\0\0\0\0\0\0\3www\6google\3com\0\0\1\0\1"..., 
32, MSG_NOSIGNAL, NULL, 0) = 32
poll([{fd=3, events=POLLIN|POLLOUT}], 1, 5000) = 1 ([{fd=3, 
revents=POLLOUT}])
sendto(3, "\37\347\1\0\0\1\0\0\0\0\0\0\3www\6google\3com\0\0\34\0\1"..., 
32, MSG_NOSIGNAL, NULL, 0) = 32
poll([{fd=3, events=POLLIN}], 1, 4999)  = 1 ([{fd=3, revents=POLLIN}])
ioctl(3, FIONREAD, [340])               = 0
recvfrom(3, 
"\374\346\201\200\0\1\0\5\0\7\0\7\3www\6google\3com\0\0\1\0\1\300"..., 
2048, 0, {sa_family=AF_INET, sin_port=htons(53), 
sin_addr=inet_addr("68.105.28.12")}, [16]) = 340
poll([{fd=3, events=POLLIN}], 1, 4990)  = 0 (Timeout)
close(3)                                = 0

68.105.28.12 is my DNS server. Notice two sendto calls, then one answer 
(recvfrom) and then, just before close(3) the poll call that waits 5 
seconds before timing out.

A similar trace from wget 1.11.1 (no speed problem there) shows a 
different picture:

socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 3
connect(3, {sa_family=AF_INET, sin_port=htons(53), 
sin_addr=inet_addr("68.100.16.25")}, 28) = 0
fcntl64(3, F_GETFL)                     = 0x2 (flags O_RDWR)
fcntl64(3, F_SETFL, O_RDWR|O_NONBLOCK)  = 0
gettimeofday({1228055607, 339121}, NULL) = 0
poll([{fd=3, events=POLLOUT, revents=POLLOUT}], 1, 0) = 1
send(3, "3\343\1\0\0\1\0\0\0\0\0\0\3www\6google\3com\0\0\34\0\1", 32, 
MSG_NOSIGNAL) = 32
poll([{fd=3, events=POLLIN, revents=POLLIN}], 1, 5000) = 1
ioctl(3, FIONREAD, [100])               = 0
recvfrom(3, 
"3\343\201\200\0\1\0\1\0\1\0\0\3www\6google\3com\0\0\34\0\1"..., 1024, 
0, {sa_family=AF_INET, sin_port=htons(53), 
sin_addr=inet_addr("68.100.16.25")}, [16]) = 100
close(3)                                = 0

This time there's only one send call, one answer (recvfrom) and that's 
all, no timeout.

My wget 1.11.4 is wget-1.11.4-1.fc10.x86_64 on a Fedora 10 machine 
(x86_64). My wget 1.11.1 is wget-1.11.1-1.fc8 on a Fedora 8 32 bits 
machine. Both machines have ipv6 disabled (lsmod | grep ipv6 returns 
nothing, /sbin/ifconfig eth0 shows no ip6 addy).

Any other information needed to pinpoint this issue?


Cheers,
Adrian