php-fpm, 0.5% запросов выполняются дольше в x50-1000+ раз медленнее

Крот

Новичок
Привет.

Возник весьма интересный вопрос и не очень понятно как подойти к его решению. Буду признателен любым идеям. Есть виртуальный сервер, который работает под KVM гипервизором. Серверу запинено 8 ядер. LA очень низкий. На сервере установлен nginx и php-fpm (v7.2), никакие кроны не выполняются. Есть скрипт, который обернут в легковесный фреймворк (routing + DI + fastcgi_finish_request). Скрипт читает из редиса (phpredis, TCP) и пишет логи через вызовы syslog().

Нагружаю yandex-tank'ом, 100-200-300rps, обычно скрипт отвечает стабильно (именно время ответа, без коннекта и получения данных) - 95 перцентиль до 100мс. Но иногда случается так, что время ответа подскакивает до 1-15 секунд. Начали проверять и экспериментировать:
  • Проверили opcache - validate_timestamp выключен, памяти достаточно, файлы в кэш попадают, hit 100% после "прогрева".
  • Поэкспериментировали со спаунингом воркеров. Спаунинг static. max_children ~ 50. Проводили эксперименты с разными значениями, остановились на этом, которое в принципе логично коррелирует с расчетным (учет rps, кол-ва ядер, время в ожиданни ответа от блокирующих операций и т.д.).
  • composer autoload оптимизирован (l1)
  • Проверили Redis - всегда отвечает стабильно за константное+- время. Время ответа Redis проверялось также внешними скриптами, а также на самом Redis проверяли latency и qbuf - все ок, "очереди" запросов не образовывается. Мониторинг сети не показывает никаких аномалий.
Далее сделали профилирование скрипта через xhprof. И сравнивали 2 профиля одного и того же скрипта - быстрый (80мс) и медленный (19сек.).

Быстрый:

Overall Summary
Total Incl. Wall Time (microsec):89,788 microsecs
Total Incl. CPU (microsecs):73,232 microsecs
Total Incl. MemUse (bytes):5,962,768 bytes
Total Incl. PeakMemUse (bytes):6,429,160 bytes


Медленный:

Overall Summary
Total Incl. Wall Time (microsec):19,406,060 microsecs
Total Incl. CPU (microsecs):826,779 microsecs
Total Incl. MemUse (bytes):5,010,392 bytes
Total Incl. PeakMemUse (bytes):5,546,416 bytes


В быстром все ожидаемо, но в медленном наблюдается жесткая аномалия, например:
is_array
Calls: 2000
Incl. Wall Time (microsec): 906108
Incl. CPU (microsecs): 44127

Хотя в быстром кейсе этот же is_array выполняется суммарно 1-2мс. Такие же аномалии для всех функций без исключения.

Создается впечатление, что при выполнении медленного кейса, ОС начинает очень много переключать контекст что и приводит к такому огромному времени выполнения. Но как понять так ли это и причину, которая вызывает такое поведение?

Буду признателен за любые мысли, доводы и т.д. Спасибо.
 

флоппик

promotor fidei
Команда форума
Партнер клуба
Если pm.max_requests = выключен в 0 (на время замеров) я бы посмотрел на iowait в моменты этого затыка. (Каким-нибудь atop в режиме лога)
Ну и если используется для fpm файловый сокет - попробовать TCP (для начала на время теста, особенно если виден затык по io)
 
Последнее редактирование:

Крот

Новичок
Если pm.max_requests = выключен в 0 (на время замеров) я бы посмотрел на iowait в моменты этого затыка. (Каким-нибудь atop в режиме лога)
Ну и если используется для fpm файловый сокет - попробовать TCP (для начала на время теста, особенно если виден затык по io)
Да, спасибо, обязательно попробую.

Еще есть мысль gdb дебагером подключиться к воркеру и посмотреть в кишки, но не совсем пока понятно как из всего пула воркеров найти того, который именно сейчас долго выполняет конкретный запрос.

Еще есть мысль до 7.3 обновиться попробовать, но тогда может получиться так, что проблема решится, а ее причина так и останется тайной за семью печатями.
 

MiksIr

miksir@home:~$
Есть виртуальный сервер, который работает под KVM гипервизором. Серверу запинено 8 ядер.
А прибиты ли виртуальные процы к ядрам? Достаточно известная проблема для cpu-bound проблем, виртуальные начинают прыгать по физическим.
 

MiksIr

miksir@home:~$
Но, имхо, для начала попробуйте обложить редис метриками и посмотреть что там происходит. xhprof все же дает оверхед.
Посмотреть, если ли всплески по хождению в редис, если есть - смотреть сеть все же.
 

Крот

Новичок
Но, имхо, для начала попробуйте обложить редис метриками и посмотреть что там происходит. xhprof все же дает оверхед.
Посмотреть, если ли всплески по хождению в редис, если есть - смотреть сеть все же.
Угу, мы коннектимся к read-only redis реплике.
Сейчас как раз буду пробовать давать на мастер write-нагрузку и буду смотреть как это влияет на время ответа реплики.
 

fixxxer

К.О.
Партнер клуба
Я бы для начала fpm slowlog включил и посмотрел чо там.
 

grigori

( ͡° ͜ʖ ͡°)
Команда форума
Еще советую проверить вакуум вокруг сферического коня.
1. Положить скрипт phpinfo();, и запустить на него ab
2. замерять отработку скрипта c new Redis(),connect(), echo get() - на час хотя бы, и посчитать отклонение
3. скорость наполнения крупного массива - проверить равномерность распределения проца и кеша 3го уровня между процессами в виртуалке

Я находил такие проблемы с железом, как: проц на одних серверах обсчитывал строковые данные в разы дольше, чем на остальных, потери пакетов между конкретными стойками датацентра приводили к непредсказуемому зависанию из-за неявных блокирующих DNS-запросов к service locator.
 
Последнее редактирование:

Крот

Новичок
Извиняюсь, что долго не отписывался. Всем спасибо за советы! В результате освоил atop - штука просто незаменимая. Ларчик, как это часто бывает, открывался просто.

Первая мысль про высокие тайминги была как раз про Redis и мы его проверили в первую очередь, но, как оказалось - некорректно. Весь затык был в командах, исполняемых на read-only репликах редиса, а именно команд записи и иногда чтения. SLOWLOG все весьма четко показал и после всех мер пустует. Интенсивная запись в мастер большими пачками HMSET блокировала реплики, также кое-где не было оптимизировано чтение. Оптимизировали формат хранения, побили запись на мелкие пачки, где можно перевели на пайплайны. Оптимизировали чтение, также перевели на пайплайны, уменьшили кол-во запрашиваемых ключей.

Попутно снизили нагрузку на диск, которую генерировали php скрипты, в которых присутствовало избыточное логгирование через syslog.
 

Крот

Новичок
Ну и если используется для fpm файловый сокет - попробовать TCP (для начала на время теста, особенно если виден затык по io)
Ага, тоже попробовали. TCP показал плюс-минус такой же результат. В результате оставили на сокетах. Спасибо!
 

Крот

Новичок
Кстати почему xhprof показывал такие странные результаты - загадка. То есть он не показывал что затык именно в Redis::exec, что конечно же, сбивало с толку.
 

fixxxer

К.О.
Партнер клуба
Если с redis-ом работаете не php-шным кодом (типа predis), а extension-ом (типа phpredis), то возможно дело в этом.
xprof цепляется на zend_execute и не факт что может нормально отследить все связанное с extension-ами
а slowlog работает примерно так же как gdb и видит всё
 
Сверху