IT блог

В поисках производительности — как мы сократили время каждого POST запроса на 200 мс
Перевод статьи.

Во время работы в нашей инструментальной панели Pro мы заметили, что поисковые запросы обслуживаются 300 мс. У нас в команде есть сотрудники, которые использовали Elasticsearch для обработки гораздо больших наборов данных, и они были удивлены тем, как медленно обрабатываются у нас запросы. Поэтому мы решили разобраться.

Сейчас мы покажем, как это расследование позволило сократить время внутренних POST запросов на 200 миллисекунд.

Что мы сделали

Мы стали выполнять типовой поисковый запрос из приложения и замерять время выполнения. Мы попробовали использовать Ruby Net::HTTP и curl из командной строки. Запросы через curl работали заметно быстрее. Проведя измерения мы увидели, что запросы от Ruby занимали 250 мс, в то время как curl обрабатывались 50 мс.

Мы были уверены, что причина была в Ruby, но хотелось копнуть глубже, поэтому мы переключились на тестовую систему. В этот момент проблема исчезла.

Мы оказались в тупике на какое-то время. В наших тествовой и продакшн системах использовались одинаковые версии Ruby и Elasticsearch. Выходила какая-то нелепица! Мы решили сделать шаг назад и разобрать наш стек шаг за шагом. В середине было кое-что, о чем мы не подумали — HAProxy.

Мы быстро обнаружили, что в результате непрерывного обновления Ubuntu мы используем разные версии HAProxy в тестовой системе (1.4.24) и production (1.4.18). Что-то в 6 (24-18) версиях обуславливало различие в поведении, поэтому мы просмотрели логи коммитов. Было несколько подозреваемых, но один из патчей выделялся.

Мы собрали свой собственный билд HAProxy 1.4.18 с одним добавленным патчем и убедились, что время выполнения запроса сократилось примерно на 200 мс. Дело было сделано.

Как это работает внутри

Проблема исправлялась с помощью обновлений Ubuntu, которые мы делали, поэтому мы решили не выпускать кастомный пакет HAProxy. Перед тем как считать дело законченным, мы решили просмотреть весь цикл запроса с помощью tcpdump для того, чтоб понять, что происходит.

Мы выяснили, что в Ruby Net::HTTP делит POST запрос на два TCP пакета — один для заголовков, один для тела. Напротив, curl обходился одним пакетом. Что еще хуже, Net::HTTP не выставлял TCP_NODELAY на открытых им сокетах, поэтому он ждет подтверждения для первого пакета перед отправкой второго. Такое поведение является следствием алгоритма Нагла.

Перейдем на другой конец соединения. HAProxy должен решить каким образом подтвердить эти два пакета. В версии 1.4.18 он использует TCP delayed acknowledgement.

Отсроченное подтверждение плохо уживается в алгоритмом Нагла и вызывает паузу в запросе: сервер должен дождаться таймаута для случая отсроченного подтверждения.

HAProxy 1.4.19 обрабатывает неполные HTTP POST запросы особым образом. Если он получает пакет, в котором есть только первая часть запроса, он устанавливает на сокете TCP_QUICKACK и сразу же отсылает подтверждение.

Проблема касается не только поиска

Разобрав поведение системы, мы поняли что решение применимо не только к нашей задаче поиска. Все наши службы работают за HAProxy, и не является секретом то, что у нас много чего написано на Ruby. Комбинация этих условий означала что почти каждый POST запрос от нашей внутренней инфраструктуры выполнялся медленнее на 200 мс по сравнению с оптимальным временем. Мы провели немного измерений до и после применения патча:

POST /endpointA
average (ms/req) before HAProxy upgrade: 271.13
average (ms/req) after HAProxy upgrade: 19.08
 
POST /endpointB
average (ms/req) before HAProxy upgrade: 323.78
average (ms/req) after HAProxy upgrade: 66.47

Улучшения налицо!

Заключение

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