При написании предыдущей статьи я наткнулся на странный эффект с производительностью TCP-сокетов. При попытке отправить пачку запросов через сокет оказалось, что выгоднее заново устанавливать TCP-соединение после каждого запроса, а не переиспользовать его. Исследованию причин этого эффекта (а заодно и поиску способов от него избавиться) и посвящена эта статья.

В чем собственно дело

Имеется два процесса, клиент (написан на PHP) и сервер (на C++). Клиент подключается к серверу по TCP и отправляет ему запросы. Запрос отправляется в виде "4 байта длины, затем тело". Сервер обрабатывает запрос (для теста - он просто XOR-ит байты запрос друг с другом) и отправляет ответ (также, 4 байта длины, затем тело).

В рамках тестирования проверялись разные варианты длины запросов, их количества и количества запросов до переустановки соединения. И вот эффект:
В качестве тестового стенда используется сервер со следующими характеристиками:

1. CPU - 2 x Intel(R) Xeon(R) CPU E5-2650 v4 @ 2.20GHz

2. RAM - 64Gb DDR4 ECC

3. OS - openSUSE Leap 15.4

Запускаем 1000 запросов, переподключаемся через 1000 (т.е. ни разу), 10 и 1 (после каждого запроса).

Testing 1000 requests, reconnect after 1000 size 2048
Testing IP socket:
Total: 30.043 seconds, 33.286 RPS

Testing 1000 requests, reconnect after 10 size 2048
Testing IP socket:
Total: 19.999 seconds, 50.001 RPS

Testing 1000 requests, reconnect after 1 size 2048
Testing IP socket:
Total: 10.546 seconds, 94.825 RPS

Видно, что вариант, в котором мы заново устанавливаем соединение после каждого запроса, работает существенно быстрее (почти в 3 (!) раза). Хотя казалось бы, установка соединения - дело не бесплатное. В чём же дело?

Немного теории о TCP

Протокол TCP - это протокол транспортного уровня. Его основная задача - обеспечивать надёжную (без потерь) доставку данных с сохранением порядка (данные отправленные раньше, приёмник получит раньше). От приложения TCP получает последовательность байт, которую требуется отправить на другую сторону и уже сам разделяет её на сегменты (блоки данных с заголовками), которые уходят для передачи в протокол более низкого уровня.

Не вдаваясь в подробности, скажем, что для обеспечения надёжности и сохранения порядка, TCP нумерует сегменты данных. Также, существует специальный вид сегмента - ACK (подтверждение), которым приёмник сообщает отправителю о том, что он получил сегмент с заданным номером. Если отправитель не получает ACK в течение некоторого времени, он отправляет сегмент повторно.

Также, для уменьшения нагрузки на сеть, TCP буферизует данные, получаемые от приложения (чтобы не отправлять слишком маленькие сегменты). Ещё, для ускорения передачи, отправитель может отправить несколько сегментов, не дожидаясь ACK от получателя (размер такого буфера называется размером окна).

Обмен данными по TCP можно разделить на две фазы: установка соединения и передача данных. При установке соединения клиент посылает серверу сегмент с флагом SYN, получает от сервера сегмент SYN-ACK и потом отправляет серверу ACK, после чего соединение считается установленным. Далее стороны обмениваются сегментами (в одном сегменте может быть как подтверждение получения, так и какие-то данные).

Ещё есть процедура закрытия соединения, но она нам здесь неинтересна. Про неё и прочие подробности работы TCP можно почитать в Википедии.

Продолжаем эксперименты

Возвращаемся к нашим серверу и клиенту. Попробуем запустить всё то же самое на виртуальной машине (просто потому что я на ней отлаживал). Получаем странное.

Testing 1000 requests, reconnect after 1000 size 2048
Testing IP socket:
Total: 2.852 seconds, 350.674 RPS
Testing 1000 requests, reconnect after 1 size 2048
Testing IP socket:
Total: 10.654 seconds, 93.861 RPS

С реконнектами работает медленнее. Эффекта, который меня заинтересовал, не наблюдается. При этом с реконнектами работает с такой же производительностью, как и на сервере.

В этот момент можно сделать вывод, что что-то происходит именно в случае длительного обмена данными.

Отлаживать подобные время-зависимые эффекты достаточно сложно. Отладчик использовать не получится (любая остановка на точке останова приведёт к нарушению всех таймингов). На сцену в этом случае выходят старые добрые логи. Добавив записей в лог в интересующие нас моменты, с указанием момента времени от старта теста, мы сможем понять, что именно вызывает тормоза.

Добавляем логирование в клиент

Отслеживать будем моменты начала и окончания установки соединения, отправки запроса и получения ответа. Количество тестируемых запросов уменьшаем до 10, чтобы лог был не слишком длинным.

Вариант с переподключениями:

Testing 10 requests, reconnect after 1 size 2048
Testing IP socket:
0.023 start
0.038 begin connecting
0.163 connected
0.437 begin sending
0.477 sent, receiving
10.597 received, time = 10.116
10.646 begin connecting
10.718 connected
11.013 begin sending
11.059 sent, receiving
21.205 received, time = 10.140
21.262 begin connecting
21.361 connected
21.615 begin sending
21.647 sent, receiving
31.760 received, time = 10.109
31.795 begin connecting
31.853 connected
32.092 begin sending
32.125 sent, receiving
42.262 received, time = 10.130
42.321 begin connecting
42.421 connected
42.719 begin sending
42.752 sent, receiving
52.865 received, time = 10.110
52.900 begin connecting
52.956 connected
53.212 begin sending
53.249 sent, receiving
63.387 received, time = 10.131
63.447 begin connecting
63.558 connected
63.784 begin sending
63.817 sent, receiving
73.956 received, time = 10.133
74.016 begin connecting
74.122 connected
74.350 begin sending
74.383 sent, receiving
84.522 received, time = 10.132
84.581 begin connecting
84.678 connected
84.907 begin sending
84.941 sent, receiving
95.084 received, time = 10.138
95.122 begin connecting
95.185 connected
95.413 begin sending
95.447 sent, receiving
105.551 received, time = 10.097
105.613 finish
Total: 0.106 seconds, 94.689 RPS

Вариант без переподключений:

Testing 10 requests, reconnect after 10 size 2048
Testing IP socket:
0.023 start
0.039 begin connecting
0.189 connected
0.430 begin sending
0.475 sent, receiving
10.605 received, time = 10.126
10.868 begin sending
10.910 sent, receiving
21.051 received, time = 10.134
21.429 begin sending
21.536 sent, receiving
31.683 received, time = 10.140
32.090 begin sending
32.144 sent, receiving
42.287 received, time = 10.139
42.517 begin sending
42.549 sent, receiving
93.198 received, time = 50.644
93.439 begin sending
93.462 sent, receiving
103.656 received, time = 10.186
103.947 begin sending
103.970 sent, receiving
114.161 received, time = 10.184
114.480 begin sending
114.503 sent, receiving
165.148 received, time = 50.638
165.566 begin sending
165.592 sent, receiving
175.804 received, time = 10.205
176.110 begin sending
176.146 sent, receiving
186.351 received, time = 10.200
186.384 finish
Total: 0.186 seconds, 53.656 RPS

Ага! Мы видим, что в самом клиенте проблем нет, но вот получение ответа от сервера занимает то 10мс, то 50мс (хотя в варианте с переустановкой соединения всегда около 10мс).

Добавляем логирование в сервер

Дабы не утомлять читателя подробностями, скажу, что после расстановки логов на методы приёма и отправки набора байт в сокет, я пришёл вот к такой истории:

174.513 Receive() start delta 0.038626
217.219 Receive() finish delta 42.7063

Иногда приём очередного запроса затягивается на примерно 40мс. Расставив ещё немного логов, я увидел, что время теряется внутри вызова recv.

113.78 Receive(), before recv delta 0.015474
164.457 Receive(), after recv delta 50.677

Итак, по непонятной пока причине, вызов recv может "застопориться" на целых 40мс на, казалось бы, ровном месте.

Добавляем tcpdump

Поскольку что-то происходит внутри сетевого стека системы, логичным шагом будет включить ему "отладочный лог". Конечно, имеется в виду tcpdump, который при нужных ключах выдаст нам ровно те пакеты, которые "ходят" между нашим клиентом и сервером.
Вот отрывок его лога:

22:58:52.119895 IP localhost.60874 > localhost.19876: Flags [P.], seq 18469:18473, ack 2341, win 512, options [nop,nop,TS val 1743945919 ecr 1743945918], length 4
22:58:52.162347 IP localhost.19876 > localhost.60874: Flags [.], ack 18473, win 512, options [nop,nop,TS val 1743945961 ecr 1743945919], length 0
22:58:52.162368 IP localhost.60874 > localhost.19876: Flags [P.], seq 18473:20521, ack 2341, win 512, options [nop,nop,TS val 1743945961 ecr 1743945961], length 2048

Отсюда видно, что наши сообщения режутся TCP-стеком системы на 2. И после получения первого из них сервер ждёт какое-то время, прежде чем выдать клиенту ACK-пакет с подтверждением получения.

Опции сокетов

Как справедливо заметили в комментариях, возможной причиной такому поведению может быть Nagle's algorithm. Это ещё одна оптимизация TCP, призванная группировать мелкие пакеты, чтобы уменьшить суммарный overhead на заголовки TCP. Суть его в том, чтобы "копить" данные не отправляя их, пока не будет получен ACK на уже отправленную часть. Сам по себе этот алгоритм ничего не ломает, однако в TCP есть ещё одна фича - Delayed ACK. Её суть в том, чтобы дождаться некоторого количества данных от источника, а только затем возвращать ему ACK-сегмент. Собственно так и получается - клиент ждёт ACK от сервера, а тот ждёт следующую порцию данных от клиента.

В прошлый раз я по-быстрому попробовал включить на сокете опцию TCP_NODELAY, которая выключает Nagle's algorithm и заставляет протокол TCP отправлять пакеты "сразу как есть". Однако я сделал это только со стороны клиента, а не со стороны сервера. И это не помогло. Что в общем-то логично, поскольку подобная ситуация с ожиданием совершенно симметрична и может произойти и при отправке сервером ответа. Если же включить опцию на обеих сторонах, проблема исчезает.

Также, в ходе разбирательства я наткнулся на рекомендации по тюнингу TCP от RedHat. В нём упоминается другая опция - TCP_CORK. Если её выставить перед вызовом send, данные будут буферизоваться до тех пор, пока не заполнится системный буфер, либо не будет снята эта опция. Это позволяет "собрать" пакет с данными прямо в системном буфере (что может сэкономить вам немного процессорного времени). Ну и исследуемую проблему эта опция тоже решает. Вероятный минус - заявлено, что она поддерживается только в Linux, потому кроссплатформенность страдает.

Из интересных наблюдений - производительность (в смысле RPS) версии с переподключением и без (после починки проблем с ACK) оказалась практически идентичной. Это как-то контринтуитивно.

Как водится, тестовый проект доступен на гитхабе.

Использованные источники

1. Описание TCP https://en.wikipedia.org/wiki/Transmission_Control_Protocol

2. Nagle's algorithm https://en.wikipedia.org/wiki/Nagle's_algorithm

3. TCP delayed acknowledgement https://en.wikipedia.org/wiki/TCP_delayed_acknowledgment

4. RHEL Tuning Guide. 4.4. TCP_NODELAY and Small Buffer Writes https://access.redhat.com/documentation/ru-ru/red_hat_enterprise_linux_for_real_time/7/html/tuning_guide/tcp_nodelay_and_small_buffer_writes