【追記アリ】Golangで1行1行がJSONのログを効率的にパースする
この記事でも書いたけど、ISUCON用のロガーを作ったので、そのログをパースするツールを書こうと思った。
少しパフォーマンスを意識して書いてみたけど、きっともっとパフォーマンスが良くなる気がするのでマサカリウェルカムです。
お急ぎの方は 結論 にどうぞ。
パースするログ
今回パースするログはこんな感じのログでこれが何千行とあるのを想像していただければ。
{"level":"info","ts":1525134349.9798086,"caller":"graqt/middleware.go:25","msg":"","time":0.013506292,"request_id":"d8523ba8-9948-4171-90ae-57f3b4649efa","path":"/user","method":"GET"} {"level":"info","ts":1525134349.9832635,"caller":"graqt/middleware.go:25","msg":"","time":0.016754381,"request_id":"378cfdee-08cd-477b-8f5b-eeeb06a1f6ce","path":"/user","method":"GET"} {"level":"info","ts":1525134349.9837048,"caller":"graqt/middleware.go:25","msg":"","time":0.017091545,"request_id":"fe339125-8bf9-4520-9b04-18a0cf6a36e2","path":"/user","method":"GET"}
ベンチマークの見方
恥ずかしながら(?)、プログラムのベンチマークをちゃんと取ったのは初めてだったので、見方を説明しておく。単位がわかれば理解できる。
10810423 ns/op 2513200 B/op 23729 allocs/op
- op
オペレーションの略だと思う。
- ns/op
1回実行したら何ナノ秒かかるか。 1,000,000nsで1ms。
- B/op
1回の実行でどんだけのメモリ使うか。
- allocs/op
1回の実行でメモリのアロケーションが何回起こっているか。
雑にいうと、この数値は全部小さいほうが良い。
スコアだと思って、大きい方が良いとか思っちゃダメw
試行錯誤の歴史
全テスト共通でこの構造体があると思って頂けると。
type Request struct { Level string `json:"level"` Ts float64 `json:"ts"` Caller string `json:"caller"` Msg string `json:"msg"` Time float64 `json:"time"` RequestID string `json:"request_id"` Path string `json:"path"` Method string `json:"method"` } type Requests []Request
毎行Unmarshal
一番最初に思いついたのはこれ。
シンプルだけど遅い。遅いのはRequestsのサイズを指定してないからアロケーションが何回も起こってるんだと思う。
// 1行読んでjsonをパースして、structに詰める func BenchmarkReadlineToJson(b *testing.B) { for i := 0; i < b.N; i++ { var requests Requests f, _ := os.Open("request.log") scanner := bufio.NewScanner(f) for scanner.Scan() { var req Request json.Unmarshal(scanner.Bytes(), &req) requests = append(requests, req) } } }
これの結果はこんな感じ。10902167nsって何秒かよくわからないけど、msに変換したら約10ms
。
Rubyとかで同様の処理書いたら 35ms
とかだったので、雑に書いても速いんだな〜と。
BenchmarkReadlineToJson-4 100 10902167 ns/op 2513180 B/op 23729 allocs/op
jsonのarrayを[]byteで作って、1回だけUnmarshal
次に思いついたのは、このログをjsonの配列とみなして、1発だけUnmarshalしたら速いんじゃないかと思って書いた。
[]byte
の扱いが難しくて、余計に非効率な感じになってしまった。けど、おしい感じがする。
// 1行ずつ読み込んでjsonのarrayを作り、最後に1発だけjsonパースする func BenchmarkCreateJsonBytesToJSONWithAppend(b *testing.B) { for i := 0; i < b.N; i++ { var requests Requests f, _ := os.Open("request.log") scanner := bufio.NewScanner(f) first := true var data []byte for scanner.Scan() { b := scanner.Bytes() if first { b = append(b, ',') data = append([]byte(`[`), b...) } else { b = append(b, ',') data = append(data, b...) } first = false } data[len(data)-1] = ']' json.Unmarshal(data, &requests) } }
結果は、さっきのやつよりはアロケーションは減ったしほんのちょっとだけ速くなったけど、メモリが使用量が増えちゃった。
BenchmarkCreateJsonBytesToJSONWithAppend-4 100 10217755 ns/op 3477959 B/op 16666 allocs/op
あらかじめファイルサイズ分のbyteを用意する
次に思いついたのはこれ。大きなbyteを作ってあげたら、良くなるんじゃないかと思ったけど全然ダメだった。
// ファイルサイズ分の[]byteを用意して、1行ずつ読み込んでjsonのarrayを作り、最後に1発だけjsonパースする func BenchmarkCreateJsonBytesToJsonWithFileSize(b *testing.B) { for i := 0; i < b.N; i++ { var requests Requests f, _ := os.Open("request.log") stat, _ := f.Stat() scanner := bufio.NewScanner(f) first := true // あらかじめfile sizeだけの[]byteを用意しておく data := make([]byte, stat.Size()) for scanner.Scan() { b := scanner.Bytes() if first { b = append(b, ',') data = append([]byte(`[`), b...) } else { b = append(b, ',') data = append(data, b...) } first = false } data[len(data)-1] = ']' json.Unmarshal(data, &requests) } }
結果はダメダメ。遅くなったし、メモリは増えちゃったし・・・。
BenchmarkCreateJsonBytesToJsonWithFileSize-4 100 10436011 ns/op 3920520 B/op 16668 allocs/op
bytes.Buffer使ってみる
弊社のGoランチで標準パッケージ輪読会をやってるんですけど、それで出てきたbytes.Buffer使えば良いのでは??と思ってやってみた。
めっちゃシンプルになって、見通しは良くなった。
// append使うより、bytes.Buffer使った方が楽だよね func BenchmarkCreateJsonBytesToJsonWithBytesBuffer(b *testing.B) { for i := 0; i < b.N; i++ { var requests Requests f, _ := os.Open("request.log") scanner := bufio.NewScanner(f) var buf bytes.Buffer buf.WriteByte('[') for scanner.Scan() { b := scanner.Bytes() buf.Write(b) buf.WriteByte(',') } data := buf.Bytes() data[len(data)-1] = ']' json.Unmarshal(data, &requests) } }
肝心のパフォーマンスは、処理速度はオチてしまったもののメモリの使用量は今までで一番少なくなった。 この線はいいけど、ボトルネックがそこじゃない気がしてきたので別の路線を探りはじめる。
BenchmarkCreateJsonBytesToJsonWithBytesBuffer-4 200 12417798 ns/op 2184089 B/op 16651 allocs/op
jsoniter使ってみる
どんなに頑張ってもUnmarshalがボトルネックになってる気がしてきたので、Unmarshalが速くなる方法はないかと調べていたら、json-iterator/goというものを見つけた。
特徴は
- high performance
- 100% compatible encoding/json
// jsoniter使ってみる func BenchmarkCreateJsonBytesToJsonWithJsoniter(b *testing.B) { for i := 0; i < b.N; i++ { var requests Requests var json = jsoniter.ConfigCompatibleWithStandardLibrary f, _ := os.Open("request.log") scanner := bufio.NewScanner(f) var buf bytes.Buffer buf.WriteByte('[') for scanner.Scan() { b := scanner.Bytes() buf.Write(b) buf.WriteByte(',') } data := buf.Bytes() data[len(data)-1] = ']' json.Unmarshal(data, &requests) } }
結果はビンゴ!!
12417798 ns/op => 2868349 ns/op
さっきのやつの20%ぐらいの処理時間になっている!!100%の互換性があると言いつつこの速度って何やってるんだろう。 今度中みてみたい。
BenchmarkCreateJsonBytesToJsonWithJsoniter-4 500 2868349 ns/op 2454464 B/op 17846 allocs/op
makeで行数分のRequestを作る
ここでやっと気づいたのだけど、Request構造体の数がforループの数になるはずなので、カウントしてmakeでドカンと作ってしまう。
// makeで行数分のRequest作った方が速いはず func BenchmarkCreateJsonBytesToJsonWithArraySize(b *testing.B) { for i := 0; i < b.N; i++ { var json = jsoniter.ConfigCompatibleWithStandardLibrary f, _ := os.Open("request.log") scanner := bufio.NewScanner(f) var buf bytes.Buffer buf.WriteByte('[') lineCount := 0 for scanner.Scan() { b := scanner.Bytes() buf.Write(b) buf.WriteByte(',') lineCount += 1 } data := buf.Bytes() data[len(data)-1] = ']' requests := make([]Request, lineCount) json.Unmarshal(data, &requests) } }
これまたビンゴ!!速度はそんなには速くならなかったけど、メモリ使用量を結構抑えられた。
2454464 B => 1649510 B
今回はこの辺りが落とし所かな〜と思いこれが結論となる。
BenchmarkCreateJsonBytesToJsonWithArraySize-4 500 2661742 ns/op 1649510 B/op 17815 allocs/op
結論
bytes.Buffer & jsoniter & makeでドカン が速い
// makeで行数分のRequest作った方が速いはず func BenchmarkCreateJsonBytesToJsonWithArraySize(b *testing.B) { for i := 0; i < b.N; i++ { var json = jsoniter.ConfigCompatibleWithStandardLibrary f, _ := os.Open("request.log") scanner := bufio.NewScanner(f) var buf bytes.Buffer buf.WriteByte('[') lineCount := 0 for scanner.Scan() { b := scanner.Bytes() buf.Write(b) buf.WriteByte(',') lineCount += 1 } data := buf.Bytes() data[len(data)-1] = ']' requests := make([]Request, lineCount) json.Unmarshal(data, &requests) } }
まとめ
ベンチマークを書いてちゃんと計測した上で改善していったので、速くもなったしメモリ使用量も減ったしアロケーションも減った最高のコードになった。
- 速度は4倍
- メモリ使用量は35%削減
- アロケーションは25%削減
おまけ
全体のコードはgistに上げてます。
追記
全部をメモリに載せる必要はないんじゃないかというマサカリを頂きました。 全部メモリに載せないと計算できない値があったりするかと思っていたのですが、大体加算したり今の値と前の値を比べてあげればなんとかなりそうです。 alpも全部メモリには載せていませんでした。
あら、俺はひょっとしてめっちゃおろかなブログを書いてしまったかもしれん。
— serinuntius (@_serinuntius) 2018年5月14日
streamでjson Decodeできるんか。
わかったようでわかってなかったw pic.twitter.com/5h0FsWDA4o
なので、一番良さそうなコードはこちらになります。
var json = jsoniter.ConfigCompatibleWithStandardLibrary f, _ := os.Open("request.log") dec := json.NewDecoder(f) for { var r Request if err := dec.Decode(&r); err == io.EOF { break } else if err != nil { b.Fatal(err) } }
他のベンチと同一の条件でメモリに載せる要件があれば、結論で書いたやつがこの記事の中では最速です。