WordPressでは、いろいろな原因で反応が遅くなるんですが、真っ先に影響を受けるのが管理画面の投稿編集です。
3年以上もサイトを運営しているとボリュームが大きくなり、その分、DBの保存データも増えます。
DBアクセスの反応も遅くなった気がする。今回は、Monitの設定を変えます。
WP編集画面が遅くなったときのサーバーの状況
今回、WP編集画面の一部の機能が異常に遅くなりました。
WP5からGutenbergを使っていてコンテンツはすべてブロック単位になっています。そのブロックには検索を使った機能も多い。
REST-APIを多用してるからなんですが、そこのDBアクセスがサーバーに大きな負荷をかけたのが原因。
ボクの環境では、テキストにアンカーリンクを付ける際の検索がどうもおかしい。
サーバーの状態で気になったところです。
- CPU負荷が高い(100%が数十秒続く)
- CPUを喰ってるほとんどがNginx。(集中アクセスが起きてる。)
- なぜか、メモリは余裕
- 仮想メモリを使ってるが、ストレージ負荷は若干増えるだけ。(気にするほどではない。)
- DBアクセスの負荷が高い
- PHP-FPMのキュー(Max Listen Queue)が異常に少ない。(0もある。)
- kusanagi restartコマンドが滞留している。
今回とくに、なんだこれ? と思ったところに色を付けました。
PHP-FPMが動かないってどういうこと?
その中でも異質なところはPHP-FPMが異常に動いていないところ。
普通、Webサーバー(ここでは、アプリケーションサーバー、DBサーバーも含めた全体を指す。)のDBで高負荷になるとき、CPUやメモリをパンパンにするのはPHP-FPMです。
今までも、これをどうにかするのにどれだけ苦労したことか。
1 | Nginxがリクエスト受信 PHP-FPMへ以降の処理を委譲。 | 受信したリクエストをアプリケーションサーバ ー(PHP-FPM)に丸投げするので負荷は小さ い。 |
2 | PHP-FPM内のWordPressが処理 を行う。 DBアクセスもここ。 処理結果をNginxへ返す。 | 普通、CPUやメモリがパンパンになるところ。 |
3 | Nginxがレスポンス送信 PHP-FPMの結果をそのままレス ポンスとして返す。 | PHP-FPMから得た結果をそのままHTTPレス ポンスとして返すので負荷は小さい。 |
でも今回は、そのPHP-FPMが逆に動いてなくて、CPUを喰っていたのはNginx(Webサーバー)。
リバースプロキシとして使ったときのNginxは、CPUやメモリの消費量は大したことありません。処理の大部分をPHP-FPMへ移譲して、リクエスト受信とレスポンス送信くらいしか仕事がないから。
それなのに、そのNginxが原因とは...。どういうこと?
リバースプロキシサーバーはプロキシサーバー(代理サーバー)のサーバーサイドに設置されるもの。
KUSANAGIの環境では、サイトの主な処理はPHP-FPM(WordPress)で行われるので、NginxはWebサーバーというよりリバースプロキシとして動いている。
ちなみに、リバースプロキシとしてのWebサーバーから仕事を引き受けて、PHPやPythonなどのプログラムによる処理を行うものをアプリケーションサーバーともいう。
ここではPHP-FPM(WordPress含む)のこと。
1 | Nginxがリクエスト受信 PHP-FPMへ以降の処理を委譲。 | 集中アクセスでリクエストが滞留。 CPUがパンパンになる。 メモリは余裕。 |
2 | PHP-FPM内のWordPressが処理 を行う。 DBアクセスもここ。 処理結果をNginxへ返す。 | DB負荷が高い。 集中アクセスの初期がNginxの不調と関係 していると思う。 NginxがCPUを占拠してPHP-FPMが使う 分が無くなり、子プロセスのキューが作れ ない。 Max Listen Queueが0になることも。 (0で動くわけがない。) リクエストを任せるPHP-FPMが無いので 、さらにNginxのリクエスト滞留を生む負 のループが起きる。 |
3 | Nginxがレスポンス送信 PHP-FPMの結果をそのままレス ポンスとして返す。 | 受信リクエストが滞留して処理が進まない ので、短時間に大量の502レスポンスが発 生。 |
問題はこれだけではない。KUSANAGIの再起動が短時間に頻発。
じつはこの現象、大変なことが起きたようで大したことはありません。ほっとけば数十秒くらいで収まるから。
なんかサーバーが固まったなというのは編集画面でも分かります。
アンカーリンクなどの検索では、検索結果に投稿記事のタイトルのリストが表示されるんですが、その結果が0件になるのですぐに分かる。
固まったことが分かるのでしばらく作業を止めれば数十秒で復旧します。
(ただし、サイトが一時ダウンすることになるが。)
そこでしつこく検索しまくったら収まりません。
(どうなってるのか分かってるのでそんなことしないが。)
Nginxが落ちたとしても、そのリカバリはすでに対応済みです。
ただ、この収まりを邪魔をするものがあります。kusanagi restart コマンド、KUSANAGIの再起動の実行です。
MonitはHTTPステータス5xxを監視している。
KUSANAGIは、WebサーバーのNginx, Apache httpd のアクセスログファイルを監視します。
そして、5xxのHTTPステータスを見つけたらKUSANAGI全体を再起動します。
この機能はMonitを使っている。
その再起動コマンドが "kusanagi restart" です。
もう1回サーバーで何が起きているのか見てみましょう。そこに KUSANAGI 再起動の動きも入れてみます。
1 | Nginxがリクエスト受信 PHP-FPMへ以降の処理を委譲。 | 集中アクセスでリクエストが滞留。 CPUがパンパンになる。 メモリは余裕。 |
2 | PHP-FPM内のWordPressが処理 を行う。 DBアクセスもここ。 処理結果をNginxへ返す。 | DB負荷が高い。 集中アクセスの初期がNginxの不調と関係 していると思う。 NginxがCPUを占拠してPHP-FPMが使う 分が無くなり、子プロセスのキューが作れ ない。 Max Listen Queueが0になることも。 (0で動くわけがない。) リクエストを任せるPHP-FPMが無いので 、さらにNginxのリクエスト滞留を生む負 のループが起きる。 |
3 | Nginxがレスポンス送信 PHP-FPMの結果をそのままレス ポンスとして返す。 | リクエスト受信が滞留して処理が進まない のでするので、短時間に大量の502レスポ ンスが発生。 |
4 | Monitによる KUSANAGI 再起動 | HTTPステータス5xxを見つけると、1分後 に再起動コマンドが実行される。 2分半以内に5回の再起動が起きると監視を 停止。 kusanagi restart で再起動プロセスが始まる が、CPUがパンパンなので時間がかかる。 その間にも502HTTPステータスは発生し 続け、Monitが502ステータスをキャッチし て新たにkusanagi restart 起動。 (前の再起動コマンドは終わっていない。 ) それが繰り返され、kusanagi restart が多重 起動。 (htopコマンドで確認したところ最低でも 5回以上は起動していた。) kusanagi restart が終わり、CPU負荷が落 ち着くのに1~2分かかる。 |
ここで気になるのは、2分半以内に5回の再起動が起きたら監視が停止するはずなのに、あきらかにそれ以上のkusanagi restartが起動しているところ。
Monitの設定を変える
ここまでは前フリです。ちょっと長かったですが大事なポイントがいくつもあったので。
さっき、Nginxのアクセス滞留は大したことないと言いました。数十秒での復旧は何かをするよりも速いから。
そこでその時間を長くしてしまうMonitのKUSANAGI再起動の設定を見直します。
まずは、KUSANAGIの初期設定です。
check file html_nginx with path /home/(kusanagi_user)/(profile)/log/nginx/access.log
restart program = "/bin/kusanagi restart"
depends on nginx
if match '"(GET|POST) /.* HTTP/.*" 5[0-9][0-9] [0-9]+ ' for 2 cycle then restart
if 5 restarts within 5 cycles then alert
if 5 restarts within 5 cycles then unmonitor
group nginx
check file html_nginx_ssl with path /home/(kusanagi_user)/(profile)/log/nginx/ssl_access.log
restart program = "/bin/kusanagi restart"
depends on nginx
if match '"(GET|POST) /.* HTTP/.*" 5[0-9][0-9] [0-9]+ ' for 2 cycle then restart
if 5 restarts within 5 cycles then alert
if 5 restarts within 5 cycles then unmonitor
group nginx
Monitの時間間隔の基準は 'cycle(s)' です。これはMonitの共通設定ファイルにあります。
set daemon 30 # check services at 30 seconds intervals
これが1サイクルの時間。30秒。
Nginx再起動の設定はこういう内容。
- 1サイクル(30秒)ごとにNginxのアクセスログを参照
- HTTPステータス5xxを見つけたら 'kusanagi restart' を1分後(2サイクル)に起動
- 5サイクル(2分半)以内に5回の再起動が行われたら、アラート発信と監視を停止
再起動回数を大幅縮小
このMonitの設定を下記のように変更しました。
if 2 restarts within 2 cycles then alert
if 2 restarts within 2 cycles then unmonitor
アラート送信と監視の停止までの再起動数を5サイクル・5回から2サイクル・2回へ短縮させてます。
『5サイクル(2分半)で5回の再起動って多くね?』とシンプルに思ったから。
そんなに再起動を繰り返す状態って相当やばいはずで、再起動でどうにかなるもんじゃないと思う。
再起動のチャレンジは3回くらいまででいいでしょ? というのと、今回の内容からして再起動数は少なければ少ないほどいいと思って2回にしました。
ちなみにサイクル数も2にしたのに深い意味はありません。最初の設定のサイクル数と再起動数の関係性を維持しただけ。
監視サイクルはそのまま
最初、再起動のための5xx監視サイクルも長めに取ろうと思いましたが、これはやめました。
監視間隔を取ってしまうと、発見までの時間が、復旧作業が始まって終わる時間にプラスされてしまって、サーバーが固まる時間が長くなってしまうから。
if match '"(GET|POST) /.* HTTP/.*" 5[0-9][0-9] [0-9]+ ' for 2 cycle then restart
現状、1分おきに監視しているので、ちょうどいいのかなと感じてます。
2, 3分おきぐらいまではかまわないというのであれば、サイクル数を増やしてもいいかもしれません。
それでも kusanagi restart は結構起きてる。
KUSANAGIの再起動数を抑制した結果ですが、あいも変わらず設定以上の 'kusanagi restart' が起きてます。
htopコマンドの目視なので確実なデータではありませんが、1回の集中アクセスで5回の再起動が起きている。
結局、『2サイクルで2回の設定って何の意味が?』という疑問しかないんですが、前よりは確実に再起動数は減ってるし、復旧への時間が短縮されました。
データではなく感覚で申し訳ないですが、サーバーが固まる頻度も少なくなってる気がします。
とりあえず前より若干改善したということでよしとするか。
『5xxを見つけたら〇〇秒後に再起動スタート』はどうにかなんないか?
根本的にはこの設定だと思います。
if match '"(GET|POST) /.* HTTP/.*" 5[0-9][0-9] [0-9]+ ' for 2 cycle then restart
『HTTPステータス5xxを見つけたら1分後(2サイクル)に再起動スタート』
この内容だと、5xxを見つけた瞬間、リスタート起動を予約することになる。
で、Nginxに出力されたログがこれ。
1.221 - - XX.XX.XXX.152 - wp_user_name [05/Jul/2022:19:12:59 +0900] "POST /wp-admin/admin-ajax.php HTTP/2.0" 502 552 "https://xxx.com/wp-admin/edit.php?s=search_key&post_status=publish&post_type=post&action=-1&m=0&cat=0&taxonomy_name=0&paged=1&action2=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/103.0.0.0 Safari/537.36" "-"
1.694 - - XX.XX.XXX.152 - wp_user_name [05/Jul/2022:19:13:15 +0900] "POST /wp-admin/admin-ajax.php HTTP/2.0" 502 552 "https://xxx.com/wp-admin/edit.php?s=search_key&post_status=publish&post_type=post&action=-1&m=0&cat=0&taxonomy_name=0&paged=1&action2=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/103.0.0.0 Safari/537.36" "-"
1.644 - - XX.XX.XXX.152 - wp_user_name [05/Jul/2022:19:13:30 +0900] "POST /wp-admin/admin-ajax.php HTTP/2.0" 502 552 "https://xxx.com/wp-admin/edit.php?s=search_key&post_status=publish&post_type=post&action=-1&m=0&cat=0&taxonomy_name=0&paged=1&action2=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/103.0.0.0 Safari/537.36" "-"
2.353 - - XX.XX.XXX.152 - wp_user_name [05/Jul/2022:19:13:33 +0900] "POST /wp-admin/admin-ajax.php HTTP/2.0" 502 552 "https://xxx.com/wp-admin/admin.php?page=wp_admin_page_origin.php" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/103.0.0.0 Safari/537.36" "-"
0.002 - - XX.XX.XXX.152 - wp_user_name [05/Jul/2022:19:13:36 +0900] "POST /wp-admin/admin-ajax.php?_fs_blog_admin=true HTTP/2.0" 502 552 "https://xxx.com/wp-admin/edit.php?s=search_key&post_status=publish&post_type=post&action=-1&m=0&cat=0&taxonomy_name=0&paged=1&action2=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/103.0.0.0 Safari/537.36" "-"
1秒間に5回のアクセスがありすべて502ステータスを返してます。またすべてがWordPressの管理画面へのアクセス。(そのほとんどが編集画面。)
Monitの設定どおりだとすれば、1秒間に5回の再起動予約をしていることになる。そして1分後にはそれが起動される。
それで、次に出てくるのがこの設定。
if 2 restarts within 2 cycles then unmonitor
『1分以内(2サイクル)に2回再起動が起きたらモニタ停止』
これが効いてなくて、なんならぜんぶ 'kusanagi restart' が起動している気がする。
(以前はもっと起動していたが。)
5xxステータスを見つけるたびに再起動予約はちょっと...
『HTTPステータス5xxを見つけたら1分後(2サイクル)に再起動スタート』
じゃなくて、
『〇〇を〇〇秒(サイクル)で1件でも見つけたら〇〇後に再起動スタート』
みたいにできないかね?
5xxを見つけるたびに再起動予約は厳しい。1秒間に5件もあってすべてに再起動予約されたら、そりゃ1分後に一気に "kusanagi restart" が始まる。
CPU負荷を抑え込むための再起動が逆に状況をひどくしている。
これは1件の再起動にできないだろうか?
(今のところ解決策は見つけていない。)