Package: nscd Version: 2.3.2.ds1-18
System Description: kernel = 2.4.27-1-k7 libc6 = 2.3.2.ds1-18 mozilla = 1.7.3-5
Symptom:
After completing an 'apt-get upgrade', I noticed that mozilla was frequently taking a long amount of time to do a host name lookup. Even sites visited a few minutes previously required 10+ seconds to complete a host name lookup. Additionally, 'ping <hostname>' also takes an inordinate amount of time in it's host lookup (see below).
My initial thinking was nscd and I've found some issues that may be the cause of this problem. Note that I am using a cable modem on my home connection.
***************** Case 1 (Case 2 follows) - Hostname not in cache:
console command (debug output follows):
# ping www.drudgeport.com
<delay of about 6 seconds>
PING drudgereport.com (66.28.209.210) 56(84) bytes of data.
<delay of about 6 seconds>
64 bytes from 66.28.209.210.ha-hosting.com (66.28.209.210): icmp_seq=1 ttl=51 time=82.8 ms
...
Debug output (note this is the first time I've ping this host so I expect the following output):
handle_request: request received (Version = 2) from PID 2299
2264: GETHOSTBYNAME (www.drudgereport.com)
2264: Haven't found "www.drudgereport.com" in hosts cache!
2264: handle_request: request received (Version = 2) from PID 2299
2264: GETHOSTBYADDR (66.28.209.210)
2264: Haven't found "66.28.209.210" in hosts cache!
2264: handle_request: request received (Version = 2) from PID 2299
2264: GETHOSTBYADDR (66.28.209.210)
***************
Case 2 - Hostname should be in cache...I'm repeating the ping <hostname> command about 5 seconds after completing Case 1 above.
console command (debug output follows):
# ping www.drudgeport.com
<delay of about 6 seconds>
PING drudgereport.com (66.28.209.210) 56(84) bytes of data.
<delay of about 6 seconds>
64 bytes from 65.77.130.210.ha-hosting.com (65.77.130.210): icmp_seq=1 ttl=51 time=90.8 ms
...
Debug output: 2356: handle_request: request received (Version = 2) from PID 2364 2356: GETHOSTBYNAME (www.drudgereport.com) 2356: Haven't found "www.drudgereport.com" in hosts cache! 2360: handle_request: request received (Version = 2) from PID 2364 2360: GETHOSTBYADDR (66.28.209.210) 2360: Haven't found "66.28.209.210" in hosts cache! 2361: handle_request: request received (Version = 2) from PID 2364 2361: GETHOSTBYADDR (66.28.209.210) 2362: handle_request: request received (Version = 2) from PID 2364 2362: GETHOSTBYADDR (66.28.209.210)
Stack trace:
[pid 2357] getppid() = 2356
[pid 2357] poll( <unfinished ...>
[pid 2358] <... poll resumed> [{fd=3, events=POLLRDNORM, revents=POLLRDNORM}],1, 15000) = 1
[pid 2356] <... accept resumed> 0, NULL) = 7
[pid 2358] accept(3, <unfinished ...>
[pid 2356] read(7, "\2\0\0\0\4\0\0\0\25\0\0\0", 12) = 12
[pid 2356] getsockopt(7, SOL_SOCKET, SO_PEERCRED, "<\t\0\0\0\0\0\0\0\0\0\0", [12]) = 0
[pid 2356] read(7, "www.drudgereport.com\0", 21) = 21
[pid 2356] getpid() = 2356
[pid 2356] write(4, "2356: handle_request: request re"..., 67) = 67
[pid 2356] getpid() = 2356
[pid 2356] write(4, "2356: \tGETHOSTBYNAME (www.drudge"..., 44) = 44
[pid 2356] getpid() = 2356
[pid 2356] write(4, "2356: Haven\'t found \"www.drudger"..., 59) = 59
[pid 2356] gettimeofday({1099173622, 875148}, NULL) = 0
[pid 2356] getpid() = 2356
[pid 2356] open("/etc/resolv.conf", O_RDONLY) = 8
[pid 2356] fstat64(8, {st_mode=S_IFREG|0644, st_size=266, ...}) = 0
[pid 2356] old_mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x40018000
[pid 2356] read(8, "# Dynamic resolv.conf(5) file fo"..., 4096) = 266
[pid 2356] read(8, "", 4096) = 0
[pid 2356] close(8) = 0
[pid 2356] munmap(0x40018000, 4096) = 0
[pid 2356] open("/etc/hosts", O_RDONLY) = 8
[pid 2356] fcntl64(8, F_GETFD) = 0
[pid 2356] fcntl64(8, F_SETFD, FD_CLOEXEC) = 0
[pid 2356] fstat64(8, {st_mode=S_IFREG|0644, st_size=309, ...}) = 0
[pid 2356] old_mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x40018000
[pid 2356] read(8, "127.0.0.1\tlocalhost\tarrakis\n\n192"..., 4096) = 309
[pid 2356] read(8, "", 4096) = 0
[pid 2356] close(8) = 0
[pid 2356] munmap(0x40018000, 4096) = 0
[pid 2356] socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 8
[pid 2356] connect(8, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("10.0.0.1")}, 28) = 0
[pid 2356] send(8, "]O\1\0\0\1\0\0\0\0\0\0\3www\fdrudgereport\3co"..., 38, 0) = 38
[pid 2356] gettimeofday({1099173622, 877606}, NULL) = 0
[pid 2356] poll( <unfinished ...>
[pid 2357] <... poll resumed> [{fd=5, events=POLLIN}], 1, 2000) = 0
[pid 2357] getppid() = 2356
[pid 2357] poll([{fd=5, events=POLLIN}], 1, 2000) = 0
[pid 2357] getppid() = 2356
[pid 2357] poll([{fd=5, events=POLLIN}], 1, 2000) = 0
[pid 2357] getppid() = 2356
[pid 2357] poll( <unfinished ...>
[pid 2356] <... poll resumed> [{fd=8, events=POLLIN}], 1, 5000) = 0
[pid 2356] socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 9
[pid 2356] connect(9, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("66.235.59.6")}, 28) = 0
[pid 2356] send(9, "]O\1\0\0\1\0\0\0\0\0\0\3www\fdrudgereport\3co"..., 38, 0) = 38
[pid 2356] gettimeofday({1099173627, 880871}, NULL) = 0
[pid 2356] poll([{fd=9, events=POLLIN, revents=POLLIN}], 1, 3000) = 1
[pid 2356] ioctl(9, FIONREAD, [152]) = 0
[pid 2356] recvfrom(9, "]O\201\200\0\1\0\3\0\2\0\2\3www\fdrudgereport\3co"...,1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("66.235.59.6")}, [16]) = 152
[pid 2356] close(8) = 0
[pid 2356] close(9) = 0
[pid 2356] time(NULL) = 1099173628
[pid 2356] write(7, "\2\0\0\0\1\0\0\0\21\0\0\0\1\0\0\0\2\0\0\0\4\0\0\0\2\0\0"..., 82) = 82
[pid 2356] close(7) = 0
[pid 2356] poll([{fd=3, events=POLLRDNORM}], 1, 0) = 0
[pid 2356] time(NULL) = 1099173628
[pid 2356] poll([{fd=3, events=POLLRDNORM}], 1, 0) = 0
[pid 2356] time(NULL) = 1099173628
[pid 2356] stat64("/etc/passwd", {st_mode=S_IFREG|0644, st_size=1151, ...}) = 0
[pid 2356] time(NULL) = 1099173628
[pid 2356] poll([{fd=3, events=POLLRDNORM}], 1, 0) = 0
[pid 2356] time(NULL) = 1099173628
[pid 2356] poll( <unfinished ...>
[pid 2360] <... accept resumed> 0, NULL) = 7
[pid 2356] <... poll resumed> [{fd=3, events=POLLRDNORM, revents=POLLRDNORM}],1, 15000) = 1
[pid 2360] read(7, <unfinished ...>
[pid 2356] accept(3, <unfinished ...>
[pid 2360] <... read resumed> "\2\0\0\0\6\0\0\0\4\0\0\0", 12) = 12
[pid 2360] getsockopt(7, SOL_SOCKET, SO_PEERCRED, "<\t\0\0\0\0\0\0\0\0\0\0", [12]) = 0
[pid 2360] read(7, "B\34\321\322", 4) = 4
[pid 2360] getpid() = 2360
[pid 2360] write(4, "2360: handle_request: request re"..., 67) = 67
[pid 2360] getpid() = 2360
[pid 2360] write(4, "2360: \tGETHOSTBYADDR (66.28.209."..., 37) = 37
[pid 2360] getpid() = 2360
[pid 2360] write(4, "2360: Haven\'t found \"66.28.209.2"..., 52) = 52
[pid 2360] open("/etc/hosts", O_RDONLY) = 8
[pid 2360] fcntl64(8, F_GETFD) = 0
[pid 2360] fcntl64(8, F_SETFD, FD_CLOEXEC) = 0
[pid 2360] fstat64(8, {st_mode=S_IFREG|0644, st_size=309, ...}) = 0
[pid 2360] old_mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x40018000
[pid 2360] read(8, "127.0.0.1\tlocalhost\tarrakis\n\n192"..., 4096) = 309
[pid 2360] read(8, "", 4096) = 0
[pid 2360] close(8) = 0
[pid 2360] munmap(0x40018000, 4096) = 0
[pid 2360] socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 8
[pid 2360] connect(8, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("10.0.0.1")}, 28) = 0
[pid 2360] send(8, "G,\1\0\0\1\0\0\0\0\0\0\003210\003209\00228\00266\7in-a"..., 44, 0) = 44
[pid 2360] gettimeofday({1099173628, 128120}, NULL) = 0
[pid 2360] poll( <unfinished ...>
[pid 2357] <... poll resumed> [{fd=5, events=POLLIN}], 1, 2000) = 0
[pid 2357] getppid() = 2356
[pid 2357] poll([{fd=5, events=POLLIN}], 1, 2000) = 0
[pid 2357] getppid() = 2356
[pid 2357] poll( <unfinished ...>
[pid 2360] <... poll resumed> [{fd=8, events=POLLIN}], 1, 5000) = 0
[pid 2360] socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 9
[pid 2360] connect(9, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("66.235.59.6")}, 28) = 0
[pid 2360] send(9, "G,\1\0\0\1\0\0\0\0\0\0\003210\003209\00228\00266\7in-a"..., 44, 0) = 44
[pid 2360] gettimeofday({1099173633, 129966}, NULL) = 0
[pid 2360] poll([{fd=9, events=POLLIN, revents=POLLIN}], 1, 3000) = 1
[pid 2360] ioctl(9, FIONREAD, [140]) = 0
[pid 2360] recvfrom(9, "G,\201\200\0\1\0\1\0\3\0\0\003210\003209\00228\00266\7"..., 1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("66.235.59.6")}, [16]) = 140
[pid 2360] close(8) = 0
[pid 2360] close(9) = 0
[pid 2360] time(NULL) = 1099173633
[pid 2360] write(7, "\2\0\0\0\1\0\0\0\35\0\0\0\0\0\0\0\2\0\0\0\4\0\0\0\1\0\0"..., 65) = 65
[pid 2360] close(7) = 0
[pid 2360] poll([{fd=3, events=POLLRDNORM}], 1, 0) = 0
[pid 2360] accept(3, <unfinished ...>
[pid 2361] <... accept resumed> 0, NULL) = 7
[pid 2361] read(7, "\2\0\0\0\6\0\0\0\4\0\0\0", 12) = 12
[pid 2361] getsockopt(7, SOL_SOCKET, SO_PEERCRED, "<\t\0\0\0\0\0\0\0\0\0\0", [12]) = 0
[pid 2361] read(7, "B\34\321\322", 4) = 4
[pid 2361] getpid() = 2361
[pid 2361] write(4, "2361: handle_request: request re"..., 67) = 67
[pid 2361] getpid() = 2361
[pid 2361] write(4, "2361: \tGETHOSTBYADDR (66.28.209."..., 37) = 37
[pid 2361] write(7, "\2\0\0\0\1\0\0\0\35\0\0\0\0\0\0\0\2\0\0\0\4\0\0\0\1\0\0"..., 65) = 65
[pid 2361] close(7) = 0
[pid 2361] poll([{fd=3, events=POLLRDNORM}], 1, 0) = 0
[pid 2361] accept(3, <unfinished ...>
[pid 2357] <... poll resumed> [{fd=5, events=POLLIN}], 1, 2000) = 0
[pid 2357] getppid() = 2356
[pid 2357] poll( <unfinished ...>
[pid 2362] <... accept resumed> 0, NULL) = 7
[pid 2362] read(7, "\2\0\0\0\6\0\0\0\4\0\0\0", 12) = 12
[pid 2362] getsockopt(7, SOL_SOCKET, SO_PEERCRED, "<\t\0\0\0\0\0\0\0\0\0\0", [12]) = 0
[pid 2362] read(7, "B\34\321\322", 4) = 4
[pid 2362] getpid() = 2362
[pid 2362] write(4, "2362: handle_request: request re"..., 67) = 67
[pid 2362] getpid() = 2362
[pid 2362] write(4, "2362: \tGETHOSTBYADDR (66.28.209."..., 37) = 37
[pid 2362] write(7, "\2\0\0\0\1\0\0\0\35\0\0\0\0\0\0\0\2\0\0\0\4\0\0\0\1\0\0"..., 65) = 65
[pid 2362] close(7) = 0
[pid 2362] poll([{fd=3, events=POLLRDNORM}], 1, 0) = 0
[pid 2362] accept(3, <unfinished ...>
[pid 2357] <... poll resumed> [{fd=5, events=POLLIN}], 1, 2000) = 0
[pid 2357] getppid() = 2356
[pid 2357] poll( <unfinished ...>
<END OF TRACE>
Thanks for your help, Cliff
-- To UNSUBSCRIBE, email to [EMAIL PROTECTED] with a subject of "unsubscribe". Trouble? Contact [EMAIL PROTECTED]
