AWKのススメ

はじめまして。インフラチームの菅原といいます。

今年の7月に入社してから、コンソールとにらめっこする毎日を過ごしています。クックパッドのようにアクセスの多いサイトのサーバを扱うことが今まで無かったので、いろいろと勉強になることが多いです。

さて、インフラチームではサーバの状況をモニタリングして、サーバに問題がないかを常に把握するようにしています。そのため日常的にtailでログを追いかけているのですが、そんなときはAWKが非常に便利なことに気付き、最近はかなりAWKにハマっています。

今回は絶賛マイブーム中のAWKの活用例をご紹介したいと思います。

なぜAWKなのか?

残念ながらAWKの知名度はあまり高くないようで、社内でも「なぜRubyでやらないのか?」と聞かれることがありました。僕も入社するまではcutの代わりぐらいにしか使っていなかったのですが、あるときログ出力の整形に使って以来、AWKのおもしろさにすっかりハマってしまいました。

AWKの魅力はいろいろとあるのですが、ひとつあげるとすれば「ワンライナーの書きやすさ」です。もちろんRubyでもPerlでもワンライナーは書けるのですが、AWKはさらにワンライナーが書きやすい言語です。

仕事での活用例

普段、僕が仕事で使っているAWKスクリプトをいくつかご紹介します。AWKの文法についてはGNU Awk User's Guideなどを参照してください。

Railsの500msec以上かかっている処理を追いかける

後からRailsのログを集計してもよいのですが、その場で状況を知りたいときは tail -f と AWK の組み合わせが強力です。次の簡単なAWKスクリプトは、遅くなっている処理をさくっと把握したいときに使っています。

[sourcecode language="bash"] $ tail -f log/production.log | ¥ awk '/^Completed/{if($3 > 0.5) print }' Completed in 0.56046 (1 reqs/sec) | Rendering: 0.23351 (41%) ... Completed in 0.59227 (1 reqs/sec) | Rendering: 0.00010 (0%) ... Completed in 1.90438 (0 reqs/sec) | Rendering: 1.87990 (98%) ... ... [/sourcecode]

Apacheの平均応答時間を追いかける

アクセスが多くなると tail -f でaccess_logを追いかけようとしても、流れが速すぎて状況を把握できません。そこでAWKで100リクエストごとの平均応答時間を計算して、現在の応答時間がどのくらいなのかを把握しています。

[sourcecode language="bash"] $ tail -f access_log | awk ' {i++; t+=$4} i > 100 { print strftime("%H:%M:%S"), "|", t / i / 1000, "ms" i=t=0 }' 18:58:34 | 97.1538 ms 18:58:38 | 80.6553 ms 18:58:42 | 75.4794 ms [/sourcecode]

ちなみにクックパッドのaccess_logは以下のようなフォーマットで出力されます。

[sourcecode language="bash"]

ステータス, 時間, 処理時間(マイクロ秒), リクエストuri, パラメータ...

LogFormat "%>s\t%{%Y-%m-%d %H:%M:%S}t\t%D\t%U\t%q..." [/sourcecode]

上記のスクリプトを少し修正して、単位時間あたりのリクエスト数を出力するようにすると、サービスへどのくらいアクセスがあるのかを把握できるようになります。

[sourcecode language="bash"] [...]$ tail -f access_log | awk ' BEGIN{st=systime()} {i++} i > 200 { et=systime() printf("%s | %.1f req/sec\n", strftime("%H:%M:%S"), i / (et - st)) i=0; st=et }' 19:10:45 | 16.8 req/sec 19:10:55 | 20.1 req/sec 19:11:06 | 18.3 req/sec [/sourcecode]

slow-query.logを追いかける

mysqldumpslowというスロークエリログ用のツールがありますが、その場で状況を知りたいときには tail -f で追いかけるのが手軽です。しかし、そのままでは少々見にくいので、次のようなAWKスクリプトで整形します。

[sourcecode language="bash"] [...]$ tail -f slow-query.log | awk ' /^# Time/ { q=substr(q,0,64) printf("%s %s %-17s %2d %s\n", d, t, h, s, q) d=$3; t=$4 } /User/ {h=$5} /Query_time/ {s=$3} /^[^ ]/ {q=$0}' 091010 17:46:45 [192.168.xxx.xxx] 2 SELECT foo, bar, zoo FROM... 091010 17:55:29 [192.168.xxx.xxx] 3 SELECT foo FROM... 091010 17:56:08 [192.168.xxx.xxx] 3 SELECT foo FROM... [/sourcecode]

ANSIエスケープシーケンスを使えば、10秒以上かかったクエリだけ赤く表示することもできます。

[sourcecode language="bash"] awk ' /^# Time/ { if (s > 9) { printf("33[0;31m") } else { q=substr(q,0,64) } printf("%s %s %-17s %2d %s\n", d, t, h, s, q) printf("33[0m") d=$3; t=$4 } /User/ {h=$5} /Query_time/ {s=$3} /^[^ ]/ {q=$0}' [/sourcecode]

まとめ

今回は、仕事で使っているAWKスクリプトをいくつかご紹介させていただきました。僕もまだAWK初心者なのでお世辞にも洗練されたコードとはいえませんが、それでも非常に役に立っています。 ちなみに、AWKワンライナーには何か癖になるものがあり、最近はワンライナーばかり書いているので、historyがスクリプトの保存先と化しつつあります。

みなさんもAWKで一行野郎を使いこなしましょう!

おまけ

GNU Awkはソケットが使えるので、カレントディレクトリをDocumentRootとするWebサーバを、ワンライナーで書いてみました。

[sourcecode language="bash"] awk 'BEGIN{s="/inet/tcp/80/0/0";"pwd" |& getline;r=$0;while((s |& getline) >; 0){gsub(/[\r\n]/,"");if($0 ~ /^\s*$/){c="cat " r path;printf "HTTP/1.0 200 OK\r\n\r\n" |& s;while((c |& getline) > 0){print |& s}close(c);close(s)}else if($0 ~ /HTTP/){print;path=$2}}}' [/sourcecode]

きちんと改行をいれるとこんな感じになります。 [sourcecode language="bash"] awk ' BEGIN { s = "/inet/tcp/80/0/0" "pwd" |& getline r = $0

while ((s |& getline) > 0) { gsub(/[\r\n]/, "")

if ($0 ~ /^\s*$/) {
  c = "cat " r path
  printf "HTTP/1.0 200 OK\r\n\r\n" |& s

  while ((c |& getline) > 0) {
    print |& s
  }

  close(c)
  close(s)
} else if ($0 ~ /HTTP/){
  print
  path = $2
}

} }' [/sourcecode]

AWKを使ったことがなくても、わかりやすいコードではないでしょうか?

GNU Awkのネットワーク機能はとても面白いです。AWKを始めた人には、ネットワーク機能のマニュアルを一読することをお薦めします。