この記事は Go Advent Calendar 2014 の6日目の記事です。
fmt.Fprintf および Sprint は、実行時にフォーマット文字列を毎回解析するという性質上、パフォーマンスに余計なオーバーヘッドが発生すると言えます。よって、その解析処理をコンパイル時に行えば、大幅にパフォーマンスが改善することは、C言語において kazuho さん(h2oプロジェクト)の h2o/qprintf が証明しています。
今回は qprintf にインスパイアされて、同様のことを golang で行ったらどの程度速くできるのかを、簡単な実験(koron/qfmt)で確認してみました。
方式の説明
C言語用であるqprintf ではフォーマット文字列の解析処理を、コンパイル時(直前)にソースを書き換えることで実現しています。それに対してgolangのqfmtでは、関数が一級オブジェクトであることを利用して、初回の実行時にフォーマット文字列の解釈結果を出力関数(列)として記憶(キャッシュ)し、次回以降はそのキャッシュした関数を用いることで高速化を図ります。
一例を示しましょう。 "PREFIX %s SUFFIX" というフォーマット文字列を解釈するとしましょう。qfmt ではこの文字列を3つの部分に分解し、それぞれ以下のように関数に変換し、関数列を生成します。
- 固定文字列
"PREFIX "を出力する関数 - 第1引数を文字列として出力する関数
- 固定文字列
" SUFFIX"を出力する関数
出力時にはこの関数列を順番に実行することで、意図した文字列が出力されます。
実験の準備
実験の準備として koron/qfmt を手元に clone し、v0.1 タグを checkout します。
$ cd $GOPATH/src
$ mkdir -p github.com/koron
$ cd github.com/koron
$ git clone https://github.com/koron/qfmt.git
$ cd qfmt
$ git checkout v0.1
実験結果と内容の解説
以降の実験結果は Windows 7 SP1 (64bit) + golang 1.3.3 (amd64) + Core i7 2600K 3.4GHz + 16GB RAMでのものです。
固定文字列の出力
手始めに固定文字列を出力する処理 (FprintfConst) をベンチマークしてみましょう。
$ go test -run X -bench FprintfConst
PASS
BenchmarkQfmtFprintfConst-64 50000000 54.8 ns/op
BenchmarkFmtFprintfConst-64 20000000 84.9 ns/op
Qfmt が含まれているのが koron/qfmt の結果で、もう片方は golang の fmt のものです。FprintfConst 自身の内容はこのようなものです。
Fprintf(ioutil.Discard, "Hello World")
僅かに qfmt のほうが速くなっているように見えます。次にそのSprintf版 (SprintfConst) をベンチマークしてみます。
$ go test -run X -bench SprintfConst
PASS
BenchmarkQfmtSprintfConst-64 10000000 190 ns/op
BenchmarkFmtSprintfConst-64 10000000 184 ns/op
若干ですが qfmt のほうが遅くなっています。これは qfmt の性質上 Fprintf で io.Discard へ出力した時に、メモリコピーが発生しないことに起因していると考えられます。一方のSprintf では、近い量のメモリコピーが発生するので、実行結果も近くなると考えられます。
文字列の出力
次に文字列の出力 (%s) のベンチマーク (printfString) を実行してみます。
$ go test -run X -bench printfString
PASS
BenchmarkQfmtFprintfString-64 10000000 264 ns/op
BenchmarkFmtFprintfString-64 5000000 308 ns/op
BenchmarkQfmtSprintfString-64 5000000 493 ns/op
BenchmarkFmtSprintfString-64 5000000 361 ns/op
printfString の内容は以下のとおりです。
Fprintf(ioutil.Discard, "PREFIX %s SUFFIX", "contents")
Fprintf版において Const と同様の理由で qfmt が速い一方で、Sprintf ではかなり悪くなっています。これはメモリコピーが最適化できていないものによると推測されます。
数値(int)の出力
次に数値の出力 (%d) のベンチマーク (printfInt) を実行してみます。
$ go test -run X -bench printfInt
PASS
BenchmarkQfmtFprintfInt-64 10000000 258 ns/op
BenchmarkFmtFprintfInt-64 5000000 313 ns/op
BenchmarkQfmtSprintfInt-64 5000000 470 ns/op
BenchmarkFmtSprintfInt-64 5000000 478 ns/op
printfInt の内容は以下のとおりです。
Fprintf(ioutil.Discard, "PREFIX %d SUFFIX", 1234567890)
概ね傾向はこれまでと同様です。一点、fmt の Sprintf があまり速くないのが気になります。
擬似 IPv4 アドレスの出力
次に qprintf で劇的な改善が見られた IPv4 アドレスの出力ベンチマーク (printfIPv4) を実行してみます。これはフォーマット要素が多い場合に、どのような傾向を示すかを確認するのが目的です。
$ go test -run X -bench printfIPv4
PASS
BenchmarkQfmtFprintfIPv4-64 5000000 623 ns/op
BenchmarkFmtFprintfIPv4-64 5000000 553 ns/op
BenchmarkQfmtSprintfIPv4-64 5000000 732 ns/op
BenchmarkFmtSprintfIPv4-64 5000000 657 ns/op
printfIPv4 の内容は以下のとおりです。
Fprintf(ioutil.Discard, "%d.%d.%d.%d", 192, 168, 10, 254)
qfmt では数値の文字列化に strconv.FormatInt を用いているのですが、その内部で余分なメモリコピーが発生するので、自前でバッファを管理している fmt よりも、遅くなってしまったのだと考えられます。
4個の文字列の出力
IPv4 アドレスの出力では4つの数値をフォーマットしたので、それを文字列に変更したもの (printfFourString) のベンチマークを実行してみます。
$ go test -run X -bench printfFourString
PASS
BenchmarkQfmtFprintfFourString-64 1000000 1010 ns/op
BenchmarkFmtFprintfFourString-64 1000000 1011 ns/op
BenchmarkQfmtSprintfFourString-64 1000000 1102 ns/op
BenchmarkFmtSprintfFourString-64 1000000 1101 ns/op
内容は以下のとおりです。
Fprintf(ioutil.Discard, "%s.%s.%s.%s", "192", "168", "10", "254")
ほぼ同等の性能になりました。
10個の文字列の出力
最後に出力する要素の数を増やした printfTenString をベンチマークしてみます。(結果を一部整列加工しています)
$ go test -run X -bench printfTenString
PASS
BenchmarkQfmtFprintfTenString-64 1000000 2471 ns/op
BenchmarkFmtFprintfTenString-64 1000000 1966 ns/op
BenchmarkQfmtSprintfTenString-64 1000000 2833 ns/op
BenchmarkFmtSprintfTenString-64 1000000 2365 ns/op
内容は以下のとおりです。
Fprintf(ioutil.Discard, "%s.%s.%s.%s.%s.%s.%s.%s.%s.%s", "000",
"111", "222", "333", "444", "555", "666", "777", "888", "999")
完全に qfmt のほうが遅くなってしまいました。
結論・考察
現時点の qfmt (v0.1) は完全に失敗でした。
methane さんの Why my Go program is slow? の 12 ページでは、golang を遅くする要因として、GCとメモリコピーと関数呼び出しが挙げられています。前述の結果はこれらを(GCを除いて)色濃く反映したものだといえるでしょう。
qfmt では、フォーマット文字列の解析にかかる時間を節約した一方、その分を関数呼び出しに浪費してしまったように推測されます。これはフォーマットする要素数が多くなった時に、qfmtが遅くなることから推測されます。qfmt では関数オブジェクトを活用したトレードオフとして、インライン展開が望めません。一方 fmt ならばそのようなことはなく、インライン展開が期待できるのです。
加えて関数オブジェクト方式は、プログラム全体でフォーマットの種類が多くなることで実行コードが多くなり、メモリを大量に消費すること、CPUのキャッシュに乗らなくなることが予想され、パフォーマンスに影響があると考えられます。
また各ベンチマークにおいて -run X オプションを付けたのは、テストを実行しないことで速度を稼ぐ目的がありました。これはベンチマーク時にテストを実行してしまうと、テストでキャッシュされる関数群の数が、キャッシュへのアクセス時間のオーバーヘッドとして顕著に現れるので、それを回避するためです。私の手元の計測では、mapにおよそ10個の要素があると、30ns/op ほど余計にかかっていました。
今後の展望
現在の関数オブジェクト方式は、一見エレガントに見えるので好きなのですが、諸々を考慮すると ほぼ詰み と考えられます。
一方ソースコードの書き換え方式は、リリース間近の golang 1.4 で導入される generate を用いることで、まだまだ面白い展開が考えられるのではないかと期待しています。