Из-за чего скачки времени обработки запросов?

Question

[Tutucu]

Всем привет! Что есть:

1. сервер: 2 x 2.8 ГГц, оперативка 4 гб, NVMe 50 ГБ (заполнено 13 гб), 200 мбит/с
   
2. ubuntu, nginx, php-fpm, php 7.3, laravel, mysql
   
3. на нём сервер API, который должен выдавать json строку Яндексу за 3 секунды (API Яндекс.Диалогов), если Яндекс не получает ответа, он закрывает соединение засчитывает ошибку.
   
4. Запросов может быть много, особенно вечером
   

Проблема: от 0.5 % до 1 % запросов выполняются больше 3 секунд, из-за чего образуется ошибка, причём скачки резкие, рандомные, но постоянные. Все остальные запросы выполняются за 0.3 секунд.

Что делал:
- Увеличил оперативку до 6 гб и 3 ядер (вообще не помогло).
- Проставил все индексы в базе данных. (Вообще не помогло).
- Оптимизировал запросы в базу данных с 10-16 до 2-6 за 1 запрос к API (не помогло).
- Поменял Apache на NGINX и php-fpm (не помогло)
- Отключал все сайты кроме проблемного (не помогло)
- Логгирование медленных запросов в БД - пусто.
- Логгирование медленных скриптов в php-fpm - пусто.
- Пытался мониторить через innotop, atop и iotop (везде смешные цифры в десятые проценто, иногда только бд вылезает в топ, но там что то около 5% бывает). И не особо понятно, как мониторить, если я не знаю когда в следующий раз будет скачок.
Куда ещё копать и что делать? Уже неделю сижу и не знаю что ещё попробовать :( Помогите, пожалуйста. Вот скрины от Яндекса:
За сегодня (желтые бугорки) в зависимости от кол-ва нормальных запросов:

Скорость запросов за сегодня:

Процентное соотношение долгих запросов за весь месяц в процентах:

Ночью (желтые бугорки) в зависимости от кол-ва нормальных запросов (ночь, единичные запросы):

Причём на последней картинке долгие запросы появлялись, когда были единичные запросы, а когда начались постоянные (большая зелёная гора) - они исчезли.

UPD:
Сделал логирование nginx с временем запросов и обнаружил один такой медленный запрос, почему то у его размер всего 0 байт:

Comments

[d-sem]

выглядит как начало чего то интересного)

[Tutucu]

d-sem, Я уже неделю с этим интересным вожусь, вся работа встала из-за этого :(

[vism]

Tutucu, график работы с файловой системы покажите

[Tutucu]

vism, через что его получить?

[vism]

Tutucu, я ньюрелик использую

[Tutucu]

vism, https://newrelic.com/ - это оно?
А бесплатного или подешевле ничего нет?

[Vitaly Karasik]

Tutucu, в NewRelic есть бесплатный план

[Сергей Семенко]

Проверьте параметры pm.min_spare_servers и pm.max_spare_servers в конфигурации PHP-FPM, возможно там указаны небольшие значения.

[Tutucu]

Сергей Семенко,
pm.start_servers = 2
pm.min_spare_servers = 1
pm.max_spare_servers = 3

[Сергей Семенко]

Tutucu, попробуйте вот такие параметры:

pm = dynamic
pm.max_children = 50
pm.start_servers = 15
pm.min_spare_servers = 10
pm.max_spare_servers = 20
pm.max_requests = 0

[neol]

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

[neol]

ИМХО всё это больше похоже на проблемы с сетью. Я бы попробовал mtr погонять до серверов яндекса с которых приходят проблемные запросы.

[Сергей Семенко]

neol, количество запросов не увидел.

[Tutucu]

neol, Отправил им запрос на список серверов. А если это проблемы с сетью - что делать? Хостер Timeweb, VDS.

[neol]

Tutucu,

Отправил им запрос на список серверов.

Посмотреть в логах IP, с которых прилетали запросы, не быстрее?

А если это проблемы с сетью - что делать?

Смотря где эти проблемы. Яндекс тоже далеко не идеален и, внезапно, тупить может их сеть.

[Tutucu]

neol, добавил скрин логов nginx с тем самым медленным запросом - что это может быть?

Посмотреть в логах IP, с которых прилетали запросы, не быстрее?

Да, сейчас вот проверяю.

[Даша Циклаури]

499 статус - это клиент закрыл соединение, яндекс не дождался видимо 3 сек отсечка. 0 потому что тело пустое не дождались ведь

тебе надо в первую очередь обложиться не логами nginx а из apache залогировать какие куски кода подвисают, оборачивай соединение с базой и сам запрос, если больше секунды выводи в лог тело SQL запроса и сюда выкладывай

[Tutucu]

Даша Циклаури а почему апач? У меня nginx + fpm. slow-log mysql не показывает запросы даже длиннее 0.25 секунд (Иногда падают, но не по таймингам).

[neol]

Tutucu, вот теперь не очень похоже на проблему с сетью. В slow_log php-fpm точно ничего по этому поводу нет? Он вообще включен?

[Tutucu]

neol, Появилось!

Пометил стрелками, что моё, всё остальное это Laravel. Код мне знаком, это запись текста обращений к API. Происходит при каждом обращении send() и save() - формирует json и добавляет новую запись в базу данных.
Непонятно почему лог появился только сейчас. В slow log mysql по прежнему ничего нет :/
А как теперь найти конкретный участок проблемы?

[Даша Циклаури]

Tutucu, тааааааак, а случаем диск/база/чтоугодно куда запись ведётся не на виртуалках крутится?

[Даша Циклаури]

если виртуалка - переезжай на железо, у нас такая же шляпа была, вот мой вопрос
Почему может быть долгий fdatasync?

[Tutucu]

Даша Циклаури,
у меня всё на одном и том же сервере VDS крутится.

переезжай на железо

Это я так понимаю реальный сервер арендовать?

[Даша Циклаури]

Tutucu, ну железка, да, не обязательно там всякие HP Proliant, я беру на Hetzner на аукционе, можно за 80 евро урвать на Зеоне/64РАМ/480НВМе(крутейший) и не переплачивать столько же за установку, развернут за час

[Tutucu]

Даша Циклаури,
Очень брутальное решение проблемы, если не разберусь - придётся, спасибо :)

Answer 1

[Виктор Таран]

1. iotop -okaво время таких фризов
2. переведите режим работы процессоров с энерджи сейв в перфоманс cat /proc/cpuinfo | grep MHz все процессоры должны иметь или максимальную частоту или близкую к ней.
Когда процессор "холодный" то ему нужно время поднять частоту, и получается что он быстрей иногда отрабатывает под нагрузкой чем полностью пустой но с 800MHz
3. не забывайте что php+sql один и тот же запрос могут выполнить с разной скоростью, притом эта разница нифига не в 1% а порой доходит до 300% и усугубляется очередью как в sql так и на любом этапе.
4. Могу вам сказать что по факут является самым распространенным

а) i-o диска особенно HDD ( nvme) можно даже не тестировать.
б) sql параллелит свои запросы но один запрос делает на 1 ядре, в результате 128 ядерный камень по 2Ghz может работать медленней вашего офисного Corei3 поскольку такт на ядро у него больше.
в) кеш php кешируйте все что только можно и грамотно, как правило в этом месте можно ускориться раз в 10-30, даже не оптимизируя запросы в бд
г) находите самые тяжелые запросы в бд и оптимизируйте их.

Теперь что скорее всего происходит
у вас встает очередь запросов в бд, например идет тяжелый хит скажем каталог с 5 фильтрами, в это время остальные запросы встают в очередь, и даже мелкие из них выполняюются медленно поскольку пред ними стоит тяжелый товарищь.
ТАк вот к примеру когда делается 1 тяжелый запрос встало еще 300, и они вместе начинают лезть и выполняться.
В результате получается то - же самое что выделить 10000 файлов в винде на hdd и скопировать параллельно а не последовательно
I-O проседает многократно порой до десятков тыс раз.
Пример утрированный но тем не менее.
В результате у вас затык на пустом месте, когда LA системы 5 I-O 10% sql=100% на 1 камне.
Как правило ситуация дальше осложняется по следующей схеме
занимаются все камни тяжелыми хитами, тем более с каждым разом это становится легче, поскольку ресурсы других камней уже заняты, в результате раз в день база начинает тормозить, и ее рестартуют по крону.
;)))
Но все индивидуально.

Comments

[Даша Циклаури]

IO диска как раз таки скорее всего и проблема
Почему может быть долгий fdatasync?

[Tutucu]

1. Проблема в том, что эти фризы возникают хаотично, сегодня днём был 1, а ночью - 5. iotop же только в реальном времени показывает.
2. Ок, спс.
3. Понял.
4.
а) Немного не понял, т.е. не тестировать? Это точно не он или наоборот скорее всего он?
б) Понял
в) Понял
г) А как? В лог медленных запросов очень мало, что падает.

Т.е. мне надо каждый день рестартить MySql? И у меня в среднем 1 запрос в 2 секунды, бывает, что вырастает до 1-2, но это только вечером, в основном нагрузка не большая.

[Даша Циклаури]

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

[Виктор Таран]

Даша Циклаури,

IO диска как раз таки скорее всего и проблема

/
Товарищ сказал что это NVMe - вы смеетесь?
такие проблемы были часто с HDD и иногда с простыми SSD но I-O NVMe просаить это прям сказка какая-то.

[Виктор Таран]

Tutucu, Нет тебе не нужно рестартовать, это тупиковая ветвь развития.
Тебе нужно найти проблему.
1. то что в медленные запросы попадает может быть следствием, нет смысла там даже лазить.
2. оптимизируй код, как правило проблема с самыми тяжелыми запросами, или импортами экспортами, опять же посколькуо это больные селекты и инсерты.
3. Посмотрите хиты которые неачались момент тормоза анализируйте этот хит смотрите что на этой страничке не кешируется.
По факту если у вас кешируется все, то запросов в бд настолько минимальное количество что это никак не сказывается на производительность.
4. Исключите пролемы со внешними сервисами, когда вы подключили внешние js шрифты и тд
Поскольку доступность этих товарищей так же через веб и они так же в среднем могут сильно варьировать свой ответ по времени. Так что избавься от всего CDN внешнего перенеси все че можно локально (без фанатизма метрику можно не трогать, она все-равно самый медленный жс на твоем сайте )

[Даша Циклаури]

Виктор Таран, у нас на виртуалке тоже было типа NVMe общее
вот такие проблемы)

Answer 2

[Антон Шаманов]

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

Answer 3

[Vitaly Karasik]

сервер: 2 x 2.8 ГГц, оперативка 4 гб, NVMe 50 ГБ (заполнено 13 гб)

А какой размер самой базы?
И сколько использует MySQL?
Много записей?

Логгирование медленных запросов в БД - пусто.
- Логгирование медленных скриптов в php-fpm - пусто.

А вы уверены что mysql slow query log действительно работает?
Можно включить логирование времени на каждый запрос в nginx.

Comments

[Tutucu]

Записей много, несколько сотен тысяч, вес таблицы 1.1 гб.
В лог mysql падают медленные запросы, но только когда я в админке большие каталоги данных открываю и по таймингам они вообще не подзодят и их мало.
В php-fpm тоже падают, но очень редко и тоже когда я по админке смотрю.

У меня была мысль, что медленные запросы не записываются из-за того что соединение после 3 секунд сбрасывается. такое может быть?

[Vitaly Karasik]

Много записей?

Я неправильно выразился - я хотел спросить много ли writes в базу.

вес таблицы 1.1 гб.

это маленькая база.
Пришлите ваш my.cnf пож-ста. И "show create table".

оединение после 3 секунд сбрасывается.

Нет. Даже если веб-клиент сбрасывает соединение, sql запрос уже послан и будет обработан.

Как я уже написан, интересно тайминг вебсервера.

[Tutucu]

Каждый запрос - это всегда от 1 до 6 записей в БД. Запросов много, иногда раз в 2 секунды.

[mysqld_safe]
socket= /var/run/mysqld/mysqld.sock
nice= 0
user= mysql
pid-file= /var/run/mysqld/mysqld.pid
socket= /var/run/mysqld/mysqld.sock
port= 3306
basedir= /usr#
[mysqld_safe]
socket= /var/run/mysqld/mysqld.sock
nice= 0
user<--><------>= mysql
pid-file<------>= /var/run/mysqld/mysqld.pid
socket<><------>= /var/run/mysqld/mysqld.sock
port<--><------>= 3306
basedir><------>= /usr
datadir><------>= /var/lib/mysql
tmpdir<><------>= /tmp
lc-messages-dir>= /usr/share/mysql
skip-external-locking
key_buffer_size><------>= 32M
max_allowed_packet<---->= 16M
thread_stack<--><------>= 192K
thread_cache_size       = 8
myisam-recover-options  = BACKUP
query_cache_limit<----->= 1M
query_cache_size        = 32M
log_error = /var/log/mysql/error.log
slow_query_log<><------>= 1
slow_query_log_file<--->= /var/log/mysql/mysql-slow.log
long_query_time = 0.25
log-queries-not-using-indexes
expire_logs_days<------>= 10
max_binlog_size   = 100M
#binlog_do_db<-><------>= include_database_name
#binlog_ignore_db<----->= include_database_name

[Tutucu]

Насчёт

show create table

не понял.

[Vitaly Karasik]

Tutucu, я хочу понять, используете вы InnoDB или MyISAM.
show create table (https://dev.mysql.com/doc/refman/8.0/en/show-creat...) показывает это.

UPDATE: честно говоря, если slow query log работает и в нем не видно медленный запросов во время проблем, то можно оставить mysql в покое и проверять вебсервер.
Если и там все ОК - менять хостинг, так как проблема в сети.

[Vitaly Karasik]

.добавьте в лог nginx - это поможет понять сколько времени забирает каждый запрос.
возможно вообще сервер не виновать, а просто сеть плохая.

https://lincolnloop.com/blog/tracking-application-...
request_time
upstream_response_time

[Nird]

Запросов много, иногда раз в 2 секунды.

Для мускуля это не много. Думаю, что БД можно оставить в покое, проблема не там. Как уже писали вероятнее дело в сетке\хостере. Похоже хостер балансирует нагрузку, но делает это не правильно и в моменты вам просто не хватает канала. Нет ли возможности протестить систему на железе?

[Tutucu]

Nird, Нет такой возможности, а как измерить канал?

[Tutucu]

Vitaly Karasik, Поставил наблюдение за логами и нашёл 1 такой запрос:

Что это может быть? Почему запрос содержит всего 0 байт?

[Vitaly Karasik]

Tutucu, у него статус не 200, а 499, так что скорее всего запрос плохой

[Tutucu]

Vitaly Karasik, т.е. проблема где-то между хостером и тем, кто отправляет запросы?

[Vitaly Karasik]

т.е. проблема где-то между хостером и тем, кто отправляет запросы?

Или так, или иногда Яндекс обрывает связь или шлет плохие пакеты.
Я бы собрал логи за сутки, и сопоставил со статистикой яндекса - я имею в виду графы, кот. вы посылали в начале.

[Виктор Таран]

Поставь в my.cnf
innodb_flush_log_at_trx_commit = 2
и рестартани, может очень сильно помочь , вплоть до 50 раз !
Однако у тебя
2 x 2.8 ГГ
это я так понимаю процессоры 4 поколения назад, что от них ожидать сам понимаешь.

[batyrmastyr]

Tutucu, 499 ошибка значит, что клиент оборвал соединение. Время 2,935 близко к названному вами пределу ожидания яндекса.
proxy_ignore_client_abort =on заставит nginx дожидаться ответа от php и возможно тогда вы что-то увидите в журнале запросов php.
В принципе, вы можете сами писать в какой-нибудь файл, если разница между $_server[request_time] и текущим временем больше секунды. Желательно это делать на разных этапах жизни скрипта.
Виктор Таран, про innodb_flush_log_at_trx_commit вы правы, а вот претензии к процессору несколько беспочвенны, если глянуть на нагрузку с которой живёт автор.

[Виктор Таран]

batyrmastyr, запустите бенчмарк у себя на офисном core i3 5 летней давности, проверьте скорость веб сервера на нем,
будете удивлины.

[batyrmastyr]

Виктор Таран, из разряда “Hello, world” пару запросов в секунду, но на пару часов? И как предлагаете отличить от ситуации «опкеш и все остальные кеши протухли», которая на любом проце может случиться? Запустить можно, думаю и на семилетнем i5 воспроизведётся не хуже.