【追記アリ】Golangで1行1行がJSONのログを効率的にパースする

この記事でも書いたけど、ISUCON用のロガーを作ったので、そのログをパースするツールを書こうと思った。

serinuntius.hatenablog.jp

少しパフォーマンスを意識して書いてみたけど、きっともっとパフォーマンスが良くなる気がするのでマサカリウェルカムです。

お急ぎの方は 結論 にどうぞ。

パースするログ

今回パースするログはこんな感じのログでこれが何千行とあるのを想像していただければ。

{"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に変換したら約10msRubyとかで同様の処理書いたら 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というものを見つけた。

github.com

特徴は

  • 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)
    }
}

まとめ

ベンチマークを書いてちゃんと計測した上で改善していったので、速くもなったしメモリ使用量も減ったしアロケーションも減った最高のコードになった。

おまけ

全体のコードはgistに上げてます。

gist.github.com

追記

全部をメモリに載せる必要はないんじゃないかというマサカリを頂きました。 全部メモリに載せないと計算できない値があったりするかと思っていたのですが、大体加算したり今の値と前の値を比べてあげればなんとかなりそうです。 alpも全部メモリには載せていませんでした。

なので、一番良さそうなコードはこちらになります。

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)
    }
}

他のベンチと同一の条件でメモリに載せる要件があれば、結論で書いたやつがこの記事の中では最速です。