ポンコツエンジニアのごじゃっぺ開発日記。

いろいろポンコツだけど、気にするな。エンジニアの日々の開発などの記録を残していきます。 自動で収入を得られるサービスやシステムを作ることが目標！！

トップ > gcp > WordPressサーバのCPU使用率が100%に達してしまった。

WordPressサーバのCPU使用率が100%に達してしまった。

gcp wordpress 技術

早朝から自作の監視ツールからアラートが飛んできた。お手製LINE Bot監視ツールです。

f:id:ponkotsu0605:20190526200135p:plain

このブログサーバがヤバイらしいと。

ということで、実際にこのブログにアクセスしてみると、レスポンスがとても遅い。。ページが表示されるまで10秒くらいかかっている。。

ということで、GCPのコンソールからCompute Engineのページを開いて、モニタリングを開いてみた。

f:id:ponkotsu0605:20190526200203p:plain

↑こちらのスクショは解決後でもあるので、今は落ち着いているが。

CPU使用率を見るとアラートが飛んでくる時間帯にちょうどCPU使用率が100%に達してしまっている。。

サーバを再起動してみる

CPU使用率のグラフから推測するに、6時23分くらい。

暴走したらとりあえず再起動だ！っていう雑な知識で、とりあえず再起動をしてみました。

$ ssh xxx.xxx.xxx.xxx

$ sudo su

$ reboot

リブートした結果はグラフを見てわかるようにおよそ75%くらいまで下がった。

ログを見てみる

ターミナル上のログを見た感じだと、6時23分くらい。

Webサーバなので、とりあえずapacheのログを見ればわかるっしょーと思って、リクエストを疑ってみました。もしかしたらどこかから大量のリクエストで攻撃されてるのかも？と思ったので。

$ tail -f /var/log/apache2/access.log

130.211.2.200 - - [02/May/2018:06:23:37 +0900] "GET / HTTP/1.1" 200 62803 "-" "GoogleHC/1.0"
130.211.1.81 - - [02/May/2018:06:23:37 +0900] "GET / HTTP/1.1" 200 62803 "-" "GoogleHC/1.0"
130.211.2.200 - - [02/May/2018:06:23:38 +0900] "GET / HTTP/1.1" 200 62803 "-" "GoogleHC/1.0"
130.211.1.81 - - [02/May/2018:06:23:38 +0900] "GET / HTTP/1.1" 200 62803 "-" "GoogleHC/1.0"
130.211.1.96 - - [02/May/2018:06:23:38 +0900] "GET / HTTP/1.1" 200 62803 "-" "GoogleHC/1.0"
130.211.1.96 - - [02/May/2018:06:23:38 +0900] "GET / HTTP/1.1" 200 62803 "-" "GoogleHC/1.0"
130.211.1.99 - - [02/May/2018:06:23:38 +0900] "GET / HTTP/1.1" 200 62803 "-" "GoogleHC/1.0"
130.211.1.73 - - [02/May/2018:06:23:39 +0900] "GET / HTTP/1.1" 200 62803 "-" "GoogleHC/1.0"
130.211.1.73 - - [02/May/2018:06:23:39 +0900] "GET / HTTP/1.1" 200 62803 "-" "GoogleHC/1.0"
130.211.1.99 - - [02/May/2018:06:23:39 +0900] "GET / HTTP/1.1" 200 62803 "-" "GoogleHC/1.0"
::1 - - [02/May/2018:06:23:41 +0900] "OPTIONS * HTTP/1.0" 200 126 "-" "Apache/2.4.10 (Debian) (internal dummy connection)"
130.211.2.200 - - [02/May/2018:06:23:42 +0900] "GET / HTTP/1.1" 200 62803 "-" "GoogleHC/1.0"
130.211.1.81 - - [02/May/2018:06:23:42 +0900] "GET / HTTP/1.1" 200 62803 "-" "GoogleHC/1.0"
130.211.2.200 - - [02/May/2018:06:23:43 +0900] "GET / HTTP/1.1" 200 62803 "-" "GoogleHC/1.0"
130.211.1.81 - - [02/May/2018:06:23:43 +0900] "GET / HTTP/1.1" 200 62803 "-" "GoogleHC/1.0"
130.211.1.96 - - [02/May/2018:06:23:43 +0900] "GET / HTTP/1.1" 200 62803 "-" "GoogleHC/1.0"
130.211.1.96 - - [02/May/2018:06:23:43 +0900] "GET / HTTP/1.1" 200 62803 "-" "GoogleHC/1.0"
130.211.1.99 - - [02/May/2018:06:23:43 +0900] "GET / HTTP/1.1" 200 62803 "-" "GoogleHC/1.0"
130.211.1.73 - - [02/May/2018:06:23:44 +0900] "GET / HTTP/1.1" 200 62803 "-" "GoogleHC/1.0"
130.211.1.73 - - [02/May/2018:06:23:44 +0900] "GET / HTTP/1.1" 200 62803 "-" "GoogleHC/1.0"
130.211.1.99 - - [02/May/2018:06:23:44 +0900] "GET / HTTP/1.1" 200 62803 "-" "GoogleHC/1.0"
130.211.2.200 - - [02/May/2018:06:23:47 +0900] "GET / HTTP/1.1" 200 62803 "-" "GoogleHC/1.0"
130.211.1.81 - - [02/May/2018:06:23:47 +0900] "GET / HTTP/1.1" 200 62803 "-" "GoogleHC/1.0"
130.211.2.200 - - [02/May/2018:06:23:48 +0900] "GET / HTTP/1.1" 200 62803 "-" "GoogleHC/1.0"
130.211.1.81 - - [02/May/2018:06:23:48 +0900] "GET / HTTP/1.1" 200 62803 "-" "GoogleHC/1.0"
130.211.1.96 - - [02/May/2018:06:23:48 +0900] "GET / HTTP/1.1" 200 62803 "-" "GoogleHC/1.0"
130.211.1.96 - - [02/May/2018:06:23:48 +0900] "GET / HTTP/1.1" 200 62803 "-" "GoogleHC/1.0"
130.211.1.99 - - [02/May/2018:06:23:48 +0900] "GET / HTTP/1.1" 200 62803 "-" "GoogleHC/1.0"
130.211.1.73 - - [02/May/2018:06:23:49 +0900] "GET / HTTP/1.1" 200 62803 "-" "GoogleHC/1.0"
130.211.1.73 - - [02/May/2018:06:23:49 +0900] "GET / HTTP/1.1" 200 62803 "-" "GoogleHC/1.0"
130.211.1.99 - - [02/May/2018:06:23:49 +0900] "GET / HTTP/1.1" 200 62803 "-" "GoogleHC/1.0"
・・・

犯人はGoogleHC/1.0だった！

というのも、このブログはこちらの記事（GCP上でWordPressを動かしてみた。）でも紹介したように、VMインスタンスの手前にロードバランサを挟んでいて、それのヘルスチェックがたくさん飛んできていたのです。

その時のヘルスチェックの設定がこちら。

f:id:ponkotsu0605:20190526200313p:plain

5秒間隔に/のパスでチェックしています。

でも、上のログを見てわかるように、5秒間に10リクエストも飛んできています。2rpsのindex.phpをさばかなきゃいけないのです。ものすごい少なく見えると思いますが、インスタンスのスペックが低いせいか、辛かったんですかね。

f:id:ponkotsu0605:20190526200332p:plain

記事数も増えたせいか、このブログを開設してから半月ほどでCPU使用率がどんどん増えているのがわかります。

ちなみに、このインスタンスのスペックは「マシンタイプ n1-standard-1（vCPU x 1、メモリ 3.75 GB）」にしています。アクセス数が伸びてさばけなくなってきたらスペックアップをしようと思ってました。

さて、話は戻りまして、ヘルスチェックのチェック間隔を5秒から10秒に変更しました。これで、「10秒間隔のチェックを2回連続失敗したら」という条件なので、サーバが死んでから最大30秒でLBのターゲットから切りはずされてしまいますが、こんなブログサイトの緊急度で言ったら問題ありません。なんなら10分くらいサーバ死んでても問題ないし。ちなみに、ヘルスチェックのパラメータの変更がロードバランサの各インスタンスに反映されるまで数分から長いときで10分とかかかるときがありますので、落ち着いてコーヒーでも飲みながら待っててください。

ということで、ヘルスチェック間隔を5秒から10秒に変更した結果は、グラフの6時30分以降になるので、40%弱くらいまで落ち着きました。

f:id:ponkotsu0605:20190526200358p:plain

スクロールが大変だと思うので、最初のグラフをもう一度載せておきます。

ヘルスチェックの改良

完了時間はグラフから推測するに、6時40分頃。

さて、ヘルスチェックで毎回index.phpを叩いているわけなのですが、そこまでしなくていいかなと思いまして、ちょっと変更をしたいと思います。

/healthcheck.phpというパスにOKっていう文字列だけを返すPHPファイルを用意して、ヘルスチェックのチェックする先をそこに変更するというもの。

サーバ側の設定

サーバにhealthcheck.phpというファイルを置いて、/healthcheck.phpというパスにリクエストが来たら、OKを返すようにしてあげます。

$ vim /var/www/html/healthcheck.php

<?php

echo "OK";

サーバ側の設定としてはただこれだけです。実際に設定したので、こちらにアクセスしてみてください。

https://blog.pnkts.net/healthcheck.php

（この記事を書いているときはちゃんとOKが表示されると思います。このあと改修するかもしれないので、いつかは見れなくなっちゃうかも。。）

ロードバランサの設定

先程はチェックされる側の設定をしたのですが、次にチェックする側の設定をしていきたいと思います。

GCPのコンソール画面を出して、ヘルスチェックの設定ページを開きます。

f:id:ponkotsu0605:20190526200444p:plain

リクエストパスのところを/healthcheck.phpに書き換えてあげます。

これで、保存をして10分程度待つとリクエスト先が/healthcheck.phpに変わります。

f:id:ponkotsu0605:20190526200504p:plain

もう一度グラフを確認してみますと、6時40分以降CPU使用率がほぼ0%まで下がっています。なるほど、全てはヘルスチェックが問題だったんですね。

問題点

ヘルスチェックのチェック項目が今回大きく減りました。

というのも、今まではindex.phpを開いて、ブログでいうトップページが正常に開けるかを確認していたのですが、今回の対応以降ではhealthcheck.phpというOKという文字列だけを返す確認になっています。

なので、今まではMySQLサーバが死んでも検知できていたと思いますが、今後はMySQLサーバが死んでもPHP（apache）は動いているので問題ないという判断をされていしまいます。

まぁ、ここもこのブログ程度なんでいいっしょーっていう判断で許容しちゃいましたし、あと最初に紹介した独自の監視ツールでそこら辺はチェックしているので問題ないのです！

まとめ

ということで、今回は障害発生から30分以内に解消させることができました。

早朝から何してるんだろうね。

お問い合わせ｜プライバシーポリシー｜制作物