在 php-fpm 運行的 WordPress 下利用 Slow LOG 找到拖垮網站速度的元兇

這幾天發現 WordPress 的速度突然變慢,利用網站檢閱器發現伺服器的 TTFB 大幅提升至 20 秒以上,遠超過正常值。原本以為是 NGINX 設定的關係,先後調整了.conf檔案裡的設定、利用 ApacheBench 測試調校、還設定access.log紀錄了每個 Request 的時間,但問題並沒有解決,開始懷疑問題出在 php-fpm 上,但 php-fpm 的連線數設定,因為一開始會發生行程佔用過多記憶體導致 MySQL 當機的事件,所以我早就已經調校過了。想來想去剩下的問題,就是源自於 WordPress 的程式碼身上。

不過要從龐大的原始碼中,找出發生問題的那個點,其實沒那麼容易。然而 php-fpm 裡 Slow LOG 的功能,可以讓這件事情變得簡單。

設定開啟 Slow LOG

首先進入設定檔www.conf

$ vi /etc/php-fpm.d/www.conf

找到以下設定值,可以設定超過request_slowlog_timeout這個秒數就寫進LOG檔案裡,跟設定 LOG 檔案位置在slowlog

request_slowlog_timeout = 5 # unit is sec
slowlog = /var/log/php-fpm/www-slow.log

另外一個跟 Timeout 有關的設定是request_terminate_timeout,這個是執行一次 php-fpm 的有效時間,超過就會終止程式,可以視情況調整秒數。

重新啟動 php-fpm

使得新設定生效,輸入以下命令。

$ systemctl restart php-fpm

查看速度拖油瓶

隨意的瀏覽個幾次速度變得很慢的網站後,現在 php-fpm 就會紀錄下那些執行時間超過request_slowlog_timeout的程式碼,打開 Slow LOG 來看看。

$ tail -100 /var/log/php-fpm/www-slow.log

發現如下的訊息:

[29-May-2019 22:46:38]  [pool www] pid 24097
script_filename = /var/www/foo.com/index.php
[0x00007f7260c21a30] file_get_contents() /var/www/foo.com/wp-content/themes/dazzling/functions.php:85
[0x00007f7260c20a50] [INCLUDE_OR_EVAL]() /var/www/foo.com/wp-settings.php:499
[0x00007f7260c1d930] [INCLUDE_OR_EVAL]() /var/www/foo.com/wp-config.php:103
[0x00007f7260c1d770] [INCLUDE_OR_EVAL]() /var/www/foo.com/wp-load.php:37
[0x00007f7260c1d1e0] [INCLUDE_OR_EVAL]() /var/www/foo.com/wp-blog-header.php:13
[0x00007f7260c1d0c0] [INCLUDE_OR_EVAL]() /var/www/foo.com/index.php:17

摁?原來問題就發生在functions.php的第 85 行,趕緊來去檢查,發現是沒有用的 AJAX 請求,卻因為這個請求的回應速度太慢而拖累整個網站的執行,遂刪除之。每個人的情況可能不一樣,不過這依然是個很好的檢測方法。

重新瀏覽了一遍網站,歐耶!搞定。

References

  1. Tuning NGINX: Part I
  2. Tuning NGINX: Part II
  3. NGINX – Configuring Logging