Opened 4 years ago

Closed 4 years ago

Last modified 4 years ago

#1283 closed defect (invalid)

FreeBSD 11 + nginx + apache delay +0.1 second on files greater than 32768 bytes

Reported by: iHeadRu@… Owned by:
Priority: minor Milestone: 1.13
Component: nginx-core Version: 1.10.x
Keywords: Cc:
uname -a: FreeBSD freebsd11.build.ihead.ru 11.0-RELEASE-p8 FreeBSD 11.0-RELEASE-p8 #0: Wed Feb 22 06:12:04 UTC 2017 root@amd64-builder.daemonology.net:/usr/obj/usr/src/sys/GENERIC amd64
nginx -V: nginx version: nginx/1.13.0
built by clang 3.8.0 (tags/RELEASE_380/final 262564) (based on LLVM 3.8.0)
built with OpenSSL 1.0.2l 25 May 2017
TLS SNI support enabled
configure arguments: --with-http_stub_status_module --with-http_flv_module --without-http_empty_gif_module --without-http_memcached_module --without-http_upstream_ip_hash_module --without-http_browser_module --with-http_ssl_module --without-http_uwsgi_module --without-http_scgi_module --with-openssl=../openssl-1.0.2l --with-http_v2_module --with-pcre-jit --with-http_auth_request_module --with-file-aio

Description

Я напишу по-русски.

Freebsd 11. В 10 проблем нет.

  1. В httpd.conf ставим

Listen 127.0.0.1:80
MaxClients 1

  1. Кладем файл ihead.txt (35204 байт) в DocumentRoot (/usr/local/www/apache24/data). Файл можно любой, главное, что его размер вместе с заголовками ответа был больше байт 32768.
  1. В nginx.conf добавляем в server {...}

location /ihead.txt {
proxy_pass http://127.0.0.1:80;
}

  1. находим номера процессов nginx и apache

ps -aux | grep nginx
ps -aux | grep httpd

  1. запускаем ktrace по нужным процессам

ktrace -p 42260 -t cfinpstuwy -f nginx
ktrace -p 42184 -t cfinpstuwy -f apache

  1. Обращаемся к http://IP_nginx/ihead.txt.
  1. Останавливаем ktrace

ktrace -C

  1. Превращаем дампы в читаемый вид

kdump -E -f nginx > nginx.txt
kdump -E -f apache > apache.txt

  1. фиксируется задержка 0.1с при отдаче файла от апача к nginx 42260 nginx 0.004903 CSW stop kernel "kqread" 42260 nginx 0.110929 CSW resume kernel "kqread"


42184 httpd 0.000591 CSW stop kernel "select"
42184 httpd 0.199081 CSW resume kernel "select"

Attachments (4)

ihead.txt (34.4 KB ) - added by iHeadRu@… 4 years ago.
nginx.txt (51.9 KB ) - added by iHeadRu@… 4 years ago.
apache.txt (9.4 KB ) - added by iHeadRu@… 4 years ago.
tcpdump.txt (2.0 KB ) - added by iHeadRu@… 4 years ago.

Download all attachments as: .zip

Change History (10)

by iHeadRu@…, 4 years ago

Attachment: ihead.txt added

by iHeadRu@…, 4 years ago

Attachment: nginx.txt added

by iHeadRu@…, 4 years ago

Attachment: apache.txt added

comment:1 by Maxim Dounin, 4 years ago

Некоторые наблюдения, in no particular order:

  • Задержка в 100 миллисекунд как бы намекает, что дело в Delayed ACK. Можно подёргать за net.inet.tcp.delayed_ack / net.inet.tcp.delacktime для подтверждения. Ну и посмотреть на tcpdump между nginx'ом и бекендом было бы неплохо.
  • С точки зрения nginx'а всё выглядит штатно: сначала от бекенда приходит 16332 байт (4096 x 3 + 4044):
     42260 nginx    0.001005 RET   recvfrom 4096/0x1000
     42260 nginx    0.001052 RET   readv 4096/0x1000
     42260 nginx    0.001075 RET   readv 4096/0x1000
     42260 nginx    0.001098 RET   readv 4044/0xfcc
    

Потом 100 миллисекунд ожидания в kevent(), потом остальные данные. Цифра 16332 подозрительно похожа на максимальный размер пакета по loopback-интерфейсу.

  • В trace'е апача никаких явных проблем не видно: делается один вызов writev() для всего ответа, ответ должен бы уходить сразу.

По совокупности это всё выглядит как ошибка в ядре. Каких-либо проблем со стороны nginx'а - не просматривается. Стоит сообщить разработчикам FreeBSD.

comment:2 by iHeadRu@…, 4 years ago

sysctl net.inet.tcp.delayed_ack
net.inet.tcp.delayed_ack: 1

sysctl net.inet.tcp.delacktime
net.inet.tcp.delacktime: 100

1)
sysctl net.inet.tcp.delayed_ack=0
net.inet.tcp.delayed_ack: 1 -> 0
проблема ушла

2)
sysctl net.inet.tcp.delayed_ack=1
net.inet.tcp.delayed_ack: 0 -> 1

sysctl net.inet.tcp.delacktime=200
net.inet.tcp.delacktime: 100 -> 200

проблема есть +0.2с

by iHeadRu@…, 4 years ago

Attachment: tcpdump.txt added

comment:3 by Maxim Dounin, 4 years ago

Resolution: invalid
Status: newclosed

То есть как и предполагалось, проблема с delayed ack'ом. При этом видно, что пакеты идут полные, и флаг push стоит только в конце, т.е. проблема явно в ядре - по каким-то причинам оно ждёт ack'а на единственный отправленный пакет, и наступает на собственный же delayed ack:

12:45:38.286536 IP 127.0.0.1.80 > 127.0.0.1.36654: Flags [.], seq 1:16333, ack 457, win 1276, options [nop,nop,TS val 4239743513 ecr 1989698682], length 16332: HTTP: HTTP/1.1 200 OK
12:45:38.392445 IP 127.0.0.1.36654 > 127.0.0.1.80: Flags [.], ack 16333, win 1276, options [nop,nop,TS val 1989698788 ecr 4239743513], length 0
12:45:38.392471 IP 127.0.0.1.80 > 127.0.0.1.36654: Flags [.], seq 16333:32665, ack 457, win 1276, options [nop,nop,TS val 4239743619 ecr 1989698788], length 16332: HTTP
12:45:38.392481 IP 127.0.0.1.80 > 127.0.0.1.36654: Flags [FP.], seq 32665:35458, ack 457, win 1276, options [nop,nop,TS val 4239743619 ecr 1989698788], length 2793: HTTP

Можно ещё попробовать посмотреть в сторону настроек congestion control, возможно - проблема где-то там. В любом случае это не выглядит проблемой в nginx'е, так что тикет я закрываю.

Just for the record, соответствующий тикет на bugs.freebsd.org:
https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=219644

comment:4 by iHeadRu@…, 4 years ago

Изначально о проблеме сообщил клиент. Это был боевой сервер.
Когда стало понятно, как воспроизводить проблему, я решил повторить ее на пустых виртуальных машинах, с настройками по умолчанию.
Я сомневаююсь, что congestion control может иметь отношение при минимальной нагрузке и давать 100% воспроизводимость проблемы.

comment:5 by Maxim Dounin, 4 years ago

Congestion control во многом состоит из алгоритма начального увеличения congestion-окна, обычно стартующего с фиксированного начального значения (slow start). Если проблема именно в начальных значениях, которые не дают послать второй пакет данных до получения ack'а на первый, то воспроизводиться всё будет при любой нагрузке и с вероятностью 100%.

Last edited 4 years ago by Maxim Dounin (previous) (diff)

comment:6 by iHeadRu@…, 4 years ago

спасибо.

Note: See TracTickets for help on using tickets.