DNS-поиск в конечном итоге становится постоянно медленным в долгоживущем рубиновом процессе

У меня есть приложение Ruby, работающее на сервере Ubuntu, и этому приложению часто приходится выполнять HTTP-запросы к другим службам. Некоторые из этих служб находятся во внутреннем домене, некоторые доступны через общедоступный DNS. У меня есть агент Consul, размещенный в моем приложении Ruby, чья работа заключается в разрешении DNS-запросов для внутренних компонентов.

В конце концов, приложение Ruby замедляется, и это сводится к DNS-запросам к внешним доменам, на разрешение которых требуется более 5 секунд. Мне нужна помощь в понимании того, почему может происходить описанное ниже поведение.

Чтобы уточнить, моя цель - понять следующее поведение, у меня уже есть несколько исправлений / обходных путей, которые я рассматриваю.

Я Я изолировал проблему следующим образом:

Минимальный воспроизводимый пример:

/etc/resolv.conf

nameserver 127.0.0.1
nameserver 8.8.8.8

Я заменил Consul следующим DNS-резольвером Always-SERVFAIL, прослушивающим порт 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

Я установил выше в файле ( /var/vcap/data/tmp/dns.rb ), затем запустите его:

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

Это не очень важно, но вышеупомянутое выполняется с системным рубином, который равен 1.9 . Затем я запускаю следующую команду (опять же, вероятно, не важно, но здесь используется другая версия Ruby):

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'

Выше небольшая ложь, было немного больше форматирования вокруг того, что было распечатано, но чтобы оно поместилось в этом сообщении без требуя прокрутки влево / вправо, я немного упростил его.

Наблюдаемое поведение:

Я вижу, что какое-то время каждая итерация цикла занимает порядка 10 мс, но в конечном итоге начинает принимать порядка 5000 мс.

Продолжительность медленного поведения

В какой-то момент я изменил /etc/resolv.conf , чтобы иметь таймаут опций: 4 , и повторно запустил этот эксперимент , и каждая итерация займет около 4000 мс. Таким образом, 5000 мс, похоже, исходит из тайм-аута resolvconf по умолчанию, равного 5 с.

Число итераций до замедления

Для проявления поведения может потребоваться от нескольких сотен до десятков тысяч итераций, но так бывает всегда. Если вы остановите цикл и снова запустите команду, то же самое, сотни или тысячи итераций ~ 10 мс, а затем последовательно итераций ~ 5000 мс. Часто между ними проходит одна или две итерации, которые занимают промежуточное время, 2000-4000 мс.

Долгоживущий цикл рубина против повторяющихся одноразовых команд рубина

Я считаю, что это как-то связано с длинными -lived ruby ​​процессы, потому что, если я вместо этого запускаю цикл bash, и внутри каждой итерации цикла bash он выполняет некоторый рубин, я не вижу этого возможного замедления. Например, следующий не демонстрирует плохое поведение:

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

Только локальный сервер имен против двух серверов имен

Кроме того, это как-то связано с наличием нескольких серверов имен. Если я отредактирую /etc/resolv.conf , чтобы у меня был только сервер имен 127.0.0.1 , и добавлю rescue nil в итерацию ruby ​​(чтобы предотвратить сценарий от взрыва на первой итерации), кажется, что он идет очень долго без замедления.

Отладочная информация:

Я выполнил strace вышеуказанного цикла в одном случае где было 7873 быстрых итерации (~ 10 мс), затем одна итерация заняла 3013 мс, а затем все последующие итерации заняли чуть более 5000 мс. Выходные данные strace всех быстрых итераций в основном выглядят одинаково, а выходные данные strace для всех итераций ~ 5000 мс выглядят в основном одинаково друг с другом. Я включу сюда результат последней быстрой итерации, итерация 3013 мс, и итерация первая ~ 5000 мс. Конечно, в выводе strace это все непрерывно, но я разбил его на отдельные части для облегчения просмотра.

последняя быстрая итерация: 9 мс

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

промежуточная итерация: 3013 мс

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

первая медленная итерация: 5014 мс

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

] Дополнительные наблюдения:

Пара странных вещей в приведенном выше. Обратите внимание, что итерация ~ 3000 мс прерывает время ожидания дескриптора файла опроса 8, который он использует для связи с сервером имен 8.8.8.8 , тогда как итерация ~ 5000 мс (и все последующие итерации) истекает время ожидания дескриптора файла опроса 7, что предназначен для сервера имен 127.0.0.1 . Также обратите внимание, что все быстрые итерации и промежуточные итерации используют sendmmsg для связи через сокет, но все итерации ~ 5000 мс используют sendto .