Групування slow logs PHP-FPM, щоб знайти, на що чекає ваш сайт

«Сайт повільний» не є чимось, що хтось може виправити. «Чотири з десяти повільних запитів чекають на один виклик зовнішнього API» є. PHP-FPM може сказати вам друге речення безкоштовно, через лог, який на більшості серверів вимкнений. Ось як його увімкнути, читати і групувати так, щоб відповідь випала сама.

Проблема: повільно, але де?

Коли сторінки PHP повільні, більшість розслідувань починаються ззовні (інструменти вимірювання часу сторінки) або з бази даних (slow query log). Обидва корисні, і обидва пропускають найпоширенішу причину на сучасних сайтах: PHP чекає на щось, що не є ні CPU, ні локальною базою даних. Платіжний шлюз. API складу або ERP. Перевірка ліцензії. Блокування сесії, яке тримає інший запит від того самого відвідувача. Ці очікування не проявляються як CPU, тож сервер виглядає вільним, поки відвідувачі дивляться на спінер.

Slow log PHP-FPM ловить їх усі, бо йому байдуже, чому запит повільний. Він просто робить знімок того, що запит робить.

Увімкніть його

У конфігурації pool (наприклад, /etc/php-fpm.d/www.conf):

slowlog = /var/log/php-fpm/www-slow.log
request_slowlog_timeout = 3s
request_terminate_timeout = 60s

Коли запит виконується довше за request_slowlog_timeout, майстер FPM знімає backtrace worker і пише його в slow log. Запит продовжується; нічого не вбивається. request_terminate_timeout є окремим запобіжником, який таки завершує запити, що втекли, і його варто встановити, поки ви тут.

Оберіть поріг трохи вище того, як виглядає «нормально» для ваших некешованих сторінок. Занизько, і ви логуєте здорові запити. Зависоко, і ви бачите лише катастрофи. Перезавантажте FPM і дайте йому назбирати протягом завантаженого періоду.

Прочитайте один запис

Запис slow log виглядає так:

[22-Oct-2026 10:14:07]  [pool www] pid 41822
script_filename = /var/www/shop/index.php
[0x00007f1c2a614f20] curl_exec() /var/www/shop/modules/erpsync/Client.php:188
[0x00007f1c2a614e10] request() /var/www/shop/modules/erpsync/Client.php:97
[0x00007f1c2a614d00] getStock() /var/www/shop/modules/erpsync/Stock.php:42
[0x00007f1c2a614bf0] hookDisplayProduct() /var/www/shop/classes/Hook.php:1017
...
[0x00007f1c2a6140a0] dispatch() /var/www/shop/index.php:28

Верхній кадр, той, що безпосередньо під script_filename, є тим, на чому запит був заблокований у момент знімка. Нижче йде те, як він туди дійшов. У цьому прикладі сторінка товару чекає на curl_exec(), викликаний модулем синхронізації складу під час показу товару.

Один запис є анекдотом. День таких записів є профілем.

Групуйте за кадром, що блокує

Згрупуйте кожен запис за його верхнім кадром і порахуйте:

awk '/^script_filename/ { w = 1; next }
     w && /^\[0x/ {
       fn = $2
       match($0, /[^ ]+:[0-9]+$/)
       print fn " @ " substr($0, RSTART, RLENGTH)
       w = 0
     }' /var/log/php-fpm/www-slow.log \
  | sort | uniq -c | sort -rn | head -25

Результат є ранжованим списком того, що повільні запити насправді робили. На типовому повільному магазині він може виглядати так:

 812 curl_exec() @ .../modules/erpsync/Client.php:188
 497 execute() @ .../classes/db/DbPDO.php:132
 251 session_start() @ .../config/bootstrap.php:61
  88 file_get_contents() @ .../themes/shop/fonts.php:12

Потім згрупуйте другим способом: за першим кадром усередині каталогу плагіна, модуля або теми. Це перетворює список з «яка функція» на «чий код», а саме це питання поставлять розробники.

Що означають поширені кадри

curl_exec(), file_get_contents() на URL, fsockopen(): зовнішній виклик, зроблений синхронно під час генерації сторінки. Подивіться на timeout, який він використовує; довгий timeout на повільній третій стороні зупиняє worker на весь цей час. Виправлення: короткий timeout, кешування відповіді або винесення виклику за межі запиту сторінки.

execute(), query(), mysqli_query(): очікування бази даних. Візьміть файл і рядок у slow query log і зробіть EXPLAIN запиту, який там виконується. Якщо buffer pool відповідає з пам’яті, а запит усе одно займає секунди, проблема в запиті або його індексах, а не в обладнанні.

session_start(): майже завжди блокування сесії. Файлові й деякі базоданні обробники сесій блокують сесію на весь запит, тож відвідувач, чий браузер запускає кілька запитів одночасно, бачить, як вони шикуються один за одним. Закривайте сесію рано через session_write_close(), щойно код має те, що йому потрібно, або використовуйте неблокувальний обробник.

sleep(), usleep(), цикли повторів: чийсь код навмисно чекає. Зазвичай повтор проти зовнішнього сервісу, у якого поганий день.

Чисті функції PHP глибоко в шаблоні або циклі: справжня робота CPU. Рідше, ніж люди очікують, і єдина група, де швидше обладнання допомагає безпосередньо.

Зважте, потім підтвердьте pool

Slow log рахує запити вище порога; він не каже, скільки загального часу коштує кожна група. Поєднайте його з access log вашого web-сервера, логуючи $request_time і $upstream_response_time в nginx, щоб зважити повільні запити за URL і за тривалістю. Група з меншою кількістю записів, але значно довшими запитами може важити більше.

Потім перевірте, чи повільні запити також виснажують pool:

grep -c 'reached pm.max_children' /var/log/php-fpm/error.log
curl -s 'http://localhost/fpm-status?full' | head -20

Якщо workers вичерпані, відвідувачі стоять у черзі навіть за сторінками, які самі по собі швидкі. Підвищення pm.max_children лікує симптом; скорочення повільного зовнішнього виклику лікує причину.

Слово про накладні витрати

Зняття backtrace означає, що майстер FPM ненадовго приєднується до worker. За розумного порога накладні витрати мізерні, бо це трапляється лише із запитами, які вже повільні. Не встановлюйте поріг на частку секунди на завантаженому сайті й не лишайте так. Зберіть, проаналізуйте, потім підніміть його назад до рівня моніторингу.

Ваш чекліст

• slowlog, request_slowlog_timeout і request_terminate_timeout встановлені в кожному pool.
• День slow log, згрупований за кадром, що блокує, потім за плагіном або модулем.
• Зовнішні виклики знайдені, їхні timeouts прочитані.
• Кадри бази даних простежені до запитів у цих рядках, з EXPLAIN.
• Записи session_start() перевірені на блокування сесії.
• Повільні запити зважені за тривалістю з access log, виснаження pool підтверджене або виключене.

Коли slow log вказує кудись, куди вам нелегко піти далі, ми радо допоможемо його прочитати.

Поговоріть з інженером

Related

Пов’язане: Аудити продуктивності web-застосунків · Оновлення PHP і патчі безпеки на весь парк · Web-рівні високої доступності, N+1 на кожному рівні