Nginxとphp-fpmでWordPressを動かしていて503エラーが頻発していたので調査した記録です。原因は WordPress Popular Posts がMySQLに投げているクエリでした。
出ていたエラー
Nginxで出ていたエラー
host:xxx.xxx.xxx.xxx user:- time:2018-03-19T15:03:55+09:00 method:GET uri:/ protocol:HTTP/1.1 status:499 size:0 request_time:59.028 upstream_response_time:59.028 upstream_addr:unix:/var/run/php-fpm/php-fpm.sock referer:https://example.com/ user_agent:Mozilla/5.0 (Linux; Android 7.0; ASUS_Z017DA Build/NRD90M; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/65.0.3325.109 Mobile Safari/537.36 YJApp-ANDROID jp.co.yahoo.android.yjtop/3.16.0 vhost:example.com
php-fpmで出ていたエラー
2018/03/19 14:51:40 [error] 4041#4041: *5816 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: xxx.xxx.xxx.xxx, server: example.com, request: "GET / HTTP/1.1", upstream: "fastcgi://unix:/var/run/php-fpm/php-fpm.sock:", host: "example.com"
MySQL
メモリやCPU負荷も特別高くなく、AWSのメトリクスみても特別変なところは見つけられなかったのですが、mysqlコマンドでDBにアクセスして SHOW FULL PROCESSLIST; を実行するとこのようなプロセスが大量に溜まっていました。
| 6640638 | dbuser | xxxx.xxxx.xxx.xxx:xxxxx | database_name | Query | 143 | Sending data | SELECT p.ID AS id, p.post_title AS title, p.post_author AS uid, p.post_date AS date, SUM(v.pageviews) AS pageviews FROM `wp_prefix_popularpostssummary` v LEFT JOIN `wp_prefix_posts` p ON v.postid = p.ID WHERE 1 = 1 AND p.post_type IN('post') AND v.view_datetime > DATE_SUB('2018-03-19 15:04:10', INTERVAL 6 DAY) AND p.post_password = '' AND p.post_status = 'publish' GROUP BY v.postid ORDER BY pageviews DESC LIMIT 15 OFFSET 0 |
SELECT p.ID AS id, p.post_title AS title, p.post_author AS uid, p.post_date AS date, SUM(v.pageviews) AS pageviews FROM `wp_prefix_popularpostssummary` v LEFT JOIN `wp_prefix_posts` p ON v.postid = p.ID WHERE 1 = 1 AND p.post_type IN('post') AND v.view_datetime > DATE_SUB('2018-03-19 15:05:58', INTERVAL 6 DAY) AND p.post_password = '' AND p.post_status = 'publish' GROUP BY v.postid ORDER BY pageviews DESC LIMIT 15 OFFSET 0;
このクエリを直に打ってみたところ、
15 rows in set (2 min 47.88 sec)
と50秒近くかかっており、Nginxのログのupstream_response_timeとも近い値だったのでこれが原因だ！となりました。
原因
wp_prefix_popularpostssummary のレコードが日毎にアクセス数を記録しておりレコード数が45万程度まで膨れ上がっていたことでした。そのレコードに対して絞り込まずLEFT JOINしているのでここが重そうです。このままでは使えないので wp_prefix_posts を基準に絞り込んだ後JOINするように取得部分を書き直すか違うプラグインを使うかする必要があります。
＊後日詳細調べたところ、4.0.13のバージョンではwp_wedding_dress_popularpostssummaryテーブルにアクセスの度pageviewsが1のレコードができていることがわかりました。アクセスのたびにレコードが増えるのでGROUP BYのコストが大きすぎて1週間でSUMをとっても時間がかかっていたので、バージョンを3系に戻しPopularPostのプラグインを表示側では使わないようにして対処しました