Меню
Что нового?

Высокая нагрузка на CPU в php-fpm

Labutin

Новичок
У нас наблюдается странная проблема на Web-сервере.
Оборудование следующее
2 процессора Intel(R) Xeon(R) CPU E5520 @ 2.27GHz
12 GB памяти
У нас порядка 20 хитов в секунду. Из них 4-5 – это тяжелые поисковые запросы.
У нас nginx + php-fpm (5.3.22)
MySQL сервер установлен на втором сервере.
В 99% времени у нас Load Average меньше 10 и нагрузка на процессорах около 50%. Сайт работает стабильно и относительно быстро.
Но в произвольный момент нагрузка на процессоры вырастает мгновенно под 100% и начинает ползти вверх Load Average. Сайт начинает тормозить.


Единственный выход из проблемной ситуации –это релоад php-fpm ( /etc/init.d/php-fpm reload )
Такое случает насколько раз в день. У нас есть монитор, который следит на Load Average и автоматом рестартует php-fpm – эдакий костыль.
Решил использовать strace для изучения проблемы.
Прошу прощения за длинные логи. Ниже приведены выводы команды strace -cp PID
PID – это случайно выбранный процесс php-fpm (запущено их порядка 100).
Вот вывод трассировки двух процессов именно в тот момент, когда мы имеем проблему.
PHP: 
Process 17272 attached - interrupt to quit
Process 17272 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 65.56    0.008817         267        33           munmap
 13.38    0.001799         900         2           clone
  9.66    0.001299           2       589           read
  7.43    0.000999         125         8           mremap
  2.84    0.000382           1       559        96 access
  0.59    0.000080          40         2           waitpid
  0.29    0.000039           0       627           gettimeofday
  0.16    0.000022           0       346           write
  0.04    0.000006           0        56           getcwd
  0.04    0.000005           0       348           poll
  0.00    0.000000           0        55           open



[root@hp-php ~]# strace -cp 30767
Process 30767 attached - interrupt to quit
Process 30767 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 52.88    0.016926         220        77           munmap
 29.06    0.009301           2      4343           read
  8.73    0.002794         466         6           clone
  3.59    0.001149           0      5598           time
  3.18    0.001017           0      3745           write
  1.12    0.000358           0      7316           gettimeofday
  0.64    0.000205           1       164           fcntl64
  0.39    0.000124          21         6           waitpid
  0.22    0.000070           0      1496       326 access
  0.13    0.000041           0      3769           poll
  0.03    0.000009           0       151           close
  0.02    0.000008           0       114           clock_gettime
  0.02    0.000007           0       110           getcwd
  0.00    0.000000           0       112           open
  0.00    0.000000           0        38           chdir
  0.00    0.000000           0        47           lseek
  0.00    0.000000           0         6           pipe
Да, наш скрипт много читает - это нормально
Почему munmap работает так долго??!! И я много разных процессов цеплял strace’ом и ВСЕГДА в топе именно munmap!!!
Для сравнения приведу вывод strace в момент штатного функционирования сервера.
PHP: 
Process 28606 attached - interrupt to quit
Process 28606 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 45.72    0.001816           1      2601           read
 32.88    0.001306         435         3           clone
  9.19    0.000365           0      2175           write
  6.95    0.000276           0      7521           time
  2.24    0.000089           0      4158           gettimeofday
  2.01    0.000080           1       114           brk
  0.28    0.000011           0      2166           poll
  0.20    0.000008           0       833       155 access
  0.20    0.000008           0        53           recv
  0.18    0.000007           2         3           waitpid
  0.15    0.000006           0        18           munlock
  0.00    0.000000           0        69           open
  0.00    0.000000           0        96           close
  0.00    0.000000           0        29           chdir
  0.00    0.000000           0        36           lseek
  0.00    0.000000           0         3           pipe
  0.00    0.000000           0        29           times
  0.00    0.000000           0        10           getrusage
  0.00    0.000000           0         5           munmap
  0.00    0.000000           0         1           ftruncate

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 54.81    0.002366           1      1717           read
 26.41    0.001140           1      1696           poll
  8.29    0.000358           0      1662           write
  7.37    0.000318           2       131       121 stat64
  1.53    0.000066           0      3249           gettimeofday
  1.18    0.000051           0       746       525 access
  0.23    0.000010           0        27           fcntl64
  0.19    0.000008           0        62           brk
  0.00    0.000000           0         1           restart_syscall
  0.00    0.000000           0         7           open
  0.00    0.000000           0        16           close
  0.00    0.000000           0         3           chdir
  0.00    0.000000           0      1039           time
  0.00    0.000000           0         1           lseek
  0.00    0.000000           0         3           times
  0.00    0.000000           0         3           ioctl
  0.00    0.000000           0         1           getrusage
  0.00    0.000000           0         4           munmap
  0.00    0.000000           0         3           setitimer
  0.00    0.000000           0         1           sigreturn
  0.00    0.000000           0         1           flock
И видно, что munmap отрабатывает как надо.
Какие версии мы проверили:
- вдруг на сервер приходит больше запросов
- сервер начинает свопиться
- на сервере появляется дополнительный трафик
- запускаются долго работающие скрипты
Ответ на все эти версии – «НЕТ».
В чем может быть проблема?
[root@hp-php ~]# uname -a
Linux hp-php 2.6.18-348.3.1.el5.centos.plusPAE #1 SMP Mon Mar 11 20:38:49 EDT 2013 i686 i686 i386 GNU/Linux
 
fixxxer

fixxxer

К.О.
Партнер клуба
FPM status (pm.status_path) не включен, случаем?

попробую погадать на кофейной гуще:

1) если статус включен - выключить нафиг
2) если используется pm=dynamic, поставить static
 

Labutin

Новичок
Заранее спасибо за внимание в нашему вопросу.
pm.status_path действительно включен, сейчас отключу
pm=dynamic тоже есть. Чем он принципиально плох? Сейчас попробую статик поставить.
Какие еще сведения будут полезны, чтобы не гадать?
 
fixxxer

fixxxer

К.О.
Партнер клуба
У меня подозрение на код в fpm_scoreboard, если поставить статик и вырубить статус он вроде бы не будет использоваться.
 

Labutin

Новичок
Хорошо, уже поменял конфиг php-fpm (убрал pm.status_path и поставил pm = static)
Посмотрим до конца дня - будут ли всплески.
 

Labutin

Новичок
Не помогло. Точнее так. Утром сегодня снова процессор под 100% загрузился. Правда при этом Load Avegare поднялся с 5 до 35. Раньше необъяснимая нагрузка на CPU поднимала Load Avegare точно выше 40, т.к. у нас настроен монитор, который рестартует php-fpm при Load Avegare > 40
 
fixxxer

fixxxer

К.О.
Партнер клуба
Значит, не угадал. :)

В slowlog ничего интересного нет? А в fpm-логах?
Акселератор какой?
 

Labutin

Новичок
slow log от php-fpm не пуст, есть служебные скрипты, которые долго работают - и мы про них знаем. В момент аномалии эти скритпы не работали.
В качестве акселератора Zend Optimizer+ https://github.com/zend-dev/ZendOptimizerPlus
 
fixxxer

fixxxer

К.О.
Партнер клуба
slow log от php-fpm не пуст, есть служебные скрипты, которые долго работают - и мы про них знаем
Нажмите для раскрытия...
ну понятно что я про записи в оном в момент резкого роста LA

В качестве акселератора Zend Optimizer+ https://github.com/zend-dev/ZendOptimizerPlus
Нажмите для раскрытия...
ну он недавно появился, а до него что было? нет ли связи между появлением проблем и переходом на zo+? штука то свежая и мало тестированная.

вообще я бы попробовал:
1) сдампать strace-ом пачку всей радости и выковырять последовательность сисколлов вокруг медленного сисколла. по статистике то - чего там, непонятно нихрена
2) взять нестрипанные бинари, словить момент, прицепиться через gdb, добавить catchpoint на munmap, пытаясь попасть на тормозной (ыхыхых =), и посмотреть, откуда он дергается.

а так гадать можно долго
 

Labutin

Новичок
На скрине в первом посте видно, что грузится проц user + system
 

Labutin

Новичок
fixxxer написал(а):
ну он недавно появился, а до него что было? нет ли связи между появлением проблем и переходом на zo+? штука то свежая и мало тестированная.
Нажмите для раскрытия...
До zo+ вообще без акселератора жили. Но всплески необъяснимые были. Установка zo+ помогла переживать эти всплески без явно видимых тормозов для клиентов.
Я strace'ом не только статистику снимал, но и полностью вызовы дампил. В момент высокой нагрузки выполняется все тот же код. НО munmap действительно начинает выполняться дольше! Другого отличия от штатного поведения я не обнаружил.
 

Labutin

Новичок
Еще ядро Linux обновляли, php-fpm обновляли, zo+ обновляли - никакой реакции.
 
fixxxer

fixxxer

К.О.
Партнер клуба
Перед всплесками нет какой-то известной активности? Типа ротации логов или подобного?
 

Labutin

Новичок
В том то и дело, что нет.
Сайтом пользуются внешние пользователи и сотрудники (аналитики всякие).
Отключали внутренних пользователей - всплеск все равно есть.
Отключали внутренние долго работающие сервисы - всплеск все равно есть. Причем эти скрипты запускаются регулярно по несколько раз в день и к всплескам не приводят.
Ротация логов, резервные копии и другие ОЧЕНЬ тяжелые операции всегда происходят только ночью. Днем все по максимуму отдается внешним пользователям.
Уже месяц голову ломаем. Свой код прошерстили. Оптимизировали. В целом нагрузку снизили. А всплески все равно есть.
И самое интересное, что появились они после новогодних каникул. В праздники единственное, что изменилось - это IP адрес сервера. Потом как-то мирились с этими всплесками, а сейчас решили всерьез взяться за выяснение причины их возникновения.
 
fixxxer

fixxxer

К.О.
Партнер клуба
Ну надо смотреть, откуда эти вызовы.

Если в zend_alloc.c, то я даже и не знаю. Боюсь, кроме тех трех людей, которые перечислены в заголовке файла в Authors, никто не понимает, как оно работает =)
 

Sender

Новичок
снимите во время всплеска iotop, top (память особенно интересна), mysqltop и mysql - show status, ну и сетевые интерфейсы на всякий случай
CPU может быть всего лишь следствием
ну и все логи шерстите

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

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