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

[iHeadRu@…]

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

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

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

Listen 127.0.0.1:80
MaxClients 1

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

3. В nginx.conf добавляем в server {...}

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

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

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

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

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

6. Обращаемся к ​http://IP_nginx/ihead.txt.

7. Останавливаем ktrace

ktrace -C

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

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

9. фиксируется задержка 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"

[Maxim Dounin]

Некоторые наблюдения, 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.

[iHeadRu@…]

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с

[Maxim Dounin]

То есть как и предполагалось, проблема с 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

[iHeadRu@…]

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

[Maxim Dounin]

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

[iHeadRu@…]

спасибо.