下記のフォーマットで出力されるアクセスログからレスポンスタイムだけ取り出して集計したくなったときに、コマンドラインでできたよ、という話です。

2023-06-04T01:31:26+09:00	apache.access.hoge	{"host":"XX.XX.XX.XX","user":"-","method":"GET","path":"/foo/baa","protpcol":"HTTP/1.1","status":200,"size":471,"referer":"https://example.com/?aaa=bbb","agent":"Mozilla/5.0 (iPhone; CPU iPhone OS 13_2_3 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/13.0.3 Mobile/15E148 Safari/604.1","cookie":{"object1":{"tag":"hoge"}},"set_cookie":"-","authorization":"-","response_time":408417,"time":1685809886,"url":{"path":"/foo/baa"},"hostname":"sugoi-host-1"}

これが1アクセスごとに1行ずつ出力されたものが複数のgzipになってるので、全部読み込んで集計します。

集計ワンライナー

$ gzcat access_log.* | awk -F 'response_time\":' '{print $2}' | awk -F ',' '{print $1}' | awk '{if($1 <= 700) print "under700"; else if($1 <= 1000) print "under1000"; else if($1 <= 2000) print "under2000"; else if($1 <= 3000) print "under3000"; else if($1 <= 4000) print "under4000"; else print "over4000";}' | sort | uniq -c

最後の uniq は awk で書くことも可能です。

これを実行すると、こんな感じで出力してくれます。

 314 over4000
  56 under1000
 652 under2000
  98 under3000
  45 under4000
4396 under700

解説

上記のワンライナーでやっていることを前方から順番に説明していきます。

1) gzcat(zcat)で対象のファイルを読み出しawkに渡す

gzcat access_log.*

awkコマンドは何か入力を受け取って、その文字列対して処理をするコマンドなので、処理対象のファイルを最初に回答してパイプで渡しています。
圧縮されていないテキストファイルの状態であれば、awkコマンドの最後にファイルを指定してやればよいようです。

ちなみに通常Linuxだとzcatでgzipファイルを開いて出力しますが、今回操作した環境がMacだったのでzcatが使えずgzcatを使用しています。

2) awkでレスポンスタイムの列より後をまるごと取り出す

awk -F 'response_time\":' '{print $2}'

awkコマンドは入力文字列を何らかの区切り文字で分割し、列に対する操作ができるコマンドで、-Fオプションで任意の区切り文字を指定できます。

カンマ区切りのログなので、本当はカンマを区切り文字として目的の列を取り出すのが素直な操作ですが、
取り出したい列よりも前で登場するカンマの数が異なる場合があり、列番号が行ごとに変わってしまうということが起きていました。
そこで「"response_time":」は1行に1回しか登場せず、その後ろに必ず必要な値が入っているということで、
区切り文字を'response_time\":'と指定しています。

そしてほしい値は区切り文字の後ろにあるので、{print $2}で必要な箇所だけを取り出しています。

ここまでで以下のような文字列を取り出してくれます。

408417,"time":1685809886,"url":{"path":"/foo/baa"},"hostname":"sugoi-host-1"}

3) awkでレスポンスタイムの値だけを取り出す

awk -F ',' '{print $1}'

一つ前の手順と同じく、区切り文字を指定して408417の部分だけを取り出して、レスポンスタイムの値を集計できるように加工します。
必ず数値,"timeとなるので、最初二登場するカンマよりも前が取り出せればOK。
ということで区切り文字はカンマで、プリントさせるのは1列目。

ここまでで以下のような文字列だけになります。

4) awk内でif文を使って分類

awk '{if($1 <= 700) print "under700"; else if($1 <= 1000) print "under1000"; else if($1 <= 2000) print "under2000"; else if($1 <= 3000) print "under3000"; else if($1 <= 4000) print "under4000"; else print "over4000";}'

やっていることはbashでif文を使うのと同じです。

一つ前の手順までで$1にはレスポンスタイムの値だけが入ってくるようになっているので、それを順番にif-elseで評価して分類していきます。
if($1 <= 700) なんか処理; else if($1 <= 1000)とすることで、700以下の値、700より大きく1000以下の値…というふうに分類させます。

print "under700"といったprintは、分類した結果に基づいてそれぞれ数をかぞえたいので各カテゴリのラベルを出力させています。
どこに分類されたか分かればいいので、A/B/C/Dとかでもいいです。

ここまでで下記のような

under2000
under2000
under700
under700
under1000
under700
under700

5) uniqで分類した結果の数を数える

sort | uniq -c

uniq -cで、入力ファイル内で重複する文字列を数えてくれます。
ただしこのとき、入力はソート済みでないと正しく集計が行えないためsortを挟んでから集計させます。
このソート処理がなかなかに重いため、集計する行数が膨大な場合はsort&uniqではなくawkを使用すると良いようです。(こちらで解説されていました。)

こうすると一つ前の手順でつけたラベルごとに数を数えて、以下のように出力してくれます。
完成パチパチです

 314 over4000
  56 under1000
 652 under2000
  98 under3000
  45 under4000
4396 under700

注意: 区切り文字の指定には気をつけましょう

適切に指定しないと、「思ったのと違う」ということが起きるので注意です。
今回でいうとユーザーエージェントの中にカンマが入っていたりいなかったりして、素直にカンマ区切りではほしい列が正しく取り出せないということがありました。

もともと決まった区切り文字で記述されたcsvファイルなんかを操作する場合は問題ないですが、
今回のアクセスログのように、列の中身が自由な文字列になりうる場合は注意が必要です。

2023/06/11追記 jqコマンドを使うバージョン

区切り文字問題のせいで行内から必要な値を取り出すためにawkでレスポンスタイムの列より後をまるごと取り出すとしていますが、
基本的にjsonなのでjqコマンドを使えばもう少しスマートにできるのでは？ということで、改良してみました。

改良版ワンライナー

$ gzcat access_log.* | sed -e "s/^[0-9]...-[0-9].-[0-9].T[0-9].:[0-9].:[0-9].+09:00\tapache.access.hoge\t{/{/" | jq '.response_time' | awk '{if($1 <= 700) print "under700"; else if($1 <= 1000) print "under1000"; else if($1 <= 2000) print "under2000"; else if($1 <= 3000) print "under3000"; else if($1 <= 4000) print "under4000"; else print "over4000";}' | sort | uniq -c

元々のコマンドから
2) awkでレスポンスタイムの列より後をまるごと取り出す
3) awkでレスポンスタイムの値だけを取り出す
の箇所を改良しています。

解説

sedで行頭のjsonじゃない奴らの排除

処理させたいファイルを見ると、各行の先頭に下記のような感じでjson形式を崩す文字列が入っていました。

2023-06-04T01:31:26+09:00	apache.access.hoge	{"host":"XX.XX.XX.XX","user":"-",...

この2023-06-04T01:31:26+09:00 apache.access.hoge の部分がjson形式ではないので、jqコマンド実行時に次のようなパースエラーが発生します。
parse error: Invalid numeric literal at line 1, column 14

今回はこの部分は必要ないので、sedコマンドを使って不要な箇所を削ってしまいます。

sed -e "s/^[0-9]...-[0-9].-[0-9].T[0-9].:[0-9].:[0-9].+09:00\tapache.access.hoge\t{/{/"

ISO8601形式の日本時間の日時で始まって、タブ区切りでapache.access.hogeという文字列と{が続く部分を探して{だけに置き換えています。

これで下記のように正しくjson形式になっている部分だけになりました。

{"host":"XX.XX.XX.XX","user":"-","method":"GET","path":"/foo/baa","protpcol":"HTTP/1.1","status":200,"size":471,"referer":"https://example.com/?aaa=bbb","agent":"Mozilla/5.0 (iPhone; CPU iPhone OS 13_2_3 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/13.0.3 Mobile/15E148 Safari/604.1","cookie":{"object1":{"tag":"hoge"}},"set_cookie":"-","authorization":"-","response_time":408417,"time":1685809886,"url":{"path":"/foo/baa"},"hostname":"sugoi-host-1"}

レスポンスタイムの値を取り出す

jq '.response_time'

オブジェクトの中からresponse_timeを取ってきてね、というだけです。
特にオブジェクトの中でネストされたりもしていないので、指定は.response_timeだけで良いです。

すると無事下記のようにレスポンスタイムの値だけを取り出すことができました。

あとは元々のコマンドと同様に、この値を分類してラベル付け→ソートして同じラベルのものの数を数えるとすることで、同じ結果が得られます。

こちらのほうが、区切り文字に左右されたりせず確実に必要な内容を取ってくれるので良さそうですね。
（元々のコマンドだと一応、「じゃあ今度はresponse_time":って記述が偶然他のフィールドの値に含まれちゃってたらどうするの？」問題が起きかねない。）

awkとuniqがあればコマンドラインで軽い集計できる話（追記：jqで改良）