俺とおまえとawk

「EFK (Elasticsearch + Fluentd + Kibana) なんて甘えですよ、漢は黙って awk | sort | uniq -c ですよ」と誰かが言ってたような言ってなかったような気がするのでログさらう時に自分がよく使う awk 芸について書きます。

想定データサンプル

こんなフォーマットで出る TSV 形式の Web アプリケーションログがあったとします。[TAB] はタブ文字です。

時間[TAB]ステータス[TAB]HTTPメソッド[TAB]URI[TAB]リクエストタイム

例えばこんな感じです。このログを awk 芸で処理していきます。

access.log

2014-12-05 12:00:00[TAB]200[TAB]GET[TAB]/api/v1/ping[TAB]0.017832
2014-12-05 12:00:01[TAB]200[TAB]POST[TAB]/api/v1/auth[TAB]1.001628
2014-12-05 12:10:00[TAB]404[TAB]GET[TAB]/favicon.ico[TAB]0.017832
2014-12-05 12:10:01[TAB]500[TAB]POST[TAB]/api/v1/login[TAB]5.00003

１分あたりアクセス量を調べる

１分あたりのアクセス量はこんなかんじで調べられるでしょう。

$ awk '{print $2}' access.log | awk -F: '{print $1 ":" $2}' | sort | uniq -c
   2 12:00
   2 12:10

解説しておくと、最初の awk で時刻フィールドを抜き出しています。

$ awk '{print $2}' access.log
12:00:00
12:00:01
12:10:00
12:10:01

デフォルトの空白文字、タブ文字を区切り文字として、 {print $2} のようにして第2フィールドを print しています。今回の場合は時刻のフィールドが出力されます。

パイプでつなげた次の awk で「時:分:秒」を「時:分」に変換しています。 -F オプションを使って区切り文字を : に変更し、第１フィールド(時)、:、第２フィールド(分) を print しています。

$ awk '{print $2}' access.log | awk -F: '{print $1 ":" $2}'
12:00
12:00
12:10
12:10

あとは慣用句と言っても良い sort | uniq -c に渡して、ユニークな値の数をカウントして出力しています。

$ awk '{print $2}' access.log | awk -F: '{print $1 ":" $2}' | sort | uniq -c
   2 12:00
   2 12:10

ちなみに、上の例では awk を２回使いましたが、awk には substr 関数なんかもあったりするので、以下のようにすると１発で書けたりもします。 使い捨てワンライナーなので、覚えやすい方を使えば良いかと思います。

$ awk '{print substr($2,1,5)}' access.log
12:00
12:00
12:10
12:10

1秒以上時間がかかっているアクセスをリストアップする

今回のログフォーマットでは、一番最後のフィールドがリクエストタイムでした。 一番最後のフィールドは $NF で指定することができます。

$ awk '{print $NF}' access.log
0.017832
1.001628
0.017832
5.00003

で、そのフィールドに条件を指定して、1秒以上時間がかかっている行のみに絞り混んでみます。次のようにします。

$ awk '$NF > 1.0' access.log
2014-12-05 12:00:01 200 POST    /api/v1/auth    1.001628
2014-12-05 12:10:01 500 POST    /api/v1/login   5.00003

これは以下のコマンドと同等です。 {} を省略した場合、デフォルトで {print $0} (全フィールドの表示) になります。

$ awk '$NF > 1.0 {print $0}' access.log
2014-12-05 12:00:01 200 POST    /api/v1/auth    1.001628
2014-12-05 12:10:01 500 POST    /api/v1/login   5.00003

おまけ：一番最後から１個前のフィールドは $(NF-1) で指定することができます。 ２個前なら $(NF-2) ですね。例えば、こんなかんじでつかいます。

$ awk '$NF > 1.0 {print $(NF-1)}' access.log
/api/v1/auth
/api/v1/login

5xx ステータスコードのアクセスをリストアップする

ステータスコード 500 の行を抜き出すには次のようにすればよいでしょう。

$ awk '$3 == 500' access.log
2014-12-05 12:10:01 500 POST    /api/v1/login   5.00003

正規表現を使うこともできて、5xx な行を抜き出したい場合には次のようにすればよいです。

$ awk '$3 ~ /^5/' access.log
2014-12-05 12:10:01 500 POST    /api/v1/login   5.00003

こちらでも、{print フィールド番号} とすれば指定したフィールドだけ出力させることができます。

$ awk '$3 ~ /^5/ {print $5}' access.log
/api/v1/login

おまけ：正規表現マッチはフィールドを指定しない場合、行全体($0) に対する正規表現マッチ($0 ~ /正規表現/)となるので、以下のように書くと grep のような効果を出せます。

$ awk '/500/' access.log
2014-12-05 12:10:01 500 POST    /api/v1/login   5.00003

合計リクエストタイムを求める

アクセスログのうち合計リクエストタイムを求めるには、ちょっとめんどくさいですが、次のようにします。

$ awk 'BEGIN{sum=0}{sum+=$NF}END{print sum}' access.log
6.03732

変数はデフォルトで 0 に初期化されるので、BEGIN{sum=0} は省略可能です。

最大値を求めたい場合は、

$ awk '{if($NF > max)max=$NF}END{print max}' access.log
5.00003

とかですかね。めんどくさいですが、まぁそんなもんですね。

LTSV なログを処理する

最近は LTSV フォーマットが人気ですが、ラベル:値 のフィールドを分離して 値 だけを取り出した TSV 形式に変換しないと awk では扱いづらいです。例えば、次のような LTSV ログがあったとして、

time:2014-08-13T14:10:10Z[TAB]status:200
time:2014-08-13T14:10:12Z[TAB]status:500

status フィールドの値だけを awk で抜き出そうとするとこんなかんじになるでしょうか。 面倒ですね。

$ awk -F\t '{split($2, status, ":"); print status[2]}' ltsv.log
200
500

awk でも扱いやすくするために皆さん、色々試行錯誤されているようです。

• awkとシェルでLTSVの取り扱いを簡単にするフィルタを書いてみた
• LTSV のログを jq でフィルタする
• lltsv という LTSV の特定キーだけ取り出す golang アプリケーションを書いた

こちらの lltsv というツールを使うと

$ lltsv -k time,status -K ltsv.log
2014-08-13T14:10:10Z    200
2014-08-13T14:10:12Z    500

のように値を取り出す事ができるので、そのまま awk につなげて

$ lltsv -k time,status -K ltsv.log | awk '$2 == 500'
2014-08-13T14:10:12Z    500

のように扱えるようです。便利っぽいですね。

おわりに

いやー、awk サイコーですね。ログを手打ちで awk コマンド打って集計するなんて幸せすぎて泣けてきますね。Enjoy happy awk life!

追記: awk 芸の高みへ

「統計屋のためのAWK入門」の記事が大変参考になるので物足りない方は読むと良いと思いますね！