nginxのログを調査する必要があった。

やりたかったこと

nginxのログ(300万行くらいある)の中で、リクエストタイムが長くかかっているものを抽出したかった。

作ったコマンド

$ cat /var/log/nginx/access.log | awk “{print $11, “,”, $4}” | sort -rn | head -n 25

ログフォーマットについて

まず、上記コマンドでいい感じに取るためには、nginxのログフォーマットが上記コマンドに最適化されている必要がある。 筆者の環境のログフォーマットは以下の通り。

/etc/nginx/nginx.conf

$remote_addr - $remote_user [$time_local] “$request” $status $body_bytes_sent $request_time “$http_referer” “$http_user_agent” “$http_x_forwarded_for”

上記フォーマットはnginx標準。 ただまあ、実際はフォーマットが異なっていても上記コマンドをいい感じに変えれば余裕でイケる。

コマンドの説明

awk コマンドの print を使うと、対象文字列を空白でスプリットして、 $n で指定されたn番目の要素を標準出力してくれる。 上記フォーマットだと、11番目はリクエストタイムであり、4番目は対象ログの発生時間である。 注意点は、n番目というのはログフォーマットの話ではなく、実際のログの話である。 そのため、

[12/Nov/2017:03:35:01 +0900]

こういう文字列があった時、 + の前の空白でもスプリットされる。

そんな感じで、リクエストタイムと対象ログを表示し、それを降順とするために sort -rn する。そこから最初の25件を標準出力する。

結果

以下のように取れる。

$ cat access.log | awk ''{print $11, ",", $4}'' | sort -rn | head -n 25
60.309 , [12/Nov/2017:21:04:24
60.054 , [12/Nov/2017:21:02:47
59.922 , [12/Nov/2017:21:04:18
59.788 , [12/Nov/2017:21:02:56
59.773 , [12/Nov/2017:21:02:41
59.665 , [12/Nov/2017:21:04:16
59.081 , [12/Nov/2017:20:44:13
53.276 , [12/Nov/2017:17:44:08
51.800 , [12/Nov/2017:17:44:08
51.673 , [12/Nov/2017:17:44:12
50.771 , [12/Nov/2017:17:44:11
49.620 , [12/Nov/2017:17:44:08
33.279 , [12/Nov/2017:17:43:48
32.837 , [12/Nov/2017:17:43:47
30.912 , [12/Nov/2017:17:43:47
29.123 , [12/Nov/2017:17:43:47
27.221 , [12/Nov/2017:17:43:47
26.251 , [12/Nov/2017:17:43:41
25.423 , [12/Nov/2017:17:44:08
24.691 , [12/Nov/2017:17:44:08
24.659 , [12/Nov/2017:17:44:08
23.419 , [12/Nov/2017:17:43:41
22.507 , [12/Nov/2017:17:44:11
22.350 , [12/Nov/2017:17:43:41
21.383 , [12/Nov/2017:17:44:08

いい感じ。 ちなみに、300万行くらいのログを上記コマンドにかけて、30秒程度かかった。(筆者の環境)