Когда переподключения ускоряют работу по сети. Тестируем быстродействие TCP-сокетов

При написании предыдущей статьи я наткнулся на странный эффект с производительностью 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, чтобы лог был не слишком длинным.

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

Когда переподключения ускоряют работу по сети. Тестируем быстродействие TCP-сокетов.

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

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