php fpm slow requests
Анализируем php-fpm.slow.log
Итак, настал тот день когда Вы или Ваш коллега, наконец-то, запустили серьёзный проект, будь то портал/социальная сеть/игра для социалок. Но, как всегда внезапно, проект начинает тормозить. В чём же дело? Ведь и база настроена как надо, и кеш используется, даже nginx с акселератором PHP кода трудятся в поте лица.
Дабы не покрывать весь код каким-то Benchmark’ом для выявления узких мест можно воспользоваться замечательной возможностью логирования php-fpm, который будет дампить скрипты, выполнявшиеся больше N секунд. Включается это чудо в php-fpm.conf.
Что же делать?
В первую очередь, следует найти и исправить код в тех местах, где проблема возникает чаще всего. В этом нам поможет нижеследующий пример.
//чтобы отсечь лишнее, подбирается под конкретные задачи анализа лога, список функций легко определить на глаз при открытии файла лога
$functions=array(
«mysql_query»,
«session_start»,
);
//функция очищения пути к файлу
function clear_path($path)
<
return str_replace(«/home/»,»»,$path);
>
На выходе мы получаем массив, ключами которого является путь до проблемного файла, а значениями — второй массив, ключами которого является строка в файле, значением — количество выполнений более N секунд.
[/path/to/script2.php] => Array
(
[64] => 5
)
[/path/to/script3.php] => Array
(
[375] => 1
[468] => 39
[358] => 1
[391] => 5
[249] => 1
[154] => 2
)
)
Далее каждый уже для себя может настроить вывод в более приятной для глаза форме.
Debugging PHP Scripts Using slow_log and more
If you are an old PHP programmer, you must have used PHP’s error_log function sometime. But PHP itself does not provide a way to find out slowly executing scripts. Slow scripts are not the ones which break your site but they slow-down everything. Using FPM, we can have a slow_log for all such scripts. Let’s see how to use these logs to debug PHP scripts. Also, we will see how PHP’s error_log gets diverted if it is running behind FPM and Nginx.
Setup slow_log for PHP scripts
Open… vim /etc/php5/fpm/pool.d/www.conf Make necessary changes to match following values:
You can replace 10s with any other value. This will help us find scripts which execute slowly. Image resizing function, network I/O related functions are some examples which will frequently show-up in PHP slow_log. Its up to you to debug them or ignore them based on your context.
Setup error_log for PHP scripts
When running PHP using FPM, we can override any php.ini setting from FPM. Open… vim /etc/php5/fpm/pool.d/www.conf Scroll down towards bottom and uncomment/change following 3 lines to match values given below:
Please note that turning on display_errors can break ajax-based applications. So be really careful with this.
Important for Nginx Users
You will not see a file /var/log/php5/error.log or not any error being logged in that file. Errors in your PHP scripts for a site will go into error_log specified for that site in its nginx config. Most likely: /var/www/example.com/logs/error.log file If you haven’t specified any error_log path for your site, then PHP errors will go to Nginx’s default error_log. Most likely /var/log/nginx/error.log file) You can find more details here about debugging with Nginx.
Setup FPM error_log to debug FPM itself
FPM is separate process. Like others, it can run into errors itself! FPM’s error_log is on by default but we will change its path to meet our convention. Open… vim /etc/php5/fpm/php-fpm.conf Make sure error_log value looks like below
Please note that this error_log is not related to PHP’s error_log function described before.
Confirm Changes…
Create php5 log directory so we can have all PHP logs in one place:
Restart PHP-FPM for changes to take effect…
Monitoring log file
slow_log helped us many times to eliminate bottlenecking from our applications.
Always remember to turn it off when you are done with debugging. Leaving slow_log on is not a good idea.
How to log and fix slow PHP requests
When troubleshooting a slow PHP website, logging slow requests is very important.
The most common way to run a PHP website is via PHP-FPM, and, surprise, it has some directives for the job of logging slow requests.
How to enable PHP-FPM slow log
PHP-FPM slow log can be configured on a per pool basis, which means you can configure for a specific website when you need to troubleshoot performance issues.
Simply edit the PHP-FPM pool configuration, e.g. /etc/php-fpm.d/example.com.conf and add directives specifying the desired location of the slow log file and the time it takes for a script to run for it to be logged:
The slowlog directive is the path to a file where the slow requests will be logged. Of course, the path to the slow log file should be somewhere that the PHP-FPM pool user can create/read/write files.
The request_slowlog_timeout is the time after which PHP-FPM will dump a backtrace for slow requests. 3 seconds is a good starting point where a script can be deemed as slow.
Although I’d really think of any script that takes more than one second to be slow, we should account for under-powered servers.
That’s pretty much all it takes for configuring it. Simply run systemctl reload php-fpm to apply the configuration, and slow requests will be logged going forward.
Working with the PHP-FPM slow log files
The slow log entries, unfortunately, only include script_filename and not the URI that is being called.
So you can’t look at the slow log alone to get complete information about the slow request, because in most front-controller pattern frameworks (which WordPress is),
there will be mostly a single, or in some cases a couple of scripts handling all the requests (e.g. /index.php for front page and /wp-admin/index.php for the admin pages).
So you will have to correlate the time of the slow log request with the time in access.log in your web server.
To find the related access log requests, the easiest is having an aggregated log facility, e.g. PaperTrail.
In case of the aggregated log, you would simply scroll up through the log records above the slow PHP-FPM record to locate the one from the web server.
The text browser search for the specified text and you can easily locate the related access log entry.
For our sample request, the related entry in access.log is the following:
So simply browsing /wp-admin/ is slow. Why? Let’s look back at our slow PHP-FPM backtrace and see how to read it.
The function calls are listed in the order of recency: the function that ran earlier will be at the bottom; the function to run last will be at the top.
So we see that when the script exceeded the 3 seconds threshold, it was running curl_exec function, which indicates the most common reason of a slow website in modern content management systems – curl requests to remote websites.
The solution there is typically halting the often unnecessary requests from being made, or adjusting the URL of the requested remote services, if they are crucial to website’s function.
So how to identify which code is responsible for such requests, why and to which URLs? Simply read the slow entry from the bottom to the top.
The functions were in invoked in this order
You can browse through each function call via less as well.
While you can do it for each entry (in order to understand why the code ended up using curl_exec ), you can use some intuition there. Run command:
This will take you to where wp_remote_post was called. Navigating the code few lines above, you can locate the actual URL being invoked:
A Google search away, is the answer to your query:
WordPress checks whether your browser is up-to-date, and displays a notice if it is not (i.e., “You are using an insecure browser!” or “Your browser is out of date!”).
Specific to this case, it is a WordPress behavior which calls its own API to check if your browser is up-to-date.
Thanks WordPress, if you do this, at least you should have used a faster web server for your API.
So you can disable this with a simple paste-in to your functions.php :
Other common Causes of Slow Requests
Aside from slow curl function calls to remote services (a.k.a slow websites that makes your website slow), there are few other common cases why PHP is slow to run, and thus logged to slow PHP-FPM log
Slow MySQL queries
That will usually manifest in a form of logged mysql_query function calls. The issue is typically with a missing database index, which will speed up queries’ execution
Long running scripts running in web context
This is caused by long-running scripts launched via browser, where there shouldn’t be.
An example is a data import/export, that has to be executed via cron/message queues, etc.
Typical mistake is running website cron tasks via curl invocation in crontab. This is wrong in 99% cases.
When you’re done fixing slow PHP requests, do not forget to disable PHP-FPM slow log on a production website by commenting directives that enabled it.
This ensures that PHP-FPM doesn’t incur additional overhead to keep the backtrace.
Nginx + PHP-FPM + APC slow response times
We currently have a Nginx server setup with PHP-FPM and APC for caching. It was setup to run one medium load website, where we wanted to put an emphasis on site load times as their whole business relies heavily on the website (online bookings).
The specs are: 1 CPU, 1GB Ram, Ubuntu 12.04 LTS, Nginx 1.1.19, PHP-FPM 5.3.10
It has been working without any issues for quite awhile now (approx 1 year).
However we needed to setup a split testing situation to test a new version of the website. As we weren’t able to just alternate between different code snippets (using a CMS and the database structure had also changes) we decided we would use a subdomain and send 20% of traffic to the subdomain instead.
To achieve this we simply created a new server block and setup the new site completely standalone in a new folder. Then inside the original server block file we used nginx split clients to set a cookie and redirect to ‘new’ if in that percentile.
We figured it was fine to just do this on the main/old site as all of their traffic comes from Google and is unlikely to be a repeat client in the testing period so the likelyhood of someone coming direct to ‘new’ is very low and wouldn’t impact on the results
It was working fine at first be after a few days we started to get some complaints regarding slow load times. After some debugging it was only traffic heading to ‘new’ and is only intermittent. The original site isn’t being effected at all at this point.
We have slowly disabled features trying to workout where the problem is but we can’t find where the issue lies. The split testing has been disabled temporarily and it turns out that even if you try to load the subdomain directly, it will sometimes have a very slow initial response (around 20s).
At first I thought this might be a caching issue so we disabled APC completely but it hasn’t resolved the problem. We did have fastcgi cache enabled at one point to try speed it up but this was disabled long ago.
We have a few other servers with very similar setups so I am struggling to find where the issue lays.
Here are file snippets
Nginx.conf
Site 1 / Original
Site 2 / New
Bits from PHP-FPM pool.d
I also don’t think its a memory issue (not getting any memory alerts)
The log files don’t seem to provide me with any useful information and it isn’t causing anything to log in php slowlog with 15s threshold.
As mentioned this is only an intermittent problem and I can’t find a pattern to it.
Any help would be greatly appreciated.
Also if there is a better way of doing the split testing I would love to hear about it.
Сайт тормозит и php перегружает процессор
Несколько дней назад заметил, что сайт стал очень сильно тормозить, загрузка одной страницы до 10 секунд, хотя раньше было не более двух, сайт WordPress, работает на VPS CentOS 7 (2 Гб ОЗУ, 4 CPU x 2,2 Ghz) с Nginx + PHP-FPM. Поиск медленных скриптов через slow.log ничего не дал, часто попадает в лог файл index.php (выполняется более 5 секунд). Увеличение мощности сервера на одно ядро тоже. Кэширование включено через плагин W3 Total Cache, страницы кэшируются на диск, а база данных и объекты wordpress в memcached. Посещаемость до 15к уникальных пользователей в сутки. Пытался отсеять ботов с помощью модуля nginx testcookie, отсеиваются только боты поисковых систем, но да, тогда нагрузка падает, правда это не вариант. Да и директива Crawl-daily в robots.txt есть. Если W3TC отключить, PHP вообще падает по 502, а страницы начинают загружаться не быстрее, чем за 40-50 секунд. Что со всем этим можно сделать? Ниже конфигурационные файлы и статистика:
Глобальный конфиг Nginx:
Вообще мне кажется, что проблема или в вордпрессе, или в mysql.
Я, конечно, посоветую вам сделать nginx вот так:
а для fpm что-то подобное:
Хм, спасибо. Настройки Nginx похоже помогли чуть, судя по pingdom время ожидания ответа от Nginx уменьшилось с 400 до 200 мс, но с PHP ничего не изменилось, к сожалению.
Лог есть, да только там ничего нет полезного:
Отключил плагин redirection, лог больше не пополняется так интенсивно, но ситуация не улучшилась.
И заодно конфиг fpm (который основной, а не ваш пул)
по любому процессу fpm
Там иногда SIGSEGV бывают, а так конечно /var/log/nginx *error_log*
Проверьте, какие расширения грузятся + включено ли кэширование байт-кода
php-fpm.conf
Меня смущают вот эти три строчки минимум. ХЗ что вам посоветовать. В идеале strace’ом ловить, какие файлы пытается читать fpm и решать проблему с ними, но тут с вашей нагрузкой задача та еще.
Покажи, сколько занимают каталоги с кешем Покажи, сколько записей в таблицах с кешем в базе данных Можешь отсортировать записи из mysql slow_log по времени выполнения?
мож сессии надо в мемкашу тоже засунуть. надо посмотреть на waitы при большой загрузке.
Да не может оно тормозить из-за сессий при 15к суточном трафике, большинство из которых судя по всему даже неавторизованые пользователи.
Пытался закрыть доступ к wp-admin, но сейчас вечер, нагрузка немного упала, загрузка процессора держится на уровне 70-100%, но сайт по прежнему грузится долго. Нужно будет тестировать с утра. И еще только что проверил скорость по pingdom, Wait time составил до 10 секунд, с чего бы это? https://losst.ru/wp-content/uploads/2017/07/Snimok-ekrana-ot-2017-07-10-22-18.
Я вот думаю, допустим это даже поисковики, они же не будут писать комментарии, рыть поиск и т д. Они запрашивают обычные страницы. Им должна отдаваться статика (кэширование включено), а значит никакой нагрузки на PHP быть не должно. А она есть. Есть ли какой-нибудь инструмент, чтобы посмотреть при такой нагрузке что, кто и где делает, например, анализатор логов access.log? Как понять откуда та нагрузка?
Пытался закрыть доступ к wp-admin, но сейчас вечер, нагрузка немного упала
Папка с кєшем от w3tc занимает 68 мегабайт, в memcached занято около 19 мб, если я правильно понял:
access.log анализировать можно(и нужно) с помощью стандартного набора из cat,tail,awk,sort и uniq.
С помощью конвеера из данных команд с нужными параметрами вы можете получить статистику по количеству запросов к тому или иному URL, статистику по количеству запросов для каждого или наиболее активных IP и т.п.
Но, как правило, одних логов в подобной ситуации не достаточно, что-бы понять почему именно длительное время висят запросы к скриптам сайта нужен strace одного из нагруженных обработчиков php-fpm.
Если посещаемость ресурса большая, и из-за большого колчества запросов трейс затруднён, можно на время(к примеру ночью, когда посетителей меньше) перенаправить всех посетителей не с вашего внешнего ip на статический сайт-заглушку, тогда у вас появится пару десятков минут для вдумчивого трейса проблемных скриптов. И при этом запросы от других посетителей сайта не будут вам мешать трейсить скрипты сайта. Главное не забыть потом убрать заглушку:)
И еще неплохо было бы написать, с чего все началось. Были ли тормоза изначально, или появились недавно? Какие то изменения может были?
Да, есть брут, но там не очень активно. Идет четыре попытки с одного IP, потом IP меняется, видимо попадает в бан wordpress. Интервал между сериями в несколько минут. Попробую закрыть и посмотрю что будет. Спасибо!
Раньше все работало отлично, если брать тот же pingdom, то сайт загружался за плюс минус две секунды. Ничего не менялось. Буквально три дня назад нагрузка начала расти и вот до сих пор.
Ну если ничего не менялось, то можно рассмотреть вариант с хостером: например диски начали тормозить.
Глянь iotop/iostat.
Может какой-то вордпрес плагин заглючил, попробуй повыключать и посмотреть на результаты.
Использую php5 из официальных репозиториев и без opcache.
Надо обязательно переехать на 7, но это не отменяет того вопроса, что раньше не тормозило а теперь начало 🙂 Конкретно wp чуть ли не в 2 раза быстрее работает на 7, по сравнению с 5. Ну это так, оффтоп.
Медиафайлы есть, но насколько я знаю wordpress их обрабатывает во время загрузки, а пользователям отдает уже статику.
Да это понятно. Но я не думаю, что там с каждого ip всего по одному запросу, поэтому какую-то часть он отрежет. Не настолько крупный сайт, чтобы какой-то более изощренный ботнет на несколько дней натравлять.
Не настолько крупный сайт, чтобы какой-то более изощренный ботнет на несколько дней натравлять.
Это не так работает, конкретно на какие-то сайты никто ничего не направляет: берется большой список доменов и чекается, это ж бизнес.
Но я не думаю, что там с каждого ip всего по одному запросу
Чаще всего именно так.
Запросы на wp-login все еще есть, но теперь та страница закрыта аутентификацией Nginx. Теперь они php трудностей не составляют, нагрузка на процессор от php упала. Всем спасибо. Возможно действительно только в этом было дело. Вот даже сейчас есть:
Сейчас среднее время загрузки 3-4 секунд что в принципе норма. Завтра еще планирую обновить Nginx до последней версии с полной поддержкой http2 и обновить PHP до 7.0. Плюс сессии пользователей в memcached и настрою opcode. Надеюсь после этого скорость еще вырастет. Но вообще очень странно, что запросы на одну страницу смогли так уложить сайт.
Но вообще очень странно, что запросы на одну страницу смогли так уложить сайт.
Мда, школьничек какой-то с одного ip брутит 🙂