Mac の wc と go-wc を比較する

go-wc_bench1.md

Mac の wc と比較する

対象

• wc: Mac OS X El Capitan には入っているもの
• go-wc: https://github.com/takatoshiono/go-wc/blob/cea7defc2cfe0d148f7df23fe6c6e104c68eedc2/go-wc.go

ベンチスクリプト

#!/bin/sh

COMMAND=$1
FILE=$2
MAX=$3
for i in `seq 1 $MAX`; do
    $COMMAND $FILE >/dev/null
done

vimrc (約3.4KB)

https://github.com/takatoshiono/dotfiles/blob/master/vimrc

だいたい倍遅い

➜  bench-go-wc  time ./bench.sh wc vimrc 1000
./bench.sh wc vimrc 1000  0.78s user 1.13s system 75% cpu 2.528 total
➜  bench-go-wc  time ./bench.sh wc vimrc 1000
./bench.sh wc vimrc 1000  0.79s user 1.14s system 76% cpu 2.515 total
➜  bench-go-wc  time ./bench.sh wc vimrc 1000
./bench.sh wc vimrc 1000  0.79s user 1.16s system 76% cpu 2.535 total
➜  bench-go-wc  time ./bench.sh go-wc vimrc 1000
./bench.sh go-wc vimrc 1000  0.77s user 2.53s system 65% cpu 5.051 total
➜  bench-go-wc  time ./bench.sh go-wc vimrc 1000
./bench.sh go-wc vimrc 1000  0.77s user 2.52s system 65% cpu 5.049 total
➜  bench-go-wc  time ./bench.sh go-wc vimrc 1000
./bench.sh go-wc vimrc 1000  0.78s user 2.53s system 65% cpu 5.063 total

MySQLダンプファイル (約416M)

5倍くらい遅いし、実行中にメモリを900Mくらい使っていた。

➜  bench-go-wc  time ./bench.sh wc dump.sql 10
./bench.sh wc dump.sql 10  17.29s user 0.67s system 99% cpu 18.040 total
➜  bench-go-wc  time ./bench.sh go-wc dump.sql 10
./bench.sh go-wc dump.sql 10  91.87s user 4.01s system 104% cpu 1:31.42 total

メモリ消費量を少なくするために1バイトずつ読んでみたらもっと遅くなった。
特に大きいファイルだと遅い。遅すぎて途中で実行中断した。

➜  bench-go-wc  time ./bench.sh go-wc vimrc 1000
./bench.sh go-wc vimrc 1000  1.13s user 2.69s system 68% cpu 5.560 total
➜  bench-go-wc  time ./bench.sh go-wc vimrc 1000
./bench.sh go-wc vimrc 1000  1.13s user 2.69s system 69% cpu 5.525 total
➜  bench-go-wc  time ./bench.sh go-wc dump.sql 10
^C
./bench.sh go-wc dump.sql 10  515.87s user 5.46s system 107% cpu 8:02.82 total

https://github.com/takatoshiono/go-wc/blob/cabe08af93dbf2363d869bf4c5b9cd2f8acb3bfa/go-wc.go

4KBずつ読むようにしてみた。全然速くならない。

➜  bench-go-wc  time ./bench.sh go-wc vimrc 1000
./bench.sh go-wc vimrc 1000  0.77s user 2.55s system 65% cpu 5.058 total
➜  bench-go-wc  time ./bench.sh go-wc vimrc 1000
./bench.sh go-wc vimrc 1000  0.81s user 2.92s system 63% cpu 5.837 total
➜  bench-go-wc  time ./bench.sh go-wc vimrc 1000
./bench.sh go-wc vimrc 1000  0.80s user 2.90s system 64% cpu 5.713 total
➜  bench-go-wc  time ./bench.sh go-wc dump.sql 1
./bench.sh go-wc dump.sql 1  9.21s user 0.31s system 97% cpu 9.778 total
➜  bench-go-wc  time ./bench.sh go-wc dump.sql 1
./bench.sh go-wc dump.sql 1  8.94s user 0.17s system 100% cpu 9.022 total
➜  bench-go-wc  time ./bench.sh go-wc dump.sql 10
./bench.sh go-wc dump.sql 10  93.72s user 2.30s system 98% cpu 1:37.34 total

https://github.com/takatoshiono/go-wc/blob/fd6de5797cb1bc0f2911377a588402389011fe4a/go-wc.go

プロファイルした
https://gist.github.com/takatoshiono/380ac28d90383638a36ba4a8a6365b7a

(syscallに時間がかかってるぽいがよく分からない)

結局、コードをコメントアウトしながら実行したらwords countが遅いとわかった。

len(bytes.Fields(bytesRead))

dump.sqlを数えるとき、

• words count なし: 0.79s
• words count あり: 9.7s

wcが1.8sくらいなので1sでword countできれば嬉しい

正しい結果は得られないけどSplitだと2.2sくらい

len(bytes.Split(bytesRead, []byte{' '}))

bytes.Fieldsの実装を参考にしてcountだけするコードを書けばよさそう。bytes.Fieldsは区切った単語のスライスも作ってるけど今回は数だけわかればいいので。

やってみた。
takatoshiono/go-wc@f998ed1

小さいファイルだと変わらないけど、大きいファイルだと倍くらい早い。でも wc より全然遅い。

➜  bench-go-wc  time ./bench.sh go-wc vimrc 1000
./bench.sh go-wc vimrc 1000  0.73s user 2.52s system 65% cpu 4.982 total
➜  bench-go-wc  time ./bench.sh go-wc vimrc 1000
./bench.sh go-wc vimrc 1000  0.77s user 2.89s system 65% cpu 5.617 total
➜  bench-go-wc  time ./bench.sh go-wc vimrc 1000
./bench.sh go-wc vimrc 1000  0.73s user 2.52s system 65% cpu 4.983 total
➜  bench-go-wc  time ./bench.sh go-wc dump.sql 10
./bench.sh go-wc dump.sql 10  44.01s user 1.56s system 99% cpu 45.631 total
➜  bench-go-wc  time ./bench.sh go-wc dump.sql 10
./bench.sh go-wc dump.sql 10  43.70s user 1.53s system 100% cpu 45.064 total

ボトルネック判明

diff --git a/go-wc.go b/go-wc.go
index 71ef543..930247b 100644
--- a/go-wc.go
+++ b/go-wc.go
@@ -51,6 +51,9 @@ func (c *Counter) Count(r io.Reader) (bool, error) {
        c.lines += bytes.Count(bytesRead, []byte{'\n'})
        c.bytes += n

+       // ここが遅い
+       // 次の空行まで全部コメントアウトするとwcの10倍速くなる
+       // またDecodeRuneをやめて1byteずつ見ていくとwcよりちょっと遅いくらいになる
        // len(bytes.Fields(bytesRead)) だと遅いので `bytes.Fields` の前半部分を真似してカウントする
        inField := false
        for i := 0; i < len(bytesRead); {

ちなみに wc は mbrtowc というのを使って1文字読んでいた。

ボトルネックの部分を goroutine にしてみたら、大きいファイルで効果があった。小さいファイルだと意味がない。
ただCPUをその分たくさん使ってるので、ずるしてる感じはする。
takatoshiono/go-wc@5cb8d78

➜  bench-go-wc  time ./bench.sh go-wc vimrc 1000
./bench.sh go-wc vimrc 1000  0.76s user 2.82s system 65% cpu 5.429 total
➜  bench-go-wc  time ./bench.sh go-wc vimrc 1000
./bench.sh go-wc vimrc 1000  0.75s user 2.78s system 66% cpu 5.316 total
➜  bench-go-wc  time ./bench.sh go-wc dump.sql 10
./bench.sh go-wc dump.sql 10  79.22s user 2.29s system 350% cpu 23.275 total
➜  bench-go-wc  time ./bench.sh go-wc dump.sql 10
./bench.sh go-wc dump.sql 10  81.62s user 2.57s system 340% cpu 24.744 total

ちなみに wc はもうちょっと速い。

➜  bench-go-wc  time ./bench.sh wc dump.sql 10
./bench.sh wc dump.sql 10  17.49s user 0.70s system 99% cpu 18.366 total