3

I have a Ruby application running on an Ubuntu server, and this application frequently has to make HTTP requests to other services. Some of those services are on an internal domain, some are reachable by public DNS. I have a Consul agent colocated with my Ruby application, whose job it is to resolve DNS queries for internal components.

Eventually, the Ruby app slows down and it comes down to DNS queries to external domains taking 5+ seconds to resolve. I need help understanding why the behaviour described below may be happening.

To clarify, my goal is to understand the following behaviour, I already have several fixes/workaround I'm considering.

I've isolated the problem to the following:

Minimal Reproducible Example:

/etc/resolv.conf

nameserver 127.0.0.1
nameserver 8.8.8.8

I replaced Consul with the following always-SERVFAIL DNS resolver listening on port 53:

#!/usr/bin/env ruby

require "rubydns"

RubyDNS.run_server(listen: [[:udp, "0.0.0.0", 53], [:tcp, "0.0.0.0", 53]]) do
  otherwise do |transaction|
    transaction.fail!(:ServFail)
  end
end

I placed the above in a file (/var/vcap/data/tmp/dns.rb) then run it:

ruby /var/vcap/data/tmp/dns.rb

It's not super important, but the above is being run with the system ruby, which is 1.9. Then I run the following command (again, probably not important, but this uses a different ruby version):

var/vcap/packages/ruby-2.1.6/bin/ruby -r'net/protocol' -e \
'1.step do |i|; t=Time.now; TCPSocket.open("SOME.REAL.DOMAIN",80).close; p Time.now-t; end'

The above is a slight lie, there was a bit more formatting around what was printed out, but to make it fit in this post without requiring scrolling left/right, I simplified it a bit.

Observed Behaviour:

The behaviour I see is that for a while, each iteration of the loop takes on the order of 10ms, but eventually it starts taking on the order of 5000ms.

Duration of slow behaviour

At one point, I modified /etc/resolv.conf to have options timeout:4 and re-ran this experiment, and each iteration would start taking around 4000ms. So the 5000ms appears to be coming from the default resolvconf timeout of 5s.

Number of iterations before slowdown

It can take anywhere from a few hundred to tens of thousands of iterations for the behaviour to surface, but it always does. If you stop the loop and run the command again, same thing, hundreds or thousands of ~10ms iterations, and then consistently ~5000ms iterations. Often, there is one or two iterations in between that take an intermediate amount of time, 2000-4000ms.

Long-lived ruby loop vs. repeated one-off ruby commands

I believe this has something to do with long-lived ruby processes, because if I instead run a bash loop, and inside each iteration of the bash loop it executes some ruby, I don't see this eventual slowdown. E.g. the following does not exhibit the bad behaviour:

while true; do time /var/vcap/packages/ruby-VERSION/bin/ruby -r'net/protocol' -e \
'TCPSocket.open("SOME.REAL.DOMAIN, 80).close'; done

Only localhost nameserver vs. two name servers

Also, this has something to do with having multiple nameservers. If I edit /etc/resolv.conf to only have the 127.0.0.1 nameserver, and add a rescue nil to the ruby iteration (to prevent the script from blowing up on the first iteration), it seems to go for a very long time without getting slow.

Debugging Information:

I've done an strace of the above loop in one case where there were 7873 fast iterations (~10ms), then one iteration that took 3013ms, then all subsequent iterations taking just over 5000ms. The strace output from all the fast iterations look basically the same as each other and the strace output from all the ~5000ms iterations look basically the same as each other. So I will include here the output from the last fast iteration, the 3013ms iteration, and the first ~5000ms iteration. Of course, in the strace output it's all contiguous, but I'm breaking it up into separate chunks for easier viewing.

last fast iteration: 9ms

stat("/etc/resolv.conf", {st_mode=S_IFREG|0644, st_size=85, ...}) = 0
open("/etc/hosts", O_RDONLY|O_CLOEXEC)  = 7
fstat(7, {st_mode=S_IFREG|0644, st_size=305, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f4e70992000
read(7, "127.0.0.1 localhost af0a3ebe-91a"..., 4096) = 305
read(7, "", 4096)                       = 0
close(7)                                = 0
munmap(0x7f4e70992000, 4096)            = 0
stat("/etc/resolv.conf", {st_mode=S_IFREG|0644, st_size=85, ...}) = 0
socket(PF_INET, SOCK_DGRAM|SOCK_NONBLOCK, IPPROTO_IP) = 7
connect(7, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.0.1")}, 16) = 0
poll([{fd=7, events=POLLOUT}], 1, 0)    = 1 ([{fd=7, revents=POLLOUT}])
sendmmsg(7, {{{msg_name(0)=NULL, msg_iov(1)=[{"A\5\1\0\0\1\0\0\0\0\0\0\3uaa\6useast\6appfog\2q"..., 45}], msg_controllen=0, msg_flags=MSG_OOB|MSG_DONTROUTE}, 45}, {{msg_name(0)=NULL, msg_iov(1)=[{"YH\1\0\0\1\0\0\0\0\0\0\3uaa\6useast\6appfog\2q"..., 45}], msg_controllen=0, msg_flags=MSG_CONFIRM}, 45}}, 2, MSG_NOSIGNAL) = 2
poll([{fd=7, events=POLLIN}], 1, 5000)  = 1 ([{fd=7, revents=POLLIN}])
ioctl(7, FIONREAD, [45])                = 0
recvfrom(7, "A\5\201\2\0\1\0\0\0\0\0\0\3uaa\6useast\6appfog\2q"..., 2048, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.0.1")}, [16]) = 45
poll([{fd=7, events=POLLIN}], 1, 4999)  = 1 ([{fd=7, revents=POLLIN}])
ioctl(7, FIONREAD, [45])                = 0
recvfrom(7, "YH\201\2\0\1\0\0\0\0\0\0\3uaa\6useast\6appfog\2q"..., 2048, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.0.1")}, [16]) = 45
socket(PF_INET, SOCK_DGRAM|SOCK_NONBLOCK, IPPROTO_IP) = 8
connect(8, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("8.8.8.8")}, 16) = 0
poll([{fd=8, events=POLLOUT}], 1, 0)    = 1 ([{fd=8, revents=POLLOUT}])
sendmmsg(8, {{{msg_name(0)=NULL, msg_iov(1)=[{"A\5\1\0\0\1\0\0\0\0\0\0\3uaa\6useast\6appfog\2q"..., 45}], msg_controllen=0, msg_flags=MSG_OOB|MSG_DONTROUTE}, 45}, {{msg_name(0)=NULL, msg_iov(1)=[{"YH\1\0\0\1\0\0\0\0\0\0\3uaa\6useast\6appfog\2q"..., 45}], msg_controllen=0, msg_flags=MSG_CONFIRM}, 45}}, 2, MSG_NOSIGNAL) = 2
poll([{fd=8, events=POLLIN}], 1, 3000)  = 1 ([{fd=8, revents=POLLIN}])
ioctl(8, FIONREAD, [61])                = 0
recvfrom(8, "A\5\201\200\0\1\0\1\0\0\0\0\3uaa\6useast\6appfog\2q"..., 2048, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("8.8.8.8")}, [16]) = 61
poll([{fd=8, events=POLLIN}], 1, 2996)  = 1 ([{fd=8, revents=POLLIN}])
ioctl(8, FIONREAD, [109])               = 0
recvfrom(8, "YH\201\200\0\1\0\0\0\1\0\0\3uaa\6useast\6appfog\2q"..., 1987, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("8.8.8.8")}, [16]) = 109
close(7)                                = 0
close(8)                                = 0
socket(PF_INET, SOCK_STREAM|SOCK_CLOEXEC, IPPROTO_TCP) = 7
fcntl(7, F_GETFD)                       = 0x1 (flags FD_CLOEXEC)
fstat(7, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
fstat(7, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
connect(7, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("63.251.167.126")}, 16) = 0
fstat(7, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
fstat(7, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
close(7)                                = 0
write(1, "7873: 9ms", 9)                = 9
write(1, "\n", 1)                       = 1

intermediate iteration: 3013ms

stat("/etc/resolv.conf", {st_mode=S_IFREG|0644, st_size=85, ...}) = 0
open("/etc/hosts", O_RDONLY|O_CLOEXEC)  = 7
fstat(7, {st_mode=S_IFREG|0644, st_size=305, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f4e70992000
read(7, "127.0.0.1 localhost af0a3ebe-91a"..., 4096) = 305
read(7, "", 4096)                       = 0
close(7)                                = 0
munmap(0x7f4e70992000, 4096)            = 0
stat("/etc/resolv.conf", {st_mode=S_IFREG|0644, st_size=85, ...}) = 0
socket(PF_INET, SOCK_DGRAM|SOCK_NONBLOCK, IPPROTO_IP) = 7
connect(7, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.0.1")}, 16) = 0
poll([{fd=7, events=POLLOUT}], 1, 0)    = 1 ([{fd=7, revents=POLLOUT}])
sendmmsg(7, {{{msg_name(0)=NULL, msg_iov(1)=[{"u>\1\0\0\1\0\0\0\0\0\0\3uaa\6useast\6appfog\2q"..., 45}], msg_controllen=0, msg_flags=MSG_OOB|MSG_DONTROUTE}, 45}, {{msg_name(0)=NULL, msg_iov(1)=[{"e?\1\0\0\1\0\0\0\0\0\0\3uaa\6useast\6appfog\2q"..., 45}], msg_controllen=0, msg_flags=MSG_CONFIRM}, 45}}, 2, MSG_NOSIGNAL) = 2
poll([{fd=7, events=POLLIN}], 1, 5000)  = 1 ([{fd=7, revents=POLLIN}])
ioctl(7, FIONREAD, [45])                = 0
recvfrom(7, "u>\201\2\0\1\0\0\0\0\0\0\3uaa\6useast\6appfog\2q"..., 2048, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.0.1")}, [16]) = 45
poll([{fd=7, events=POLLIN}], 1, 4999)  = 1 ([{fd=7, revents=POLLIN}])
ioctl(7, FIONREAD, [45])                = 0
recvfrom(7, "e?\201\2\0\1\0\0\0\0\0\0\3uaa\6useast\6appfog\2q"..., 2048, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.0.1")}, [16]) = 45
socket(PF_INET, SOCK_DGRAM|SOCK_NONBLOCK, IPPROTO_IP) = 8
connect(8, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("8.8.8.8")}, 16) = 0
poll([{fd=8, events=POLLOUT}], 1, 0)    = 1 ([{fd=8, revents=POLLOUT}])
sendmmsg(8, {{{msg_name(0)=NULL, msg_iov(1)=[{"u>\1\0\0\1\0\0\0\0\0\0\3uaa\6useast\6appfog\2q"..., 45}], msg_controllen=0, msg_flags=MSG_OOB|MSG_DONTROUTE}, 45}, {{msg_name(0)=NULL, msg_iov(1)=[{"e?\1\0\0\1\0\0\0\0\0\0\3uaa\6useast\6appfog\2q"..., 45}], msg_controllen=0, msg_flags=MSG_CONFIRM}, 45}}, 2, MSG_NOSIGNAL) = 2
poll([{fd=8, events=POLLIN}], 1, 3000)  = 1 ([{fd=8, revents=POLLIN}])
ioctl(8, FIONREAD, [109])               = 0
recvfrom(8, "e?\201\200\0\1\0\0\0\1\0\0\3uaa\6useast\6appfog\2q"..., 2048, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("8.8.8.8")}, [16]) = 109
poll([{fd=8, events=POLLIN}], 1, 2997)  = 0 (Timeout)
poll([{fd=8, events=POLLOUT}], 1, 0)    = 1 ([{fd=8, revents=POLLOUT}])
sendto(8, "u>\1\0\0\1\0\0\0\0\0\0\3uaa\6useast\6appfog\2q"..., 45, MSG_NOSIGNAL, NULL, 0) = 45
poll([{fd=8, events=POLLIN}], 1, 3000)  = 1 ([{fd=8, revents=POLLIN}])
ioctl(8, FIONREAD, [61])                = 0
recvfrom(8, "u>\201\200\0\1\0\1\0\0\0\0\3uaa\6useast\6appfog\2q"..., 2048, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("8.8.8.8")}, [16]) = 61
poll([{fd=8, events=POLLOUT}], 1, 2997) = 1 ([{fd=8, revents=POLLOUT}])
sendto(8, "e?\1\0\0\1\0\0\0\0\0\0\3uaa\6useast\6appfog\2q"..., 45, MSG_NOSIGNAL, NULL, 0) = 45
poll([{fd=8, events=POLLIN}], 1, 2997)  = 1 ([{fd=8, revents=POLLIN}])
ioctl(8, FIONREAD, [109])               = 0
recvfrom(8, "e?\201\200\0\1\0\0\0\1\0\0\3uaa\6useast\6appfog\2q"..., 1987, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("8.8.8.8")}, [16]) = 109
close(7)                                = 0
close(8)                                = 0
socket(PF_INET, SOCK_STREAM|SOCK_CLOEXEC, IPPROTO_TCP) = 7
fcntl(7, F_GETFD)                       = 0x1 (flags FD_CLOEXEC)
fstat(7, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
fstat(7, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
connect(7, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("63.251.167.126")}, 16) = 0
fstat(7, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
fstat(7, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
close(7)                                = 0
write(1, "7874: 3013ms", 12)            = 12
write(1, "\n", 1)                       = 1

first slow iteration: 5014ms

stat("/etc/resolv.conf", {st_mode=S_IFREG|0644, st_size=85, ...}) = 0
open("/etc/hosts", O_RDONLY|O_CLOEXEC)  = 7
fstat(7, {st_mode=S_IFREG|0644, st_size=305, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f4e70992000
read(7, "127.0.0.1 localhost af0a3ebe-91a"..., 4096) = 305
read(7, "", 4096)                       = 0
close(7)                                = 0
munmap(0x7f4e70992000, 4096)            = 0
stat("/etc/resolv.conf", {st_mode=S_IFREG|0644, st_size=85, ...}) = 0
socket(PF_INET, SOCK_DGRAM|SOCK_NONBLOCK, IPPROTO_IP) = 7
connect(7, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.0.1")}, 16) = 0
poll([{fd=7, events=POLLOUT}], 1, 0)    = 1 ([{fd=7, revents=POLLOUT}])
sendto(7, "\r\337\1\0\0\1\0\0\0\0\0\0\3uaa\6useast\6appfog\2q"..., 45, MSG_NOSIGNAL, NULL, 0) = 45
poll([{fd=7, events=POLLIN}], 1, 5000)  = 1 ([{fd=7, revents=POLLIN}])
ioctl(7, FIONREAD, [45])                = 0
recvfrom(7, "\r\337\201\2\0\1\0\0\0\0\0\0\3uaa\6useast\6appfog\2q"..., 2048, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.0.1")}, [16]) = 45
poll([{fd=7, events=POLLIN}], 1, 4995)  = 0 (Timeout)
socket(PF_INET, SOCK_DGRAM|SOCK_NONBLOCK, IPPROTO_IP) = 8
connect(8, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("8.8.8.8")}, 16) = 0
poll([{fd=8, events=POLLOUT}], 1, 0)    = 1 ([{fd=8, revents=POLLOUT}])
sendto(8, "\r\337\1\0\0\1\0\0\0\0\0\0\3uaa\6useast\6appfog\2q"..., 45, MSG_NOSIGNAL, NULL, 0) = 45
poll([{fd=8, events=POLLIN}], 1, 3000)  = 1 ([{fd=8, revents=POLLIN}])
ioctl(8, FIONREAD, [61])                = 0
recvfrom(8, "\r\337\201\200\0\1\0\1\0\0\0\0\3uaa\6useast\6appfog\2q"..., 2048, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("8.8.8.8")}, [16]) = 61
poll([{fd=8, events=POLLOUT}], 1, 2996) = 1 ([{fd=8, revents=POLLOUT}])
sendto(8, "}\217\1\0\0\1\0\0\0\0\0\0\3uaa\6useast\6appfog\2q"..., 45, MSG_NOSIGNAL, NULL, 0) = 45
poll([{fd=8, events=POLLIN}], 1, 2996)  = 1 ([{fd=8, revents=POLLIN}])
ioctl(8, FIONREAD, [109])               = 0
recvfrom(8, "}\217\201\200\0\1\0\0\0\1\0\0\3uaa\6useast\6appfog\2q"..., 1987, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("8.8.8.8")}, [16]) = 109
close(7)                                = 0
close(8)                                = 0
socket(PF_INET, SOCK_STREAM|SOCK_CLOEXEC, IPPROTO_TCP) = 7
fcntl(7, F_GETFD)                       = 0x1 (flags FD_CLOEXEC)
fstat(7, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
fstat(7, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
connect(7, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("63.251.167.126")}, 16) = 0
fstat(7, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
fstat(7, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
close(7)                                = 0
write(1, "7875: 5014ms", 12)            = 12
write(1, "\n", 1)                       = 1

Additional Observations:

A couple weird things in the above. Notice that the ~3000ms iteration times out polling file descriptor 8, which it's using to talk to the 8.8.8.8 nameserver, whereas the ~5000ms iteration (and all subsequent iterations) time out polling file descriptor 7, which is for the 127.0.0.1 nameserver. Also note that all the fast iterations, and the intermediate iteration, use sendmmsg to communicate over the socket, but all the ~5000ms iterations use sendto.

Improve this question
4
  • Nice debugging process so far. It may help diagnosis if you run strace with -rT, which will print the amount of time between syscalls, as well as the time spent in each syscall. That way you can see if the problem is in a syscall or process code, and where in the execution chain the pause is happening.
    – womble ♦
    Nov 13, 2015 at 5:46
  • Does it help if you remove the 8.8.8.8 DNS server from resolve.conf?
    – Wouter Verhelst
    Nov 13, 2015 at 9:51
  • @WouterVerhelst yes, I did that experiment as well, and the eventual slowness never seemed to show up. Of course, in practice there needs to be some way to correctly resolve external domains, but yes, some aspect of the problem does seem to be because of the interaction of the two nameservers.
    – Amit Kumar Gupta
    Nov 13, 2015 at 9:58
  • In other words, it "helped" the slowness, but doesn't help in the sense that the domains are no longer resolved. I've added this info to the question.
    – Amit Kumar Gupta
    Nov 13, 2015 at 10:06

2 Answers 2

Reset to default
1

Maybe I understood the problem (I hope). I think that you can fix this playing with a custom Bind DNS configuration, using a private "fake" zone and internet zone together and fixing a proper TTL in order to have more speed for response time using cache DNS engine. Hope it helps! Regards.

Improve this answer
0

Just configure bind on localhost. You will have to add a forward zone for the .consul zone (port 8600 by default), see: https://www.consul.io/docs/agent/dns.html

Be sure that your server has access to the Internet (udp and tcp port 53, and icmp).

Then you can safely remove the 8.8.8.8 part in your /etc/resolv.conf.

Improve this answer

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.