この記事は animateLAB Advent Calendar 2015 19日目の記事です。
こんにちは。ポエムおじさんこと@kariaです。今年のAdvent Calendarもついに19日目となりました。後半に入り歴戦のエンジニアたちが次々と参戦してくれて、主催者としてはありがたい限りです。
今日はポエムデーのはずだったのですが、予定を変更して私の手元の秘伝のタレに少し味付けをして公開することにしました。ということで、LAMP環境で障害対応をすることになった時にどこからアタリを付けてどう調べていくか？という初動対応のお話をします。
そもそもLAMP環境とは
- OS:Linux
- Webサーバ:Apache
- データベース:MySQL
- アプリケーション：PHP/Perl/Python
という組み合わせの、IT用語辞典に項目があるぐらいメジャーな環境構成のことをLAMPと呼びます。最近だとWebサーバがnginxだったり、データベースがMariaDBだったりと個別要素は新しいプロダクトに置き換わりつつある状況ですが、昔からある環境はやはりLAMPなことが多いのではないでしょうか。
さて、これから書いていく内容はLAMP環境であることを想定した書き方となっていますが、LAMPでない環境であっても部分的にお役に立てるのではないかな？と思います。それではどうぞ。
障害発生時にまずやること
あなたはシステム部門に配属したての新人エンジニアです。これからバリバリ働いていくぞ！！と意気込んだところで、いきなり運用中の自社サービスで障害が発生しました。何故かWebサイトが重くて繋がりません。周囲の人間が皆あたふたしています。さて、どうしましょう？
まずはログを見ろ
はい、ログを見ましょう。何はともあれログを見ましょう。いいからログを見ましょう。親の敵かというぐらいログを見ましょう。大事なことなので4回言いました。
障害対応していくにあたり、ログに出力されていないことは何も分からないし、分かるはずがありません。逆に言えば、ログを見れば今起きている事象の手がかりは何らか掴めるはずです。もちろんログ以外から事象を掴んだり推測することは不可能ではありませんが、右も左もわからないような状況で障害対応を行うことになった場合はとりあえずログを見るのが手っ取り早いです。
SSHできるアカウントを確保する
とりあえず「SSHでログインできるアカウントをよこせ！！」と叫んでサーバーへ入れてもらいましょう。これがないと何も始まりません。このときsudo可能なアカウントをもらえると、後ほど躓きにくくなります。もしここで「アカウント発行に3日かかります」と言われたら、「障害が起きてるのに何を言ってるんだ！！」と怒鳴り込んでなんとかしてもらいましょう。偉い人に申告するというのも有効な手段です。
もしアカウントが発行してもらえない場合、あなたの出番ではないかもしれません。もちろん障害でお客さまに迷惑が掛かっているのは事実ですが、会社間の契約上の問題でどうしてもどうにもならないこともあります。その場合は、おとなしく諦めるしかありません。
また、そもそもSSH接続にすら失敗する（繋がらない）場合もあります。その場合はハードウェアやクラウドの管理画面にアクセスしてポチッと再起動をかけるしかありません。管理画面すら繋がらない、もしくは存在しない場合はデータセンターへGOとなりますが、ここでは割愛します。
見るべきログ
無事にログインすることが出来たら、見るべきログは例えば以下です。
- Apacheのアクセスログ、エラーログ
Apacheのアクセスログを見れば、何時に何処からどのようなアクセスが来ているか、そして何のレスポンスを返しているかがわかります。実はこれだけで「あっ、海外からDDoS攻撃を食らっているゾ！」とか「500エラーが大量に出てるゾ！」とか、何か手がかりが掴めることが多いです。大変重要なログです。
エラーログも大事です。何故Apacheがエラーを返したか、理由がわかるからです。もしかしたら、誰かが本番のファイルをうっかり移動してしまい404 Not Foundを返しているだけかもしれませんし、場合によってはアプリケーションのFatal Errorがここに出力されていることもあります（個人的にはアプリケーションのログは別の箇所に吐かれていると嬉しいのですが）。
- MySQLのエラーログ、スロークエリログ
データベースの場合リクエスト数は大変な数になっていることがほとんどなので、見るべきログはまずはエラーログです。データベースがお亡くなりになっているのかもしれません（あんまり遭遇したことはありませんが）。あとは、スロークエリログです。 slow_query.log という名称でサーバーのどこかに出ているハズですので探しましょう。データベースで極端にリクエストが遅いクエリがあった場合、このスロークエリログに出力されます。
- アプリケーションログ
もしあなたが関わっているプロダクトのアプリケーションが独自にログを吐いているのであれば、是非それも確認すべきです。ただ、出力モードがdebugレベルになってログが出過ぎている……なんてことのないように祈りましょう。アプリケーションのログが何処におかれているかはまちまちなので、担当のエンジニアに聞くか、
$ locate log
などとして捜索活動を行いましょう。
- syslog
ごくまれにsyslogに重大なエラーが出ていることがあります。syslogにエラーを吐くように仕込んでいるアプリケーションがあるかもしれません。念のため確認しておくとよいでしょう。というか、 /var/log ディレクトリ配下は怪しいファイルが無いかどうかファイル一覧を眺めるぐらいはしても良いかと思います。
ログを見るときのポイントと注意事項
巨大なログの扱いに注意
アクセスの多いWebサイトの場合、ログファイルは時に数GB、数十GBに達していることもあります。このようなファイルをうっかりviやemacsやmoreコマンドなどで開いてしまうと、巨大なメモリを確保しようとしてOS自体がお亡くなりになることも考えられます。これを避けるために以下のようなアプローチを取ります。
- lessコマンドを使う
lessコマンドは巨大なファイルを開いてもメモリやCPUなどのリソースを食わないことが多いです（実装を確認していないので本当に食わないという保証はありませんが）。閲覧専用なのでうっかり上書きしてしまう心配もありません。とりあえずlessコマンドで開いて、Shift+gを押してログの最下部へ移動して遡る、というのが王道パターンです。このとき行番号の計算をしようとしてCPUを食うことがありますが、Ctrl+cで止めることができます。
- head/tailコマンドを併用する
tailコマンドで末尾を絞って出力し、パイプでつないで見るという手法もよく行います。たとえば、
$ tail -300000 access_log | grep hogefuga | less
みたいな感じです。数百万〜数千万行レベルのログになると有効な手段です。
レスポンスタイムを見る
Apacheの場合、ログの出力項目として %D を指定しておくとマイクロ秒単位でレスポンスタイムを記録してくれます。これは障害の切り分けを行う上で大変便利な項目なのですが、標準では指定されていませんので是非追記しておきましょう。設定方法についてはWeb上にサンプルが多数ありますので割愛しますが、一応サンプルを示しておきます。
LogFormat "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\" %D" combined
この例では各行の末尾にレスポンスタイムが出るようにしています。この状態で以下のようなコマンドを実行すると、2000000マイクロ秒（＝2秒）越えのリクエストだけが画面に流れるようになって大変便利です。
$ tail -f /var/log/httpd/access_log | awk '{if($NF>=2000000) print}'
勘がいい方ならお気づきかもしれませんが、awkの中の数値を適宜調整すればお好みの表示閾値に変更することができます。サイトの遅さに合わせて、1秒なり10秒なり適切な流量になるよう変更してやりましょう。
※なおここで表示される数値はあくまでapacheとしてのレスポンスタイムです。apacheのさらに前段のネットワークが遅い可能性もありますので、この数値を過信しすぎないように気をつけましょう。
さらっと洗って次へ行く
冒頭で散々ログを見ろといいましたが、個々のログは見すぎないことが重要です。障害発生の初動段階では、1つのログを延々眺めるのではなくて、ログの流量とかエラー文言にフォーカスしてざっくりとアタリをつけていくことが大事です。特に手がかりがなさそうなら別のログに移るなり別のアプローチを考えるなりしましょう。人生諦めが肝心です。
OS,Apache,MySQLのステータスを見る
ログを見てもイマイチ事象が掴めないときにやることは、httpd(Apache)およびデータベース(MySQL)の状態を確認することです。そもそもプロセスは生きてますか？何個プロセスが上がってますか？固まってませんか？というあたりを探っていきます。
OS/HWのステータスを見る
OSやHWのリソースを使い切っていないかどうかを念のため確認します。特にディスク・ストレージの使用状況を見ます。まさかディスクを使い切ってるとか、そんなことはまさか無いと思うのですが。念のため確認します。見るべきところは使用率（パーセンテージ）と残容量です。まさか0になってるとか、そんなことはないと思うのですが、念のため。
$ df -h
$ df -i
※ df -i はOSのiノード使用状況が示されます。iノードについての詳細な説明は Wikipediaのinodeの項目 に譲りますが、ファイルの数がとにかく多い（数十万、数百万個単位）システムになると上限に達してファイルが新規作成出来なくなったり、また普段はあまり確認することが無いため、ハマりやすいポイントでもあります。
ストレージの使用状況に問題がなければ、あとはCPUやメモリの使用状況に余裕があるかどうかを確認します。
$ top -c -d 1
詳しい見方はググると沢山出てくると思いますのでここでは割愛します。
Apacheのステータスを見る
私の経験上あまりhttpdが障害の原因ということはないのですが、一応状態を確認します。
$ ps -ef | grep httpd | grep -v grep | wc -l
※OSやインストール方法によっては httpd ではなく apache というプロセス名で上がる場合があります。
こんな感じでプロセス数をカウントして、config (httpd.confなど) のMaxClientsの数値に達していないか（超えていないか）を確認します。逆に0個であればapacheが死んでしまっているので、立ち上げてやりましょう。また、下記のコマンドも切り分けとして有効です。
$ sudo netstat -anp | grep httpd
httpdプロセスのネットワーク接続状況が確認できます。netstatコマンド自体は一般ユーザーでも実行可能ですが、 rootに限って -p オプションを付けてやることでどのプロセスがそのコネクションを掴んでいるのかが判別できて便利です。
MySQLのステータスを見る
多くの障害で詰まっている根本となっているのはデータベースです。
- データベースが応答を返さない
- DB応答待ちでhttpdも応答を返さない
- それでもリクエストはバンバン増加する
- ｵﾜﾀ＼(^o^)／
……とかよくある話です。というわけでMySQLの状況を探りにCLIに入ります。ちなみにMariaDBでもだいたい同じです。
$ mysql -u root
これで入れたらラッキーですが、普通はMySQLのrootパスワードを設定してあるのでこのコマンドでは入れません。ちゃんとMySQLのrootパスワードを管理者に聞いて、
$ mysql -u root -p
としてパスワードを入力しましょう。rootでなく一般アカウントが判明している場合はそのユーザー・パスワードを利用しましょう。
次にやることはプロセス一覧の確認です。
mysql> show processlist;
このコマンドを実行すると、今データベースに接続しているユーザー（コネクション）と、そのコネクションで発行されているSQLの一覧が表示されます。このコマンドはDBへ大きく負荷をかけるものではないので、何回か（1秒おき10回ぐらい）実行してみましょう。自分以外の接続が全く無い場合、以下のような表示となります。
+--------+------+-----------+------+---------+------+-------+------------------+
| Id | User | Host | db | Command | Time | State | Info |
+--------+------+-----------+------+---------+------+-------+------------------+
| 591103 | root | localhost | NULL | Query | 0 | NULL | show processlist |
+--------+------+-----------+------+---------+------+-------+------------------+
1 row in set (0.00 sec)
このとき、一瞬何らかのSQLが実行されている様子が見えることはありますが、同じIDのコネクションで同じSQLがずっと表示されつづけることは通常はありません。1つの同じSQLが10秒間ずっと表示されるということは、お客さまが最低でも10秒は待たされているといるのと同じです。Webサイトを表示しようとして10秒間も何も変化が起こらずに待たされたら、普通はイライラしますよね？なので、そのようなSQLが存在していたらまずそこを疑いましょう。
※例外として、Webとは関係のないバッチアプリケーションが長大なSQLを発行している可能性もありますので、いきなり悪と決めつけないように注意しましょう。
さて、問題のありそうなSQLを発見したら次に以下のコマンドを実行します。
mysql> show full processlist;
ちょっと見づらいと思いますが、今度は実行されているSQLの全文が表示されるようになります。このSQLの中身を見て、どのアプリケーションが障害を引き起こしているのか詳細な調査に入っていきましょう。
いかがでしたでしょうか。「最初のアタリをつける」ということでこの辺で一旦打ち止めにしたいと思います。ここまで見ればだいたいの障害原因は掴めてきます。あとはとにかく騒いで他のエンジニアの手を借りたり、社内外への周知をお願いしたり、上層部へのレポートしたり、といった一般的な障害対応フローを手分けして行っていきましょう。
※12/19 22:08追記 : df -iを追記した方がよいと お告げをいただきました ので追記・修正しました。ご指摘ありがとうございました。