突然のTwitter砲にもなんとか耐えたさくらVPSに感謝する

なんか、2/6の夜に「修士論文の代わりに退学願を提出してきた」がTwitterでばずったらしく、Yahoo砲よろしく突如としてアクセスが集中しました。下の方にリソースモニタリングのグラフを貼りつけてますが、今までがほぼ0に見えてしまうくらいに来てたのでびっくりでした。

まぁ色々コメントつけて頂いたりしてますが、もう2年も前なんでこのエントリについて今更僕から突っ込むことは無くて、あのエントリはあのエントリとして見て頂ければと思います。ここでは今回そんな突然のアクセス集中にも見事耐えてくれたさくらVPSに感謝しつつ、アクセス集中の状況を鯖管的立場から分析してみましょう。

ちなみに、以前エントリに書いていますがサーバの構成としてはさくらVPS1台で、CentOS+Apache+mod_fastcgi+PHP-FPM+MySQL5.5(InnoDB)でWordPressを動かしています。

• WordPressをCentOS+Apache+mod_fastcgi+PHP-FPMを使って動かしてみた

ページはちゃんと返せていたのか？

アクセスが集中すると、エラーページを返してしまう可能性があります。エラーの原因は色々あるでしょうが、500番台のステータスコードが返っているか確認することでざっと見ることはできます。（そもそもApacheがちゃんと動いていなければアクセスログすら残らないですが今回それは大丈夫だったようです）

別に記録しているグラフで見ると、「2/6の22:00過ぎ」にhttpの通信が返ってこないことがあったみたいでしたのでこの時間帯を調べてみましょう。

アクセスログをlessとかで開いてざっと目視で確認(俗に言う「目grep」)してもいいですが、仕事とかではきちんと数値で出す必要がありますよね。そういう時、僕はコマンドの組み合わせでさっと集計することが多いので、今回それをご紹介。

アクセスログはいわゆるApache標準のcombinedの最後に処理マイクロ秒(%D)を追加したものだとします。

LogFormat "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\" %D" combined

tail -3 access_log.20110206
192.168.1.1 - - [06/Feb/2011:23:59:57 +0900] "GET /2009/03/02/185833 HTTP/1.0" 200 34092 "-" "Mozilla/4.0 (..." 1199490
192.168.1.2 - - [06/Feb/2011:23:59:57 +0900] "GET /2009/02/27/120733 HTTP/1.1" 200 77154 "-" "Mozilla/5.0 (..." 1065235
192.168.1.3 - - [06/Feb/2011:23:59:57 +0900] "GET /2009/02/27/120733 HTTP/1.0" 200 40960 "-" "-" 1097226

awk入門

まず集計したいのは「2/6の22:00過ぎ」に「500番が返っていたか」です。とりあえず見るならこんな感じ。うーん。出てますね。

grep "2011:22:" access_log.20110206 | awk '$9==500{print}'
192.168.1.1 - - [06/Feb/2011:22:00:37 +0900] "GET /2009/02/27/120733 HTTP/1.1" 500 534 "-" "Mozilla/5.0 (..." 30000774
192.168.1.2 - - [06/Feb/2011:22:00:37 +0900] "GET /2009/02/27/120733 HTTP/1.1" 500 534 "-" "Mozilla/5.0 (..." 29999308
192.168.1.3 - - [06/Feb/2011:22:00:40 +0900] "GET /2009/02/27/120733 HTTP/1.1" 500 534 "http://twitter.com/" "Mozilla/5.0 (..." 29999068

awkはログの分析の時には必須のスクリプト言語です。後ほどもうちょっと込み入った使い方を紹介しますが、とりあえずここでは、「9カラム目が500だったら出力する」というのを毎行実行したと思って下さい。9カラム目というのはログをheadで眺めてみて、空白とかタブで区切られた数を数えてステータスコードに相当する所を数えた結果です(上のログ参照)。

最強のcut | sort | uniq -cを使う

500番がどういう時間帯で出ていたのかを見てみましょう。awkで書いてもいいんですがワンライナーにはちょっと長いので、もっとお手軽にできる最強の組み合わせを使いましょう。

awk '$9==500{print}' blog_access_log.20110206 | cut -f2,3 -d: | sort | uniq -c
      1 19:46
      1 20:50
      1 20:57
      1 21:54
      1 21:55
    *** 22:00
    *** 22:01
    *** 22:02
    *** 22:03
    *** 22:04
    *** 22:05
    *** 22:06
    *** 22:07
     ** 22:08
     ** 22:09
      1 23:11
      1 23:41

それぞれの意味は自分で調べるのが一番ですが簡単に書くと、まずcutで「HH::mm」の部分を「:」を区切り文字に抜き出しています。そのあとsortで並べ替えて同じ時刻が連続並ぶ様にしておいて、uniq -cで集計しています。sortするのはログのタイムスタンプが前後してしまっている場合もあるからですね。というわけで、一応数は伏せてますが22:00〜22:09に集中して出ているようです。

ちなみにこのawk or cut | sort | uniq -cは本当に強力で、例えばアクセスログからアクセス上位のIPアドレスを集計したければこういう風にやるだけで簡単にできます。不正アクセスとかあったときにご活用くださいｗ

awk '{print $1}' access_log | sort | uniq -c | sort -n | tail -5
    *** 192.168.1.1
    *** 10.1.1.1
    *** 192.168.1.3
    *** 172.16.1.1
    *** 192.168.1.2

500の原因を探る

さてApacheで500が出るパターンというのはサーバ側の問題なので、エラーログにも何かしら情報があることが多いです。

grep " 22:0" error_log
[Sun Feb 06 22:01:07 2011] [error] [client 192.168.1.1] FastCGI: comm with server "/etc/httpd/fcgi-bin/php-cgi" aborted: idle timeout (30 sec)
[Sun Feb 06 22:01:07 2011] [error] [client 192.168.1.1] FastCGI: incomplete headers (0 bytes) received from server "/etc/httpd/fcgi-bin/php-cgi"
[Sun Feb 06 22:01:07 2011] [error] [client 192.168.1.2] FastCGI: comm with server "/etc/httpd/fcgi-bin/php-cgi" aborted: idle timeout (30 sec)

出てますね。サーバの構成は紹介したエントリの通りApacheがmod_fastcgi経由でTCPのソケットを使ってPHP-FPMデーモンと喋っているのですが、どうやらそこでtimeoutしてしまっているようです。つまり、PHP側がうまくしゃべれなくて、30秒待ってApache側でtimeoutした結果、ユーザにはサーバ側のエラーということで500番が返ってしまっていました様です。

その原因はちょっとわかんないですがその当時のグラフは以下の様な感じなのでそもそもCPUが90%とかいってたみたいですので色々おかしなことは起こっててもおかしくないでしょうね。

awk入門その2

影響がどの程度だったのかをみておきたいので、500番はどの位でていたのかを200番と比較してみましょう。これもawkが大活躍です。

grep "2011:22:0" access_log.20110206 | awk '$9==200{ok++}$9==500{ng++}END{print ng/(ok+ng)*100}'
38.9419

{}の前がif文みたいなもので、9番目のカラムが200だったらokという変数をインクリメント、500だったらngをインクリメントしておきます。END{...}と書くと全行評価したあとに実行されるものを定義できるので、そこで割合をパーセントで計算して出力。

該当時間には39%位が500番になってしまっていたようです。誠に申し訳ない＞＜でもまぁこんなことはそうは起こらないのでとりあえず対応は無しとします。仕事じゃないしね！キリッ

リソースモニタリングしてた

さてもったいぶりましたが、さくらのVPSにはCloudForecast入れてリソースを可視化していたのでそちらをお見せします。 左上がトラフィック、その下がCPU使用率、ロードアベレージ、右上がApacheのstatus、その下がメモリ使用量になります。kazeburo++

一見して分かる通り、2/6おかしいｗ　iowaitも結構でてしまっていたのは、トラフィック出てるところを考えるとおそらく画像とかなぁ。そのせいでPHPも割を食ってた気はするので、S3とかに置いてしまう手も検討中です。

ちなみに注目して頂きたいのはメモリのグラフです(右下)。メモリを食うのは主にPHP-FPMのプロセスなんですが、さくらVPSは512MBとかなり小さいため、負荷に応じてこのプロセス数を調整したりするとswapしてしまうのが怖いです。なので、プロセスの数は3つに固定にしてしまっています。そのため、httpdのプロセスの数(右上)はアクセス数に応じて増減していますが、メモリの使用量はほぼ一定になっています。swapしてしまうとディスクIOは相当性能悪いみたいで、大抵はサーバを再起動しないといけなくなるので、そうなるよりは多少500番を返してしまってもプロセス数を制限しておいた方がいいですよ、という好例になりました。

そういえばレスポンスタイムってどんな感じ？awk入門その3

さて、そういえばcombinedのアクセスログに処理時間を入れてる話はしましたが、実際どの位で返せているのか気になりました。ではまずは平均から。

grep "2011:21:" access_log.20110206 | awk '$9==200{l++;sum+=$NF/1000000}END{print sum/l}'
1.78198
grep "2011:22:0" access_log.20110206 | awk '$9==200{l++;sum+=$NF/1000000}END{print sum/l}'
20.7464
grep "2011:23:" access_log.20110206 | awk '$9==200{l++;sum+=$NF/1000000}END{print sum/l}'
2.08723

grep "2011:22:" access_log.20110205 | awk '$9==200{l++;sum+=$NF/1000000}END{print sum/l}'
0.74092

$NFというのは各行の最終カラムを意味しています。lに200の件数、sumにレスポンス時間を秒単位で足し算していって、最後に割り算して平均をだしています。

昨日までは平均1秒もかかっていなかったのに、昨日から2秒位になってしまった。。。そして問題のあった22:00〜22:09だと20秒とかになってますね。これはひどい。

ただ、平均というやつは異常値に引きずられやすいのでもしかしたらこれはものすごい遅いものが引っ張っているだけなのではないか？というわけで、次に95パーセンタイル(全体の95%が収まっている値)を出してみたいと思います。さっき書いたけどこれもawk(実際はasort関数のあるgawk)だったら手書きできる程度で一発です。

grep "2011:21" access_log.20110206 | awk '$9==200{l++;data[l]=$NF/1000000}END{pct=int(l*0.95);asort(data);print data[pct]'}
6.47321
grep "2011:22:0" access_log.20110206 | awk '$9==200{l++;data[l]=$NF/1000000}END{pct=int(l*0.95);asort(data);print data[pct]'}
30.016
grep "2011:23" access_log.20110206 | awk '$9==200{l++;data[l]=$NF/1000000}END{pct=int(l*0.95);asort(data);print data[pct]'}
6.72018

grep "2011:22" access_log.20110205 | awk '$9==200{l++;data[l]=$NF/1000000}END{pct=int(l*0.95);asort(data);print data[pct]'}
1.21503

パーセンタイルを計算するには全行を評価した後に、並び替えて、小さい方から95%番目に当たるものを表示すればいいだけです。END{...}の部分がまさにそのまんまですね。data[l]という形で各行の秒数を入れておいて、asort関数で並び替え。lの95%を整数にしておいて、その番号を指定してdataを表示してるだけです。gawkが使えない環境だとsortをやるには自前で書く必要があるので、その場合は一発でやるのはちょっと面倒そう。

で、、、結果としてはむしろ沢山ある小さい方の値が平均値を引き下げてくれていたようですね。。。だったら、ちょっと分布を見てみたい！というときには今度はcut | sort | uniq -cが役にたちます。ここではとりあえず2/6の23:00台。22:00の様なアクセス集中は収まっていますがどんな感じだったのかな。

grep "2011:23:" access_log.20110206 | awk '$9==200{print $NF/1000000}' | cut -f1 -d. | sort -n | uniq -c
    **** 0
    **** 1
     *** 2
     *** 3
     *** 4
     *** 5
...

$NF/1000000で小数点付きの秒単位になるので、小数点でcutしてます（awkでintにキャストすればいいだけじゃんというのは言わないで＞＜）。あとはsort -nで数値として評価して並び替えてuniq -cで集計すればヒストグラムの完成。

うーむ。。。なんか普通に数秒かかってるのもあるのね。。。こうなったらどの秒が何パーセンタイルなのかも出してやる！

grep "2011:23:" access_log.20110206 | awk '$9==200{print int($NF/1000000)}' | sort -n | uniq -c | awk '{sum+=$1;data[NR]=$1;s[NR]=$2}END{for(i=1;i<=NR;i++){tmp+=data[i]; print s[i], tmp/sum*100}}'
0 47.2555
1 71.1387
2 80.9197
3 87.1387
4 91.0511
5 93.6788
6 95.4307
...

さっきの結果をまたawkに食わせて計算してます。説明は割愛。これくらいが限度だな。。。

うーむ。。。結構遅いね。50%以上が1秒超えてる。。。2/5まではどうだったのかな。

grep "2011:23:" access_log.20110205 | awk '$9==200{print int($NF/1000000)}' | sort -n | uniq -c | awk '{sum+=$1;data[NR]=$1;s[NR]=$2}END{for(i=1;i<=NR;i++){tmp+=data[i]; print s[i], tmp/sum*100}}'
0 85.4701
1 97.4359
2 99.1453
...

Σ(ﾟдﾟlll)ｶﾞｰﾝ。。。かなり劣化してる様です。まぁアクセス数自体が増えてるのでしょうがないですね。単体でチューニングしてもいいんですが、まぁ一過性のものでしょうしとりあえず様子見。もしこれが続くようであれば、負荷分散してついでに可用性も上げておきたいので複数台運用したいところです。

いじょ。

というわけで、この程度の統計分析(と呼ぶのもおこがましいですが＞＜)であれば、コマンドラインのワンライナーで十分に分析できます。

いや、こんなのperlで書いて使い回せばいいじゃん、とかいう意見もあると思うのですが、例えば複数サーバ運用してるとスクリプトを各サーバに置くのは面倒(更新したら配布しなきゃいけないし)だったりします。あとは、どの様な計算を行ったかがワンライナーに全て書かれているため、レポートするときにもコマンドを一緒に貼りつければそれがミスってないかどうかだれでも検証できます。そして、それを見た他の人が試してみたり改変したい時もコピペするだけなので便利です。

現場でトラブルシューティングするときなども、僕は上記の様なコマンドを駆使しています。よほど複雑な分析とかグラフを使って可視化したいとかがなければ、Excelなどを使う必要はなくて、というかExcelなんか起動するのは待ってられないので、こんな感じで手元でやれるとスピードアップ間違いなしですね！