Почему php-fpm плодит процессы и грузит систему?

Question

[Виталий Р]

Есть сервер заббикс версии 3.0. Работал всегда исправно. Недавно стал жутко тормозить. Исследования показали, что плодятся процессы php-fpm и жутко грузят систему. Причем отследить какую-то закономерность пока что не удалось.

Лог php-fpm

[23-Jan-2018 14:55:17.187223] DEBUG: pid 8266, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool www] currently 20 active children, 0 spare children, 20 running children. Spawning rate 1
[23-Jan-2018 14:55:18.188435] DEBUG: pid 8266, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool www] currently 20 active children, 0 spare children, 20 running children. Spawning rate 1
[23-Jan-2018 14:55:19.189574] DEBUG: pid 8266, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool www] currently 20 active children, 0 spare children, 20 running children. Spawning rate 1
[23-Jan-2018 14:55:19.304932] WARNING: pid 8266, fpm_request_check_timed_out(), line 271: [pool www] child 9011, script '/usr/share/zabbix/map.php' (request: "GET /map.php") executing too slow (13.250784 sec), logging
[23-Jan-2018 14:55:19.305105] WARNING: pid 8266, fpm_request_check_timed_out(), line 271: [pool www] child 8353, script '/usr/share/zabbix/map.php' (request: "GET /map.php") executing too slow (12.110724 sec), logging
[23-Jan-2018 14:55:19.305144] DEBUG: pid 8266, fpm_got_signal(), line 76: received SIGCHLD
[23-Jan-2018 14:55:19.305169] NOTICE: pid 8266, fpm_children_bury(), line 227: child 8353 stopped for tracing
[23-Jan-2018 14:55:19.305175] NOTICE: pid 8266, fpm_php_trace(), line 144: about to trace 8353
[23-Jan-2018 14:55:19.305548] NOTICE: pid 8266, fpm_php_trace(), line 172: finished trace of 8353
[23-Jan-2018 14:55:19.305563] NOTICE: pid 8266, fpm_children_bury(), line 227: child 9011 stopped for tracing
[23-Jan-2018 14:55:19.305568] NOTICE: pid 8266, fpm_php_trace(), line 144: about to trace 9011
[23-Jan-2018 14:55:19.305729] NOTICE: pid 8266, fpm_php_trace(), line 172: finished trace of 9011
[23-Jan-2018 14:55:19.305742] DEBUG: pid 8266, fpm_got_signal(), line 76: received SIGCHLD
[23-Jan-2018 14:55:19.305748] DEBUG: pid 8266, fpm_event_loop(), line 419: event module triggered 1 events
[23-Jan-2018 14:55:20.190686] DEBUG: pid 8266, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool www] currently 20 active children, 0 spare children, 20 running children. Spawning rate 1
[23-Jan-2018 14:55:32.640866] WARNING: pid 8266, fpm_request_check_timed_out(), line 271: [pool www] child 9040, script '/usr/share/zabbix/map.php' (request: "GET /map.php") executing too slow (13.057358 sec), logging
[23-Jan-2018 14:55:32.641051] DEBUG: pid 8266, fpm_got_signal(), line 76: received SIGCHLD
[23-Jan-2018 14:55:32.641077] NOTICE: pid 8266, fpm_children_bury(), line 227: child 9040 stopped for tracing
[23-Jan-2018 14:55:32.641085] NOTICE: pid 8266, fpm_php_trace(), line 144: about to trace 9040
[23-Jan-2018 14:55:32.641415] NOTICE: pid 8266, fpm_php_trace(), line 172: finished trace of 9040
[23-Jan-2018 14:55:32.641428] DEBUG: pid 8266, fpm_event_loop(), line 419: event module triggered 1 events
[23-Jan-2018 14:55:33.205565] DEBUG: pid 8266, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool www] currently 20 active children, 0 spare children, 20 running children. Spawning rate 1
[23-Jan-2018 14:55:39.211917] DEBUG: pid 8266, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool www] currently 20 active children, 0 spare children, 20 running children. Spawning rate 1
[23-Jan-2018 14:55:39.308203] WARNING: pid 8266, fpm_request_check_timed_out(), line 271: [pool www] child 8969, script '/usr/share/zabbix/map.php' (request: "GET /map.php") executing too slow (10.989382 sec), logging
[23-Jan-2018 14:55:39.308357] DEBUG: pid 8266, fpm_got_signal(), line 76: received SIGCHLD
[23-Jan-2018 14:55:39.308381] NOTICE: pid 8266, fpm_children_bury(), line 227: child 8969 stopped for tracing
[23-Jan-2018 14:55:39.308388] NOTICE: pid 8266, fpm_php_trace(), line 144: about to trace 8969
[23-Jan-2018 14:55:39.308678] NOTICE: pid 8266, fpm_php_trace(), line 172: finished trace of 8969
[23-Jan-2018 14:55:39.308691] DEBUG: pid 8266, fpm_event_loop(), line 419: event module triggered 1 events
[23-Jan-2018 14:55:40.213576] DEBUG: pid 8266, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool www] currently 20 active children, 0 spare children, 20 running children. Spawning rate 1

Лог php-fpm-slow

[23-Jan-2018 14:57:09.329814] [pool www] pid 9040
script_filename = /usr/share/zabbix/map.php
[0x00007fe2fed799e0] get() /usr/share/zabbix/include/classes/api/services/CMap.php:256
[0x00007ffe350accc0] get() unknown:0
[0x00007fe2fed78f48] call_user_func_array() /usr/share/zabbix/include/classes/api/clients/CLocalApiClient.php:123
[0x00007fe2fed78d20] callMethod() /usr/share/zabbix/include/classes/api/wrappers/CFrontendApiWrapper.php:97
[0x00007fe2fed78c18] callClientMethod() /usr/share/zabbix/include/classes/api/wrappers/CApiWrapper.php:94
[0x00007fe2fed787e0] callMethod() /usr/share/zabbix/include/classes/api/wrappers/CFrontendApiWrapper.php:63
[0x00007fe2fed786b8] callMethod() /usr/share/zabbix/include/classes/api/wrappers/CApiWrapper.php:82
[0x00007ffe350acfc0] __call() unknown:0
[0x00007fe2fed77520] get() /usr/share/zabbix/include/maps.inc.php:366
[0x00007fe2fed75490] add_elementNames() /usr/share/zabbix/map.php:105

[23-Jan-2018 14:57:19.325910] [pool www] pid 8996
script_filename = /usr/share/zabbix/map.php
[0x00007fe2fed799a0] get() /usr/share/zabbix/include/classes/api/services/CMap.php:261
[0x00007ffe350accc0] get() unknown:0
[0x00007fe2fed78f08] call_user_func_array() /usr/share/zabbix/include/classes/api/clients/CLocalApiClient.php:123
[0x00007fe2fed78ce0] callMethod() /usr/share/zabbix/include/classes/api/wrappers/CFrontendApiWrapper.php:97
[0x00007fe2fed78bd8] callClientMethod() /usr/share/zabbix/include/classes/api/wrappers/CApiWrapper.php:94
[0x00007fe2fed787a0] callMethod() /usr/share/zabbix/include/classes/api/wrappers/CFrontendApiWrapper.php:63
[0x00007fe2fed78678] callMethod() /usr/share/zabbix/include/classes/api/wrappers/CApiWrapper.php:82
[0x00007ffe350acfc0] __call() unknown:0
[0x00007fe2fed774e0] get() /usr/share/zabbix/include/maps.inc.php:366

Собственно логично предположить, что проблема в php скрипте map. Только вот как её исправить ? и что именно это за проблема ? Бывает так, что веб интерфейс забикс работает пол дня идеально, открывая всё что угодно, в том числе и все карты, за милисекунды, а потом резко начинается *опа. Все тормозит и открывается по 10 секунд. Причем я никак не могу отследить, после каких и чьих действий это происходит.

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

Подскажите, куда капнуть ? Где глянуть ?

Answer 1

[Пума Тайланд]

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

Comments

[Виталий Р]

Обновиться можно. Если с проблемой не разберусь, то так и сделаю.

Вообще.... какашки в логи по поводу медленного map.php падают круглосуточно, но в не рабочее время (а иногда и в рабочее время) веба откликается моментально (как положено).

[Пума Тайланд]

Виталий Р, ну очевидно что в нерабочее время не может сыпаться , так как никто в заббикс не заходит

[Виталий Р]

Пума Тайланд, с забиксом у нас могут работать круглосуточно. Я пытаюсь объяснить то, что не понятно в чём дело.

По какой причине, веб интерфейс например в 12:47 Резко начинает тормозить. Просто жутко тормозит, открывая всё по 20 секунд, а новых ошибок в логах не появляется.

[Пума Тайланд]

Виталий Р, ну я же вам сказал посмотреть слоулоги ну и почистить базу например скриптами от хуябикса

[Виталий Р]

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

[Пума Тайланд]

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

[Виталий Р]

Пума Тайланд,

"на основе чего вы такое приняли решение?" - первое что я стал исследовать, это мускуль. На нём нет никаких задержек. Система не загружена вообще.

Ну и самое главное, почему мускуль не причем - второй веб сервер работает идеально.
На сервере мускула нету никаких задержек. Это взято не с неба.

Если не хотите помогать, не надо сарказма, про иконки и боженьку. Просто пройдите мимо либо найдите смелость сказать "я не знаю".

[Виталий Р]

"а вы с потолка взяли информацию что с мускулом" прям взбесило.... что за идиотский подход... Вы то откуда знаете какой анализ я проводил ?

php-fpm грузит систему. php-fpm не равно mysql. php-fpm запускает скрипты которые работают нормально, а вдруг в какой-то момент начинают вешать сервер. На мускуле в это время НИЧЕГО не происходит. Он как отдавал ответы на запросы с одним временем, так и отдаёт.

Советы уровня "переустанови виндовс"... специалист прям от бога.

[Пума Тайланд]

Виталий Р, что значит не загружен то? Я вот на основе ваших данных вижу что загружен
Тем более если на второй вебе такая же проблема

[Виталий Р]

Пума Тайланд, вы, простите, слепой ???

Вторая веба работает ИДЕАЛЬНО. Нету на ней проблемы.

mysql server не загружен. Вам скрин htop показать ? или чё ? или пустой mysql_slow_log ?

Я говорю - не загружен. Вы мне - загружен. У меня серв под рукой, у вас фантазии. Что за компетентность ?

[Виталий Р]

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

Давайте заново:

Есть физическая машина с mysql + zabbix server - на ней нет проблем. Проц не загружен. Памяти свободной куча. В логах всё хорошо.

Есть виртуальная машина с hginix + php5. Служит вебмобрдой для забикса на ней иногда! повторюсь, ИНОГДА взлетает загрузка процессора (всех 12 ядер) до 100%. htop показывает что это делает процесс php-fpm. Чем это вызвано я и пытаюсь разобраться. Обновиться или "переустановить винду", я всегда успею.

[Пума Тайланд]

Виталий Р, ну если на новой ноде все ок, значит найдите пять отличий от старой и будет ясно в чем причина

[Виталий Р]

Пума Тайланд, а их нет. Сервер полный клон. Разница только в пользователях.

[Пума Тайланд]

Виталий Р, ну посмотрите по айпи кто их пользователей ломает все и узнайте как

[Виталий Р]

Пума Тайланд, я долго держал это в себе, но теперь я уверен - вы просто не разбираетесь в этом вопросе.

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

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

[Пума Тайланд]

Виталий Р, ну сделайте им прокси местные и прокиньте реальные айпи, ну и для чистоты эксперимента просто перекиньте всех на второй сервер.

Answer 2

[Fortop]

не может быть же такого, что скрипт отработал 100 раз нормально, а потом стал резко отрабатывать сбойно, а потом снова нормально

Может.
Но информации недостаточно.

Версии пхп - не указаны.
Железо - не указано.
Работают ли на этом сервере другие приложения - не указано

Это то, что нужно узнать в первую очередь для постановки хотя бы начального диагноза в виде "в какую сторону копать".

Comments

[Виталий Р]

Debian 9
php5
i7 12 ядер, 8гб оперативы

Кроме php есть zabbix-agent, nginix.

Често не понимаю, что это вам даст.

[Fortop]

Виталий Р, я правильно понимаю, что БД находится физически на другой машине?

И, говоря о "других" приложениях, я имел в виду в том числе другие ваши сайты/сервисы/скрипты работающие на этом сервере.

[Виталий Р]

Fortop, Да, вы правильно понимаете. сервер бд, а так же сервер забикса находится на другой машине.

На этой крутится только то что я написал. забикс агент и вебморда забикс сервера на nginx + php5-fpm

[Fortop]

Виталий Р, промониторьте через заббикс состояние нагрузки на процессор, диск и память в моменты "залипания" скрипта

[Виталий Р]

Fortop, нету никакого залипания скрипта. Ругань по поводу мап.пхп в пхп-слоу падает круглосуточно. Но Нагрузка от пхп5-фпм появляется приблизительно в одно и тоже время и грузит ТОЛЬКО проц, все ядра на 100 процентов. Иногда начинается в 11 утра, иногда в 9 утра, но чаще всего перед обедом примерно в 12:50

[Fortop]

Виталий Р, ставьте xhprof если не 7-ка
И tideways если 7
Можете его активацию внести в скрипт по времени +/- возникновения проблем.

Или New Relic, но не могу точно сказать зайдет ли он для мониторинга заббикса.

Соберете профайлы исполнения - будете знать что именно происходит на какой части кода.

Дальше уже исследовать подсистемы с которыми эта часть связана.