サーバーが遅くなったと思ったらMySQLが原因だったという件

早朝にサーバーアラートメールが飛んできた。 httpアクセスで10秒遅延という事だったのだが、確かにサイトにアクセスしてみると遅い・・・ たま〜に、こういう事象になる事ってよくあるよね。 こういう時こそ慌てず焦らず、きちんとした手順を踏んで、サーバーを快適状態に修復できれば立派なプロの仕事です。

原因はMysql

調査してみた所、今回の原因はMysqlだったことが判明したので、確認の為にlogデータを見てみたら下記のような大漁のメッセージログが・・・ ここで気になったのは「page_cleaner」という事と、「The settings might not be optimal.」と言う箇所と、「loop took ****ms.」ですね。 page_cleanerという機能が実行されて、５秒近くもレスポンスがかかってしまっている（ずっとログを見ていくと２０秒近くかかっている場合もある）のが、1分以内にログとして発生しているという事象です。 2017-11-20T22:45:27.523062Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 5253ms. The settings might not be optimal. (flushed=0 and evicted=744, during the time.) 2017-11-20T22:45:52.794671Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4346ms. The settings might not be optimal. (flushed=22 and evicted=1478, during the time.) 2017-11-20T22:46:05.654437Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4922ms. The settings might not be optimal. (flushed=157 and evicted=828, during the time.) 2017-11-20T22:46:35.412835Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 5109ms. The settings might not be optimal. (flushed=82 and evicted=573, during the time.) 2017-11-20T22:46:49.283352Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 7359ms. The settings might not be optimal. (flushed=200 and evicted=731, during the time.) 2017-11-20T22:47:08.617390Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4424ms. The settings might not be optimal. (flushed=200 and evicted=0, during the time.) 2017-11-20T22:47:22.144770Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4799ms. The settings might not be optimal. (flushed=261 and evicted=608, during the time.) なんじゃこりゃ！！！ 今まで見たこと無い！！！ そのまま慌ててしまってはダメですね。クールに対応しましょう。 モジュールの暴走系は、素早くrestartをしてあげると、一時的には問題が改修されるでしょう。 $ service mysqld restart Stopping mysqld: [ OK ] Starting mysqld: [ OK ] とりあえずは、これだけで遅延は改修されたんですが、気になったので調べてみると、mysqlの「page_cleaner」という機能は、あまり日本語で書かれているところが無かったので、深く調べませんでしたが、 rails日誌(2) mysqlが原因というわけではなく、プログラム部分で書かれている箇所でmysqlを正常に終了処理させていないことが原因とのことでした。 今回のサイトでmysqlを使っているのはwordpressで公開しているこのブログだけだったので、どれかのプラグインがこうした記述ミスをしているのでしょう。 改めて、OSSに頼り切りになっているこうしたシステムに依存している事の怖さを思い知りました。

サーバーチェック

ついでに、サーバーアラートが発生した場合のチェックについて簡単に書いておこうと思います。 サーバー運用担当者の人は当たり前の事なんですが、初心者エンジニアの方は、本番運用など始めたばかりの場合は参考になると思います。

まずは、生死確認

サーバーアラートは外部監視が鉄則です。 ローカルにインストールされているnagiosなどのモジュール監視アプリで満足していたら、そのサーバーがダウンした時に機能せず、とんでもないしっぺ返しをくらいます。 外部監視から来たアラートは、なかなかの緊張感があります。 監視内容にも寄りますが、まずは、サーバーがダウンしきっているか、半分死にかかっているかどうかで、対応内容も変わってくるので、pingやsshでちゃんと判断します。 こういう時に、サーバーがダウンしていたらログインしてサーバー内のログを確認できなくなるので、ある程度の判断になるように外部にログを残しておくようにしましょう。 理想的な生存確認は、「急激に○○の値が直前に増加したのでサーバーがダウンした」と言える事ですね。

一番やっかいな半死状態

サーバーダウンしている時は、サーバーのスイッチを入れ直す以外の対応方法は無いので、考えることは無いのですが、半死状態の場合は、何故そうなったのかの調査も含めて、非常に時間が掛かることが多いのが現状です。 電源やインターフェイスなどのサーバー機器の問題なのか、過剰アクセスによる過負荷が問題なのか、元々のプログラムに不備があったのか、調査はとてつもなく時間を有します。 でも、だいたいの場合、ログデータから判断することが殆どになるので、色々なログデータの保持は改めて重要な証拠残しであると言えます。

対処の最初の行動は、冗長サーバーへの切り替え

サーバーダウンの状態や、半死状態を確認できると、そのサーバーでのサービス運用を行うことが難しいと考えて、事前に用意してある、冗長環境（予備サーバー）への切り替えをすることが、いち早くサーバー復帰する重要な対応策です。 この時に、予備サーバーには、最新データが保持されていないとか、そもそも、電源が入っていないなんていうコールドスタンバイになっていて、「意味ないじゃん」とメンバーに突っ込まれることも、非常によくある事なので、いかに事前に第２環境を構築できているかも、サービス運用には必要な要素なんですね。

もしネットワーク障害だったら・・・

過去に、大手キャリアの回線障害というのを経験したのですが、何も手が出せなくなってしまうことはあります。 そんな時に、即座に別回線に切り替えられたり、DNS切り替えを行ったり、できるとこれもまたサービス運用には優位でしょう。 でも、そもそも高額な回線契約をそんなに何本もできるものではないので、サービスの費用対効果と考えながら冗長環境構築はしなければいけません。 「AWSに乗せているから安心」というエンジニアとたまに出会いますが、その多くのエンジニアが実際にサービス障害を経験した事のない人でした。 実際の世の中で発生する事故でもそうですが、いかに不足の事態を検討して保険を掛けられるかが、自分にとっても、サービス運用に関してもリスクヘッジなので、「もし・・・」を考えてみることをオススメします。