俺とおまえとperlワンライナー

※7号の『俺とおまえとawk』にはてブがいっぱいついて羨ましかったので、丸パクしたのっかりエントリです。

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

想定データサンプル

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

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

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

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

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

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

$ perl -nale 'print $F[1]' access.log | perl -F: -nale 'print "$F[0]:$F[1]"' | sort | uniq -c
   2 12:00
   2 12:10

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

$ perl -nale 'print $F[1]' access.log
12:00:00
12:00:01
12:10:00
12:10:01

aオプションでデフォルトの空白文字、タブ文字を区切り文字として、@F配列に各フィールドの値がセットされます。 print $F[1] のようにして第2フィールドを print しています。今回の場合は時刻のフィールドが出力されます。
※全体の行テキストは$_に格納されます。

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

$ perl -nale 'print $F[1]' access.log | perl -F: -nale 'print "$F[0]:$F[1]"'
12:00
12:00
12:10
12:10

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

$ perl -nale 'print $F[1]' access.log | perl -F: -nale 'print "$F[0]:$F[1]"' | sort | uniq -c
   2 12:00
   2 12:10

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

$ perl -nale 'print substr($F[1], 0, 5)' access.log 
12:00
12:00
12:10
12:10

ちなみに自分は正規表現で抜き出す事が多いです。

$ perl -nale '/ (\d\d:\d\d):/;print $1' access.log
12:00
12:00
12:10
12:10

慣れるとApacheのデフォルトフォーマットでも、かなりの精度で必要な値を抜き出せるようになります。

$ head -1 apache_access.log
66.249.71.229 - - [06/Dec/2014:04:04:58 +0900] "GET /robots.txt HTTP/1.1" 200 202 "-" "Mozilla/5.0 (compatible; Googlebot/2.1; +http://www.google.com/bot.html)" "-"

$ perl -nale '/2014:(\d\d:\d\d):.* "GET (\S+)/;print "$1 $2"' apache_access.log
04:04 /robots.txt
04:04 /index.html
05:15 /blog/?category=1

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

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

$ perl -nale 'print $F[-1]' access.log 
0.017832
1.001628
0.017832
5.00003

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

$ perl -nale 'print if $F[-1] > 1' 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

もう少し複雑な処理を書く場合は、or next等でその行の処理をスキップするのもいいかもですね。

$ perl -nale '$F[-1] > 1 or next;print' 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

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

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

$ perl -nale 'print if $F[2] == 500' access.log
2014-12-05 12:10:01 500 POST    /api/v1/login   5.00003

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

$ perl -nale 'print if $F[2] =~ /^5/' access.log
2014-12-05 12:10:01 500 POST    /api/v1/login   5.00003

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

$ perl -nale 'print $F[4] if $F[2] =~ /^5/' access.log
/api/v1/login

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

$ perl -nale 'print $F[4] if /500/' access.log
2014-12-05 12:10:01 500 POST    /api/v1/login   5.00003

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

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

$ perl -nale 'BEGIN{$sum=0};$sum += $F[-1];END{print $sum}' access.log
6.03732

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

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

$ perl -nale '$max = $F[-1] if $F[-1] > $max;END{print $max}' access.log
5.00003

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

特定の条件ごとのアクセス数、平均応答速度、合計応答速度を求める

例として、1分ごとのアクセス数、平均応答速度、合計応答速度を出力してみます。
複雑な例ですが、このぐらいの処理がサクッと書けると各種調査、障害時の切り分けにかなり役立ちます。

$ perl -nale '/ (\d\d:\d\d):/;$cnt{$1}++;$sum{$1}+=$F[-1];END{print join " ", ($_, $cnt{$_}, $sum{$_}/$cnt{$_}, $sum{$_}) for sort keys %cnt}' access.log
12:00 2 0.50973 1.01946
12:10 2 2.508931 5.017862

%cnt、%sumに抽出した条件(今回は時間)ごとのアクセス数と応答速度をカウントアップしていき、最後にまとめて出力しています。

LTSV なログを処理する

最近は LTSV フォーマットが人気です。
例えば、次のような LTSV ログがあったとして、

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

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

$ perl -F'\t' -nale 'for(@F){($k, $v) = split(":", $_, 2);$h{$k} = $v};print $h{status}' ltsv.log
200
500

『LTSVログをパースする最強のワンライナー集』には以下のような記法が紹介されています。

$ perl -F'\t' -nale '%h=map{split/:/,$_,2}@F;print $h{status}' ltsv.log
200
500

番外編：sedの代わりに使う

nオプションの代わりにpオプションを使って、引数にs式を渡すとsedと同じように使えます。

$ perl -pe 's/\tstatus:\d+$//' ltsv.log 
time:2014-08-13T14:10:10Z
time:2014-08-13T14:10:12Z

perl互換の正規表現が使えるので非常に便利です。 iオプションなども同じように使えます。

おわりに

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