awkを使ってApacheのログを加工してみた

awkをつかっていい感じにデータを加工に挑戦したので、メモ。

目的としては、ログを漁って重たい処理を探すのに使いました。

そもそもawkって?

AWK(オーク)は、UNIX 上で開発されたプログラミング言語で、CSVファイルなどの文字ファイルの処理に用いられる。

(Wikipediaより)

要はテキストを加工するのに使えるプログラムです。

ちょっと動かしてみる

ログはこのブログの裏側で吐き出してるやつをちょっと加工したものをサンプルとして用意。

$ head -n 3 sample.log

127.0.0.1 - - [19/Jul/2013:00:27:24 +0900] "GET /blog/ HTTP/1.0" 404 2116 75180 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_7_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/28.0.1500.71 Safari/537.36"

127.0.0.1 - - [19/Jul/2013:00:27:37 +0900] "GET / HTTP/1.0" 200 4970 479480 "-" "Mozilla/5.0 (iPhone; CPU iPhone OS 6_1_3 like Mac OS X) AppleWebKit/536.26 (KHTML, like Gecko) Version/6.0 Mobile/10B329 Safari/8536.25"

127.0.0.1 - - [19/Jul/2013:00:27:49 +0900] "GET /aboutas/ HTTP/1.0" 200 4914 133634 "http://slothlibrary.com/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_7_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/28.0.1500.71 Safari/537.36"

でこれを加工していきます。

head -n 3 sample.log | awk '{print $4}'

[19/Jul/2013:00:27:24

[19/Jul/2013:00:27:37

[19/Jul/2013:00:27:49

このように書くと、4フィールド目を出力します。(区切り文字のデフォルトはスペース)

必要最低限のところを抽出していろいろ加工していきます。

まぁawkについてはドットインストールにあるので興味あればそちらへ。

awk入門

HTTPステータスコードとアクセスのあったURLを出す

$ head -n 3 sample.log | awk '{print $9,$7}'

404 /blog/

200 /

200 /aboutas/

アクセスされたURLをアクセスが数が多かった順に出す

$ cat sample.log | awk '{print $7}' | sort | uniq -c | sort -r

5 /blog/

4 /blog/index.php

3 /

2 /sample

1 /home/index.php

1 /home/

1 /aboutas/

レスポンスタイムがある一定以上なら出す

Apacheの設定ファイルで、ログのフォーマットを決めてるが、%Dを入れておこう。

レスポンスタイムをマイクロ秒で返してくれます。(100万秒で1秒)

レスポンスを返すまでの処理時間をアクセスログに記録する

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

レスポンス時間と転送サイズ、対象のURLだけを抽出。

head -n 3 sample.log | awk '{ print $11 / 1000 "ms \t| " $10 " size \t| " $7 }'

75.18ms | 2116 size | /blog/

479.48ms | 4970 size | /

133.634ms | 4914 size | /aboutas/

で、0.5秒以上かかってる行を出す

$ cat sample.log | awk '{if($11 > 500000) print $11 / 1000 "ms \t| " $10 " size \t| " $7 }'

503.647ms | 4970 size | /sample

# 予め特定のURL(フレームワークとか使ってると特定のアクション)がわかってるのであれば、絞ったほうがいい

# cat sample.log | awk '/sample/{if($11 > 500000) print $11 / 1000 "ms \t| " $10 " size \t| " $7 }'

対象のリクエストの平均アクセスタイム

$ cat sample.log | awk '

/sample/{i++; t+=$11}

END{

print t / i / 1000, "ms"

}'

290.154 ms

sampleというところにアクセスされた時間を加算しておいて、それを割って平均レスポンスタイムを出しています。

まとめ

perlとかrubyを使えば同様の処理もできそう。

でもワンライナーで簡単に使えるawkもお手軽で良いと思います。

ボトルネックを探すのに使えるお手軽なawkを覚えて、ボトルネックを撲滅しましょう。

その他参考URL

独り言

catを使ってるが、tail -fでも多分動くはず。

あと、時間で絞るときはgrep -Eでゴニョゴニョすればいける。