AWKのススメ

2009年10月23日

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

今年の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スクリプトは、遅くなっている処理をさくっと把握したいときに使っています。

$ 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%) ...
...

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

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

$ 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

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

# ステータス, 時間, 処理時間(マイクロ秒), リクエストuri, パラメータ...
LogFormat "%>s\t%{%Y-%m-%d %H:%M:%S}t\t%D\t%U\t%q..."

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

[...]$ 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

slow-query.logを追いかける

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

[...]$ 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...

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

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}'

まとめ

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

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

おまけ

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

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}}}'

きちんと改行をいれるとこんな感じになります。

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
    }
  }
}'

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

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

Posted by cookpadtech
Filed in エンジニア日記
Leave a Comment »