Home

Very slow DNS lookups (5s timeouts) for network clients

Wed, 2011.10.26 - 14:07 — müzso
https://bbs.archlinux.org/viewtopic.php?id=75770
I've experienced the same 5 second long DNS lookups on a Debian 6.* (Squeeze) server using amd64 architecture and the options single-request in /etc/resolv.conf helped me too. Using strace -T ... on the command that exhibits the slow DNS behaviour you can easily identify the culprit.

Eg. for my wget command I've found this in the strace output:
...
open("/lib/libresolv.so.2", O_RDONLY)   = 4 <0.000014>
read(4, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\3008\0\0\0\0\0\0"..., 832) = 832 <0.000006>
fstat(4, {st_mode=S_IFREG|0644, st_size=80712, ...}) = 0 <0.000006>
mmap(NULL, 2185864, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 4, 0) = 0x7f5f30dcd000 <0.000008>
mprotect(0x7f5f30de0000, 2093056, PROT_NONE) = 0 <0.000009>
mmap(0x7f5f30fdf000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 4, 0x12000) = 0x7f5f30fdf000 <0.000008>
mmap(0x7f5f30fe1000, 6792, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f5f30fe1000 <0.000008>
close(4)                                = 0 <0.000005>
mprotect(0x7f5f30fdf000, 4096, PROT_READ) = 0 <0.000016>
mprotect(0x7f5f311e7000, 4096, PROT_READ) = 0 <0.000008>
munmap(0x7f5f3279f000, 27837)           = 0 <0.000009>
stat("/etc/resolv.conf", {st_mode=S_IFREG|0644, st_size=63, ...}) = 0 <0.000008>
open("/etc/resolv.conf", O_RDONLY)      = 4 <0.000008>
fstat(4, {st_mode=S_IFREG|0644, st_size=63, ...}) = 0 <0.000006>
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5f327a5000 <0.000006>
read(4, "nameserver 84.2.44.1\nnameserver "..., 4096) = 63 <0.000008>
read(4, "", 4096)                       = 0 <0.000005>
close(4)                                = 0 <0.000011>
munmap(0x7f5f327a5000, 4096)            = 0 <0.000008>
socket(PF_INET, SOCK_DGRAM|SOCK_NONBLOCK, IPPROTO_IP) = 4 <0.000009>
connect(4, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("84.2.44.1")}, 16) = 0 <0.000010>
poll([{fd=4, events=POLLOUT}], 1, 0)    = 1 ([{fd=4, revents=POLLOUT}]) <0.000006>
sendto(4, "5]\1\0\0\1\0\0\0\0\0\0\5apps4\texample\2com\0"..., 36, MSG_NOSIGNAL, NULL, 0) = 36 <0.000020>
poll([{fd=4, events=POLLIN|POLLOUT}], 1, 5000) = 1 ([{fd=4, revents=POLLOUT}]) <0.000007>
sendto(4, "\232\177\1\0\0\1\0\0\0\0\0\0\5apps4\texample\2com\0"..., 36, MSG_NOSIGNAL, NULL, 0) = 36 <0.000015>
poll([{fd=4, events=POLLIN}], 1, 4999)  = 1 ([{fd=4, revents=POLLIN}]) <0.001566>
ioctl(4, FIONREAD, [52])                = 0 <0.000006>
recvfrom(4, "5]\201\200\0\1\0\1\0\0\0\0\5apps4\t3example\2com\0"..., 2048, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("84.2.44.1")}, [16]) = 52 <0.000009>
poll([{fd=4, events=POLLIN}], 1, 4998)  = 0 (Timeout) <5.001842>
...

Wget uses libresolv for DNS resolution, while other utilities (eg. PHP) use libnss_dns (as mentioned in the forum post too).
For the latter the timeout looks in the strace -T ... output like this:
...
open("/lib/libnss_dns.so.2", O_RDONLY)  = 3 <0.000009>
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\0\20\0\0\0\0\0\0"..., 832) = 832 <0.000006>
fstat(3, {st_mode=S_IFREG|0644, st_size=22928, ...}) = 0 <0.000006>
mmap(NULL, 2117888, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f102ff1f000 <0.000016>
mprotect(0x7f102ff24000, 2093056, PROT_NONE) = 0 <0.000010>
mmap(0x7f1030123000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x4000) = 0x7f1030123000 <0.000008>
close(3)                                = 0 <0.000006>
mprotect(0x7f1030123000, 4096, PROT_READ) = 0 <0.000009>
munmap(0x7f1038662000, 27837)           = 0 <0.000009>
stat("/etc/resolv.conf", {st_mode=S_IFREG|0644, st_size=63, ...}) = 0 <0.000008>
open("/etc/resolv.conf", O_RDONLY)      = 3 <0.000009>
fstat(3, {st_mode=S_IFREG|0644, st_size=63, ...}) = 0 <0.000005>
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f1038668000 <0.000006>
read(3, "nameserver 84.2.44.1\nnameserver "..., 4096) = 63 <0.000008>
read(3, "", 4096)                       = 0 <0.000009>
close(3)                                = 0 <0.000006>
munmap(0x7f1038668000, 4096)            = 0 <0.000016>
socket(PF_INET, SOCK_DGRAM|SOCK_NONBLOCK, IPPROTO_IP) = 3 <0.000009>
connect(3, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("84.2.44.1")}, 16) = 0 <0.000011>
poll([{fd=3, events=POLLOUT}], 1, 0)    = 1 ([{fd=3, revents=POLLOUT}]) <0.000009>
sendto(3, "m\272\1\0\0\1\0\0\0\0\0\0\5apps4\texample\2com\0"..., 36, MSG_NOSIGNAL, NULL, 0) = 36 <0.000019>
poll([{fd=3, events=POLLIN|POLLOUT}], 1, 5000) = 1 ([{fd=3, revents=POLLOUT}]) <0.000008>
sendto(3, "\240E\1\0\0\1\0\0\0\0\0\0\5apps4\texample\2com\0"..., 36, MSG_NOSIGNAL, NULL, 0) = 36 <0.000019>
poll([{fd=3, events=POLLIN}], 1, 4999)  = 1 ([{fd=3, revents=POLLIN}]) <0.002000>
ioctl(3, FIONREAD, [103])               = 0 <0.000007>
recvfrom(3, "m\272\201\200\0\1\0\1\0\2\0\0\5apps4\texample\2com\0"..., 2048, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("84.2.44.1")}, [16]) = 103 <0.000009>
poll([{fd=3, events=POLLIN}], 1, 4997)  = 0 (Timeout) <5.001428>
...

The options single-request solution worked for me for both libs.

Some links related to the matter: