golang
Go のライトバリアに関するバグを修正した話
Goのランタイムのバグを踏んで解決しました。解決までの過程を記事にします。
同じようなランタイムのバグを踏んで、小さい再現コードを作れない場合の参考にしてください。
自分のプログラムを疑う
あるSlackチャンネルで Go で書かれたサーバーのクラッシュが話題になっているのを見つけました。その時に共有してもらったトレースバックです。
runtime: pointer 0xc007b8af97 to unused region of span span.base()=0xc004000000 span.limit=0xc004002000 span.state=1
fatal error: found bad pointer in Go heap (incorrect use of unsafe or cgo?)
runtime stack:
runtime.throw(0xc046ca, 0x3e)
/usr/local/Cellar/go/1.11.2/libexec/src/runtime/panic.go:608 +0x72 fp=0xc0001dff00 sp=0xc0001dfed0 pc=0x42bf02
runtime.findObject(0xc007b8af97, 0x0, 0x0, 0xc005eb4780, 0x7f3d1915b7b8, 0x5)
/usr/local/Cellar/go/1.11.2/libexec/src/runtime/mbitmap.go:399 +0x3b6 fp=0xc0001dff50 sp=0xc0001dff00 pc=0x413bf6
runtime.wbBufFlush1(0xc000047900)
(長いバージョン)
エラーメッセージに "incorrect use of unsafe or cgo?" って言われてるので、まずはそれを疑います。
cgoは使っていませんでした。 unsafe は使わないようにビルドするのは大変なので、コードをチェックアウトして怪しいところを探します。 プロジェクトのコードには見当たりません。vendoringしているコードにはたくさんありますが、このプログラムで実際に利用されてそうな部分で怪しいものはありませんでした。
また、 race はすでに疑っていて、 -race オプション付きで見つけたレースコンディションを全て潰したあとだったようです。
これでランタイムバグの可能性が高くなってきました。
修正済みバグの可能性と、最近のリグレッションの可能性を調べるため、Go 1.11.4 と Go 1.10.5 で試してもらいました。 1.11.4 ですぐに再現し、 1.10.5 では再現しなかったそうです。 もちろん再現確率が違うだけの可能性も残ってるので、リグレッションだと確定したわけではありません。
Goのデバッグ機能を利用して原因特定を試みる
時系列的には上と同時になりますが、Goが標準で持っているデバッグ機能をつかって原因特定できないか試行錯誤をします。
まず大事なのは、スタックトレースとコードを読みクラッシュした状況を理解することです。
今回のケースは、ライトバリアの実装の中で（性能のために）一旦バッファリングしていたポインタを処理する前に有効な（ヒープ内を指している）ポインタかどうかチェックしている箇所で、無効なポインタを見つけたというものです。
悪いポインタがバッファの中から見つかっているために、そのポインタがどの変数に書かれていたのかとか、どのコードによって書かれたのかがわかりません。そこで試してもらったのが、 GODEBUG 環境変数のうち invalidptr=0 と GODEBUG=gcstoptheworld=1 です。
invalidptr=0 を使うと、このポインタのチェックがなくなります。それでクラッシュしなくなれば、問題解決に時間がかかったときのワークアラウンドになります。クラッシュすれば、今度はその悪いポインタが入っている変数を特定するヒントが得られる可能性が高いです。
gcstoptheworld=1 はコンカレントGC自体を無効にするもので、ライトバリアが使われなくなるので同じく悪いポインタを利用している箇所の近くでクラッシュすることが期待できます。
結果として、どちらのオプションを使ってもクラッシュしなくなりました。ここまでの状況を整理した上で、一旦バグ報告しておきました。
https://github.com/golang/go/issues/29362
ローカルでの再現できるようにする
そろそろ手詰まり感が出てきました。腰を落ち着けて、自分で自由に使える再現環境を作ります。
docker-compose を使った開発環境構築手順を教えてもらい、現象を再現できるようになるまで試験環境との差異を調べて減らしていきます。ログの量を同じにしたところで、１日に数回クラッシュをさせられるようになりました。
反省点として、これは手詰まりになる前にさっさとやっておくべきでした。
print & throw デバッグ
runtime.wbBufFlush1 はライトバリア・バッファの中のポインタを処理する関数なので、ライトバリア・バッファにポインタを書き込む場所を探します。 runtime/mwbbuf.go はたった311行の小さいコードなので、すぐに (*wbBuf).putFast() という関数が見つかりました。ここに、 fatal error の原因になっているチェックと throw を仕込んでみます。
runtime: bad pinter: 0xc007435e93
fatal error: XXXXXX
runtime stack:
runtime.throw(0xbeaeb3, 0x6)
/home/ubuntu/local/go/src/runtime/panic.go:608 +0x72
runtime.(*wbBuf).putFast(0xc00003b290, 0xc007435e93, 0xc007435e93, 0x7f4b766b6d88)
/home/ubuntu/local/go/src/runtime/mwbbuf.go:143 +0x1f8
runtime.bulkBarrierBitmap(0xc0038a6fd8, 0xc0038a6fd8, 0x8, 0x0, 0xc19258)
/home/ubuntu/local/go/src/runtime/mbitmap.go:682 +0x12d
runtime.newproc1(0xc194f0, 0xc0002c8708, 0x8, 0xc00222e780, 0x7f1edd)
/home/ubuntu/local/go/src/runtime/proc.go:3373 +0x441
runtime.newproc.func1()
/home/ubuntu/local/go/src/runtime/proc.go:3309 +0x4f
runtime.systemstack(0x0)
/home/ubuntu/local/go/src/runtime/asm_amd64.s:351 +0x66
runtime.mstart()
/home/ubuntu/local/go/src/runtime/proc.go:1229
goroutine 66219 [running]:
runtime.systemstack_switch()
/home/ubuntu/local/go/src/runtime/asm_amd64.s:311 fp=0xc0002c86b0 sp=0xc0002c86a8 pc=0x45bb70
runtime.newproc(0xc000000008, 0xc194f0)
/home/ubuntu/local/go/src/runtime/proc.go:3308 +0x6e fp=0xc0002c86f8 sp=0xc0002c86b0 pc=0x43750e
XXX/game/connection.Keep(0x7435e93)
これで、プロジェクトの connection.Keep 関数から runtime.newproc が呼び出され、そこから bad pointer がライトバリア・バッファに書き込まれていることがわかります。
また、よくみてみると、 bad pointer の壊れている下位バイトが、 Keep 関数の引数と完全に一致していますね。
throw を仕込む前の完全なスタックダンプ（クラッシュしたgoroutine以外の全部のgoroutineが、引数付きで書き出される）を見直してみると、さらに面白い事がわかりました。
runtime: pointer 0xc00659e432 to unused region of span span.base()=0xc004000000 span.limit=0xc004001f80 span.state=1
fatal error: found bad pointer in Go heap (incorrect use of unsafe or cgo?)
runtime stack:
runtime.throw(0xc0f417, 0x3e)
/home/ubuntu/local/go/src/runtime/panic.go:608 +0x72 fp=0x7ff10e99fd98 sp=0x7ff10e99fd68 pc=0x42dec2
runtime.findObject(0xc00659e432, 0x0, 0x0, 0xc004ab0180, 0x7ff10d5f3e70, 0x1)
...
goroutine 29115 [runnable]:
XXX/game/connection.Keep.func1(0xc00659e432)
XXX/game/connection/connection.go:22 fp=0xc0044a97d8 sp=0xc0044a97d0 pc=0x7f1ff0
runtime.goexit()
/home/ubuntu/local/go/src/runtime/asm_amd64.s:1333 +0x1 fp=0xc0044a97e0 sp=0xc0044a97d8 pc=0x45dc51
created by XXX/game/connection.Keep
XXX/game/connection/connection.go:22 +0x3d
bad pointer のアドレスと Keep.func1 の引数が完全に一致しています。 Keep 関数のコードを見てみましょう。
func Keep(playerID int32) {
go func() { // この無名関数が Keep.func1
err := updateAliveTime(playerID)
if err != nil {
logger.Errorf("Failed to keep connection. err=[%v]", err)
}
}()
}
なんとなく、スタックに残っていたポインタ (64bit) の下位 32bit を int32 の変数で上書きして bad pointer が生成されてそうなのがわかります。とはいえ、 int32 の変数がある場所をポインタとして扱っているのはコンパイラかランタイムのどちらかのバグのはずです。
ここまで追い詰めたら、この部分に詳しい人ならすぐに解析できるでしょう。一旦ここまでをまとめて報告しておきます。
コードリーディング＆バグ修正
ここまでくれば待っていても誰かが直してくれると思いますが、クリスマスを過ぎてしまって欧米の開発者は holiday に入ってしまっている時期だし、何より楽しいので、 newproc ... putFast までのコードを読んでいきます。
newproc1 が新しい goroutine のための G オブジェクトを用意し、親 goroutine のスタックから新しい goroutine のスタックに最初の関数の引数をコピーした上で、ライトバリアが有効なら bulkBarrierBitmap を呼び出しています。 bulkBarrierBitmap は渡されたビットマップを使ってメモリ中のポインタをライトバリア・バッファに putFast していきます。
本来なら、 Keep.func1 の引数は（クロージャ変数の） playerID int32 一つだけなので、 putFast が呼び出されるはずがありません。 bulkBarrierBitmap の呼び出しの前に print を仕込んでビットマップの内容を表示してみます。すると、 Keep.func1 は引数の長さが１ワードなのに、引数のビットマップは長さが 0 になっていました。
このスタック用のビットマップに関連するコードを読んでみると、該当するスタックの中にポインタが１つもない時は空のビットマップが使われるようでした。なので、 bulkBarrierBitmap はオーバーランして別のデータ（多分実行バイナリ上で隣に配置された別のビットマップ）を参照してしまい、int32 の変数が入っている箇所を間違えて処理しているようです。
bulkBarrierBitmap を呼び出す前にビットマップの長さが 0 でないかテストする事で問題が解消することを確認し、報告しました。
https://github.com/golang/go/issues/29362#issuecomment-449964832
パッチ送信＆再現コード作成
runtime の他の場所で似たことをしている場所を探し、自分の書いた if 文が他の場所と(> 0 か != 0 かのスタイルまで)同一であることを確認した上で、 Gerrit にパッチを送信します。
https://go-review.googlesource.com/c/go/+/155779
また、レビューアーが確認できるように、クラッシュの小さい再現コードも作ってみます。ライトバリアが常に有効になるように、ヒープ上にポインタ変数をたくさん作った上で runtime.GC() をループで呼び出します。また、スタック上に残っていたゴミポインタと int32 の値の合体で偶然 bad pointer を作るのでなく、意図的に bad pointer を作った上で、それを整数型の引数として関数を呼び出します。
残る再現条件は、長さ0のビットマップをオーバーランしたときにたまたまその場所のビットが1になっていることなのですが、この条件は Go プログラムで意図的に作り出すことが難しい。確率を上げるためにとりあえず引数を１つではなく４つにしてみたら、あっさり再現できました。
https://gist.github.com/methane/b61dcfb504d54de5bced1c6e3209a91d
理想的にはこの再現コードをリグレッション・テストに落とし込むなり、 newproc1 に対するユニットテストが書ければ完璧なのですが、この辺は Go のプログラムから直接呼び出されるのではなく Go コンパイラが呼び出しコードを生成する部分でテストが難しいので今後レビューアーと相談します。
@methane
Re: Configuring sql.DB for Better Performance
Configuring sql.DB for Better Performance という記事を知りました。 コネクションプールの大きさを制御する3つの設定を丁寧に解説されたとても良い記事です。
しかし、この記事で推奨されている設定については同意することができません。私が推奨する設定とその理由を解説していきたいと思います。
Limit ConnMaxLifetime instead of MaxIdleConns
Allowing just 1 idle connection to be retained and reused makes a massive difference to this particular benchmark — it cuts the average runtime by about 8 times and reduces memory usage by about 20 times. Going on to increase the size of the idle connection pool makes the performance even better, although the improvements are less pronounced.
この、 "to this particular benchmark" というのが問題です。このベンチマークでは、8並列で常にDBにクエリを投げ続けています。1つのクエリが終了するとすぐに次のクエリを投げるので、 DB.SetMaxIdleConns(1) で大きな効果が現れました。
このベンチマークの動作は、例えばDBに大量のデータを挿入するバッチ処理などに当てはまりますが、Web アプリケーションなどには当てはまりません。
1秒間に1000回クエリを実行するアプリケーションを想定した簡単なシミュレータを書いてみました。クエリは一様分布でランダムなタイミングで実行され、各クエリと新規接続には10msかかるとします。 (このシミュレータのgist)
MaxOpenConns(20) の時、 MaxIdleConns(4) と MaxIdleConns(10) の動作を比べてみましょう。オレンジの線は総接続数、青い線は使用中の接続数、緑の線は接続が利用可能になるのを待っている時間の最大値をミリ秒で表しています。
1000回のクエリを実行するのに、 MaxIdleConns(4) だと 285 回接続していますが、 MaxIdleConns(10) だとそれを 69 回まで減らすことができています。一方で、負荷が止まった後もずっと維持し続ける接続も増えてしまっています。
今度は SetMaxIdleConns(100); SetConnMaxLifetime(time.MilliSecond * 300) のシミュレーション結果を見てください。
20x4=80 回の接続をしています。 MaxIdleConns(10) のときの 69 回よりも多いですが、これは動作をわかりやすくするために lifetime を短く設定しているためです。シミュレーション時間を100秒に伸ばしたら、MaxIdleConns(10) の場合では接続回数はおよそ 690 回になり、 SetConnMaxLifetime(time.Second * 30) の場合の接続回数は 80 回になるでしょう。
このグラフで、再接続が特定のタイミングに集中し、そのタイミングでレイテンシが伸びてしまっているのが気になるかもしれません。これはシミュレーションが完全に一様分布になっていて、最初に全ての接続がほぼ同時に作られてしまっているからです。時間によって負荷が変動するアプリケーションでは、接続が作られるタイミングがもっと分散するので、このスパイクは発生しにくいはずです。次のグラフは、200msかけて段階的に負荷が増えた後に、上のグラフと同じ1000msの負荷がかかったときのものです。
SetConnMaxLifetime を使う他の理由
DB.SetConnMaxLifetime() を提案し実装したのは私です。このAPIはアイドルな接続を減らす SetMaxIdleConns() よりも良い方法ですが、それだけではありません。
"Configuring sql.DB for Better Performance" で紹介されたとおり、 MySQL では wait_timeout という設定で接続がサーバーから切られる恐れがあります。また、OSやルーターが長時間利用されていないTCP接続を切断することもあります。どのケースでも、 go-sql-driver/mysql はクエリを送信した後、レスポンスを受信しようとして初めてTCPが切断されたことを知ります。切断を検知するのに何十秒もかかるかもしれませんし、送信したクエリが実行されたかどうかを知ることもできないので安全なリトライもできません。
こういった危険をなるべく避けるためには、長時間使われていなかった接続を再利用せずに切断し、新しい接続を使うべきです。 SetConnMaxLifetime() は接続の寿命を設定するAPIですが、寿命を10秒に設定しておけば、10秒使われていなかった接続を再利用することもありません。
接続の寿命を設定することで、他にも幾つかの問題に対処することができます。
- DBサーバーがロードバランスされているとき、サーバーの増減をしやすくする
- DBサーバーのフェイルオーバーをしやすくする
- MySQL でオンラインで設定変更したとき、古い設定で動作するコネクションが残り続けないようにする
接続のアイドル時間を制限するAPIを別に追加しなかったのは、現実的な環境における性能への影響と、 sql.DB の実装の複雑さを天秤にかけた結果です。
推奨する sql.DB の設定
- SetMaxOpenConns() は必ず設定する。負荷が高くなってDBの応答が遅くなったとき、新規接続してさらにクエリを投げないようにするため。できれば負荷試験をして最大のスループットを発揮する最低限のコネクション数を設定するのが良いが、負荷試験をできない場合も
max_connectionやコア数からある程度妥当な値を判断するべき。 - SetMaxIdleConns() は SetMaxOpenConns() 以上に設定する。アイドルな接続の解放は SetConnMaxLifetime に任せる。
- SetConnMaxLifetime() は最大接続数 × 1秒 程度に設定する。多くの環境で1秒に1回接続する程度の負荷は問題にならない。1時間以上に設定したい場合はインフラ／ネットワークエンジニアによく相談すること。
@methane
ISUCON6予選をトップ通過しました
@methane です。「この技術部には問題がある！」というチーム名で @kizkoh (インフラ担当), @mecha_g3 (アプリ担当) とともに ISUCON 6 に参戦し、予選をトップスコアで通過しました。 恒例のふりかえり記事を書きます。
ふりかえり
残念ながらスコアは記録してないのですが、時系列順にやったことをまとめます。 アプリのコードは methane/isu6q-app で公開しているので、興味がある方はコードを確認してください。
strings.Replacer を使う
使用言語は最初から Go と決めていたのですが、Goの初期実装は遅すぎてタイムアウトで最初からスコア無しでした。 top でアプリのCPUが支配的なのはすぐ判りましたし、コードを読めばなにが遅いのかも一発で判りました。そんなに長くないので関数全体を張ります。
func htmlify(w http.ResponseWriter, r *http.Request, content string) string {
if content == "" {
return ""
}
rows, err := db.Query(`
SELECT * FROM entry ORDER BY CHARACTER_LENGTH(keyword) DESC
`)
panicIf(err)
entries := make([]*Entry, 0, 500)
for rows.Next() {
e := Entry{}
err := rows.Scan(&e.ID, &e.AuthorID, &e.Keyword, &e.Description, &e.UpdatedAt, &e.CreatedAt)
panicIf(err)
entries = append(entries, &e)
}
rows.Close()
keywords := make([]string, 0, 500)
for _, entry := range entries {
keywords = append(keywords, regexp.QuoteMeta(entry.Keyword))
}
re := regexp.MustCompile("("+strings.Join(keywords, "|")+")")
kw2sha := make(map[string]string)
content = re.ReplaceAllStringFunc(content, func(kw string) string {
kw2sha[kw] = "isuda_" + fmt.Sprintf("%x", sha1.Sum([]byte(kw)))
return kw2sha[kw]
})
content = html.EscapeString(content)
for kw, hash := range kw2sha {
u, err := r.URL.Parse(baseUrl.String()+"/keyword/" + pathURIEscape(kw))
panicIf(err)
link := fmt.Sprintf("<a href=\"%s\">%s</a>", u, html.EscapeString(kw))
content = strings.Replace(content, hash, link, -1)
}
return strings.Replace(content, "\n", "<br />\n", -1)
}
今回の問題ははてなキーワード＋はてなスターのようなサービスで、この関数はキーワードの紹介記事に対して他のキーワードへのリンクを生成しつつHTMLエスケープするものです。キーワードは文字数順でソートしているので、最長一致でリンクになります。
キーワードからリンクへの変換が一発でされていないのは、先に変換するとHTMLエスケープで <a> タグまでエスケープされてしまうし、逆に先にHTMLエスケープをするとキーワードを見つけられなくなるからです。（一度これに気づかず一気に変換するようにしてハマりました）
正規表現のビルドと置換のどちらがどれくらいの割合で重いのかまではまだプロファイルを始めてなかったのでわかりませんが、初手からGoらしい最適化を始めてみます。
まずGoの正規表現は遅いので strings.Replacer を使ってキーワードからリンクへの変換をします。 Replacer を構築するのにも時間がかかるので、 htmlify() という関数で毎回構築するのではなく、起動時と、キーワードの追加削除時に再構築をするようにします。（実際にはすでに存在するキーワードの記事に対する修正のケースを見逃していて無駄に再構築していました。これに気づいていたらもっとスコア上がったはず…）
var (
mKwControl sync.Mutex
kwdList KeywordArray
mKwReplacer sync.RWMutex
kwReplacer1st, kwReplacer2nd *strings.Replacer
)
func updateReplacer() {
reps1 := make([]string, 0, len(kwdList)*2)
reps2 := make([]string, 0, len(kwdList)*2)
for i, k := range kwdList {
if k.holder == "" {
k.holder = fmt.Sprintf("isuda_%x", sha1.Sum([]byte(k.Key)))
kwdList[i].holder = k.holder
}
reps1 = append(reps1, k.Key)
reps1 = append(reps1, k.holder)
reps2 = append(reps2, k.holder)
reps2 = append(reps2, k.Link)
}
r1 := strings.NewReplacer(reps1...)
r2 := strings.NewReplacer(reps2...)
mKwReplacer.Lock()
kwReplacer1st = r1
kwReplacer2nd = r2
mKwReplacer.Unlock()
}
func AddKeyword(key, link string) {
k := Keyword{Key: key, Link: link}
mKwControl.Lock()
kwdList = append(kwdList, k)
sort.Sort(kwdList)
updateReplacer()
mKwControl.Unlock()
}
func ReplaceKeyword(c string) string {
mKwReplacer.RLock()
r1 := kwReplacer1st
r2 := kwReplacer2nd
mKwReplacer.RUnlock()
x := r1.Replace(c)
x = html.EscapeString(x)
return r2.Replace(x)
}
AddKeyword はキーワードをポストしたときに、 ReplaceKeyword は htmlify から呼ばれます。これで NewReplacer を呼び出す回数を大幅に削減することができました。
この変更を投入するタイミングで、 MySQL に接続するときに '127.0.0.1' からの接続が許可されていないというエラーがでるようになって（何もしてないのに壊れた追記: 秘伝のタレでskip-name-resolveが入ったのが原因の模様） Unix Domain Socket を使うようにしました。
@kizkoh による nginx や MySQL の設定 (静的ファイルを nginx で返す等) や、初期実装にあったバグを潰したりして、14:00すぎに12万点を出しました。
isutar を isuda にマージ
これは @mecha_g3 に任せた部分です。 isutar と isuda がお互いにJSON APIを使ってやり取りをしている部分があって、2つのアプリとMySQLが1台のマシンに乗っている以上完全に無駄なので全部1つにまとめました。スコアを記録してないのですが順当に性能アップしたはずです。
これを投入してベンチをかけるときにハマったのが、DBコネクションのデッドロックです。もともと2コアの1台のマシンなので、DBへの接続は4本も要らないだろうと思いつつ、念のために8本にしていました。ところが、次のようなコードが原因で8本あっても足りなくなってしまいました。
rows, err := db.Query(fmt.Sprintf(
"SELECT * FROM entry ORDER BY updated_at DESC LIMIT %d OFFSET %d",
perPage, perPage*(page-1),
))
if err != nil && err != sql.ErrNoRows {
panicIf(err)
}
entries := make([]*Entry, 0, 10)
for rows.Next() {
e := Entry{}
err := rows.Scan(&e.ID, &e.AuthorID, &e.Keyword, &e.Description, &e.UpdatedAt, &e.CreatedAt)
panicIf(err)
e.Html = htmlify(w, r, e.Description)
e.Stars = loadStars(e.Keyword)
entries = append(entries, &e)
}
rows.Close()
このコードはトップページのハンドラーの一部です。 for rows.Next() ループが終了して rows.Close() が呼ばれるまでDBの接続を握るのですが、このループ中の loadStars(e.Keyword) の部分が中でさらにSQLを呼び出しています。
この状態で、 top ページに8個並列でアクセスが来てループの外側のクエリを実行すると、8本の接続を使い切った状態になり、どの goroutine も内側の loadStars() でDB接続を無限に待ってしまうことになります。
落ち着いて考えればすごく当たり前のことなのですが、最初は rows.Close() を呼んでない場所がどこかにあるんじゃないかと探し回ったり、この形のネストがまずいことに気づいたときも「でも1goroutineあたりのDB接続数が2倍になるだけだから、その程度の余裕は見込んで8本にしたんだけどなあ。」と考えてしまったりしてしまいました。
結果、この問題の対策もちゃんとネストを潰すのではなく、単にコネクションプールの数を倍の16に増やしただけです。ベンチマーカーがどんどん並列度上げてくるタイプだったらこれでも死んでました。
教訓として、 rows.Next() ループ内でネストしてクエリを実行するのは単に必要な接続数が倍になる以上の凶悪さを持っているので、 rows.Close() までの処理は単純にクエリ結果のフェッチだけにしましょう。
Replacer の構築を zero time cache 化
プロファイルを取ってみたところまだ Replacer の構築が重いので、個人的に zero time cache と呼んでいるイディオムを使って安全にキャッシュをしてみます。次のコードを見てください。
var (
mKwControl sync.Mutex
kwdList KeywordArray
mUpdateReplacer sync.Mutex
repLastUpdated time.Time
)
func AddKeyword(key, link string) {
k := Keyword{Key: key, Link: link}
mKwControl.Lock()
kwdList = append(kwdList, k)
mKwControl.Unlock()
updateReplacer()
}
func updateReplacer() {
now := time.Now()
mUpdateReplacer.Lock()
defer mUpdateReplacer.Unlock()
if repLastUpdated.After(now) {
return
}
repLastUpdated = time.Now()
reps1 := make([]string, 0, len(kwdList)*2)
reps2 := make([]string, 0, len(kwdList)*2)
mKwControl.Lock()
kws := kwdList[:]
mKwControl.Unlock()
sort.Sort(kws)
// ... 以降 Replacer の構築処理
}
mUpdateReplacer と repLastUpdated が追加した変数で、 updateReplacer() の repLastUpdated = time.Now() までがイディオムになっています。
例えば、キーワードA, B, C がほぼ同時に追加されたとします。
- まずAが最初にロックを取得して、
repLastUpdated = time.Now()を実行して Replacer の構築を始めます。 - 続いてキーワードBとCがともに
mUpdateReplacer.Lock()で停止します。ロック直前に取得したnowは (1) で更新したrepLastUpdatedよりも未来の時間になります。 - キーワードAの Replacer 更新が終了し、
mUpdateReplacerが開放されます。キーワードBを処理していた goroutine がそのロックを取得します。 - ロック取得前に取得した
nowがrepLastUpdatedよりも新しいので、if repLastUpdated.After(now)が真になりません。なので Replacer を再構築します。キーワードAを更新したときのkwdListにキーワードBは入っていなかった（厳密にはタイミング依存で入っていた可能性もある）ので、これは必要な処理です。 - さらにキーワードBの Replacer 更新が終わり、キーワードCが
mUpdateReplacerのロックを取得します。今度はif repLastUpdated.After(now)が真になるので、 Replacer の再構築はスキップされます。 (4) で Replacer を再構築したときには確実にキーワードCもkwdListに入っていたので、スキップしても安全です。
この説明を一度読んだだけでは理解できないかもしれませんが、ぜひじっくりとコードと見比べて理解してみてください。 このイディオムはISUCONだけではなく、実際にGoで高性能なサーバーを書くときに大変便利です。
また、例えば MySQL が複数のトランザクションを一度の fsync でコミットするグループコミットなど、「同時に実行される重い処理をバッチ化する」というのは並列処理のデザインパターンと呼んでも良いくらい汎用的だと思うのですが、どなたかこのパターンの名前をご存知でしたら @methane 宛の Tweet などで教えてください。
仕上げ
まだ top ページのハンドラーが重かったので、再び zero time cache パターンを使ってさらにトップページの内容の取得を効率化します。
ただしこのときは効率より実装の手早さを優先して、 zero time cache パターンをトップページのハンドラ内に直接実装してしまいました。着実には性能向上しましたが、これもキーワードの更新側に処理を持っていけばもっと劇的な性能向上が見込めたはずです。
最後に、アプリの環境変数で GOGC=400 を設定し、プロファイルやモニタリングやnginxのアクセスログを切り、ベストスコアを出すまで enqueue を数回実行して終了しました。
考察
POST /keyword のアクセスがキーワードの追加だけではなく更新にも使われていることを見逃していて、一番重い Replacer の再構築を必要以上に実行してしまっていたのが悔やまれます。
また、上に書いたようにトップページの内容の更新も、 GET / ではなく POST /keyword で行えばもっと劇的なスコアアップができたでしょう。
さらに、非ログインユーザーのトップページを静的ファイルに書き出してしまって nginx に直接返させるのも、ISUCONで頻出の攻略法で事前に判っていたはずで、実装する時間もあったはずなのにやるタイミングを逸してしまいました。
これらを全部できていれば、ベンチマーカーの実装次第ですが、倍の50万点の可能性もあったかもしれません。
感想
今までは毎年予選は一人で戦って勝ち抜いてきたのですが、去年の予選のボリュームが本戦と同じくらいあってキツかったので、今年は予選からチームで戦うことにしました。
「直したはずのバグがこっちのブランチでは直ってなかった」「プロファイルが違う場所のバイナリ／ソースを参照してたかもしれなくてくてアテにならない」系のトラブルはあったものの、自分がアプリを書くときに心配事を忘れて集中できたり、逆に実装を任せてる間に自分は休憩したり落ち着いて見直しをしたりできて、精神的な負荷が大幅に減り、余裕を持って優雅に戦えたと思います。
一方で、Azureに慣れていなかったことや、14時過ぎに取った初めての0点以外のスコアがその時点の断トツトップで、そこからもほぼずっと2位のダブルスコアをキープしていたこともあって、保守的になりすぎて全力を出し切れたとは言い難いです。
本戦では全力を出せるように、もう少しチームワーク練習や環境構築の練習を重ねて行きます。
それでは、決勝進出者のみなさん、決勝でお会いしましょう。 運営・出題者のみなさんはお疲れ様でした。決勝も引き続きお願いいたします。
pixiv private isucon 2016 攻略 (5/5)
攻略記事一覧:
ボトルネック探し
前回は一番重かったトップページにページキャッシュを導入して劇的に高速化したものの、CPU以外がボトルネックになって大した高速化はできませんでした。 こういう場合は dstat が役に立つことが多いです。
----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system-- usr sys idl wai hiq siq| read writ| recv send| in out | int csw 2 0 98 0 0 0| 596k 271k| 0 0 | 0 0 | 606 755 1 0 100 0 0 0| 0 0 | 192B 1190B| 0 0 | 119 177 0 0 100 0 0 0| 0 0 | 66B 350B| 0 0 | 103 158 1 0 98 1 0 0| 512k 0 | 537B 783B| 0 0 | 962 1035 48 7 38 3 0 5| 16M 728k|4590k 60M| 0 0 | 24k 20k 44 7 36 5 0 8| 11M 376k|6568k 71M| 0 0 | 34k 26k 44 11 35 4 0 7| 18M 312k|6190k 71M| 0 0 | 33k 27k 48 8 33 3 0 8| 14M 272k|7784k 71M| 0 0 | 31k 24k 41 7 42 4 0 6| 17M 352k|8097k 72M| 0 0 | 31k 23k 44 9 38 4 1 5| 14M 256k|8019k 71M| 0 0 | 33k 25k 44 10 35 3 0 8| 10M 448k|7705k 71M| 0 0 | 32k 25k 36 9 46 3 0 6| 14M 224k|7196k 71M| 0 0 | 32k 22k 38 10 39 6 0 7| 16M 18M|7812k 71M| 0 0 | 31k 22k 47 9 28 11 0 4| 20M 47M|6683k 72M| 0 0 | 29k 19k 45 7 39 3 0 6| 10M 696k|6113k 71M| 0 0 | 33k 24k 42 7 39 4 0 8| 12M 672k|3825k 71M| 0 0 | 33k 24k 51 8 31 3 0 6| 13M 512k|6750k 71M| 0 0 | 31k 22k 44 9 39 2 0 5|5496k 648k|8045k 71M| 0 0 | 32k 24k 53 9 28 3 0 6| 20M 544k|5832k 71M| 0 0 | 29k 20k 41 7 42 3 0 7| 14M 616k|7459k 71M| 0 0 | 35k 24k 48 9 31 4 0 8| 17M 608k|5869k 71M| 0 0 | 30k 23k 38 11 40 3 0 8| 14M 752k|8956k 71M| 0 0 | 32k 24k 44 11 36 4 0 5| 13M 576k|7181k 71M| 0 0 | 33k 25k 47 7 35 7 0 5| 14M 62M|5753k 65M| 0 0 | 30k 22k ...
net の send が 71M で張り付いてるのが目につきますね。アプリサーバーは c4.large なのでこんなもんでしょう。
ですが、 pixiv さんの Blog 記事 のスクリーンショットを見ると、多くのチームが 40k 点を超えていて、トップチームは180k点に到達しています。こっちは40k点の手前で帯域の壁にぶつかってるのに、変だぞ？ (Twitter で pixiv の @catatsuy さんに、ポータルのスコアとコマンドラインによるベンチマーカーのスコアが同一であることを確認しました。)
さて、2つ目の記事で、次のように言っていましたね。
帯域は /image/ が支配的。帯域ネックになるようだったら、画像は再圧縮しにくいので、ヘッダーを適切に設定すればクライアントに "304 Not Modified" を返せるようになって大きなブレークスルーがあるかもしれない。
試しにクライアントのキャッシュ実装に影響を与えそうなヘッダーを追加してみましょう。 "nginx 静的ファイル キャッシュ" でググってそれっぽいのを探します
upstream app {
server 127.0.0.1:8080;
keepalive 64;
}
server {
listen 80;
client_max_body_size 10m;
root /home/isucon/private_isu/webapp/public/;
location / {
try_files $uri @app;
}
location ~* \.(?:ico|css|js|gif|jpe?g|png)$ {
try_files $uri @app;
expires max;
add_header Pragma public;
add_header Cache-Control "public, must-revalidate, proxy-revalidate";
etag off;
}
location @app {
proxy_set_header Host $host;
proxy_set_header X-Real-IP $remote_addr;
proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
proxy_pass http://app;
}
}
計測してみます。
スコア:
{"pass":true,"score":182435,"success":174747,"fail":0,"messages":[]}
pixiv 社内 isucon のトップと同じくらいのスコアがでました。(これはプロファイルを取ったりいろいろしながらのスコアなので、仕上げしたらもう少し伸びるはずです)
top, dstat:
Tasks: 81 total, 3 running, 78 sleeping, 0 stopped, 0 zombie %Cpu(s): 80.7 us, 11.5 sy, 0.0 ni, 3.0 id, 0.5 wa, 0.0 hi, 4.2 si, 0.0 st KiB Mem: 1022972 total, 954144 used, 68828 free, 25432 buffers KiB Swap: 0 total, 0 used, 0 free. 557948 cached Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 1397 isucon 20 0 377096 97572 8880 S 100.5 9.5 0:27.35 app.dc4a3eaa 731 mysql 20 0 1059292 183956 10552 S 65.9 18.0 2:26.08 mysqld 1396 www-data 20 0 92088 5304 3144 R 18.6 0.5 0:04.99 nginx 1069 isucon 20 0 33140 10476 2636 S 5.7 1.0 0:12.10 tmux 308 memcache 20 0 334624 9744 2228 S 0.7 1.0 0:01.38 memcached 110 root 20 0 0 0 0 S 0.3 0.0 0:00.08 jbd2/xvda2-8 1034 root 20 0 0 0 0 S 0.3 0.0 0:02.89 kworker/1:0
----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system-- usr sys idl wai hiq siq| read writ| recv send| in out | int csw 0 0 100 0 0 0| 0 0 | 0 0 | 0 0 | 45 76 21 5 71 2 0 1| 11M 0 |1987k 12M| 0 0 |8731 9184 73 15 5 2 0 5| 17M 904k|4574k 25M| 0 0 | 19k 20k 78 13 3 1 0 6| 20M 272k|3815k 18M| 0 0 | 15k 17k 80 9 6 2 0 4| 25M 272k|7221k 20M| 0 0 | 16k 17k 81 11 4 1 0 4| 18M 272k|5953k 20M| 0 0 | 15k 16k 81 10 4 0 0 5| 24M 256k|5363k 24M| 0 0 | 15k 17k 76 13 6 2 0 4| 20M 272k|8293k 18M| 0 0 | 16k 17k 82 11 2 1 0 5| 15M 552k|2665k 18M| 0 0 | 16k 16k 80 14 3 1 0 4| 14M 408k|2870k 15M| 0 0 | 15k 16k 79 12 5 1 0 4| 16M 360k|5475k 19M| 0 0 | 17k 18k 79 11 5 2 0 3| 16M 65M|5456k 21M| 0 0 | 15k 16k 77 12 6 1 0 4| 19M 760k|6763k 23M| 0 0 | 19k 20k 79 12 4 2 0 4| 23M 592k|6824k 19M| 0 0 | 16k 17k 79 12 5 2 0 3| 11M 632k|5994k 20M| 0 0 | 16k 18k 82 11 3 1 0 4| 11M 680k|3447k 16M| 0 0 | 15k 17k 83 11 2 0 0 4| 13M 792k|5076k 18M| 0 0 | 16k 18k ...
CPUを使い切るようになったのが判ります。
access.log 集計:
Request by count 117444 GET /image/* 7987 GET / 6394 GET /js/jquery-2.2.0.js 6394 GET /css/style.css 6394 GET /js/jquery.timeago.ja.js 6394 GET /favicon.ico 6394 GET /js/jquery.timeago.js 6394 GET /js/main.js 4028 POST /login 1459 GET /login 1176 GET /posts/* 959 POST /register 958 GET /admin/banned 873 GET /@user 731 GET /logout 609 POST / 330 GET /posts?max_created_at= 268 POST /comment 1 GET /initialize Request by total time 98.996 0.299987878788 GET /posts?max_created_at= 84.66 0.0105997245524 GET / 84.077 0.0963081328751 GET /@user 52.172 0.0129523336643 POST /login 39.666 0.0337295918367 GET /posts/* 33.621 0.0552068965517 POST / 19.801 0.0738843283582 POST /comment 17.144 0.0117505140507 GET /login ... Request by out bytes 894159053 7613 GET /image/* 185613643 23239 GET / 16456443 18850 GET /@user 11202870 33948 GET /posts?max_created_at= 4098331 3484 GET /posts/* ...
image の転送量が大幅に減ったことが確認できます。また、集計せずに access.log を見ると、狙い通り 304 を返せていることが判ります。
(余談) 壁の超え方
2つ目の記事で 304 Not Modified を返せることを予想していたのは、エスパーでもなんでもありません。一昨年 (2014年) の決勝であったんです。その時はこの壁を超えられず悔しい思いをしました。
その時、壁を超えたチームが2チームありました。準優勝チームは静的ファイルを返すための nginx の設定のテンプレ（いわゆる「秘伝のタレ」）を使ったらいきなりスコアが上がったけど何が起こったのか設定した本人にも分からなかった、そして優勝チームは順優勝チームのスコアを見て「必ず壁を超える方法があるはずだ」と試行錯誤した結果壁を超えたと記憶しています。（興味がある方は当時の blog 記事を探してみてください）
「秘伝のタレ」が偶然ハマる、という壁の超え方は準備の賜物です。 個人的にはチューニングするときはパラメーターを1つ1ついじって効果確認したいところですが、それだと時間がもったいないし、ベンチマーカーの挙動についての予想が当てられないと壁が超えられないので、やはり「秘伝のタレ」は強力な武器になります。
一方、ベンチマーカーの動作を予想し試行錯誤するやり方は、問題作成側の心理を読む ISUCON 力、可能性のある試行錯誤をするための引き出し(今回でいえば HTTP ヘッダーとキャッシュに関する知識)、精神力などが求められます。 過去に決勝で優勝したチームはどれもこの能力が特に優れていたチームだと思います。難しいですが優勝を目指して勉強と鍛錬をしましょう。
雑巾絞り
CPUネックになったことですし、CPUプロファイルを見てみましょう。
(pprof) top30 -cum
7.63s of 29.87s total (25.54%)
Dropped 601 nodes (cum <= 0.15s)
Showing top 30 nodes out of 296 (cum >= 4.36s)
flat flat% sum% cum cum%
0 0% 0% 28.68s 96.02% runtime.goexit
0 0% 0% 24.58s 82.29% net/http.(*conn).serve
0 0% 0% 23.35s 78.17% net/http.(*ServeMux).ServeHTTP
0 0% 0% 23.35s 78.17% net/http.serverHandler.ServeHTTP
0 0% 0% 23.32s 78.07% github.com/zenazn/goji/web.(*Mux).ServeHTTP
0 0% 0% 23.30s 78.00% github.com/zenazn/goji/web.(*cStack).ServeHTTP
0 0% 0% 23.30s 78.00% github.com/zenazn/goji/web/middleware.RequestID.func1
0 0% 0% 23.30s 78.00% net/http.HandlerFunc.ServeHTTP
0 0% 0% 23.25s 77.84% github.com/zenazn/goji/web/middleware.Logger.func1
0 0% 0% 22.71s 76.03% github.com/zenazn/goji/web.(*mStack).newStack.func1
0.01s 0.033% 0.033% 22.71s 76.03% github.com/zenazn/goji/web.(*router).route
0 0% 0.033% 22.71s 76.03% github.com/zenazn/goji/web/middleware.AutomaticOptions.func1
0 0% 0.033% 22.71s 76.03% github.com/zenazn/goji/web/middleware.Recoverer.func1
0.01s 0.033% 0.067% 18.11s 60.63% github.com/zenazn/goji/web.netHTTPHandlerFuncWrap.ServeHTTPC
0 0% 0.067% 12.85s 43.02% main.getPosts
0 0% 0.067% 12.46s 41.71% github.com/jmoiron/sqlx.(*DB).Select
0 0% 0.067% 12.46s 41.71% github.com/jmoiron/sqlx.Select
0.07s 0.23% 0.3% 11.69s 39.14% github.com/jmoiron/sqlx.scanAll
1.72s 5.76% 6.06% 9.78s 32.74% runtime.mallocgc
0.16s 0.54% 6.60% 8.62s 28.86% runtime.systemstack
5.02s 16.81% 23.40% 7.29s 24.41% runtime.scanobject
0.15s 0.5% 23.90% 5.91s 19.79% runtime.newobject
0 0% 23.90% 5.33s 17.84% runtime.gcAssistAlloc
0 0% 23.90% 5.33s 17.84% runtime.gcAssistAlloc.func1
0.04s 0.13% 24.04% 5.33s 17.84% runtime.gcDrainN
0.04s 0.13% 24.17% 5.22s 17.48% database/sql.(*Rows).Next
0.03s 0.1% 24.27% 5.04s 16.87% github.com/go-sql-driver/mysql.(*textRows).Next
0.34s 1.14% 25.41% 5.01s 16.77% github.com/go-sql-driver/mysql.(*textRows).readRow
0 0% 25.41% 4.55s 15.23% github.com/zenazn/goji/web.handlerFuncWrap.ServeHTTPC
0.04s 0.13% 25.54% 4.36s 14.60% main.makePosts
(pprof) list getPosts
Total: 29.87s
ROUTINE ======================== main.getPosts in /home/isucon/private_isu/webapp/golang/app.go
0 12.85s (flat, cum) 43.02% of Total
. . 593: fmt.Println(terr)
. . 594: return
. . 595: }
. . 596:
. . 597: results := []Post{}
. 11.19s 598: rerr := db.Select(&results, "SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= ? ORDER BY `created_at` DESC", t.Format(ISO8601_FORMAT
))
. . 599: if rerr != nil {
. . 600: fmt.Println(rerr)
. . 601: return
. . 602: }
. . 603:
. 1.03s 604: posts, merr := makePosts(results, getCSRFToken(r), false)
. . 605: if merr != nil {
. . 606: fmt.Println(merr)
. . 607: return
. . 608: }
. . 609:
. . 610: if len(posts) == 0 {
. . 611: w.WriteHeader(http.StatusNotFound)
. . 612: return
. . 613: }
. . 614:
. . 615: fmap := template.FuncMap{
. . 616: "imageURL": imageURL,
. . 617: }
. . 618:
. . 619: template.Must(template.New("posts.html").Funcs(fmap).ParseFiles(
. 10ms 620: getTemplPath("posts.html"),
. . 621: getTemplPath("post.html"),
. 620ms 622: )).Execute(w, posts)
. . 623:}
. . 624:
. . 625:func getPostsID(c web.C, w http.ResponseWriter, r *http.Request) {
. . 626: pid, err := strconv.Atoi(c.URLParams["id"])
. . 627: if err != nil {
(pprof) list makePosts
Total: 29.87s
ROUTINE ======================== main.makePosts in /home/isucon/private_isu/webapp/golang/app.go
40ms 4.36s (flat, cum) 14.60% of Total
. . 188:}
. . 189:
. . 190:func makePosts(results []Post, CSRFToken string, allComments bool) ([]Post, error) {
. . 191: var posts []Post
. . 192:
. 20ms 193: for _, p := range results {
. 720ms 194: err := db.Get(&p.CommentCount, "SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = ?", p.ID)
. . 195: if err != nil {
. . 196: return nil, err
. . 197: }
. . 198:
. . 199: query := "SELECT * FROM `comments` WHERE `post_id` = ? ORDER BY `created_at` DESC"
. . 200: if !allComments {
. . 201: query += " LIMIT 3"
. . 202: }
. . 203: var comments []Comment
. 920ms 204: cerr := db.Select(&comments, query, p.ID)
. . 205: if cerr != nil {
. . 206: return nil, cerr
. . 207: }
. . 208:
. . 209: for i := 0; i < len(comments); i++ {
20ms 1.89s 210: uerr := db.Get(&comments[i].User, "SELECT * FROM `users` WHERE `id` = ?", comments[i].UserID)
. . 211: if uerr != nil {
. . 212: return nil, uerr
. . 213: }
. . 214: }
. . 215:
. . 216: // reverse
. . 217: for i, j := 0, len(comments)-1; i < j; i, j = i+1, j-1 {
. . 218: comments[i], comments[j] = comments[j], comments[i]
. . 219: }
. . 220:
. . 221: p.Comments = comments
. . 222:
20ms 780ms 223: perr := db.Get(&p.User, "SELECT * FROM `users` WHERE `id` = ?", p.UserID)
. . 224: if perr != nil {
. . 225: return nil, perr
. . 226: }
. . 227:
. . 228: p.CSRFToken = CSRFToken
. . 229:
. . 230: if p.User.DelFlg == 0 {
. 30ms 231: posts = append(posts, p)
. . 232: }
. . 233: if len(posts) >= postsPerPage {
. . 234: break
. . 235: }
. . 236: }
getPosts が重いのは、前に getIndex が重いのを直した時と同じく、 LIMIT すれば良さそうですね。
makePosts もクエリを投げすぎているので、 Post の取得とその User の取得は INNER JOIN で一気にする、コメント一覧はメモリ上にキャッシュしてしまうことにします。
あとテンプレートのコンパイルも事前にするようにしていきます。 Go アプリ側で出力しているログも tmux や ssh の CPU を食ってるのでそろそろ止めてしまいましょう。 (nginx のログを止めるのは一番最後です)
diff --git a/app.go b/app.go
index f246ad6..eca8413 100644
--- a/app.go
+++ b/app.go
@@ -187,54 +184,78 @@ func getFlash(w http.ResponseWriter, r *http.Request, key string) string {
}
}
-func makePosts(results []Post, CSRFToken string, allComments bool) ([]Post, error) {
- var posts []Post
+var (
+ commentM sync.Mutex
+ commentStore map[int][]Comment = make(map[int][]Comment)
+)
- for _, p := range results {
- err := db.Get(&p.CommentCount, "SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = ?", p.ID)
+func getCommentsLocked(postID int) []Comment {
+ if cs, ok := commentStore[postID]; ok {
+ return cs
+ }
+
+ var cs []Comment
+ query := ("SELECT comments.id, comments.comment, comments.created_at, users.id, users.account_name " +
+ " FROM `comments` INNER JOIN users ON comments.user_id = users.id " +
+ " WHERE `post_id` = ? ORDER BY comments.`created_at`")
+
+ rows, err := db.Query(query, postID)
+ if err != nil {
+ log.Println(err)
+ return cs
+ }
+ for rows.Next() {
+ var c Comment
+ err := rows.Scan(&c.ID, &c.Comment, &c.CreatedAt, &c.User.ID, &c.User.AccountName)
if err != nil {
- return nil, err
+ log.Println(err)
+ continue
}
+ cs = append(cs, c)
+ }
+ rows.Close()
- query := "SELECT * FROM `comments` WHERE `post_id` = ? ORDER BY `created_at` DESC"
- if !allComments {
- query += " LIMIT 3"
- }
- var comments []Comment
- cerr := db.Select(&comments, query, p.ID)
- if cerr != nil {
- return nil, cerr
- }
+ commentStore[postID] = cs
+ return cs
+}
- for i := 0; i < len(comments); i++ {
- uerr := db.Get(&comments[i].User, "SELECT * FROM `users` WHERE `id` = ?", comments[i].UserID)
- if uerr != nil {
- return nil, uerr
- }
- }
+func getComments(postID int) []Comment {
+ commentM.Lock()
+ defer commentM.Unlock()
+ return getCommentsLocked(postID)
+}
- // reverse
- for i, j := 0, len(comments)-1; i < j; i, j = i+1, j-1 {
- comments[i], comments[j] = comments[j], comments[i]
- }
+func appendComent(c Comment) {
+ commentM.Lock()
+ cs := getCommentsLocked(c.PostID)
+ commentStore[c.PostID] = append(cs, c)
+ commentM.Unlock()
+}
+
+func makePosts(results []Post, CSRFToken string, allComments bool) ([]Post, error) {
+ var posts []Post
+ for _, p := range results {
+ comments := getComments(p.ID)
+ if !allComments && len(comments) > 3 {
+ comments = comments[len(comments)-3:]
+ }
p.Comments = comments
+ p.CSRFToken = CSRFToken
perr := db.Get(&p.User, "SELECT * FROM `users` WHERE `id` = ?", p.UserID)
if perr != nil {
return nil, perr
}
- p.CSRFToken = CSRFToken
-
- if p.User.DelFlg == 0 {
- posts = append(posts, p)
+ if p.User.DelFlg != 0 {
+ continue
}
+ posts = append(posts, p)
if len(posts) >= postsPerPage {
break
}
}
-
return posts, nil
}
@@ -411,8 +432,9 @@ func getLogout(w http.ResponseWriter, r *http.Request) {
}
var (
- indexTemplate *template.Template
- postsTemplate *template.Template
+ indexTemplate *template.Template
+ postsTemplate *template.Template
+ accountNameTempalte *template.Template
indexPostsM sync.Mutex
indexPostsT time.Time
@@ -434,6 +456,13 @@ func init() {
getTemplPath("posts.html"),
getTemplPath("post.html"),
))
+
+ accountNameTempalte = template.Must(template.New("layout.html").Funcs(fmap).ParseFiles(
+ getTemplPath("layout.html"),
+ getTemplPath("user.html"),
+ getTemplPath("posts.html"),
+ getTemplPath("post.html"),
+ ))
}
func renderIndexPosts() {
@@ -506,7 +535,6 @@ func getAccountName(c web.C, w http.ResponseWriter, r *http.Request) {
}
results := []Post{}
-
rerr := db.Select(&results, "SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `user_id` = ? ORDER BY `created_at` DESC", user.ID)
if rerr != nil {
fmt.Println(rerr)
@@ -527,12 +555,10 @@ func getAccountName(c web.C, w http.ResponseWriter, r *http.Request) {
}
postIDs := []int{}
- perr := db.Select(&postIDs, "SELECT `id` FROM `posts` WHERE `user_id` = ?", user.ID)
- if perr != nil {
- fmt.Println(perr)
- return
+ for _, r := range results {
+ postIDs = append(postIDs, r.ID)
}
- postCount := len(postIDs)
+ postCount := len(results)
commentedCount := 0
if postCount > 0 {
@@ -557,16 +583,7 @@ func getAccountName(c web.C, w http.ResponseWriter, r *http.Request) {
me := getSessionUser(r)
- fmap := template.FuncMap{
- "imageURL": imageURL,
- }
-
- template.Must(template.New("layout.html").Funcs(fmap).ParseFiles(
- getTemplPath("layout.html"),
- getTemplPath("user.html"),
- getTemplPath("posts.html"),
- getTemplPath("post.html"),
- )).Execute(w, struct {
+ accountNameTempalte.Execute(w, struct {
Posts []Post
User User
PostCount int
@@ -595,7 +612,7 @@ func getPosts(w http.ResponseWriter, r *http.Request) {
}
results := []Post{}
- rerr := db.Select(&results, "SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= ? ORDER BY `created_at` DESC", t.Format(ISO8601_FORMAT))
+ rerr := db.Select(&results, "SELECT posts.`id`, `user_id`, `body`, `mime`, posts.`created_at` FROM `posts` INNER JOIN `users` ON posts.user_id=users.id WHERE users.del_flg = 0 AND posts.`created_at` <= ? ORDER BY `created_at` DESC LIMIT 20", t.Format(ISO8601_FORMAT))
if rerr != nil {
fmt.Println(rerr)
return
@@ -806,9 +823,24 @@ func postComment(w http.ResponseWriter, r *http.Request) {
return
}
- query := "INSERT INTO `comments` (`post_id`, `user_id`, `comment`) VALUES (?,?,?)"
- db.Exec(query, postID, me.ID, r.FormValue("comment"))
-
+ now := time.Now()
+ commentStr := r.FormValue("comment")
+ query := "INSERT INTO `comments` (`post_id`, `user_id`, `comment`, `created_at`) VALUES (?,?,?,?)"
+ res, err := db.Exec(query, postID, me.ID, commentStr, now)
+ if err != nil {
+ log.Println(err)
+ return
+ }
+ lid, _ := res.LastInsertId()
+ c := Comment{
+ ID: int(lid),
+ PostID: postID,
+ UserID: me.ID,
+ Comment: commentStr,
+ CreatedAt: now,
+ User: me,
+ }
+ appendComent(c)
renderIndexPosts()
http.Redirect(w, r, fmt.Sprintf("/posts/%d", postID), http.StatusFound)
}
@@ -921,6 +953,7 @@ func main() {
go http.ListenAndServe(":3000", nil)
+ goji.DefaultMux = web.New()
goji.Get("/initialize", getInitialize)
goji.Get("/login", getLogin)
goji.Post("/login", postLogin)
計測
スコア:
{"pass":true,"score":271542,"success":256436,"fail":0,"messages":[]}
pixiv 社内 isucon の優勝チームのスコアを超えることができたと思います。
top:
ks: 82 total, 4 running, 78 sleeping, 0 stopped, 0 zombie
%Cpu(s): 57.1 us, 13.8 sy, 0.0 ni, 16.5 id, 5.1 wa, 0.0 hi, 7.3 si, 0.2 st
KiB Mem: 1022972 total, 926504 used, 96468 free, 27152 buffers
KiB Swap: 0 total, 0 used, 0 free. 432620 cached Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 1494 isucon 20 0 544796 191292 8940 S 81.5 18.7 0:29.06 app.7f063c1
731 mysql 20 0 1125024 182444 10552 S 44.9 17.8 3:04.05 mysqld
1524 www-data 20 0 92056 5276 3140 R 27.6 0.5 0:09.65 nginx
308 memcache 20 0 336672 11756 2228 S 1.7 1.1 0:02.25 memcached
31 root 20 0 0 0 0 S 0.7 0.0 0:00.40 kswapd0
89 root 0 -20 0 0 0 S 0.3 0.0 0:00.73 kworker/0:1H
1 root 20 0 28636 4736 3100 S 0.0 0.5 0:01.31 systemd
ちょっと idle が出てきたかな。
dstat:
----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system-- usr sys idl wai hiq siq| read writ| recv send| in out | int csw 0 0 100 0 0 0| 0 0 | 0 0 | 0 0 | 82 283 11 3 82 2 0 2| 12M 0 |1684k 15M| 0 0 |7607 5952 55 13 17 9 0 7| 49M 864k| 11M 44M| 0 0 | 27k 20k 58 15 14 8 0 6| 48M 416k| 13M 43M| 0 0 | 28k 20k 48 14 21 12 0 5| 43M 63M| 12M 40M| 0 0 | 25k 19k 55 17 14 7 0 7| 48M 528k| 14M 42M| 0 0 | 25k 18k 55 12 19 8 0 6| 45M 488k| 12M 42M| 0 0 | 27k 20k 52 17 16 6 0 8| 35M 592k| 14M 38M| 0 0 | 27k 19k 50 12 19 14 0 6| 34M 59M| 11M 38M| 0 0 | 25k 17k 56 12 18 6 0 7| 42M 720k| 11M 45M| 0 0 | 28k 20k 51 15 18 9 0 8| 45M 704k| 14M 39M| 0 0 | 26k 19k 52 17 17 7 0 7| 39M 3936k| 14M 45M| 0 0 | 27k 19k 47 17 18 13 0 5| 41M 56M| 12M 39M| 0 0 | 24k 17k 53 13 19 9 0 6| 45M 848k| 13M 41M| 0 0 | 27k 20k 57 15 16 6 0 6| 38M 776k| 13M 42M| 0 0 | 27k 19k 53 14 20 9 0 4| 28M 58M| 11M 29M| 0 0 | 24k 16k 53 13 19 6 0 8| 44M 672k| 13M 38M| 0 0 | 26k 18k 57 13 16 9 0 6| 46M 872k| 10M 38M| 0 0 | 25k 18k 53 12 22 7 0 6| 44M 776k| 12M 41M| 0 0 | 28k 20k 54 16 16 8 0 6| 33M 57M|9049k 33M| 0 0 | 24k 18k 51 16 21 5 0 7| 32M 888k| 12M 38M| 0 0 | 27k 19k 54 13 19 7 0 7| 49M 2264k| 11M 46M| 0 0 | 26k 18k 54 14 19 6 0 7| 36M 680k| 12M 42M| 0 0 | 28k 19k 48 16 19 10 0 7| 33M 52M| 14M 31M| 0 0 | 23k 16k 55 15 15 7 0 7| 42M 720k| 12M 34M| 0 0 | 26k 20k 59 14 17 5 0 6| 33M 744k| 12M 35M| 0 0 | 25k 18k 47 15 25 7 0 6| 34M 736k|9604k 43M| 0 0 | 28k 19k 47 11 27 8 0 6| 31M 51M| 12M 39M| 0 0 | 25k 17k 54 18 17 5 0 7| 34M 816k| 12M 33M| 0 0 | 27k 20k 55 16 16 6 0 6| 35M 888k| 14M 34M| 0 0 | 27k 19k 57 13 18 6 0 6| 34M 720k| 11M 37M| 0 0 | 27k 19k 52 12 18 12 0 6| 36M 53M| 11M 34M| 0 0 | 23k 17k 62 12 15 4 0 7| 26M 720k|9309k 29M| 0 0 | 25k 19k 46 20 19 5 0 9| 30M 560k| 16M 35M| 0 0 | 28k 20k 59 12 20 5 0 5| 23M 544k| 10M 36M| 0 0 | 25k 17k 53 13 21 8 0 5| 25M 47M| 11M 31M| 0 0 | 23k 16k 54 14 18 6 0 9| 38M 584k| 14M 35M| 0 0 | 27k 21k ...
帯域は半分強使っていますね。大きい js があるので、 `nginx の gzip_static モジュールを使うなどでもう少し帯域を開けられると思います。
pprof:
(pprof) top30 -cum
6.95s of 22.25s total (31.24%)
Dropped 621 nodes (cum <= 0.11s)
Showing top 30 nodes out of 321 (cum >= 2.44s)
flat flat% sum% cum cum%
0 0% 0% 20.30s 91.24% runtime.goexit
0.02s 0.09% 0.09% 17.03s 76.54% net/http.(*conn).serve
0 0% 0.09% 14.60s 65.62% net/http.(*ServeMux).ServeHTTP
0 0% 0.09% 14.60s 65.62% net/http.serverHandler.ServeHTTP
0 0% 0.09% 14.58s 65.53% github.com/zenazn/goji/web.(*Mux).ServeHTTP
0 0% 0.09% 14.57s 65.48% github.com/zenazn/goji/web.(*cStack).ServeHTTP
0 0% 0.09% 14.57s 65.48% github.com/zenazn/goji/web.(*mStack).newStack.func1
0 0% 0.09% 14.57s 65.48% github.com/zenazn/goji/web.(*router).route
0 0% 0.09% 14.57s 65.48% net/http.HandlerFunc.ServeHTTP
0 0% 0.09% 10.03s 45.08% github.com/zenazn/goji/web.netHTTPHandlerFuncWrap.ServeHTTPC
0.01s 0.045% 0.13% 6.12s 27.51% html/template.(*Template).Execute
0 0% 0.13% 5.58s 25.08% text/template.(*Template).Execute
0.12s 0.54% 0.67% 5.57s 25.03% text/template.(*state).walk
0.01s 0.045% 0.72% 5.20s 23.37% text/template.(*state).walkTemplate
0.04s 0.18% 0.9% 4.68s 21.03% text/template.(*state).walkRange
0.01s 0.045% 0.94% 4.65s 20.90% text/template.(*state).walkRange.func1
0.97s 4.36% 5.30% 4.60s 20.67% runtime.mallocgc
0 0% 5.30% 4.46s 20.04% github.com/zenazn/goji/web.handlerFuncWrap.ServeHTTPC
0.23s 1.03% 6.34% 4.38s 19.69% runtime.systemstack
0.04s 0.18% 6.52% 4.07s 18.29% text/template.(*state).evalPipeline
0.08s 0.36% 6.88% 4.03s 18.11% text/template.(*state).evalCommand
2.54s 11.42% 18.29% 3.71s 16.67% runtime.scanobject
0.10s 0.45% 18.74% 3.09s 13.89% text/template.(*state).evalCall
0.03s 0.13% 18.88% 3.07s 13.80% text/template.(*state).evalFunction
0 0% 18.88% 2.99s 13.44% main.getAccountName
2.48s 11.15% 30.02% 2.70s 12.13% syscall.Syscall
0 0% 30.02% 2.62s 11.78% main.getPosts
0.01s 0.045% 30.07% 2.56s 11.51% reflect.Value.Call
0.26s 1.17% 31.24% 2.52s 11.33% reflect.Value.call
0 0% 31.24% 2.44s 10.97% github.com/jmoiron/sqlx.(*DB).Get
テンプレートの実行とが重いのと、あとGCが重いですね。
テンプレートが重いのは、ページキャッシュだとトップページ以外はどれくらいキャッシュヒット率が見込めるかわかりません。 valyala/quicktemplate などの、リフレクションを多用しない高速なテンプレートエンジンに乗り換えるほうが早いかもしれません。
GCの方は、クエリ実行回数をさらに削っていけば、一時オブジェクトがを削減するのが有効そう。どこでアロケートが多発しているのかを確認したい場合は pprof -alloc_objects を使ってみてください。
まとめ
スコア: 4745 (初期状態) -> 39743 (前回) -> 182435 (Not Modified) -> 271542 (最終版)
壁を超えた効果で、いままで伸び悩んでいたスコアが一気にジャンプしました。
攻略記はここまでにしますが、できればさらにチューニングを続けてみてください。練習で実際に手を動かしていないことは、本番ではほぼ確実にできません。 私の場合は、次のようなチューニングで500k点を超えましたが、これでもまだ帯域を使い切っていないし nginx よりも app と MySQL が使用するCPUの方が大きいのでさらに上を狙えるはずです。
- gzip_static を使う (スコアは上がりませんでしたが、帯域に余裕を作りました)
- テンプレートが重い posts の部分で valyala/quicktemplate を使ってみる
- ユーザーをオンメモリキャッシュし、強引なJOINをやめる
- セッションストアを memcached からオンメモリに切り替える
- nginx と app の間を unix domain socket に切り替える
- nginx が重くなってきていたので worker_processes を 2 にする
- 更新系のリクエストであえて
time.Sleep()で待たせて、スコアへの影響が大きいシナリオの処理にリソースを向ける - アクセスログを切る (最初は静的ファイルだけ、最後は全部のアクセスログを消す)
ここまでのコミットログは methane/pixiv-private-isucon-2016 に置いてあります。 ですが、できるだけ自力で 500k 点超えを目指してみてください。
最後に、ISUCON の練習にとても良い題材を提供して頂いた pixiv さんに感謝します。
@methane
pixiv private isucon 2016 攻略 (4/5)
攻略記事一覧:
ここから、いよいよ ISUCON らしくなってきますよ。
現状確認
access.log の集計はこんな感じです。
Request by count 12317 GET /image/* 2797 GET / 1983 POST /login 1218 GET /posts/* 1029 GET /js/jquery-2.2.0.js 1029 GET /favicon.ico 1029 GET /js/jquery.timeago.js 1028 GET /css/style.css 1028 GET /js/jquery.timeago.ja.js 1028 GET /js/main.js 930 GET /@user 655 POST /register 654 GET /admin/banned 579 POST /comment 579 POST / 112 GET /login 83 GET /posts?max_created_at= 56 GET /logout 1 GET /initialize Request by total time 72.877 0.0260554165177 GET / 34.018 0.0365784946237 GET /@user 18.444 0.22221686747 GET /posts?max_created_at= 15.705 0.0271243523316 POST / 12.566 0.0103169129721 GET /posts/* 8.439 0.000685150604855 GET /image/* 5.644 0.00284619263742 POST /login 1.825 0.00278625954198 POST /register 1.661 0.00286873920553 POST /comment 1.648 0.00251987767584 GET /admin/banned 0.475 0.00424107142857 GET /login 0.45 0.00803571428571 GET /logout 0.026 0.026 GET /initialize
top はこんな感じ
Tasks: 73 total, 1 running, 72 sleeping, 0 stopped, 0 zombie %Cpu(s): 55.4 us, 10.8 sy, 0.0 ni, 23.5 id, 3.1 wa, 0.0 hi, 6.7 si, 0.5 st KiB Mem: 1022972 total, 617428 used, 405544 free, 18260 buffers KiB Swap: 0 total, 0 used, 0 free. 314552 cached Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 1122 isucon 20 0 403944 68064 8328 S 76.3 6.7 0:16.87 app.f9aa6c7 731 mysql 20 0 993756 159744 10756 S 62.6 15.6 0:15.46 mysqld 1033 www-data 20 0 92024 5136 3056 S 7.0 0.5 0:01.63 nginx 1069 isucon 20 0 28796 6136 2636 S 2.7 0.6 0:00.80 tmux 308 memcache 20 0 330528 6060 2228 S 0.7 0.6 0:00.14 memcached
そろそろリクエスト数が増えてきたのと、まだ少し idle が残っているので、念の為ベンチマーク直後の netstat を確認しておきます。
$ netstat -tn ... tcp6 0 0 127.0.0.1:8080 127.0.0.1:63462 TIME_WAIT tcp6 0 0 127.0.0.1:8080 127.0.0.1:64494 TIME_WAIT tcp6 0 0 127.0.0.1:8080 127.0.0.1:63477 TIME_WAIT tcp6 0 0 127.0.0.1:8080 127.0.0.1:63563 TIME_WAIT tcp6 0 0 127.0.0.1:8080 127.0.0.1:63877 TIME_WAIT tcp6 0 0 127.0.0.1:8080 127.0.0.1:64234 TIME_WAIT tcp6 0 0 127.0.0.1:8080 127.0.0.1:63565 TIME_WAIT tcp6 0 0 127.0.0.1:8080 127.0.0.1:64008 TIME_WAIT tcp6 0 0 127.0.0.1:8080 127.0.0.1:63594 TIME_WAIT tcp6 0 0 127.0.0.1:8080 127.0.0.1:64065 TIME_WAIT $ netstat -tn | grep -c TIME_WAIT 1981
まだ詰まるほどじゃないけど一応 /etc/nginx/sites-enabled/isucon.conf で upstream の keepalive を 64 に増やしておきます。
ページキャッシュ
プロファイルを見てみます。
(pprof) top30 -cum
5.66s of 23.80s total (23.78%)
Dropped 584 nodes (cum <= 0.12s)
Showing top 30 nodes out of 326 (cum >= 3.55s)
flat flat% sum% cum cum%
0 0% 0% 22.30s 93.70% runtime.goexit
0 0% 0% 19.44s 81.68% net/http.(*conn).serve
0.01s 0.042% 0.042% 18.79s 78.95% net/http.serverHandler.ServeHTTP
0 0% 0.042% 18.78s 78.91% net/http.(*ServeMux).ServeHTTP
0 0% 0.042% 18.76s 78.82% github.com/zenazn/goji/web.(*Mux).ServeHTTP
0 0% 0.042% 18.72s 78.66% github.com/zenazn/goji/web.(*cStack).ServeHTTP
0 0% 0.042% 18.72s 78.66% github.com/zenazn/goji/web/middleware.RequestID.func1
0 0% 0.042% 18.72s 78.66% net/http.HandlerFunc.ServeHTTP
0.01s 0.042% 0.084% 18.69s 78.53% github.com/zenazn/goji/web/middleware.Logger.func1
0 0% 0.084% 18.27s 76.76% github.com/zenazn/goji/web/middleware.Recoverer.func1
0 0% 0.084% 18.21s 76.51% github.com/zenazn/goji/web.(*mStack).newStack.func1
0 0% 0.084% 18.21s 76.51% github.com/zenazn/goji/web.(*router).route
0 0% 0.084% 18.21s 76.51% github.com/zenazn/goji/web/middleware.AutomaticOptions.func1
0.01s 0.042% 0.13% 14.43s 60.63% github.com/zenazn/goji/web.netHTTPHandlerFuncWrap.ServeHTTPC
0 0% 0.13% 12.63s 53.07% main.getIndex
0.07s 0.29% 0.42% 9.88s 41.51% main.makePosts
0.01s 0.042% 0.46% 6.89s 28.95% github.com/jmoiron/sqlx.(*DB).Get
0.01s 0.042% 0.5% 6.88s 28.91% github.com/jmoiron/sqlx.Get
0.03s 0.13% 0.63% 6.80s 28.57% database/sql.(*DB).Query
0.02s 0.084% 0.71% 6.77s 28.45% database/sql.(*DB).query
0.03s 0.13% 0.84% 6.43s 27.02% database/sql.(*DB).queryConn
0.06s 0.25% 1.09% 6.02s 25.29% github.com/go-sql-driver/mysql.(*mysqlConn).Query
0.02s 0.084% 1.18% 4.65s 19.54% github.com/jmoiron/sqlx.(*DB).QueryRowx
4.06s 17.06% 18.24% 4.38s 18.40% syscall.Syscall
1.17s 4.92% 23.15% 4.08s 17.14% runtime.mallocgc
0 0% 23.15% 3.83s 16.09% github.com/jmoiron/sqlx.(*DB).Select
0.01s 0.042% 23.19% 3.83s 16.09% github.com/jmoiron/sqlx.Select
0 0% 23.19% 3.72s 15.63% github.com/zenazn/goji/web.handlerFuncWrap.ServeHTTPC
0.12s 0.5% 23.70% 3.58s 15.04% runtime.systemstack
0.02s 0.084% 23.78% 3.55s 14.92% syscall.Write
(pprof) list getIndex
Total: 23.80s
ROUTINE ======================== main.getIndex in /home/isucon/private_isu/webapp/golang/app.go
0 12.63s (flat, cum) 53.07% of Total
. . 413:
. . 414: http.Redirect(w, r, "/", http.StatusFound)
. . 415:}
. . 416:
. . 417:func getIndex(w http.ResponseWriter, r *http.Request) {
. 330ms 418: me := getSessionUser(r)
. . 419:
. . 420: results := []Post{}
. . 421:
. 600ms 422: err := db.Select(&results, "SELECT posts.`id`, `user_id`, `body`, `mime`, posts.`created_at` FROM `posts` INNER JOIN `users` ON posts.user_id=users.id WHERE users.del_flg = 0 ORDER BY `created_at` DESC LIMIT 20")
. . 423: if err != nil {
. . 424: fmt.Println(err)
. . 425: return
. . 426: }
. . 427:
. 8.43s 428: posts, merr := makePosts(results, getCSRFToken(r), false)
. . 429: if merr != nil {
. . 430: fmt.Println(merr)
. . 431: return
. . 432: }
. . 433:
. . 434: fmap := template.FuncMap{
. . 435: "imageURL": imageURL,
. . 436: }
. . 437:
. 40ms 438: template.Must(template.New("layout.html").Funcs(fmap).ParseFiles(
. 10ms 439: getTemplPath("layout.html"),
. 10ms 440: getTemplPath("index.html"),
. . 441: getTemplPath("posts.html"),
. . 442: getTemplPath("post.html"),
. 1.20s 443: )).Execute(w, struct {
. . 444: Posts []Post
. . 445: Me User
. . 446: CSRFToken string
. . 447: Flash string
. 2.01s 448: }{posts, me, getCSRFToken(r), getFlash(w, r, "notice")})
. . 449:}
. . 450:
. . 451:func getAccountName(c web.C, w http.ResponseWriter, r *http.Request) {
. . 452: user := User{}
. . 453: uerr := db.Get(&user, "SELECT * FROM `users` WHERE `account_name` = ? AND `del_flg` = 0", c.URLParams["accountName"])
テンプレートに渡すための []Post を用意する makePosts 関数が一番重いものの、最初に Post 一覧を取得する select が 600ms, テンプレートのコンパイルと実行を足して 3.2sec ありますね。
テンプレートのコンパイルは起動時に一度やればいい処理なので 1.2sec は無駄です。
また、トップページに表示される内容はユーザーにかかわらず一定なので、レンダリング結果をまるごとページキャッシュできれば、 makePosts の 8.4sec とテンプレートのレンダリングの 2sec の合わせて 10sec をほぼ消し去ることができます。
ページキャッシュが実現できそうかテンプレートの中身を確認してみると、ユーザーごとに異なる内容は、 (1) ヘッダー部分, (2) 全フォームにある csrf token, でした。レンダリングが重いのはポスト一覧の部分でしょうから、ヘッダーはページキャッシュの対象外にして、ポスト一覧部分だけをキャッシュすれば (1) は問題ありません。問題は (2) ですが、レンダリング時に固定のキーワードを入れてレンダリングしておき、ユーザーに返すときに本当の csrf token に文字列置換することにします。
ページキャッシュを作るタイミングですが、 getIndex() が呼ばれた時にするよりも、トップページに何か変更があったとき (画像が投稿された、コメントされた、ユーザーが削除されたなど) にレンダリングするほうが効率的です。
さらに、性能が上がってくるとトップページに変更があるリクエストが並列で来る可能性があるので、レンダリングを Mutex で排他したうえで、 Mutex を待ってる goroutine が同時に複数存在した場合はそのうちの1つだけがレンダリングする方式を採用しました。
この方式は GoCon 2016 Spring で zero time cache パターンとして紹介したもので、全ての POST リクエストがレンダリングを待ってからレスポンスを返すので、キャッシュによる更新が反映されるまでの遅延が存在しません。
diff --git a/app.go b/app.go
index b5a8fac..f246ad6 100644
--- a/app.go
+++ b/app.go
@@ -1,6 +1,7 @@
package main
import (
+ "bytes"
crand "crypto/rand"
"crypto/sha512"
"encoding/hex"
@@ -109,6 +110,8 @@ func dbInitialize() {
for _, sql := range sqls {
db.Exec(sql)
}
+
+ renderIndexPosts()
}
func tryLogin(accountName, password string) *User {
@@ -414,38 +410,85 @@ func getLogout(w http.ResponseWriter, r *http.Request) {
http.Redirect(w, r, "/", http.StatusFound)
}
-func getIndex(w http.ResponseWriter, r *http.Request) {
- me := getSessionUser(r)
+var (
+ indexTemplate *template.Template
+ postsTemplate *template.Template
- results := []Post{}
+ indexPostsM sync.Mutex
+ indexPostsT time.Time
+ indexPostsRenderedM sync.RWMutex
+ indexPostsRendered []byte
+)
+
+func init() {
+ fmap := template.FuncMap{
+ "imageURL": imageURL,
+ }
+ indexTemplate = template.Must(template.New("layout.html").Funcs(fmap).ParseFiles(
+ getTemplPath("layout.html"),
+ getTemplPath("index.html"),
+ ))
+
+ postsTemplate = template.Must(template.New("posts.html").Funcs(fmap).ParseFiles(
+ getTemplPath("posts.html"),
+ getTemplPath("post.html"),
+ ))
+}
+
+func renderIndexPosts() {
+ now := time.Now()
+ indexPostsM.Lock()
+ defer indexPostsM.Unlock()
+ if indexPostsT.After(now) {
+ return
+ }
+ now = time.Now()
+
+ results := []Post{}
err := db.Select(&results, "SELECT posts.`id`, `user_id`, `body`, `mime`, posts.`created_at` FROM `posts` INNER JOIN `users` ON posts.user_id=users.id WHERE users.del_flg = 0 ORDER BY `created_at` DESC LIMIT 20")
if err != nil {
- fmt.Println(err)
+ log.Println(err)
return
}
- posts, merr := makePosts(results, getCSRFToken(r), false)
+ posts, merr := makePosts(results, "[[[CSRFTOKEN]]]", false)
if merr != nil {
- fmt.Println(merr)
+ log.Println(merr)
return
}
- fmap := template.FuncMap{
- "imageURL": imageURL,
+ var b bytes.Buffer
+ if err := postsTemplate.Execute(&b, posts); err != nil {
+ log.Println(err)
+ return
}
- template.Must(template.New("layout.html").Funcs(fmap).ParseFiles(
- getTemplPath("layout.html"),
- getTemplPath("index.html"),
- getTemplPath("posts.html"),
- getTemplPath("post.html"),
- )).Execute(w, struct {
- Posts []Post
- Me User
- CSRFToken string
- Flash string
- }{posts, me, getCSRFToken(r), getFlash(w, r, "notice")})
+ indexPostsT = now
+ indexPostsRenderedM.Lock()
+ indexPostsRendered = b.Bytes()
+ indexPostsRenderedM.Unlock()
+}
+
+func getIndexPosts(csrf string) template.HTML {
+ indexPostsRenderedM.RLock()
+ t := bytes.Replace(indexPostsRendered, []byte("[[[CSRFTOKEN]]]"), []byte(csrf), -1)
+ indexPostsRenderedM.RUnlock()
+ return template.HTML(string(t))
+}
+
+func getIndex(w http.ResponseWriter, r *http.Request) {
+ me := getSessionUser(r)
+ csrf := getCSRFToken(r)
+ posts := getIndexPosts(csrf)
+
+ indexTemplate.Execute(w,
+ map[string]interface{}{
+ "Me": me,
+ "CSRFToken": csrf,
+ "Flash": getFlash(w, r, "notice"),
+ "Posts": posts},
+ )
}
func getAccountName(c web.C, w http.ResponseWriter, r *http.Request) {
@@ -708,8 +751,9 @@ func postIndex(w http.ResponseWriter, r *http.Request) {
}
tf.Close()
copyImage(int(pid), tf.Name(), mime)
+
+ renderIndexPosts()
http.Redirect(w, r, "/posts/"+strconv.FormatInt(pid, 10), http.StatusFound)
- return
}
func getImage(c web.C, w http.ResponseWriter, r *http.Request) {
@@ -765,6 +809,7 @@ func postComment(w http.ResponseWriter, r *http.Request) {
query := "INSERT INTO `comments` (`post_id`, `user_id`, `comment`) VALUES (?,?,?)"
db.Exec(query, postID, me.ID, r.FormValue("comment"))
+ renderIndexPosts()
http.Redirect(w, r, fmt.Sprintf("/posts/%d", postID), http.StatusFound)
}
@@ -821,6 +866,7 @@ func postAdminBanned(w http.ResponseWriter, r *http.Request) {
db.Exec(query, 1, id)
}
+ renderIndexPosts()
http.Redirect(w, r, "/admin/banned", http.StatusFound)
}
@@ -864,6 +910,15 @@ func main() {
db.SetMaxIdleConns(8)
defer db.Close()
+ for {
+ if db.Ping() == nil {
+ break
+ }
+ log.Println("waiting db...")
+ }
+
+ renderIndexPosts()
+
go http.ListenAndServe(":3000", nil)
goji.Get("/initialize", getInitialize)
diff --git a/templates/index.html b/templates/index.html
index 22ff9c2..8c2b639 100644
--- a/templates/index.html
+++ b/templates/index.html
@@ -19,7 +19,7 @@
</form>
</div>
-{{ template "posts.html" .Posts }}
+{{ .Posts }}
<div id="isu-post-more">
<button id="isu-post-more-btn">もっと見る</button>
計測
スコア:
{"pass":true,"score":39743,"success":32254,"fail":0,"messages":[]}
top:
Tasks: 77 total, 1 running, 76 sleeping, 0 stopped, 0 zombie
%Cpu(s): 44.7 us, 8.3 sy, 0.0 ni, 35.3 id, 5.1 wa, 0.0 hi, 6.0 si, 0.5 st
KiB Mem: 1022972 total, 961900 used, 61072 free, 23704 buffers
KiB Swap: 0 total, 0 used, 0 free. 604328 cached Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
1337 isucon 20 0 207476 68192 8880 S 63.6 6.7 0:13.73 app.dc4a3eaa
731 mysql 20 0 1059292 181996 10552 S 45.6 17.8 1:49.68 mysqld
1033 www-data 20 0 92008 5092 3056 S 8.0 0.5 0:11.70 nginx
1069 isucon 20 0 32140 9332 2636 S 4.0 0.9 0:07.71 tmux
3 root 20 0 0 0 0 S 0.3 0.0 0:15.56 ksoftirqd/0
13 root 20 0 0 0 0 S 0.3 0.0 0:29.07 ksoftirqd/1
43 root 20 0 0 0 0 S 0.3 0.0 0:00.15 kworker/u30:1
308 memcache 20 0 332576 7896 2228 S 0.3 0.8 0:00.89 memcached
968 isucon 20 0 80656 3496 2656 S 0.3 0.3 0:00.28 sshd
CPU がだいぶ遊んできましたね。どこか別のところにあるボトルネックを見つけないといけません。
myprofiler:
34 SELECT * FROM `users` WHERE `id` = N 30 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= S ORDER BY `created_at` DESC 23 SELECT * FROM `posts` WHERE `id` = N 19 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `user_id` = N ORDER BY `created_at` DESC 11 SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = N 10 SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC LIMIT N 8 SELECT `id` FROM `posts` WHERE `user_id` = N 2 INSERT INTO `users` (`account_name`, `passhash`) VALUES (S,S) 1 SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC 1 SELECT COUNT(*) AS count FROM `comments` WHERE `post_id` IN (...N)
user を PK で取得する部分が重いみたいです。
access.log:
Request by count 12394 GET /image/* 4149 GET / 2791 POST /login 1395 GET /posts/* 1207 POST /register 1207 GET /admin/banned 1049 GET /@user 1021 GET /js/jquery-2.2.0.js 1021 GET /css/style.css 1021 GET /js/jquery.timeago.ja.js 1021 GET /favicon.ico 1021 GET /js/jquery.timeago.js 1021 GET /js/main.js 704 POST /comment 698 POST / 120 GET /login 77 GET /posts?max_created_at= 61 GET /logout 1 GET /initialize Request by total time 30.646 0.0292144899905 GET /@user 24.051 0.0344570200573 POST / 14.411 0.187155844156 GET /posts?max_created_at= 12.099 0.00867311827957 GET /posts/* 11.879 0.0168735795455 POST /comment 9.296 0.00224053988913 GET / 6.612 0.00236904335364 POST /login 3.355 0.00277961888981 POST /register 2.882 0.00023253187026 GET /image/* 2.21 0.00183098591549 GET /admin/banned 0.448 0.00373333333333 GET /login 0.443 0.00726229508197 GET /logout 0.038 0.038 GET /initialize Request by out bytes 3847419944 310426 GET /image/* 264074503 258643 GET /js/jquery-2.2.0.js 99628388 24012 GET / ...
GET / が 2.2msec まで速くなりました。まだ速く出来る余地はあるけど、先に GET /@user などの高速化が先でしょうね。
まとめ
スコア: 4745 (初期状態) -> 32771 (前回) -> 39743 (トップページのページキャッシュ)
ボトルネックがCPU以外に移っているので、スコアが期待したほど伸びませんでした。次回はそのボトルネックを調査・解決します。
ページキャッシュに利用した zero time cache パターンは Go だから簡単に実現できるものなので、 prefork 型のアプリサーバーを使う他の言語ではちょっと難しいです。 (node.js なら、2コアマシンならシングルプロセスで頑張れるかも知れません)
他の言語では、普通に getIndex でページキャッシュしてベンチが完走するようにキャッシュの生存期間を調整するとか、バックグラウンドで動くデーモンが定期的にページキャッシュを生成するようにしてベンチが通るようにその生成間隔を調整するといったやり方がISUCONでは一般的だと思います。
しかし、今回の pixiv private isucon ではルールに POST が返ってからその内容が別の GET リクエストに反映されるまでの猶予が明記されていないので、調整のために複数回ベンチを走らせる必要があるかもしれません。 (Go 推し)
@methane
pixiv private isucon 2016 攻略 (3/5)
攻略記事一覧:
現状確認
access.log をもう一度見直しましょう。
Request by total time 74.113 0.0307140489018 GET / 70.007 0.00532696697611 GET /image/* 43.428 0.0575205298013 GET /@user 24.058 0.283035294118 GET /posts?max_created_at= 23.976 0.0522352941176 POST / 12.767 0.012987792472 GET /posts/* 6.642 0.00390476190476 POST /login ...
CPU を一番使っているのはトップページですが、レスポンスタイムに占める時間で言えば /image/* がほとんど並びました。
そろそろ /image/* をリバースプロキシするのは止めないといけません。
Go を使う場合は nginx を使うのをやめるのも候補になるのですが、静的ファイル配信は nginx に任せたほうがてっとり早いので、 nginx を外さない方針で行きましょう。
nginx の設定
僕も ISUCON 前以外は nginx の設定に詳しくないので、とりあえずこんな感じで設定しました。
root /home/isucon/private_isu/webapp/public/;
location / {
try_files $uri @app;
}
location @app {
proxy_set_header Host $host;
proxy_set_header X-Real-IP $remote_addr;
proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
proxy_pass http://app;
}
public ディレクトリは css とか js も入ってるので、その中に mkdir image しておき、 try_files ディレクティブでファイルが有ればそれを返す、なければリバースプロキシの設定を書いた @app location を使う設定にしています。
アプリ側は、 /image/* にアクセスがあったときに画像を返すついでにファイルに書き出すのと、画像がアップロードされたときにファイルに書いてDBには書かないように修正します。DBに書かないのは Disk IO 負荷低減のためです。
--- a/app.go
+++ b/app.go
@@ -78,6 +78,29 @@ func init() {
store = gsm.NewMemcacheStore(memcacheClient, "isucogram_", []byte("sendagaya"))
}
+func writeImage(id int, mime string, data []byte) {
+ var ext string
+ switch mime {
+ case "image/jpeg":
+ ext = ".jpg"
+ case "image/png":
+ ext = ".png"
+ case "image/gif":
+ ext = ".gif"
+ default:
+ fmt.Println("Failed to write file: ", id, mime)
+ return
+ }
+
+ fn := fmt.Sprintf("../public/image/%d%s", id, ext)
+ f, err := os.OpenFile(fn, os.O_WRONLY|os.O_CREATE, 0666)
+ if err != nil {
+ panic(err)
+ }
+ f.Write(data)
+ f.Close()
+}
+
func dbInitialize() {
sqls := []string{
"DELETE FROM users WHERE id > 1000",
@@ -652,7 +675,7 @@ func postIndex(w http.ResponseWriter, r *http.Request) {
query,
me.ID,
mime,
- filedata,
+ []byte(""),
r.FormValue("body"),
)
if eerr != nil {
@@ -665,7 +688,7 @@ func postIndex(w http.ResponseWriter, r *http.Request) {
fmt.Println(lerr.Error())
return
}
-
+ writeImage(int(pid), mime, filedata)
http.Redirect(w, r, "/posts/"+strconv.FormatInt(pid, 10), http.StatusFound)
return
}
@@ -695,6 +718,7 @@ func getImage(c web.C, w http.ResponseWriter, r *http.Request) {
if err != nil {
fmt.Println(err.Error())
}
+ writeImage(pid, post.Mime, post.Imgdata)
return
}
メモリが足りない！！
ここで問題にぶつかりました。メモリが足りなくてベンチが完走しません。 静的ファイル配信を nginx に任せることでメモリ使用量が減らせると思っていたのに！
多分、性能が向上したためにメモリアロケートのペースが早くなって問題が顕在化したのでしょう。プロファイラーで、ベンチマーク中 (メモリ使用量が増えてきたけどメモリ不足で落ちるよりは前) のメモリ使用量を調査してみます。
$ go tool pprof -inuse_space app.e27b8a http://localhost:3000/debug/pprof/heap
Fetching profile from http://localhost:3000/debug/pprof/heap
Saved profile in /home/isucon/pprof/pprof.app.e27b8a.localhost:3000.inuse_objects.inuse_space.002.pb.gz
Entering interactive mode (type "help" for commands)
(pprof) top40 -cum
319.72MB of 338.26MB total (94.52%)
Dropped 338 nodes (cum <= 1.69MB)
Showing top 40 nodes out of 52 (cum >= 8.34MB)
flat flat% sum% cum cum%
0 0% 0% 337.76MB 99.85% runtime.goexit
0 0% 0% 336.72MB 99.54% net/http.(*conn).serve
0 0% 0% 322.22MB 95.26% github.com/zenazn/goji/web.(*mStack).newStack.func1
0 0% 0% 322.22MB 95.26% github.com/zenazn/goji/web.(*router).route
0 0% 0% 322.22MB 95.26% github.com/zenazn/goji/web/middleware.AutomaticOptions.func1
0 0% 0% 322.22MB 95.26% github.com/zenazn/goji/web/middleware.Logger.func1
0 0% 0% 322.22MB 95.26% github.com/zenazn/goji/web/middleware.Recoverer.func1
0 0% 0% 322.22MB 95.26% github.com/zenazn/goji/web/middleware.RequestID.func1
0 0% 0% 322.22MB 95.26% net/http.HandlerFunc.ServeHTTP
0 0% 0% 321.72MB 95.11% github.com/zenazn/goji/web.(*Mux).ServeHTTP
0 0% 0% 321.72MB 95.11% github.com/zenazn/goji/web.(*cStack).ServeHTTP
0 0% 0% 321.72MB 95.11% net/http.(*ServeMux).ServeHTTP
0 0% 0% 321.72MB 95.11% net/http.serverHandler.ServeHTTP
0 0% 0% 309.80MB 91.59% github.com/zenazn/goji/web.netHTTPHandlerFuncWrap.ServeHTTPC
0 0% 0% 301.29MB 89.07% net/http.(*Request).FormValue
0 0% 0% 301.29MB 89.07% net/http.(*Request).ParseMultipartForm
0 0% 0% 299.29MB 88.48% main.postIndex
0.50MB 0.15% 0.15% 298.79MB 88.33% mime/multipart.(*Reader).ReadForm
0 0% 0.15% 298.29MB 88.18% bytes.(*Buffer).ReadFrom
298.29MB 88.18% 88.33% 298.29MB 88.18% bytes.makeSlice
0 0% 88.33% 298.29MB 88.18% io.Copy
0 0% 88.33% 298.29MB 88.18% io.CopyN
0 0% 88.33% 298.29MB 88.18% io.copyBuffer
0 0% 88.33% 15MB 4.44% net/http.(*conn).readRequest
1MB 0.3% 88.63% 15MB 4.44% net/http.readRequest
0 0% 88.63% 12.42MB 3.67% github.com/zenazn/goji/web.handlerFuncWrap.ServeHTTPC
10.50MB 3.11% 91.73% 11MB 3.25% net/textproto.(*Reader).ReadMIMEHeader
0 0% 91.73% 10.50MB 3.10% github.com/bradleypeabody/gorilla-sessions-memcache.(*MemcacheStore).Get
0 0% 91.73% 10.50MB 3.10% main.getSession
0 0% 91.73% 9.42MB 2.78% database/sql.(*Rows).Next
9.42MB 2.78% 94.52% 9.42MB 2.78% github.com/go-sql-driver/mysql.(*buffer).fill
0 0% 94.52% 9.42MB 2.78% github.com/go-sql-driver/mysql.(*buffer).readNext
0 0% 94.52% 9.42MB 2.78% github.com/go-sql-driver/mysql.(*mysqlConn).readPacket
0 0% 94.52% 9.42MB 2.78% github.com/go-sql-driver/mysql.(*textRows).Next
0 0% 94.52% 9.42MB 2.78% github.com/go-sql-driver/mysql.(*textRows).readRow
0 0% 94.52% 8.34MB 2.47% github.com/jmoiron/sqlx.(*DB).Get
0 0% 94.52% 8.34MB 2.47% github.com/jmoiron/sqlx.(*Row).Scan
0 0% 94.52% 8.34MB 2.47% github.com/jmoiron/sqlx.(*Row).scanAny
0 0% 94.52% 8.34MB 2.47% github.com/jmoiron/sqlx.Get
0 0% 94.52% 8.34MB 2.47% main.getImage
(pprof) list ReadForm
Total: 338.26MB
ROUTINE ======================== mime/multipart.(*Reader).ReadForm in /home/isucon/.local/go/src/mime/multipart/formdata.go
512.02kB 298.79MB (flat, cum) 88.33% of Total
. . 19:// ReadForm parses an entire multipart message whose parts have
. . 20:// a Content-Disposition of "form-data".
. . 21:// It stores up to maxMemory bytes of the file parts in memory
. . 22:// and the remainder on disk in temporary files.
. . 23:func (r *Reader) ReadForm(maxMemory int64) (f *Form, err error) {
512.02kB 512.02kB 24: form := &Form{make(map[string][]string), make(map[string][]*FileHeader)}
. . 25: defer func() {
. . 26: if err != nil {
. . 27: form.RemoveAll()
. . 28: }
. . 29: }()
. . 30:
. . 31: maxValueBytes := int64(10 << 20) // 10 MB is a lot of text.
. . 32: for {
. . 33: p, err := r.NextPart()
. . 34: if err == io.EOF {
. . 35: break
. . 36: }
. . 37: if err != nil {
. . 38: return nil, err
. . 39: }
. . 40:
. . 41: name := p.FormName()
. . 42: if name == "" {
. . 43: continue
. . 44: }
. . 45: filename := p.FileName()
. . 46:
. . 47: var b bytes.Buffer
. . 48:
. . 49: if filename == "" {
. . 50: // value, store as string in memory
. . 51: n, err := io.CopyN(&b, p, maxValueBytes)
. . 52: if err != nil && err != io.EOF {
. . 53: return nil, err
. . 54: }
. . 55: maxValueBytes -= n
. . 56: if maxValueBytes == 0 {
. . 57: return nil, errors.New("multipart: message too large")
. . 58: }
. . 59: form.Value[name] = append(form.Value[name], b.String())
. . 60: continue
. . 61: }
. . 62:
. . 63: // file, store in memory or on disk
. . 64: fh := &FileHeader{
. . 65: Filename: filename,
. . 66: Header: p.Header,
. . 67: }
. 298.29MB 68: n, err := io.CopyN(&b, p, maxMemory+1)
. . 69: if err != nil && err != io.EOF {
. . 70: return nil, err
. . 71: }
. . 72: if n > maxMemory {
. . 73: // too big, write to disk and flush buffer
(pprof) list postIndex
Total: 338.26MB
ROUTINE ======================== main.postIndex in /home/isucon/private_isu/webapp/golang/app.go
0 299.29MB (flat, cum) 88.48% of Total
. . 612: Me User
. . 613: }{p, me})
. . 614:}
. . 615:
. . 616:func postIndex(w http.ResponseWriter, r *http.Request) {
. 512.17kB 617: me := getSessionUser(r)
. . 618: if !isLogin(me) {
. . 619: http.Redirect(w, r, "/login", http.StatusFound)
. . 620: return
. . 621: }
. . 622:
. 298.79MB 623: if r.FormValue("csrf_token") != getCSRFToken(r) {
. . 624: w.WriteHeader(StatusUnprocessableEntity)
. . 625: return
. . 626: }
メモリーを使ってる箇所はわかりましたが、どう見てもリークではないです。
ファイルアップロードの効率化
ググったり、multipart の ReadForm 周辺のソースコードを読んで、原因を調べ、対策を考えます。
原因:
postIndexで最初にRequest.FormValueを呼んだときにフォームを解析する処理が実行されていて、そこでアップロードされたファイルを読み込んでいる。- アップロードされたファイルは、ある程度 (デフォルト32MB) までは
bytes.Bufferに読み込まれ、それを超える場合はテンポラリファイルに書き出される。 bytes.Bufferは小さいサイズからどんどんリアロケートして拡大していくので、短時間に大量のアロケートが発生する。アプリの性能が上がるのに連動してファイルのアップロードの頻度が増え、アロケートのペースが速すぎてGCが追いつかなくなったようだ。
対策:
- multipart を解析するときに明示的に
ParseMultipartFormを呼び出し、32MBよりももっと早めにテンポラリファイルを使うようにする。 - 並列にファイルアップロードの解析が走らないように Mutex で保護する。
--- a/app.go
+++ b/app.go
@@ -17,6 +17,7 @@ import (
"regexp"
"strconv"
"strings"
+ "sync"
"time"
"github.com/bradfitz/gomemcache/memcache"
@@ -613,6 +614,8 @@ func getPostsID(c web.C, w http.ResponseWriter, r *http.Request) {
}{p, me})
}
+var uploadM sync.Mutex
+
func postIndex(w http.ResponseWriter, r *http.Request) {
me := getSessionUser(r)
if !isLogin(me) {
@@ -620,6 +623,9 @@ func postIndex(w http.ResponseWriter, r *http.Request) {
return
}
+ uploadM.Lock()
+ defer uploadM.Unlock()
+ r.ParseMultipartForm(1 << 10)
if r.FormValue("csrf_token") != getCSRFToken(r) {
w.WriteHeader(StatusUnprocessableEntity)
return
これでもまだ足りませんでした。なので、一旦メモリに置いてからファイルに書き出すのを止め、一時ファイルにコピーして、それを image/ ディレクトリ配下にリネームするように改修しました。
--- a/app.go
+++ b/app.go
@@ -80,26 +80,21 @@ func init() {
}
func writeImage(id int, mime string, data []byte) {
- var ext string
- switch mime {
- case "image/jpeg":
- ext = ".jpg"
- case "image/png":
- ext = ".png"
- case "image/gif":
- ext = ".gif"
- default:
- fmt.Println("Failed to write file: ", id, mime)
- return
+ fn := imagePath(id, mime)
+ err := ioutil.WriteFile(fn, data, 0666)
+ if err != nil {
+ log.Println("failed to write file; path=%q, err=%v", fn, err)
}
+}
- fn := fmt.Sprintf("../public/image/%d%s", id, ext)
- f, err := os.OpenFile(fn, os.O_WRONLY|os.O_CREATE, 0666)
- if err != nil {
- panic(err)
+func copyImage(id int, src, mime string) {
+ dst := imagePath(id, mime)
+ if err := os.Chmod(src, 0666); err != nil {
+ log.Println("failed to chmod: path=%v, %v", src, err)
+ }
+ if err := os.Rename(src, dst); err != nil {
+ log.Println("failed to rename; src=%q, dst=%q; %v", src, dst, err)
}
- f.Write(data)
- f.Close()
}
func dbInitialize() {
@@ -260,6 +255,19 @@ func imageURL(p Post) string {
return "/image/" + strconv.Itoa(p.ID) + ext
}
+func imagePath(id int, mime string) string {
+ var ext string
+ switch mime {
+ case "image/jpeg":
+ ext = ".jpg"
+ case "image/png":
+ ext = ".png"
+ case "image/gif":
+ ext = ".gif"
+ }
+ return fmt.Sprintf("../public/image/%d%s", id, ext)
+}
+
func isLogin(u User) bool {
return u.ID != 0
}
@@ -662,16 +670,20 @@ func postIndex(w http.ResponseWriter, r *http.Request) {
}
}
- filedata, rerr := ioutil.ReadAll(file)
- if rerr != nil {
- fmt.Println(rerr.Error())
+ tf, err := ioutil.TempFile("../upload", "img-")
+ if err != nil {
+ log.Panicf("failed to create image: %v", err)
}
-
- if len(filedata) > UploadLimit {
+ written, err := io.CopyN(tf, file, UploadLimit+1)
+ if err != nil && err != io.EOF {
+ log.Panicf("failed to write to temporary file: %v", err)
+ }
+ if written > UploadLimit {
+ os.Remove(tf.Name())
+ tf.Close()
session := getSession(r)
session.Values["notice"] = "ファイルサイズが大きすぎます"
session.Save(r, w)
-
http.Redirect(w, r, "/", http.StatusFound)
return
}
@@ -694,7 +706,8 @@ func postIndex(w http.ResponseWriter, r *http.Request) {
fmt.Println(lerr.Error())
return
}
- writeImage(int(pid), mime, filedata)
+ tf.Close()
+ copyImage(int(pid), tf.Name(), mime)
http.Redirect(w, r, "/posts/"+strconv.FormatInt(pid, 10), http.StatusFound)
return
}
これでメモリ不足は落ち着き、とりあえず静的ファイルと投稿画像を nginx から返す設定でベンチが完走しました。
{"pass":true,"score":32771,"success":27352,"fail":0,"messages":[]}
本当は、 http.Request の Form 解析によって作られる一時ファイルからアプリケーションの一時ファイルへのコピーが無駄なので、 Request の Form 系のAPIを使わず直接 Body を解析するともっと効率が良くなります。（難しそうに聞こえるかもしれませんが、ほぼ Request.ParseMultipartFormのコピペで行けるはずです）
ただし、この時点でメモリ不足は収まったので、これ以上はディスク書き込みがネックになってどうしようもなくなるまで置いておいて、本来やりたかったチューニングにもどりましょう。
まとめ
スコア: 4745 (初期状態) -> 30076 (前回) -> 32771 (nginxで画像配信)
思っていたより性能向上が少ないです。これは次回に持ち越しです。
今回はファイルアップロードによるメモリ不足に悩まされましたが、(2010年代も後半になって)1GBメモリのマシンで、すごい大量にアップロードされる画像を裁くのは ISUCON だとありがちです。ちゃんと効率のいいファイルアップロードのやり方を調べておきましょう。
また、自分が使う予定の言語でメモリ不足を調査する方法も調べておきましょう。(例えば Python なら標準ライブラリの tracemalloc が使えると思います。)
@methane
pixiv private isucon 2016 攻略 (2/5)
攻略記事一覧:
アプリを読む
ソースコードを読みながらだいたいの構成を把握していきます。
- フレームワークは goji を使っている。 goji のサイトを見ると同じ名前で新しいフレームワークを作り直したみたいだけど、これは古い方を使ってるみたいです。
- セッションは Gorilla のライブラリに memcached store を組み合わせている
- テンプレートをレンダリングのたびにコンパイルしてるのが重そう。
- コメントのユーザーをいちいちユーザーテーブルから引っ張ってるのも JOIN かキャッシュが効きそう。
- 画像データを MySQL に突っ込んでるのは、ファイルに出す必要がありそう。(ファイルなら数十KBずつ読んでは返せるけれど、DBだと簡単な方法だと一度に全体をメモリに読んでしまうので、並列にアクセスが来たときにメモリが足りなくなります。）
読んでいると改善したいポイントがたくさん出てくるものの、いきなりあちこち改造しだすとバグったときに困ります。はじめは基礎的な設定とボトルネックに絞ったチューニングです。
最初にDBのコネクションプール設定できてないので設定しておきましょう。2コアなんでそんなにたくさんコネクションあっても仕方ないハズ。とりあえずちょい多めの8にしておきます。
+ db.SetMaxOpenConns(8)
+ db.SetMaxIdleConns(8)
defer db.Close()
アクセスログを読む
事前に用意しておいたアクセスログ集計ツール（自作してもいいですし、過去のいろいろな方のISUCONの記事を探してみれば良いツールが紹介されているはずです）を、アクセスログやアプリのURLルーティングの設定を参考にカスタマイズしましょう。
僕の場合は自作スクリプトで、次のような集計をしました。
Request by count 8028 GET /image/* 644 GET / 551 GET /js/jquery-2.2.0.js 551 GET /css/style.css 551 GET /js/jquery.timeago.ja.js 551 GET /favicon.ico 551 GET /js/jquery.timeago.js 551 GET /js/main.js 450 POST /login 299 GET /posts/* 235 GET /@user 130 POST / 98 GET /login 90 POST /comment 79 POST /register 78 GET /admin/banned 56 GET /posts?max_created_at= 50 GET /logout 1 GET /initialize Request by total time (total avg [sec]) 198.379 0.308041925466 GET / 168.858 0.021033632287 GET /image/* 47.605 0.202574468085 GET /@user 34.491 0.0766466666667 POST /login 30.444 0.543642857143 GET /posts?max_created_at= 15.095 0.0504849498328 GET /posts/* 7.068 0.0894683544304 POST /register 6.7 0.0515384615385 POST / 6.51 0.0118148820327 GET /favicon.ico 6.483 0.0117658802178 GET /js/jquery-2.2.0.js 5.784 0.010497277677 GET /js/jquery.timeago.js 5.213 0.0094609800363 GET /js/jquery.timeago.ja.js 5.095 0.00924682395644 GET /css/style.css 4.997 0.00906896551724 GET /js/main.js 2.478 0.0275333333333 POST /comment 2.257 0.0230306122449 GET /login 1.314 0.0168461538462 GET /admin/banned 1.131 0.02262 GET /logout 0.061 0.061 GET /initialize Request by out bytes (total avg) 2485959550 309661 GET /image/* 142499069 258619 GET /js/jquery-2.2.0.js 12206011 18953 GET / 4287247 18243 GET /@user 4105501 7451 GET /js/jquery.timeago.js 1912146 34145 GET /posts?max_created_at= 1108574 3707 GET /posts/* 980229 1779 GET /css/style.css 487635 885 GET /js/main.js 357048 648 GET /js/jquery.timeago.ja.js 195356 434 POST /login 177772 1814 GET /login 149872 272 GET /favicon.ico 34286 434 POST /register 23530 181 POST / 22200 444 GET /logout 16833 187 POST /comment 13104 168 GET /admin/banned 161 161 GET /initialize
これで考えるのは、主に次の2点です。
- トップページと
/image/に掛かる時間が一番重い。特にトップページを最初にチューニングするのが良さそう。 - 帯域は
/image/が支配的。帯域ネックになるようだったら、画像は再圧縮しにくいので、ヘッダーを適切に設定すればクライアントに "304 Not Modified" を返せるようになって大きなブレークスルーがあるかもしれない。
pprof
とりあえず app の CPU が重いので、CPUプロファイルから始めましょう。 pprof の基本的な使い方は、以前に Blog を書いたのでそれを参照してください。
diff --git a/app.go b/app.go
index 861ff03..eb52f47 100644
--- a/app.go
+++ b/app.go
@@ -9,6 +9,7 @@ import (
"io/ioutil"
"log"
"net/http"
+ _ "net/http/pprof"
"net/url"
"os"
"os/exec"
@@ -826,6 +827,8 @@ func main() {
+
+ db.SetMaxOpenConns(8)
+ db.SetMaxIdleConns(8)
defer db.Close()
+ go http.ListenAndServe(":3000", nil)
+
goji.Get("/initialize", getInitialize)
goji.Get("/login", getLogin)
goji.Post("/login", postLogin)
$ go tool pprof app http://localhost:3000/debug/pprof/profile
Fetching profile from http://localhost:3000/debug/pprof/profile
Please wait... (30s)
Saved profile in /home/isucon/pprof/pprof.localhost:3000.samples.cpu.001.pb.gz
Entering interactive mode (type "help" for commands)
(pprof) top 10
14440ms of 29650ms total (48.70%)
Dropped 546 nodes (cum <= 148.25ms)
Showing top 10 nodes out of 214 (cum >= 7370ms)
flat flat% sum% cum cum%
2270ms 7.66% 7.66% 8650ms 29.17% runtime.mallocgc
2220ms 7.49% 15.14% 2220ms 7.49% runtime.memclr
2150ms 7.25% 22.39% 2840ms 9.58% runtime.scanobject
1930ms 6.51% 28.90% 2060ms 6.95% syscall.Syscall
1280ms 4.32% 33.22% 1280ms 4.32% runtime.heapBitsSetType
1240ms 4.18% 37.40% 1270ms 4.28% runtime.(*mspan).sweep.func1
1000ms 3.37% 40.78% 1000ms 3.37% runtime.memmove
930ms 3.14% 43.91% 5070ms 17.10% database/sql.convertAssign
750ms 2.53% 46.44% 2240ms 7.55% time.parse
670ms 2.26% 48.70% 7370ms 24.86% github.com/go-sql-driver/mysql.(*textRows).readRow
メモリ管理が重いですね。あと MySQL から受け取った結果をパースしてる部分が重い。
メモリ管理が重い場合、メモリのアロケートしてる部分を見つけて潰していく方法もありますが、もっと高いレイヤーでのアプリのチューニングの方が先です。この場合 -cum オプションを使ってトップダウンにプロファイルを見ます。
(pprof) top -cum 40
10.25s of 29.65s total (34.57%)
Dropped 546 nodes (cum <= 0.15s)
Showing top 40 nodes out of 214 (cum >= 2.22s)
flat flat% sum% cum cum%
0 0% 0% 28.99s 97.77% runtime.goexit
0 0% 0% 25.69s 86.64% net/http.(*conn).serve
0 0% 0% 25.40s 85.67% net/http.(*ServeMux).ServeHTTP
...
0 0% 0% 25.08s 84.59% github.com/zenazn/goji/web/middleware.Recoverer.func1
0 0% 0% 22.42s 75.62% github.com/zenazn/goji/web.netHTTPHandlerFuncWrap.ServeHTTPC
0 0% 0% 20.61s 69.51% main.getIndex
0 0% 0% 20.26s 68.33% github.com/jmoiron/sqlx.(*DB).Select
0 0% 0% 20.26s 68.33% github.com/jmoiron/sqlx.Select
...
上位にいるリクエストハンドラーは getIndex だけです。ここに集中しましょう。
ソースコードの行単位のプロファイルを見るにはデバッグ情報が必要なので、 pprof 起動時にアプリのバイナリを指定しておく必要があります。
バイナリを指定し忘れて URL だけでプロファイルを取ってしまった場合も、起動したときの "Saved profile in ..." に表示されているパスにプロファイル結果が保存されているので、再度プロファイリングしなくても
go tool pprof app <プロファイル結果のパス> で大丈夫です。
isucon:~/private_isu/webapp/golang$ go tool pprof app /home/isucon/pprof/pprof.localhost:3000.samples.cpu.001.pb.gz
Entering interactive mode (type "help" for commands)
(pprof) list main.getIndex
Total: 29.65s
ROUTINE ======================== main.getIndex in /home/isucon/private_isu/webapp/golang/app.go
0 20.61s (flat, cum) 69.51% of Total
. . 388:
. . 389: http.Redirect(w, r, "/", http.StatusFound)
. . 390:}
. . 391:
. . 392:func getIndex(w http.ResponseWriter, r *http.Request) {
. 120ms 393: me := getSessionUser(r)
. . 394:
. . 395: results := []Post{}
. . 396:
. 18.39s 397: err := db.Select(&results, "SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC")
. . 398: if err != nil {
. . 399: fmt.Println(err)
. . 400: return
. . 401: }
. . 402:
. 1.34s 403: posts, merr := makePosts(results, getCSRFToken(r), false)
. . 404: if merr != nil {
. . 405: fmt.Println(merr)
. . 406: return
. . 407: }
. . 408:
. . 409: fmap := template.FuncMap{
. . 410: "imageURL": imageURL,
. . 411: }
. . 412:
. . 413: template.Must(template.New("layout.html").Funcs(fmap).ParseFiles(
. . 414: getTemplPath("layout.html"),
. . 415: getTemplPath("index.html"),
. . 416: getTemplPath("posts.html"),
. . 417: getTemplPath("post.html"),
. 70ms 418: )).Execute(w, struct {
. . 419: Posts []Post
. . 420: Me User
. . 421: CSRFToken string
. . 422: Flash string
. 690ms 423: }{posts, me, getCSRFToken(r), getFlash(w, r, "notice")})
. . 424:}
. . 425:
. . 426:func getAccountName(c web.C, w http.ResponseWriter, r *http.Request) {
. . 427: user := User{}
. . 428: uerr := db.Get(&user, "SELECT * FROM `users` WHERE `account_name` = ? AND `del_flg` = 0", c.URLParams["accountName"])
前回の記事の最後で myprofiler で見つけた、 posts からの LIMIT なしクエリが重い問題ですね。MySQL 側だけでなく、その大量の結果を全件取得してパースしてる app 側でも一番重くなっているようです。
このクエリの結果を利用している makePosts() の中を見てみると、ループの終端にこんな if 文があります。
if len(posts) >= postsPerPage {
break
}
この手前に continue 文もないので、このまま postsPerPage で LIMIT しましょう。 (注: これが確認不足で後でハマります)
diff --git a/app.go b/app.go
index eb52f47..3dd9804 100644
--- a/app.go
+++ b/app.go
@@ -394,7 +394,7 @@ func getIndex(w http.ResponseWriter, r *http.Request) {
results := []Post{}
- err := db.Select(&results, "SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC")
+ err := db.Select(&results, "SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC LIMIT 20")
if err != nil {
fmt.Println(err)
return
さて、計測です。本当は計測とプロファイルは別にした方がいいですが、時間が勿体無いのでプロファイルしながら計測です。
スコア:
{"pass":true,"score":12848,"success":22272,"fail":1201,"messages":["1ページに表示される画像の数が足りません (GET /)","リダイレクト先URLが正しくありません: expected '^/$', got '/login' (GET /login)"]}
あらら。エラーがでてきました。アプリのログを見ると、
fork/exec /bin/bash: cannot allocate memory
メモリが足りなくて fork に失敗してました。
top:
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 11931 isucon 20 0 406248 183372 9052 S 74.8 17.9 0:19.55 app 720 mysql 20 0 1226416 215076 10404 S 65.5 21.0 3:24.11 mysqld
CPU 使用率は app と mysql がだいたい一緒ですね。足しても200にだいぶ届かないので、CPU以外の部分がネックにりはじめていそうです。
myprofiler:
17 SELECT * FROM `posts` WHERE `id` = N 12 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= S ORDER BY `created_at` DESC 4 SELECT * FROM `users` WHERE `id` = N 3 SELECT * FROM `users` WHERE `id` = ?
posts から id 指定で1レコード取得が重くなりました。 N+1 かな？
外部プロセス呼び出しをやめる
fork に失敗するのは、多分（スワップがないせいで？）オーバーコミットがオフになっていて、fork した瞬間に app と同じだけのメモリを持ってるもう1プロセスを作れないからだと思います。
CPU使用率が2コアなのに200%に全然届かないのも fork のせい (Go のランタイムの都合上 fork するためには全 goroutine を一旦止めないといけなくて待ち時間が発生する) かもしれないので、メモリ使用量削減のために画像ファイルをDBから切り出すよりも外部プロセス呼び出しをやめる方を優先しましょう。
外部プロセスを読んでるところを見ると、 openssl dgst -sha512 コマンドで sha512 ダイジェストを計算しているようです。 Go で sha512 を計算する方法を調べて、同じ出力をするプログラムを書いてみます。
$ cat t.go < app.go
package main
import (
"crypto/sha512"
"fmt"
"io/ioutil"
"os"
)
func main() {
data, _ := ioutil.ReadAll(os.Stdin)
fmt.Printf("%x\n", sha512.Sum512(data))
}
isucon@ip-10-0-1-202:~/private_isu/webapp/golang$ go run t.go < t.go
b252b55576a4f4e321d5761b6dc980b8ee41fd9767765c785861a73b736f6a59aa7f40f7ba0d92c508dea32a20bc800e0198056c3dc8b33d5ac445f27b163d17
isucon@ip-10-0-1-202:~/private_isu/webapp/golang$ openssl dgst -sha512 < t.go
(stdin)= b252b55576a4f4e321d5761b6dc980b8ee41fd9767765c785861a73b736f6a59aa7f40f7ba0d92c508dea32a20bc800e0198056c3dc8b33d5ac445f27b163d17
これを参考に app.go を書き換えます。
@@ -125,14 +125,7 @@ func escapeshellarg(arg string) string {
}
func digest(src string) string {
- // opensslのバージョンによっては (stdin)= というのがつくので取る
- out, err := exec.Command("/bin/bash", "-c", `printf "%s" `+escapeshellarg(src)+` | openssl dgst -sha512 | sed 's/^.*= //'`).Output()
- if err != nil {
- fmt.Println(err)
- return ""
- }
-
- return strings.TrimSuffix(string(out), "\n")
+ return fmt.Sprintf("%x", sha512.Sum512([]byte(src)))
}
さて、プロファイル＆計測です。アプリのログには fork エラーが消えました。
スコア:
{"pass":true,"score":26755,"success":24050,"fail":119,"messages":["1ページに表示される画像の数が足りません (GET /)"]}
うーん、まだエラー出てますね。これは LIMIT 足したのがマズいかな？
top:
Tasks: 84 total, 1 running, 83 sleeping, 0 stopped, 0 zombie %Cpu(s): 54.2 us, 20.7 sy, 0.0 ni, 15.0 id, 1.4 wa, 0.0 hi, 8.3 si, 0.4 st KiB Mem: 1022972 total, 958404 used, 64568 free, 18292 buffers KiB Swap: 0 total, 0 used, 0 free. 425600 cached Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 720 mysql 20 0 1357488 210336 4476 S 78.6 20.6 5:19.05 mysqld 763 isucon 20 0 619612 198632 9120 S 70.2 19.4 0:13.54 app 2904 www-data 20 0 92028 4088 1928 S 11.3 0.4 0:29.40 nginx 2572 isucon 20 0 34344 11148 2160 S 7.3 1.1 0:28.48 tmux
idle が 15% まで下がってます。狙い通り。 あと、 tmux が 7% まで来ました。 Goji のログがリッチすぎるので、最後には切らないといけませんね。
myprofiler:
## 2016-05-25 20:18:44.06 +0900 13 SELECT * FROM `posts` WHERE `id` = N 9 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= S ORDER BY `created_at` DESC 9 SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC LIMIT N 6 SELECT * FROM `users` WHERE `id` = ? 6 SELECT `id` FROM `posts` WHERE `user_id` = N 4 SELECT * FROM `users` WHERE `id` = N 4 SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = ? 2 SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = N 2 SELECT * FROM `comments` WHERE `post_id` = ? ORDER BY `created_at` DESC LIMIT N 2 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `user_id` = N ORDER BY `created_at` DESC
バグ修正
makePosts() を見直してみると、投稿したユーザーが論理削除されていたら配列への追加をしないようなコードになっていました。
(Go だと early return (continue) イディオムを使うことが多いのでこの部分を見逃していました)
if p.User.DelFlg == 0 {
posts = append(posts, p)
}
SELECT の段階で強引に JOIN してこの論理削除のフィルタリングを実行してしまいます。
@@ -394,7 +387,7 @@ func getIndex(w http.ResponseWriter, r *http.Request) {
results := []Post{}
- err := db.Select(&results, "SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC LIMIT 20")
+ err := db.Select(&results, "SELECT posts.`id`, `user_id`, `body`, `mime`, posts.`created_at` FROM `posts` INNER JOIN `users` ON posts.user_id=users.id WHERE users.del_flg = 0 ORDER BY `created_at` DESC LIMIT 20")
if err != nil {
fmt.Println(err)
return
スコア:
{"pass":true,"score":27399,"success":23615,"fail":0,"messages":[]}
今度はちゃんと通りました。
top:
Tasks: 83 total, 4 running, 79 sleeping, 0 stopped, 0 zombie %Cpu(s): 53.9 us, 23.6 sy, 0.0 ni, 9.8 id, 4.2 wa, 0.0 hi, 8.2 si, 0.2 st KiB Mem: 1022972 total, 948340 used, 74632 free, 12604 buffers KiB Swap: 0 total, 0 used, 0 free. 486056 cached Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 720 mysql 20 0 1359224 209144 4576 S 85.9 20.4 6:06.96 mysqld 910 isucon 20 0 487224 139892 8884 S 67.9 13.7 0:09.58 app 2904 www-data 20 0 91852 2828 844 R 10.7 0.3 0:35.40 nginx 2572 isucon 20 0 34472 10100 928 S 6.7 1.0 0:33.64 tmux
ちょっと mysql が重いですね。
myprofiler:
15 SELECT * FROM `posts` WHERE `id` = N 7 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= S ORDER BY `created_at` DESC 6 SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC LIMIT N 5 SELECT * FROM `users` WHERE `id` = ? 5 INSERT INTO `comments` (`post_id`, `user_id`, `comment`) VALUES (?,?,?) 5 SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = N 5 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `user_id` = N ORDER BY `created_at` DESC 4 INSERT INTO `posts` (`user_id`, `mime`, `imgdata`, `body`) VALUES (?,?,?,?) 4 INSERT INTO `users` (`account_name`, `passhash`) VALUES (?,?) 3 SELECT * FROM `users` WHERE `id` = N
JOIN を足したけど、それでもまだ post を id で引くのが重いみたいです。
pprof top40 -cum:
...
0 0% 0.38% 13.88s 76.18% github.com/zenazn/goji/web/middleware.AutomaticOptions.func1
0.01s 0.055% 0.44% 8.85s 48.57% github.com/zenazn/goji/web.netHTTPHandlerFuncWrap.ServeHTTPC
0 0% 0.44% 6.11s 33.53% main.getIndex
0.02s 0.11% 0.55% 4.92s 27.00% github.com/jmoiron/sqlx.(*DB).Get
0.01s 0.055% 0.6% 4.90s 26.89% github.com/jmoiron/sqlx.Get
0 0% 0.6% 4.78s 26.23% github.com/zenazn/goji/web.handlerFuncWrap.ServeHTTPC
0.02s 0.11% 0.71% 4.65s 25.52% main.makePosts
3.82s 20.97% 21.68% 4.06s 22.28% syscall.Syscall
...
pprof list makePosts:
ROUTINE ======================== main.makePosts in /home/isucon/private_isu/webapp/golang/app.go
20ms 4.65s (flat, cum) 25.52% of Total
. . 173:}
. . 174:
. . 175:func makePosts(results []Post, CSRFToken string, allComments bool) ([]Post, error) {
. . 176: var posts []Post
. . 177:
10ms 10ms 178: for _, p := range results {
. 1.05s 179: err := db.Get(&p.CommentCount, "SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = ?", p.ID)
. . 180: if err != nil {
. . 181: return nil, err
. . 182: }
. . 183:
. . 184: query := "SELECT * FROM `comments` WHERE `post_id` = ? ORDER BY `created_at` DESC"
. . 185: if !allComments {
. 20ms 186: query += " LIMIT 3"
. . 187: }
. . 188: var comments []Comment
. 1.38s 189: cerr := db.Select(&comments, query, p.ID)
. . 190: if cerr != nil {
. . 191: return nil, cerr
. . 192: }
. . 193:
. . 194: for i := 0; i < len(comments); i++ {
. 770ms 195: uerr := db.Get(&comments[i].User, "SELECT * FROM `users` WHERE `id` = ?", comments[i].UserID)
. . 196: if uerr != nil {
. . 197: return nil, uerr
. . 198: }
. . 199: }
. . 200:
. . 201: // reverse
. . 202: for i, j := 0, len(comments)-1; i < j; i, j = i+1, j-1 {
. . 203: comments[i], comments[j] = comments[j], comments[i]
. . 204: }
. . 205:
10ms 10ms 206: p.Comments = comments
. . 207:
. 1.35s 208: perr := db.Get(&p.User, "SELECT * FROM `users` WHERE `id` = ?", p.UserID)
. . 209: if perr != nil {
. . 210: return nil, perr
. . 211: }
. . 212:
. . 213: p.CSRFToken = CSRFToken
. . 214:
. . 215: if p.User.DelFlg == 0 {
. 60ms 216: posts = append(posts, p)
. . 217: }
. . 218: if len(posts) >= postsPerPage {
. . 219: break
. . 220: }
. . 221: }
時間のかかってるクエリがコメント取得を除いて1レコード取得するだけのクエリなので、簡単なクエリを大量に投げてるのが問題で重いのでしょう。
プレースホルダがあるクエリは、デフォルトでは prepared statement を使い捨てにしている (prepare, execute, close の3コマンド) ので、明示的に prepared statement を再利用するコードを書くか、 prepared statement を使わないようにするのがいいです。
最高性能を目指すなら再利用の方がいいですが、改修が簡単なのは prepared statement を使わない方です。 dsn に interpolateParams=true を足すだけ！ (僕が実装した機能です。 参考)
diff:
@@ -805,7 +805,7 @@ func main() {
}
dsn := fmt.Sprintf(
- "%s:%s@tcp(%s:%s)/%s?charset=utf8mb4&parseTime=true&loc=Local",
+ "%s:%s@tcp(%s:%s)/%s?charset=utf8mb4&parseTime=true&loc=Local&interpolateParams=true",
user,
password,
host,
スコア:
{"pass":true,"score":30076,"success":25687,"fail":0,"messages":[]}
30k 点に到達。
top:
Tasks: 83 total, 5 running, 78 sleeping, 0 stopped, 0 zombie %Cpu(s): 63.1 us, 17.4 sy, 0.0 ni, 8.5 id, 3.4 wa, 0.0 hi, 7.4 si, 0.2 st KiB Mem: 1022972 total, 960140 used, 62832 free, 13192 buffers KiB Swap: 0 total, 0 used, 0 free. 472760 cached Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 720 mysql 20 0 1359224 209132 4128 S 79.7 20.4 6:56.71 mysqld 1010 isucon 20 0 514368 157192 8888 S 66.8 15.4 0:08.93 app 2904 www-data 20 0 91876 2824 844 R 11.3 0.3 0:41.86 nginx 1015 isucon 20 0 21176 18648 3444 R 8.3 1.8 0:01.31 myprofiler 2572 isucon 20 0 34920 10472 916 S 7.3 1.0 0:38.28 tmux
myprofiler:
18 SELECT * FROM `posts` WHERE `id` = N 11 INSERT INTO `posts` (`user_id`, `mime`, `imgdata`, `body`) VALUES (N,S,_binaryS,S) 9 SELECT * FROM `users` WHERE `id` = N 7 SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC LIMIT N 6 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `user_id` = N ORDER BY `created_at` DESC 5 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= S ORDER BY `created_at` DESC 4 SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = N 2 INSERT INTO `users` (`account_name`, `passhash`) VALUES (S,S) 1 SELECT * FROM `users` WHERE `account_name` = S AND `del_flg` = N 1 INSERT INTO `comments` (`post_id`, `user_id`, `comment`) VALUES (N,N,S)
pprof:
(pprof) top40 -cum
4.23s of 18.58s total (22.77%)
Dropped 583 nodes (cum <= 0.09s)
Showing top 40 nodes out of 317 (cum >= 2.07s)
flat flat% sum% cum cum%
0 0% 0% 17.10s 92.03% runtime.goexit
...
0 0% 0.22% 8.84s 47.58% github.com/zenazn/goji/web.netHTTPHandlerFuncWrap.ServeHTTPC
0 0% 0.22% 5.66s 30.46% main.getIndex
0 0% 0.22% 4.90s 26.37% github.com/zenazn/goji/web.handlerFuncWrap.ServeHTTPC
0 0% 0.22% 4.04s 21.74% github.com/jmoiron/sqlx.(*DB).Get
0.04s 0.22% 0.43% 4.04s 21.74% github.com/jmoiron/sqlx.Get
0 0% 0.43% 3.73s 20.08% html/template.(*Template).Execute
0.03s 0.16% 0.59% 3.50s 18.84% main.makePosts
0 0% 0.59% 3.32s 17.87% github.com/jmoiron/sqlx.(*DB).Select
0 0% 0.59% 3.32s 17.87% github.com/jmoiron/sqlx.Select
0.93s 5.01% 5.60% 3.23s 17.38% runtime.mallocgc
0 0% 5.60% 3.12s 16.79% text/template.(*Template).Execute
0.08s 0.43% 6.03% 3.12s 16.79% text/template.(*state).walk
0.01s 0.054% 6.08% 3.07s 16.52% text/template.(*state).walkTemplate
0 0% 6.08% 3.02s 16.25% text/template.(*state).walkRange
0 0% 6.08% 3.02s 16.25% text/template.(*state).walkRange.func1
0.13s 0.7% 6.78% 2.96s 15.93% runtime.systemstack
そろそろテンプレートの重さが上位に見え始めましたが、まだDBの方が重い。
まとめ
スコア: 4745 (初期状態) -> 14208 (前回) -> 30076 (今回)
さて、そろそろプロファイルで重いところを潰すチューニングは、乾いた雑巾絞りに近づいてきました。 次回はもっとドラスティックなチューニングに移っていきたいと思います。
今回は pprof や myprofiler を使ったチューニングの紹介の意図があったのでちょっとやりすぎてしまいました。 実際にはもっと早めに大改造を必要とするようなチューニングを考えて実行しないと、後半に時間が足りなくてジリ貧になってしまうので気をつけましょう。
@methane
pixiv private isucon 2016 攻略 (1/5)
攻略記事一覧:
pixiv さんが社内で開催したプライベート ISUCON の AMI を公開してくれたので、手順を残しながら攻略していきます。
この記事の対象読者は途中で何をすればいいかわからなくなってしまう ISUCON 初心者です。 Go を利用して攻略していきますが、他の言語で参加する場合でも考え方などは参考になると思います。
最低限の初期設定
ssh の公開鍵を入れたり、エディターや git などのツール類をインストール・設定します。
このあたりは事前に自分用のチートシートやスクリプトを作って、手早くできるようにしておきましょう。
マシン調査
スペック
とりあえず CPU とメモリくらいはちゃんと把握しておきましょう。
$ grep processor /proc/cpuinfo
processor : 0
processor : 1
$ free -m
total used free shared buffers cached
Mem: 998 906 92 12 25 335
-/+ buffers/cache: 545 453
Swap: 0 0 0
CPUは2コアですね。メモリはトータル1GBでスワップなし。要注意です。
ps aux
何が動いているか確認します。 メールサーバーとか、AppArmor のような、競技に明らかに不要そうなデーモンは、ベンチマークスコアを安定させるためとメモリの節約のために落としておいたほうが良いです。
今回は特に何もする必要はありませんでした。
アプリの仕様把握
初期状態に復元する手順を確認してから、実際にアプリをブラウザからさわってみましょう。
初期状態への復元は、 tar でアーカイブしてローカルに持ってきておいたり、 mysqldump を取ったりしておくと良いです。
ただし今回の場合はAMIからやり直せるので、 /initialize というパスで初期化されると言うことだけアプリのコードで確認し、バックアップは手抜きしました。
ISUCON 本番では初期状態を復元するのに必要なデータをオペミスで失うと即死する恐れがあるので注意しましょう。
ブラウザのデバッグ機能でどういう通信をしているのか見たり、アプリのコードのURLルーティング部分を中心に軽く目を通したり、 mysqldump --no-data isuconp で取得したスキーマを参考に、ざっくりと全体像を把握していきます。
nginx の基礎設定
アクセスログを事前に用意しておいたフォーマットに変更して、 upstream への keepalive を付ける。
コア数少ないので worker_processes を 1 にして、 keepalive の効率を上げる。
静的ファイルを nginx から返す設定は、アプリの動作を把握してからでも遅くない。 Go 以外を使う人は、完全に静的なファイルが分かった段階ですぐに、Go を使う人はある程度チューニングが進んで nginx を外すかどうかを判断するタイミングで nginx から返すようにしよう。
/etc/nginx/nginx.conf:
worker_processes 1;
...
##
# Logging Settings
##
log_format isucon '$time_local $msec\t$status\treqtime:$request_time\t'
'in:$request_length\tout:$bytes_sent\trequest:$request\t'
'acceptencoding:$http_accept_encoding\treferer:$http_referer\t'
'ua:$http_user_agent';
access_log /var/log/nginx/access.log isucon;
/etc/nginx/sites-enabled/isucon.conf:
upstream app {
server 127.0.0.1:8080;
keepalive 32;
}
server {
listen 80;
client_max_body_size 10m;
root /home/isucon/private_isu/webapp/public/;
location / {
proxy_set_header Host $host;
proxy_set_header X-Real-IP $remote_addr;
proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
proxy_pass http://app;
}
}
あと、今回は Go を使うので ruby と php のサービスも止めてしまいます。 Go のサービスは開発中はコマンドラインで起動したいのでここでは設定しません。
$ sudo systemctl stop isu-ruby $ sudo systemctl disable isu-ruby $ sudo systemctl stop php7.0-fpm $ sudo systemctl disable php7.0-fpm
MySQL の基礎設定
/etc/mysql/my.cnf を見てみます。ほぼディストリのデフォルトで使っているようなので、メモリ使用量削減とIO待ち削減のために次の設定だけ追加しておきます。
innodb_flush_method = O_DIRECT innodb_flush_log_at_trx_commit = 2
重いクエリを手早く見つけるためのツールを用意する。僕の場合は myprofiler を使う。
$ wget https://github.com/KLab/myprofiler/releases/download/0.1/myprofiler.linux_amd64.tar.gz $ tar xf myprofiler.linux_amd64.tar.gz $ sudo mv myprofiler /usr/local/bin/
myprofiler の使い方は、 myprofiler -user=root です。クエリが減ってきたら myprofiler -user=root -interval=0.2 くらいにサンプリング間隔を短くすると良いでしょう。それ以外のオプションは myprofiler -h で確認してください。
ベンチマークの実行とざっくり状況把握
スコア:
{"pass":true,"score":4745,"success":4408,"fail":0,"messages":[]}
top:
Tasks: 81 total, 1 running, 80 sleeping, 0 stopped, 0 zombie %Cpu(s): 94.1 us, 4.2 sy, 0.0 ni, 0.3 id, 0.0 wa, 0.0 hi, 1.3 si, 0.0 st KiB Mem: 1022972 total, 701036 used, 321936 free, 21396 buffers KiB Swap: 0 total, 0 used, 0 free. 346564 cached Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 720 mysql 20 0 1087768 140276 10724 S 142.8 13.7 0:52.09 mysqld 2908 isucon 20 0 582876 124364 8800 S 46.6 12.2 0:12.98 app 2904 www-data 20 0 91680 4800 2988 S 1.7 0.5 0:00.61 nginx
MySQL が app の3倍CPU食ってるのがわかります。
myprofiler:
198 SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC LIMIT N 124 SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = N 11 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC 9 SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC 5 SELECT * FROM `posts` WHERE `id` = N 4 SELECT COUNT(*) AS count FROM `comments` WHERE `post_id` IN (...N) 2 SELECT * FROM `users` WHERE `id` = ? 2 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= S ORDER BY `created_at` DESC 1 SELECT * FROM users WHERE account_name = S AND del_flg = N 1 SELECT COUNT(*) AS count FROM `comments` WHERE `user_id` = N
comments の SELECT と COUNT が遅い事がわかる。その次に posts の select。
一番最初のチューニング: インデックス
上位3件のクエリについて、インデックスが有るか確認して、なければ張っておく。
mysql> show create table comments\G
*************************** 1. row ***************************
Table: comments
Create Table: CREATE TABLE `comments` (
`id` int(11) NOT NULL AUTO_INCREMENT,
`post_id` int(11) NOT NULL,
`user_id` int(11) NOT NULL,
`comment` text NOT NULL,
`created_at` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP,
PRIMARY KEY (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=100049 DEFAULT CHARSET=utf8mb4
1 row in set (0.00 sec)
mysql> show create table posts\G
*************************** 1. row ***************************
Table: posts
Create Table: CREATE TABLE `posts` (
`id` int(11) NOT NULL AUTO_INCREMENT,
`user_id` int(11) NOT NULL,
`mime` varchar(64) NOT NULL,
`imgdata` mediumblob NOT NULL,
`body` text NOT NULL,
`created_at` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP,
PRIMARY KEY (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=10056 DEFAULT CHARSET=utf8mb4
1 row in set (0.00 sec)
comments.post_id と posts.created_at にインデックスがない。重いクエリ上位3つがこれ。
mysql> create index post_id on comments (post_id); Query OK, 0 rows affected (0.19 sec) Records: 0 Duplicates: 0 Warnings: 0 mysql> create index created_at on posts (created_at); Query OK, 0 rows affected (0.03 sec) Records: 0 Duplicates: 0 Warnings: 0
とりあえずこれでもう一度計測しておきます。
top:
top - 18:13:32 up 2:13, 1 user, load average: 2.01, 0.84, 0.52 Tasks: 79 total, 1 running, 78 sleeping, 0 stopped, 0 zombie %Cpu(s): 74.0 us, 19.3 sy, 0.0 ni, 3.2 id, 0.2 wa, 0.0 hi, 3.4 si, 0.0 st KiB Mem: 1022972 total, 944288 used, 78684 free, 23344 buffers KiB Swap: 0 total, 0 used, 0 free. 462656 cached Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 2908 isucon 20 0 640148 174444 8800 S 109.7 17.1 0:44.93 app 720 mysql 20 0 1093212 212252 10740 S 58.5 20.7 1:56.57 mysqld
app が mysql の 2倍になり、クエリがネックじゃなくなったのがわかります。
スコア:
{"pass":true,"score":14208,"success":13157,"fail":0,"messages":[]}
myprofiler:
36 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC 15 SELECT COUNT(*) AS count FROM `comments` WHERE `user_id` = N 5 SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC LIMIT N 4 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= S ORDER BY `created_at` DESC
上位2件を見ると
postsからの SELECT に LIMIT が無いcomments.user_idにインデックスがない
LIMIT がないのはアプリ側で修正が必要なのと、ボトルネックがアプリに移ってるので、アプリ改修に移る。
comments.user_id はついでにインデックス張っておく。（1番重いクエリじゃないのでベンチは省略）
mysql> create index user_id on comments (user_id); Query OK, 0 rows affected (0.14 sec) Records: 0 Duplicates: 0 Warnings: 0
まとめ
スコア: 4745 (初期状態) -> 14208 (インデックスチューニング)
systemd のコマンドとか nginx の設定とか MySQL の設定ファイルを見るとかインデックス張るとかいろいろ慣れて、ここまではスムーズにできるようになりましょう。
感覚値ですが、一人でやってる場合はここまでを2時間以内には終わらせられるようにしましょう。1時間を切れればスゴイです。
@methane
Go ではエラーを文字列比較する？という話について
Go で関数の戻り値のエラーを判別するときに、エラーメッセージの文字列をチェックするコードが存在します。 (例)
これは、 Go が言語設計としてエラー処理が貧弱だったり、標準ライブラリがエラー処理を軽視しているからでしょうか？ 言語設計や標準ライブラリのAPIの設計をみて行きましょう。
TL;DR
- 言語設計としては、Java的例外機構と同等以上の（文字列比較によらない）エラー検査が可能
- ただし Go のエラーに関する哲学により、公開されていないエラーが多い
- 実際にエラーを文字列比較されている実例についての解説
Go のエラー検査方法
Java の例外機構では、例外をキャッチするために専用の構文が用意されており、型によりマッチングすることができます。 これはクラスのツリー構造を利用してサブクラスをまとめて分岐することもできます。 一方で、同じクラスでも値によりエラー処理が異なる場合には、 try をネストしないといけないケースが有ります。
作為的な例ですが、例外が Errno クラスで、なおかつその errno が EINTR の場合はリトライし、それ以外のケースでは終了するコードはこうなります。
try {
while (true) {
try {
// ...
} catch (Errno e) {
if (e.getErrno() == Errno.EINTR) {
continue;
}
throw e;
}
}
} catch (Exception e) {
System.err.println(e.getMessage());
System.exit(1);
}
Go の場合、一般的にエラーは error というインターフェイスによって返されます。 Go にはエラー検査専用の構文はありませんが、インターフェイス一般に使える conversion 構文が Java の catch と同等以上の機能を持っているので、問題になりません。conversion には次の2種類の書き方があり、場面によって使い分けます。
// シンプルな conversion.主に if 文と組み合わせて使う。型以外の条件式を if 文に書ける。
if nerr, ok := err.(net.Error); ok && nerr.Temporary() {
continue
}
// Type switch. 複数の型の振り分けを見やすく書ける
switch e := err.(type) {
case net.Error:
if e.Temporary() {
continue
}
// ...
}
実際には複数のエラー型を扱うケースはあまりないのと、 io.EOF の様に型ではなく定数と比較するエラーがあるので、シンプルな conversion と if 文の組み合わせがよく使われます。
conversion は具体型だけでなく別の interface への変換も可能なので、 interface を抽象型として使うことで、 Java の例外階層と同じように複数の型のエラーをまとめて扱うことができます。例えば、 syscall.Errno は net.Error インターフェイスを実装しているので、先ほどのコードは次のようにより一般的に書くことができます。
defer r.Close()
for {
data, err := r.Read()
// 最後のデータを読み込みつつEOFが返る事があるので、エラーチェックよりdataチェックが先
if len(data) > 0 {
received <- data
}
if err == io.EOF {
break
}
if err != nil {
if nerr, ok := err.(net.Error); ok && nerr.Temporary() {
continue
}
log.Error(err)
break
}
}
Go のエラーに関する哲学
Go の作者の一人である Dave Cheney 氏のBlog に、Goのエラーに対する重要な哲学が紹介されています。
In the majority of cases, error values returned from functions should be opaque to the caller. That is to say, a test that error is nil indicates if the call succeeded or failed, and that’s all there is to it.
A small number of cases, generally revolving around interactions with the world outside your process, like network activity, require that the caller investigate the nature of the error to decide if it is reasonable to retry the operation.
訳:
ほとんどのケースにおいて、関数が返した error 値は呼び出し元にとって不透明であるべきです。 error が nil かどうかチェックすることで呼び出しが成功したかどうかを知ることができ、そしてそれ以上のことはできません。
少ないケースにおいて、主にネットワークなどプロセス外の世界とやりとりする場合に、呼び出し側がエラーの種別を調べて、操作をリトライするべきかどうかを決める必要があります。
この "error ... should be opaque to the caller" の部分は、後で紹介する issue でも Go の philosophy だと言及されています。 この Blog 記事は改めて翻訳したいと思いますが、要約すると次のような方針になっているようです。
- 可能な限り個別の具体的なエラー型やエラー定数はパッケージ外に公開しない
- エラー処理が必要な場合は、代わりに
Timeout() boolやTemporary() boolといった目的に応じたメソッドを定義する
この設計思想のために、特定のエラーを判別するためにエラーメッセージを文字列マッチするしか方法がないケースがあります。
Go で文字列でエラーを判別している実例
一番よく文字列比較されてしまっているエラーが、たぶん net.errClosing です。これは次のように非公開で定義されているエラー定数です。
errClosing = errors.New("use of closed network connection")
このエラーは、 Close された Listener や Conn の Accept(), Read(), Write(), Close() などのメソッドを呼び出した時に返されます。
このエラーは net パッケージ自身も戻り値として返す場合とテスト中でしか使われておらず、 if err == errClosing のような使い方はされていません。
このエラーを受け取った呼び出し側はができる回復処理は無いので、 "should be opaque" なのだと思います。
一方で、 Go はネットワークのブロッキングIOをランタイムで隠蔽してノンブロッキングIOのAPIを提供している言語なので、 Listener.Accept() や Conn.Read() は呼び出し側をブロックします。これらのメソッドを利用するときは独立した goroutine を使います。そして Accept() や Read() している goroutine を止める手段は、その Listener や Conn を Close() することです。一般的な設計のネットワークプログラムで、正常系として、 errClosing が返るのです。
errClosing のような回復不能なエラーが発生した時、一般的な後処理は、Connであればそのセッションを捨てる、Listener であればプログラム自体を止めることですが、その際にエラーをログに書くべきです。しかし、 errClosing のような正常系で発生するエラーをエラーログに書いていたら、より重要なエラーログが埋もれてしまいます。
Close() したあとの Accept() や Read() のエラーを無視することもできますが、 Close() するのは別の goroutine なので面倒ですし、 errClosing 以外のエラーまで無視してしまう可能性がある気持ち悪さも残ります。
この errClosing を公開してほしいという Issue golang/go#4373 があり、エラーログに書きたくないというユースケースが投稿された結果、 Won't fix ラベルが解除されました。まだ修正されると決まったわけではありませんが、設計者の想定（回復できないエラーを個別に見せる必要がない）と実際のユースケース（このエラーはログに書きたくない）のミスマッチの一番の例だと思います。
go#4373 と関連する Issue として、golang/go#9405 もあります。
こちらは、 http クライアントをタイムアウト付きで利用した際に (Timeout() bool を実装していない) errClosing がそのまま返されてしまうという問題で、開発中の Go 1.5 では修正済みの問題なのですが、現在リリースされている Go 1.4 までではタイムアウトしたかどうかを判定するために errClosing の文字列比較が必要になってしまっています。
このように、決して多くは無いものの、設計者の想定していないユースケースやバグによりエラーを文字列比較で判定しているケースが残念ながら存在します。 ただし、あくまでもこれらは例外であって、 Go のエラー処理が弱いからエラーを文字列比較しないといけないといったようなことはなく、 Go の哲学は現実的にうまく機能していると思います。
@methane
Goでアロケーションに気をつけたコードを書く方法
GoはPythonのようなLLと比べると実行速度は速いのですが、GCは特別速いわけではないので、相対的にGCがパフォーマンスに与える影響は大きくなります。
また、Java に比べると、一時オブジェクトなどのために頻繁にヒープアロケーションを行うとGCの停止時間が長くなりがちですが、一方でヒープアロケーションを避けたプログラミングがしやすい言語でもあります。
MySQL ドライバのような低レイヤーのライブラリを作る場合、アプリケーション側の性能要件を勝手に決めることができないので、現実的な範囲でアロケーションを減らす努力をするべきです。
ということで、前回の記事 で紹介したプレースホルダ置換を実装するにあたって経験した、アロケーションに気を使ったプログラミングについて、チューニングする手順やコード上のテクニックを紹介したいと思います。
1. まずは正しく動くものを作る
go-sql-driver/mysql のメンテナに受け入れられるかどうか分からない機能だったので、最初はなるべく簡単に実装して、この機能を取り込むかどうか、APIや設計はこれでいいかという話から始めます。
2. ベンチマークプログラムを書く
チューニングを始める前に、効果確認用のベンチマークプログラムを書きます。 テストと同じく _test.go という名前で終わるファイルに、 BenchmarkXxxx(b *testing.B) という関数を定義します。その中で b.ReportAllocs() を呼んでおくとアロケート回数を計測することができます。
今回作成したベンチマークプログラムは次のようなものです。 database/sql がユーザーが渡した値を正規化してくれるので、ドライバ側に渡される値は int64, float64, bool, time.Time, []byte, string の6つの型だけになります。そこで6つの方の値を1つずつ用意して、プレースホルダ置換を実行しています。
func BenchmarkInterpolation(b *testing.B) {
mc := &mysqlConn{
cfg: &config{
interpolateParams: true,
loc: time.UTC,
},
maxPacketAllowed: maxPacketSize,
maxWriteSize: maxPacketSize - 1,
}
args := []driver.Value{
int64(42424242),
float64(math.Pi),
false,
time.Unix(1423411542, 807015000),
[]byte("bytes containing special chars ' \" \a \x00"),
"string containing special chars ' \" \a \x00",
}
q := "SELECT ?, ?, ?, ?, ?, ?"
b.ReportAllocs()
b.ResetTimer()
for i := 0; i < b.N; i++ {
_, err := mc.interpolateParams(q, args)
if err != nil {
b.Fatal(err)
}
}
}
実行するには次のようなコマンドを実行します。
$ go test -bench=BenchmarkInterpolation PASS BenchmarkInterpolation 300000 3887 ns/op 1144 B/op 15 allocs/op ok github.com/go-sql-driver/mysql 2.386s
3. アロケーションが起こっている場所を調べる
GODEBUG=allocfreetrace=1 という環境変数を設定すると、アロケートが起こった場所のスタックトレースを見ることができます。 (ドキュメント)
そこで、ベンチマークプログラムのループの中身だけを実行する小さなプログラムを用意したいのですが、今回用意しているのは小文字から始まる名前の内部処理なので、 main パッケージから直接呼び出すことはできません。 mysql パッケージにコミットに含めないソースファイルを追加してそこから呼び出せば良いのですが、今回はベンチマークプログラムを直接利用することにしました。
GODEBUG を設定したまま go test を実行するとノイズが多すぎるので、先に go test -c を使って mysql.test という実行ファイルを作り、それを実行します。その際、オプションは go test に渡すオプションに test. という prefix をつけることになります。
$ go test -c $ GODEBUG=allocfreetrace=1 ./mysql.test -test.run=none -test.bench=BenchmarkInter -test.benchtime=10ms 2>trace.log PASS BenchmarkInterpolation 5000 4095 ns/op 1144 B/op 15 allocs/op
この例では、 -test.run にどのテストにもマッチしない適当な名前 none を指定してベンチマーク以外のテストが実行されることを防ぎ、 -test.bench で目的以外のベンチマーク関数の実行を抑止し、 -test.benchtime=10ms でデフォルト1秒のベンチマーク時間を短くしています。標準エラー出力にアロケートのスタックトレースが出力されているので、それを trace.log に出力しています。
目的の関数である interpolateParams を探し、それより手前を削除します。すると次のようなスタックトレースが得られます。
tracealloc(0xc2080100e0, 0x70, string) goroutine 5 [running]: runtime.mallocgc(0x70, 0x22e4e0, 0x0, 0x2) /usr/local/Cellar/go/1.4.1/libexec/src/runtime/malloc.go:327 +0x32a fp=0xc20802ea60 sp=0xc20802e9b0 runtime.newarray(0x22e4e0, 0x7, 0x15c5e) /usr/local/Cellar/go/1.4.1/libexec/src/runtime/malloc.go:365 +0xc1 fp=0xc20802ea98 sp=0xc20802ea60 runtime.makeslice(0x2229c0, 0x7, 0x7, 0x0, 0x0, 0x0) /usr/local/Cellar/go/1.4.1/libexec/src/runtime/slice.go:32 +0x15c fp=0xc20802eae0 sp=0xc20802ea98 strings.genSplit(0x30c190, 0x17, 0x2e1f10, 0x1, 0x0, 0x7, 0x0, 0x0, 0x0) /usr/local/Cellar/go/1.4.1/libexec/src/strings/strings.go:287 +0x14d fp=0xc20802eb60 sp=0xc20802eae0 strings.Split(0x30c190, 0x17, 0x2e1f10, 0x1, 0x0, 0x0, 0x0) /usr/local/Cellar/go/1.4.1/libexec/src/strings/strings.go:325 +0x76 fp=0xc20802ebb0 sp=0xc20802eb60 github.com/go-sql-driver/mysql.(*mysqlConn).interpolateParams(0xc20802eed0, 0x30c190, 0x17, 0xc20802ee70, 0x6, 0x6, 0x0, 0x0, 0x0, 0x0) /Users/inada-n/go1.4/src/github.com/go-sql-driver/mysql/connection.go:180 +0x86 fp=0xc20802ed38 sp=0xc20802ebb0 github.com/go-sql-driver/mysql.BenchmarkInterpolation(0xc20806a400) /Users/inada-n/go1.4/src/github.com/go-sql-driver/mysql/benchmark_test.go:240 +0x437 fp=0xc20802ef58 sp=0xc20802ed38 testing.(*B).runN(0xc20806a400, 0x1) /usr/local/Cellar/go/1.4.1/libexec/src/testing/benchmark.go:124 +0x95 fp=0xc20802ef68 sp=0xc20802ef58 testing.(*B).launch(0xc20806a400) /usr/local/Cellar/go/1.4.1/libexec/src/testing/benchmark.go:199 +0x78 fp=0xc20802efd8 sp=0xc20802ef68 runtime.goexit() /usr/local/Cellar/go/1.4.1/libexec/src/runtime/asm_amd64.s:2232 +0x1 fp=0xc20802efe0 sp=0xc20802efd8 created by testing.(*B).run /usr/local/Cellar/go/1.4.1/libexec/src/testing/benchmark.go:179 +0x3e ...(続く)
このスタックトレースで interpolateParams() から strings.Split() を呼び出している部分でアロケートが発生していることが分かります。
ソースコードのファイル名と行数も書かれているので、簡単に該当部分を特定できます。
func (mc *mysqlConn) interpolateParams(query string, args []driver.Value) (string, error) {
chunks := strings.Split(query, "?")
if len(chunks) != len(args)+1 {
return "", driver.ErrSkip
}
余談ですが、スタックトレースのような「たくさんの英数字」を見た時に、反射的に無視してエラーメッセージだけをコピペして質問する人をよく見かけます。確かに読むのに気力がいるかもしれませんが、スタックトレースはその言語やアプリケーションを深く知る重要な手がかりなので、デバッグ時やチューニングするときなどはしっかりと向きあいましょう。
4. チューニング
これで準備は万端です。あとは1つ1つ改善しながらで効果を確認していくだけです。とりあえず初期状態のベンチマーク結果を残しておきましょう。
$ go test -bench=BenchmarkInterpolation | tee old.txt PASS BenchmarkInterpolation 500000 3942 ns/op 1144 B/op 15 allocs/op ok github.com/go-sql-driver/mysql 3.219s
4.1. 文字列連結から []byte への append へ
最初の実装は、クエリ文字列を ? で分割して、 parts []string に分割された各クエリ文字列と、パラメータを文字列化したものを交互に格納し ("SELECT SLEEP(0)", 42 なら []string{"SELECT SLEEP(", "42", ")"})、最後に strings.Join(parts, "") で結合するという、LLで書くようなコードでした。
Go の文字列は immutable なので、小さい文字列をたくさんつくるこの方式ではアロケートが増えるのを避けられません。そこで、最初に []byte のバッファを確保してそこに追記していくようにしました。
バッファの容量は先にクエリ文字列と各パラメータから概算して確保することで、リアロケーションを避けます。整数や実数は strconv.AppendInt() という、 []byte に追記しつつ文字列化する関数が標準ライブラリに用意されているのでそれを使います。これで次のようなコードになりました。
buf := make([]byte, 0, estimated)
argPos := 0
// Go 1.5 will optimize range([]byte(string)) to skip allocation.
for _, c := range []byte(query) {
if c != '?' {
buf = append(buf, c)
continue
}
arg := args[argPos]
argPos++
if arg == nil {
buf = append(buf, []byte("NULL")...)
continue
}
switch v := arg.(type) {
case int64:
buf = strconv.AppendInt(buf, v, 10)
4.2. benchcmp
これで一旦効果を確認します。その際、 benchcmp というツールを使って比較し、それをコミットログに含めると Go のコミッタみたいでクールです。
$ go get -u golang.org/x/tools/cmd/benchcmp $ go test -bench=BenchmarkInterpolation > new.txt $ benchcmp old.txt new.txt benchmark old ns/op new ns/op delta BenchmarkInterpolation 3942 2573 -34.73% benchmark old allocs new allocs delta BenchmarkInterpolation 15 6 -60.00% benchmark old bytes new bytes delta BenchmarkInterpolation 1144 560 -51.05%
アロケート回数が 15 から 6 に減っているのが分かります。実行速度もメモリ消費も大幅に削減できていますね。
4.3. Time.Format() を避ける
int64 と float64 は strconv.AppendInt() と strconv.AppendFloat() でそれぞれ []byte に追記することが出来ましたが、残念ながら time.Time にはそのようなメソッドがありません。
そこで、ベッタベタなコードで文字列表現を作ります。
before:
case time.Time:
if v.IsZero() {
buf = append(buf, []byte("'0000-00-00'")...)
} else {
fmt := "'2006-01-02 15:04:05.999999'"
if v.Nanosecond() == 0 {
fmt = "'2006-01-02 15:04:05'"
}
s := v.In(mc.cfg.loc).Format(fmt)
buf = append(buf, []byte(s)...)
}
after:
case time.Time:
if v.IsZero() {
buf = append(buf, "'0000-00-00'"...)
} else {
v := v.In(mc.cfg.loc)
v = v.Add(time.Nanosecond * 500) // To round under microsecond
year := v.Year()
year100 := year / 100
year1 := year % 100
month := v.Month()
day := v.Day()
hour := v.Hour()
minute := v.Minute()
second := v.Second()
micro := v.Nanosecond() / 1000
buf = append(buf, []byte{
'\'',
digits10[year100], digits01[year100],
digits10[year1], digits01[year1],
'-',
digits10[month], digits01[month],
'-',
digits10[day], digits01[day],
' ',
digits10[hour], digits01[hour],
':',
digits10[minute], digits01[minute],
':',
digits10[second], digits01[second],
}...)
if micro != 0 {
micro10000 := micro / 10000
micro100 := micro / 100 % 100
micro1 := micro % 100
buf = append(buf, []byte{
'.',
digits10[micro10000], digits01[micro10000],
digits10[micro100], digits01[micro100],
digits10[micro1], digits01[micro1],
}...)
}
buf = append(buf, '\'')
}
after は最終版のコードで、チューニング以外にマイクロ秒部分が0なら省略するなどの改善も入っています。
digits10, digits01 は除算を減らすために 0~99 の10の位と1の位の文字を並べたものです。これは今回用意したものではなくて既に mysql ドライバの他の箇所で利用されていた最適化を適用しました。
これでアロケートを2つ減らせました。
benchmark old allocs new allocs delta
BenchmarkInterpolation 6 4 -33.33%
4.4. 文字列に対して range を使わない
Go でループを使うときは良く range 構文を使うのですが、 string 型の s に対して for i, c := range s { とすると、バイト単位ではなく unicode の code point 単位でループしてしまいます。
for i, c := range([]byte(s)) { のように []byte にキャストしてループしていたのですが、ここで string から []byte への変換でアロケートとコピーが実行されてしまいます。 (Go 1.5 では最適化されます)
そこで、これを C 言語風の for 文に書き直します。
@@ -210,8 +210,8 @@ func (mc *mysqlConn) interpolateParams(query string, args []driver.Value) (strin
buf := make([]byte, 0, estimated)
argPos := 0
- // Go 1.5 will optimize range([]byte(string)) to skip allocation.
- for _, c := range []byte(query) {
+ for i := 0; i < len(query); i++ {
+ c := query[i]
if c != '?' {
これでもう1つアロケートを減らすことができました。
benchmark old allocs new allocs delta
BenchmarkInterpolation 4 3 -25.00%
4.5. []byte に string を直接 append する
Go の append には、 []T 型のスライス ts に T 型の要素 t を1つ追加する ts = append(ts, t) と、別の []T 型のスライス ts2 を結合する ts = append(ts, ts2...) の2つの使い方があります。
ただし []byte に string を追記する場合については、 string が []byte 型であるかのように直接 append を利用することができます。 buff = append(buff, s...)
アロケートを避けるために 1 バイトずつ append していた部分を改良したり、文字列リテラルをキャストしながら append していた部分(最適化されて余計なアロケートとコピーは発生しない)を簡潔にする事ができました。
@@ -210,17 +210,19 @@ func (mc *mysqlConn) interpolateParams(query string, args []driver.Value) (strin
argPos := 0
for i := 0; i < len(query); i++ {
- c := query[i]
- if c != '?' {
- buf = append(buf, c)
- continue
+ q := strings.IndexByte(query[i:], '?')
+ if q == -1 {
+ buf = append(buf, query[i:]...)
+ break
}
+ buf = append(buf, query[i:i+q]...)
+ i += q
arg := args[argPos]
argPos++
if arg == nil {
- buf = append(buf, []byte("NULL")...)
+ buf = append(buf, "NULL"...)
continue
}
今回はこれでアロケートを避けられる部分は無かったですが、 []byte に append していくコードを書くときに覚えておきたい Tips でした。
4.6. []bytes 用の関数と string 用の関数を別に用意する
[]byte 型の引数と string 型の引数は両方同じようにクォート、エスケープします。
しかし、残念ながら Go は []byte と string の間の変換でアロケート＆コピーが発生してしまいます。
最適化で除去されるのは buf = append(buf, []byte("NULL")...) のようなシンプルなケースだけで、 string を引数に取る関数に []byte を string(bs) でキャストして渡す場合やその逆のケースでは現在の Go では最適化されません。
そこで、全く同じエスケープ処理を行う関数を、 []byte を引数に取るバージョンと string を引数に取るバージョンの2つ用意します。
せめてループ内の switch だけでも共通化できないかと思いましたが、インライン展開を行うしきい値となる大きさを超えてしまうようで性能が落ちてしまったので、殆どコピペな2つの関数を用意することになりました。
これは実行するべきか迷ったのですが、クエリ文字列に比べて、パラメータに渡される文字列／バイト列は BLOB や TEXT 型の大きなデータである可能性があるので、速度・アロケート共に妥協しないことにしました。
コピペコードはもちろんメンテナンス性に悪影響を及ぼすので、これは最後の手段です。将来の Go のバージョンで何らかの回避手段が用意されることを期待します。
これで、アロケート回数が2つにまで減りました。
benchmark old ns/op new ns/op delta
BenchmarkInterpolation 2463 2118 -14.01%
benchmark old allocs new allocs delta
BenchmarkInterpolation 3 2 -33.33%
benchmark old bytes new bytes delta
BenchmarkInterpolation 496 448 -9.68%
4.7. 送受信バッファの再利用
最後に残った2つのアロケートは、最初にバッファを用意する部分と、最後に MySQL にコマンドを投げる関数に渡す文字列を作るためにバッファを string にキャストする2箇所です。
MySQL にコマンドを送信するときに利用している送信用のバッファに、パケットヘッダの部分を空けて直接クエリを生成することで最後の2つのアロケートも消すことができます。
しかし、既存のコマンドを送る部分の設計を汚してしまうのと、テストがしにくくなるので、直接パケットを作って送るのは自重しておいて、送信用のバッファをinterpolateに使えだけにしました。送信するパケットはクエリに4バイトのヘッダを付けたものなので、サイズ的にも再利用するのにぴったりです。
benchmark old ns/op new ns/op delta
BenchmarkInterpolation 1900 1403 -26.16%
benchmark old allocs new allocs delta
BenchmarkInterpolation 2 1 -50.00%
benchmark old bytes new bytes delta
BenchmarkInterpolation 448 160 -64.29%
まとめ
アロケート箇所を特定する方法や、主に文字列処理をチューニングする際に覚えておきたいコーディング上の Tips を紹介しました。
@methane
go-sql-driver/mysql でプレースホルダ置換をサポートしました
前回の記事で少し触れましたが、 go-sql-driver/mysql にドライバ側でのプレースホルダ置換を実装するプルリクエストを出していました。
それがマージされたので、背景のおさらいと利用方法を紹介しておきます。
背景
Go の database/sql の概要については前回の記事で解説しました。
そこで説明したとおり、 DB.Prepare() を使わずに直接 DB.Exec() や DB.Query() を使った場合、
ドライバ側でのプレースホルダ置換に対応していないドライバでは prepare, exec, close
で3回のラウンドトリップが発生することになり、パフォーマンスが悪くなります。
基本的には DB.Prepare() を使えばいいのですが、前回の記事で修正したスケーラビリティの問題は Go 1.5 になるまで直りませんし、
IN 句があるSQL文などで事前に Prepare するのが難しいケースも有ります。
また、O/Rマッパーやクエリビルダーを使う場合、そのライブラリが Prepared Statement のキャッシュに対応していないと、
アプリケーションプログラマが制御できない部分で DB.Prepare() を使わないで DB.Query() が使われるケースが出てきます。
ちょうど prepared statement をクエリの都度発行するデメリットが 幾つかの
場所で 話題になったこともあり、 go-sql-driver/mysql にオプションを付与する RFC (Request For Comment)
だったプルリクエストがマージに向けて動き始めました。(マージされるまでに行ったチューニングについてはまた次回紹介しようと思います。)
go-sql-driver/mysql のプレースホルダ置換について
go-sql-drvier/mysql は go get -u github.com/go-sql-driver/mysql で取得します。
まだこの機能はマージされたばかりなので、すでに利用されている方は再度このコマンドを実行して更新してください。
sql.Open() の第二引数に渡す dsl で interpolateParams=true というオプションをURLのクエリパラメタの形で渡すことにより、プレースホルダ置換が有効になります。
ただし、文字列をエスケープする際にバイト単位で処理しているので、 collation オプションで cp932 や big5 など危険なエンコーディングを指定した場合はエラーにしています。
(ちなみに、 go-sql-driver/mysql でコネクションのエンコーディングを指定する charset オプションは非推奨なので、 collation オプションを利用してください)
collationは指定しない場合デフォルトで utf8_general_ci ですが、次の例では utf8mb4_bin に指定しています。
package main
import (
"database/sql"
"log"
_ "github.com/go-sql-driver/mysql"
)
func main() {
// localhost の 3306 番ポートで動いている MySQL に、ユーザー名=root, パスワード=password, データベース=test で接続する。
// interpolateParams=true オプションを利用する。
db, err := sql.Open("mysql", "root:password@tcp(localhost:3306)/test?interpolateParams=true&collation=utf8mb4_bin")
// プレースホルダ置換を行わない場合はこちら
//db, err := sql.Open("mysql", "root:password@tcp(localhost:3306)/test?collation=utf8mb4_bin")
if err != nil {
log.Fatal(err)
}
if _, err := db.Exec("SELECT SLEEP(?)", 42); err != nil {
log.Fatal(err)
}
}
このプログラムを実行してる時、別のセッションから SHOW FULL PROCESSLIST を実行すると、オプションの効果が確認できます。
interpolateParams=true を付けない場合は、次のように Command が Execute になり、 Info ではプレースホルダがそのまま表示されます。(とてもタイミングが良ければ、 Execute コマンドじゃなくて Prepare コマンドが見えるかもしれません)
mysql> show full processlist; +------+------+-----------------+------+---------+------+------------+-----------------------+ | Id | User | Host | db | Command | Time | State | Info | +------+------+-----------------+------+---------+------+------------+-----------------------+ | 7508 | root | localhost | NULL | Query | 0 | init | show full processlist | | 7511 | root | localhost:55283 | test | Execute | 2 | User sleep | SELECT SLEEP(?) | +------+------+-----------------+------+---------+------+------------+-----------------------+ 2 rows in set (0.00 sec)
interpolateParams=true を付けた場合は、次のように Command が Query になり、 Info でプレースホルダの部分に値が挿入されていることを確認できます。
mysql> show full processlist; +----+------+-----------------+------+---------+------+------------+-----------------------+ | Id | User | Host | db | Command | Time | State | Info | +----+------+-----------------+------+---------+------+------------+-----------------------+ | 2 | root | localhost | NULL | Query | 0 | init | show full processlist | | 3 | root | localhost:49283 | test | Query | 1 | User sleep | SELECT SLEEP(42) | +----+------+-----------------+------+---------+------+------------+-----------------------+ 2 rows in set (0.00 sec)
文字列のエスケープでは、 sql_mode に NO_BACKSLASH_ESCAPES を設定した場合にも対応しています。
次の結果は db.Exec("SELECT ?, SLEEP(?)", "Hel'lo\nWorld", 42) した時のものです。
mysql> SELECT @@GLOBAL.sql_mode; +-----------------------------------------------------------------+ | @@GLOBAL.sql_mode | +-----------------------------------------------------------------+ | NO_BACKSLASH_ESCAPES,STRICT_TRANS_TABLES,NO_ENGINE_SUBSTITUTION | +-----------------------------------------------------------------+ 1 row in set (0.00 sec) mysql> show full processlist; +------+------+-----------------+------+---------+------+------------+-----------------------------------+ | Id | User | Host | db | Command | Time | State | Info | +------+------+-----------------+------+---------+------+------------+-----------------------------------+ | 7515 | root | localhost | NULL | Query | 0 | init | show full processlist | | 7517 | root | localhost:55400 | test | Query | 2 | User sleep | SELECT 'Hel''lo World', SLEEP(42) | +------+------+-----------------+------+---------+------+------------+-----------------------------------+ 2 rows in set (0.00 sec)
@methane
Goのdatabase/sql.Stmtのスケーラビリティを改善しました
先日、 Goに初めて私のパッチが取り込まれ 、コントリビュータに仲間入りしました。
このパッチは、 database/sql.Stmt をヘビーに使った時に性能がだいたい16コア以上のコア数にスケールしないという問題を解決するものです。
こういった問題をどうやって調査するのかと、Goにパッチが取り込まれるまでの手順を紹介します。
背景
私は TechEmpower の FrameworkBenchmarks という、いろんな言語/フレームワークで同一のアプリを作ってベンチマークするというプロジェクトで、主にPython関連のメンテナをしています。 Goにも興味があるので、Ginというフレームワークを追加したりコードレビューに参加したりしています。
2014-05-01 に行われた前回のベンチマーク Round 9 では、 PEAK Hosting が実行環境に加わりました。この環境は、デュアル Xeon E5-2660 v2 のマシンを 10Gbit Ethernet で接続するというハイスペックなものです。
この環境で、少し不思議な結果が出ていました。他の環境ではJavaやnginxベースの環境に続いて上位につけていた大量のGoのフレームワークが軒並み順位を落とし、Scala, node.js, php の軽量フレームワークにまで負けてしまっていたのです。
2014-11-02 に この問題を改善するプルリクエスト が登場しました。このプルリクエストは、 *sql.DB を複数作りラウンドロビンで利用することでロック競合を改善するというものでした。
私は当初この修正方法に反対でした。このプロジェクトは単にハイスコアを狙うためだけのものではなく、各フレームワークの 現実的な コードのサンプルと、その現実的なコードがどれくらいの性能を出すのかの参考値を多くの人に提供するためのものです。 *sql.DB を複数作るのは設計意図と異なり、あまり現実的なものには感じられませんでした。
database/sql の設計について
少し寄り道して、 database/sql の基本設計について説明します。 Go でデータベースを使うプログラムを書いた経験のある方はこのセクションは読み飛ばしてください。
database/sql は、 PHP でいう PDO のように、各種データベースへ接続するドライバの上に被さり、統一したインタフェースを提供します。例えば MySQL であれば go-sql-drivers/mysql が一番有名なドライバになります。ユーザーは基本的にはドライバを直接利用することはしません。
database/sql の中心になるのが sql.DB です。これはコネクションプールになっていて、以下のような使い方をします。
DB.Exec()やDB.Query()で直接クエリを投げるDB.Prepare()でプリペアドステートメントを表すStmtオブジェクトを作り、Stmt.Exec()やStmt.Query()を使うDB.Begin()でトランザクションを表すTxオブジェクトを作り、Tx.Exec()やTx.Query()を使う
トランザクションを使う場合は Tx オブジェクトが DB からチェックアウトしたコネクションを保持しますが、それ以外の場合は DB がプールしているコネクションのいずれかでクエリが実行され、ユーザーはコネクションを選ぶことができません。 (一部のカバーできていないユースケースに対応するため、 Go 1.5 ではトランザクションなしでコネクションをチェックアウトして使う API が追加される見込みです。)
1番の方法を使う場合、 DB.Query() はドライバがプレースホルダの置換に対応していない場合は内部で DB.Prepare(), Stmt.Exec(), Stmt.Close() を行います。1回のクエリで3回のラウンドトリップが発生するので性能的には不利になります。 go-sql-drivers/mysql もプレースホルダ置換に対応していない (対応するためのプルリクエスト を投げていて議論中です) ので、 2番の方法が一番性能が出ることになります。
2番の方法を利用する場合、 Stmt が各ドライバで prepare した結果と DB 内のコネクションとの対応を管理してくれるので、ユーザーはどの接続で Prepare をしたのかを気にする必要はありません。今回の問題はこの部分がネックになってきます。
このような設計になっているために、 DB 自体を複数持つのはイレギュラーな使い方で、1つのデータベースあたり1つの DB だけで性能がスケールするようにするのが理想です。
調査
まず、現象が発生している PEAK Hosting に近い環境を用意する必要があります。 AWS で c3.8xlarge のマシンを2台、拡張ネットワーキングを有効にして、同一の placement group に配置することで、32コアのマシンを10Gbitの安定したネットワークで接続した環境を用意することができます。 Amazon Linux AMI を使えば、デフォルトで拡張ネットワーキングが有効になっているので楽です。 スポットインスタンスを利用すれば、2台の c3.8xlarge はだいたい $0.7/h で借りることができます。
次に、ベンチマークをかけて問題が再現することを確認しつつ、 top コマンドでCPUの利用状況を確認します。 Mutex を使ったロックは、ロックをすぐに取得できた場合は低コストですが、競合した場合はそこそこCPUサイクルを消費します。 問題になっている Mutex が長時間ロックされている場合は、動作できるスレッドが減るのでCPU使用率が低くなり、短時間だけど非常に頻繁にロックされる場合はロックの競合の発生頻度が激しくなり、性能がコア数にスケールしてない割にはCPU使用率は高くなる傾向にあります。今回はどちらかというと後者だということが確認できました。
最後に、 net/http/pprof を利用して、原因を特定します。 net/http/pprof はCPUプロファイルをはじめ幾つかの診断機能がありますが、ロック競合で一番役に立つのは full stack dump です。実際のスタックダンプが こちら になります。
まず、多くの goroutine が止まっている Mutex.Lock() を見つけます。今回の場合は次のようなスタックトレースで止まっている場合が多いのがわかります。 ソースコードでは この部分 になります。
goroutine 81 [semacquire]: sync.(*Mutex).Lock(0xc2080c42d0) /home/ec2-user/local/go/src/sync/mutex.go:66 +0xd3 database/sql.(*Stmt).connStmt(0xc2080c4280, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0) /home/ec2-user/local/go/src/database/sql/sql.go:1357 +0xa6 database/sql.(*Stmt).Query(0xc2080c4280, 0xc2089a1be8, 0x1, 0x1, 0x0, 0x0, 0x0) /home/ec2-user/local/go/src/database/sql/sql.go:1438 +0x120
だいぶ原因に近づいてきましたが、まだこの部分が犯人だと断言することはできません。ロック競合は、ロックを取得する頻度とロックを持っている時間の掛け算が問題になるのに対して、スタックダンプでは頻度が多い部分が多く表示されるからです。
そこで、これと同じスタックダンプを除外した中から、この Stmt.mu のロックを持っているものを探します。すると次のスタックダンプが見つかります。
goroutine 158 [semacquire]: sync.(*Mutex).Lock(0xc208096de0) /home/ec2-user/local/go/src/sync/mutex.go:66 +0xd3 database/sql.(*DB).connIfFree(0xc208096dc0, 0xc2083080c0, 0x0, 0x0, 0x0) /home/ec2-user/local/go/src/database/sql/sql.go:695 +0x67 database/sql.(*Stmt).connStmt(0xc2080c4280, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0) /home/ec2-user/local/go/src/database/sql/sql.go:1378 +0x316
Stmt.mu をロックしているのは先ほどと同じ位置なのですが、その中で今度は DB.mu のロックを待っていることがわかります。 Stmt.connStmt() と DB.connIfFree() のコードを読むと、 connStmt() が Stmt.css (prepare 済みのコネクションと stmt のペアを管理しているリスト) に対してループしつつ、 connIfFree() を呼び出し、 connIfFree() が毎回 DB.mu をロックしているために、 DB.mu が高い頻度でロックされているのがわかります。しかし、この場所は Stmt.mu をロックしている1つの goroutine しか同時にこないので、他の場所の DB.mu のロックと競合しているようです。今度はスタックダンプのなかから、 DB.mu のロックを持ってるものを探します。すると、 DB.addDep() のロック競合に行き当たります。
# DB.mu を持っている DB.addDep goroutine 18 [runnable]: database/sql.(*DB).addDep(0xc208096dc0, 0x7f0932f0e4d8, 0xc2080c4280, 0x73d340, 0xc2082ec540) /home/ec2-user/local/go/src/database/sql/sql.go:362 database/sql.(*Stmt).Query(0xc2080c4280, 0xc2087cbbe8, 0x1, 0x1, 0x0, 0x0, 0x0) /home/ec2-user/local/go/src/database/sql/sql.go:1455 +0x49a # DB.mu を待っている DB.addDep. これと同じスタックダンプが多数. goroutine 64 [semacquire]: sync.(*Mutex).Lock(0xc208096de0) /home/ec2-user/local/go/src/sync/mutex.go:66 +0xd3 database/sql.(*DB).addDep(0xc208096dc0, 0x7f0932f0e4d8, 0xc2080c4280, 0x73d340, 0xc2085f0540) /home/ec2-user/local/go/src/database/sql/sql.go:364 +0x38 database/sql.(*Stmt).Query(0xc2080c4280, 0xc20899fbe8, 0x1, 0x1, 0x0, 0x0, 0x0) /home/ec2-user/local/go/src/database/sql/sql.go:1455 +0x49a
これで問題の全体像が把握できました。
Stmt.connStmt()が(比較的)長時間Stmt.muをロックしているので、Stmtがあまりたくさん並列に動けない。Stmt.connStmt()は繰り返しDB.connIfFree()を呼び出し、そこでDB.muのロックが競合しているため遅くなる。DB.muのロック競合相手はDB.addDep()
解決策1: DB.mu を分離する
DB.addDep() を読んでみると、参照カウント方式でリソースを管理していて、最後にリソースの解放を行っているようです。
参照カウントと解放処理を管理するための map を守るために DB.mu をロックして排他していますが、これは独立した Mutex に分離できます。
DB.connIfFree() は DB.mu がロック競合を起こさなければ十分に速くなる可能性があり、それなら振る舞いを一切変更せずに問題を解決することができます。
しかし、実際にロックを分離してみたところ、2割程度しか性能が改善せず、 DB 自体を複数持ってラウンドロビンするのに比べるとまだ性能がかなり悪いです。
DB.mu のロック競合を解決しても、 Stmt.connStmt() が Stmt.mu をロックしている内側がまだ遅いので Stmt.mu のロック競合が解決されてないようです。
Mutex の分離はパッチを投げつつ、 Stmt.connStmt() の高速化に乗り出します。
解決策2: Stmt.connStmt() / DB.connIfFree() の高速化
Stmt.connStmt() が Stmt.css に対してループで DB.connIfFree() を呼び出しているのですが、このループは prepare 済みの接続が空いていたらそれを利用するという目的と、 prepare 済みの接続が close されていたら Stmt.css から除去するという2つの目的があります。
しかし、接続が close されているかどうか、利用されているかどうかは、 DB.mu をロックしてさえいれば、 DB のメンバを参照しなくても高速に判定できます。
そこで、 Stmt.connStmt() の中の、 Stmt.css に対するループの外側で直接 DB.mu をロックしてしまい、なおかつ接続のチェックもループ内で直接行い DB.connIfFree() の呼び出しを減らす修正を行ったところ、今度は複数 DB のラウンドロビンと同じ程度の速度がでるようになりました。
こちらを本命としてまたパッチを投げます。 参考
Go にパッチを送り取り込まれるまで
とりあえず Go の Contribution Guideline を読みましょう。 以下かいつまんで説明します。
最初に Github Issue で修正の大まかな方針について合意をとっておきます。
修正を始める前に、 Google の CLA に署名しておきましょう。 参考
Goのリポジトリは最近 Mercurial から Git に移行しましたが、Githubに移行したわけではありません。 Github は Issue Tracker と、リポジトリのクローンに利用されています。オリジナルのリポジトリの場所は https://go.googlesource.com/go なので、 github から clone しているなら git upstream set-url などで origin の向き先を変える必要があります。
Go のコードレビューは Gerrit で行われています。ここにアクセスしてログインし、コマンドラインツールからパッチを投げるのに必要なパスワードを発行しておきます。
次に、 git-codereview というツールをインストールします。
go get -u golang.org/x/review/git-codereview
このツールは、パッチを1コミットのブランチという形で管理し、そのパッチを gerrit に送信するものです。 git に慣れた人向けに説明すると次のようになります。
git codereview change fix-abcはgit checkout -b fix-abc相当git codereview changeは、最初のコミットであればgit commit相当、2回目以降はgit commit --amend相当. (commitと同じ-aが利用可能).git codereview syncはgit fetch origin && git rebase origin/master相当git codereview mail -diffはgit diff HEAD..master相当git codereview mailで Gerrit にパッチを送る
パッチを投げるとレビューが始まります。 (Go の開発はとても活発で、元旦にパッチを投げたらその日のうちにコメントがついてびっくりしました)
- 大まかな設計
- コードの書き方、コミットログの書き方
- テストの書き方
- コメントの書き方
という感じで、レビューの注意点が移っていき、複数の Googler から繰り返しレビューを受けます。
レビューを通った感想
レビューの初期で、 prepare 済みの接続を優先して使うという処理自体を消すなど大幅にシンプルな設計になりました。 これは Github Issue の時点で提案されていた方針で、ちゃんとコメントを読んでおけばお互いに無駄な時間を省けたはずです。
テストについては、既存のベンチマークを簡単に修正していたのですが、平行性のベンチマークは RunParallel を使うように指摘されて、そのままたたき台として使えるようなサンプルをコメントしてもらいました。既存のファイルの上下がレガシーなら自分の修正部分もレガシーな書き方が許されるわけではないようです。
最後の方は、コメントを対象行の右に書くときは主語を省略していいけど、長くなって対象行の上に移動するならちゃんと主語から書き始めるとか、英語の構文、言い回しなど全然コードと関係ない指摘と修正の繰り返しでした。最終的に取り込まれるまでにパッチを送った回数は13回になりました。
ぶっちゃけて言えば、調査結果を詳細に Issue で報告するだけで止めておいて、実際の修正は Googler に任せてしまった方が、私だけでなくレビューする側も楽だったでしょう。それでも、複数の Googler から丁寧なコードレビューを受けるというのは貴重な経験でした。「あとはやっとくから」と言わず、最後までレビューに付き合ってもらって感謝しています。
チャットで学ぶ Go ネットワークプログラミング
簡単なチャットプログラムは、ネットワークプログラミング用のフレームワークでは定番のサンプルプログラムです。
echo サーバーが Hello World とするなら、チャットは FizzBuzz といったところでしょう。
とりあえず動くだけのチャットならだれでもすぐに作れるようになりますが、まじめにチャットを作ることで、 ネットワークプログラミングで考えないといけない点やエラー処理の重要な基礎を学ぶことができます。
ということで、 Go でシンプルなチャットを実装してみました。 (ソースコード)
以降、何を考えてどういう設計を採用したのかを解説していきます。
考慮すべきポイント
- 特定のクライアントへの送信に長時間待たされた場合に、他のクライアントへの送信が遅れないようにする。
- クライアントを切断するのは、 (1)ルーム側から kick する場合, (2)受信エラー, (3)送信エラー
の3種類を考える必要がある。 - 送信待ちのメッセージを無制限にバッファリングすると、メッセージを送信するだけで受信しないような
クライアントがいるとメモリを使いきってしまうので、容易に DoS 攻撃が可能になってしまう。
この場合メモリを使いきって OOM Killer が動くなどの被害を受ける。
Read のエラー処理
受信エラーだけでなく、送信エラーやサーバーからの kick などでも Read() している goroutine を止める必要があります。
Go の Read() は同期的な API になっているので、 select などを使って他の channel
と並列に待つことはできません。
Read() 待ちの goroutine を止めるには、 Read() をエラーで停止させる必要があります。
net.Conn はスレッドセーフに作られているので、他の goroutine から conn.Close()
を呼び出すことで Read() を止められます。
この場合、 Read() は io.EOF だけでなく、 closed connection から Read しようとしたという
エラーも正常系で発生することになります。このエラーは io.EOF のように公開された変数が用意されて
いるわけではありません。
ネットワークエラーだけをログに残したいと思うかもしれませんが、もともと Go の conn.Read() は
返すエラーの一覧を公開していないので、割りきって全て(あるいは EOF を除く全て)のエラーをログに残すようにしましょう。
他の goroutine から conn.Close() が呼ばれているかどうかを正確に判断する方法がないので、
client.Stop() を呼び出しておきます。この関数の処理は後述します。
func (c *Client) receiver() {
defer c.Stop() // receiver が止まるときはかならず全体を止める.
// 1行を512byteに制限する.
reader := bufio.NewReaderSize(c.conn, 512)
for {
// Read() する goroutine を中断するのは難しい。
// 外側で conn.Close() して、エラーで死ぬのが楽.
// エラーは io.EOF であるとは限らない。
msg, err := reader.ReadString(byte('\n'))
if msg != "" {
//log.Printf("receiver: Received %#v", msg)
c.recv <- msg
}
if err != nil {
log.Println("receiver: ", err)
return
}
}
}クライアントの切断処理
メッセージの送信中に他の goroutine から conn.Close() を呼び出すと
中途半端なメッセージを送る可能性があるので、 conn.Close() は送信 goroutine から行います。
そのために、 channel を利用して送信 goroutine に停止通知を行います。
今回のサンプルだと停止しないといけないのは送信 goroutine だけ (送信 goroutine が
conn.Close() を呼ぶことで受信 goroutine も止まる)ですが、停止しないといけない
goroutine が増えた場合にその分だけ channel を作らなければなりません。
また、クライアントの停止は複数の条件で、複数の goroutine から呼ばれる可能性があります。
停止通知に使うチャンネルへの送信がブロックするといけないので、次のようなコードになるでしょう。
type Client struct {
// ...
stopA chan bool,
stopB chan bool,
// ...
}
func newClient() *Client {
c := &Client{
//...
// 1回はブロックせずに送信できるように、 buffered channel を使う.
stopA: make(chan bool, 1),
stopB: make(chan bool, 1),
// ...
}
// ...
return c
}
func (c *Client) Stop() {
select {
case c.stopA <- true:
default: // 既に停止メッセージを送信していてもブロックしない
}
select {
case c.stopB <- true:
default:
}
//...
}これをもう少し楽にするために、 channel の close をメッセージ代わりに使います。
close() は同じチャンネルに対して複数回呼び出すと2回め以降は panic を起こすので、 recover
を使って無視します。
func (c *Client) Stop() {
// ちなみに defer recover() ではダメ
defer func() {
if r := recover(); r != nil {
log.Println(r)
}
}()
close(c.stop)
}
func (c *Client) sender() {
defer func() {
if err := c.conn.Close(); err != nil {
log.Println(err)
}
log.Printf("%v is closed", c)
clientWait.Done() // graceful shutdown用. 後述
c.closed <- c // room のクライアント管理用. 後述
}()
for {
select {
case <-c.stop:
//log.Println("sender: Received stop")
return
case msg := <-c.send:
//log.Printf("sender: %#v", msg)
_, err := c.conn.Write([]byte(msg))
// net.Error.Temporary() をハンドルする必要は多分ない.
// 書き込みできたバイト数が len(msg) より小さい場合は必ず err != nil なので、
// Write() の第一戻り値は無視してエラーハンドリングだけを行う
if err != nil {
log.Println(err)
return
}
}
}
}送信遅延の管理
受信側で1メッセージのサイズは制限しているので、送信待ちメッセージ数だけ制限すれば、
メモリを無制限に使うことは防げます。
送信 goroutine へメッセージを送る channel を buffered にすることで、
room goroutine からの送信を待たせないという効果も一緒に得られます。
バッファがいっぱいになった時に単にメッセージを drop すると、クライアントは何も知らずに 受信したメッセージが歯抜けになってしまうので、その場合はクライアントを切断します。
ただし、バッファがいっぱいになる条件はネットワークの送信が遅れた場合だけではありません。
CPUコアが1つしか無いのにたくさんのクライアントを扱う場合などに、メッセージの流量が多いと、
単に全てのクライアントの送信 goroutine に十分に実行権が行き渡ってないだけの可能性があります。
なので、バッファがいっぱいになった時に無制限に待つのは避けますが、固定時間は待つことにします。 goroutine の実行優先順位を制御できないので、あまりにクライアントが多いと待ち時間内に 待っているクライアントの送信 goroutine に実行権が与えられない可能性は残りますが、 それでも高負荷時の動作はかなり安定するはずです。
// Send msg to the client.
func (c *Client) Send(msg string) error {
// 特定のクライアントが遅いときに、全体を遅くしたくないので、 select を使って
// すぐに送信できない場合は諦める。
// ただし、 room goroutine が sender goroutine より速く回ってるためにチャンネルの
// バッファがいっぱいになってるだけの可能性もあるので、一定時間は待つ.
// バッファに空きがあるときに時に time.After を生成するのは無駄なので、 select を2段にする.
select {
case c.send <- msg:
return nil
default:
select {
case c.send <- msg:
return nil
case <-time.After(time.Millisecond * 10):
return errors.New("Can't send to client")
}
}
}room のクライアント管理
ここまででクライアントの送受信部分はできてきましたが、クライアントが閉じた時に room 側が持ってる
クライアント一覧からも確実にそのクライアントを削除しないと、 channel が GC されずメモリリーク
してしまいます。
送信 goroutine で確実に conn.Close() を呼び出すようにしたので、そこで一緒に room に
メッセージを送るようにします。
room が持つ client 一覧は、 slice ではなく map にすることで、同時接続数が増えた時も
クライアント削除にかかる時間を一定にできます。
slice からの要素の削除は地味に罠があるので
(slice を縮めても背後の配列に参照が残ってるとGCされないのでリークするので縮める前に末尾へゼロ値を代入する必要がある)、
その点も delete() するだけで済む map の方が楽です。
func newRoom() *Room {
r := &Room{
Join: make(chan *Client),
Closed: make(chan *Client),
Recv: make(chan string),
Purge: make(chan bool),
Stop: make(chan chan bool),
clients: make(map[*Client]bool),
}
go r.run()
return r
}
func (r *Room) run() {
defer log.Println("Room closed.")
for {
select {
case c := <-r.Join:
log.Printf("Room: %v is joined", c)
if err := r.sendLog(c); err != nil {
log.Println(err)
c.Stop()
} else {
r.clients[c] = true
}
case c := <-r.Closed: // c は停止済み.
log.Printf("Room: %v has been closed", c)
// delete は指定されたキーが無かったら何もしない
delete(r.clients, c)
/// ...
}graceful shutdown
このチャットでは実装してませんが、例えばサーバー終了時に接続中のクライアントに終了メッセージを送信してから 接続を終了するといった仕様にしたくなる可能性もあります。 graceful shutdown の実装も練習してみましょう。
このチャットでは room を閉じてから、全クライアントの切断を待って、プロセスを終了するのが良さそうです。/> SIGINT (Ctrl-C で送られる) と SIGTERM (オプションなしの kill コマンドで送られる) で graceful shutdown しましょう。
go は main() 関数が終了すると、他にいくら goroutine が動いていてもプログラムが終了します。
なので、 main() 関数の最後で、シグナルを待って、 room に停止メッセージを送り、全クライアントの
切断を待つという処理を書きます。
クライアントの終了を待つのは sync.WaitGroup を利用するのが楽です。
クライアント生成時に wg.Add(1) を行い、送信 goroutine の conn.Close() 直後に wg.Done()
を行い、 main 関数の最後では wg.Wait() を呼びます。
// main() の最後
sigc := make(chan os.Signal, 1)
signal.Notify(sigc, syscall.SIGUSR1, syscall.SIGTERM, os.Interrupt)
for sig := range sigc {
switch sig {
case syscall.SIGUSR1:
room.Purge <- true
case syscall.SIGTERM, os.Interrupt:
room.Stop <- true
// 全ての client の sender を待つ
clientWait.Wait()
// おわり
return
}
}func (c *Client) sender() {
defer func() {
if err := c.conn.Close(); err != nil {
log.Println(err)
}
log.Printf("%v is closed", c)
clientWait.Done()
c.closed <- c
}()
//...まとめ
チャットはシンプルに見えますが、送受信がバラバラに発生するので、リクエスト - レスポンス型のプログラムよりも
書くのが難しいです。
その分、チャットを正しく書けるようになれば、それ以外のサーバーの設計をするときに大いに参考になるはずです。
このプログラムは私なりに考えて設計したものですが、他の良いやり方を知っている・思いついた方は ぜひ教えてください。
@methane
WebSocket アプリの負荷分散
最近 SPDY と WebSocket がアツいですね。 再来週の SPDY & WS 勉強会 も、定員100名に対して 参加者が 247 名とかなりアツいことになっています。
その予習というわけでもないですが、最近 WebSocket を実サービスへの 導入方法を考えながら遊んでいたので、 WebSocket の負荷分散方法について 考えていることを書いておこうと思います。
ステートフルな WebSocket アプリケーション
HTTP サービスは基本的にステートレスな実装になっており、リクエストが来るたびに DBサーバーや memcached などのバックエンドから情報を取得して返していました。
この構成では Web アプリ自体は完全にステートレス化することができているので、 負荷分散機はラウンドロビン等のアプリケーションを無視した負荷分散をすることができました。
しかし、 WebSocket が登場してリアルタイム Web が普及し、それがリッチ化してくると、 ステートレス型では効率が悪くなる事があります。
たとえば複数のチャットルームを持つチャットアプリを作る場合、チャットの内容を Redis に格納し、 Redis の pubsub 機能を使って他の Web サーバーに更新を通知することができますが、 Redis は subscribe している Web サーバー全てに通知を送り、チャットログを取得するリクエストを さばかなければなりません.
MMO ゲームのようにアプリサーバーのメモリ上にチャットログを格納し、同じチャットルームにいる ユーザーが全員同じアプリサーバーに接続するようにすればどうでしょうか？ アプリサーバーはバックエンドから通知を受け取ったりメッセージを取得しなくても全員に メッセージを配信できます。これならバックエンドとの通信はログを保存する1回で済みます。
正攻法でこの構成を組む場合、アプリをステートレスなフロントWebアプリとステートフルな バックエンドアプリの2段構成にすることができます。 でも、この程度ならリバースプロキシで直接リクエストの振り分けをやってしまったほうが 楽だし低コストですよね。
redis を使った動的な負荷分散
そこで、 redis に URL のパスごとに分散先を格納しておき、それを使って動的に リバースプロキシする構成を考えてみました。
効率や応答速度のことを考えたら、リバースプロキシは WebSocket のデコード＆エンコードをする よりも、HTTP サーバーが Upgrade ヘッダを見つけると TCP プロキシとして動作するほうがいいはずです。
Go
最初に目をつけたのは Go です。nginx よりはコードを読み書きしやすいからです。 (node.js でも良いのですが個人的には JavaScript よりも Go の方が好きです)
Go の標準ライブラリ "net/http" にはそのものズバリな revserseproxy があります。 ただしこれは WebSocket に対応していないので、ちょっと改造して Upgrade ヘッダを見つけると TCP プロキシになる機能を追加しました。 (methane/rproxy)
あとは redigo という Redis クライアント(名前がカッコイイ！) と組み合わせればお手軽に賢いリバースプロキシの完成です。
nginx + lua
そういえば nginx も最近 WebSocket に対応したって話題になってたなーと思って調べてみると、 これも Upgrade ヘッダを見て TCP プロキシとしてふるまうようです。 さらに調べてみたら Redis + Lua を使って動的な負荷分散するサンプルもいくつかみつかりました。
ただし、 nginx のサブリクエストは基本的に HTTP 用であまり memcached や redis に格納した 生の文字列を扱うのに向いていないので、 lua-resty-redis という pure Lua のライブラリを使って書きなおしてみました。
これもちゃんと nginx の非同期機能を使ってくれるので Redis に問い合わせしている間 ブロックしたりはしませんし、コネクションプールも可能です。
せっかく作ったので Go 版を紹介したものの, nginx が使えるならもう nginx でいいですね。 でも、毎回 Redis に問い合わせるのではなく expire 付きの LRU キャッシュをインメモリでやるとか、 Socket.IO のセッションを解析して自分で Redis に格納するとか複雑なことをするなら Go の強みが生きてくるかもしれません。
サンプル
お待たせしました。サンプルはこちらになります。
KLab/websocket-reverseproxy-demo
このサンプルでは、 Tornado を使ったオンメモリで動くチャットアプリを2つのポートで立ち上げ、 Redis にチャットルームごとのバックエンドを格納した上で、 nginx と go によるリバースプロクシの動作を確認しています。
Go も nginx も開発版を使っているので少しハードルが高いかもしれませんが、 SPDY & WS 勉強会の 参加者はぜひ予習として試してみてください。
因縁の Google 独自言語対決！ Go 1 vs PyPy
エイプリルフールネタが思いつかないけど4/1は休日なんで問題ありません。 methane です。
とうとう ゴー のバージョン 1 がリリースされましたね。おめでとうございます。 まだRC2が出てからあまり時間が経ってない気がするのですが、パイソンにグーグル独自言語の称号を奪われそうになって慌てたのかもしれません。
前回のechoサーバー対決 から半年すこし経ったのですが、この間にどれくらい高速化したのか、早速ベンチマークをアップデートしました。
echoserver on github
Google Docs Spreadsheet
前回のスコアと比較してみると、 Go の r59 では
Throughput: 52087.16 [#/sec] Throughput: 52070.02 [#/sec] Throughput: 52068.27 [#/sec]だったのが、 Go 1 では
Throughput: 55872.09 [#/sec] Throughput: 55857.82 [#/sec] Throughput: 55949.57 [#/sec]と、順位に変動があるほどではありませんが、着実に速くなってます。一方、 PyPy 1.6では
Throughput: 79193.30 [#/sec] Throughput: 81063.83 [#/sec] Throughput: 81442.70 [#/sec]だったのが、 PyPy 1.8 だと、、、
Throughput: 84852.55 [#/sec] Throughput: 106760.88 [#/sec] Throughput: 107032.43 [#/sec]
なんと、シングルスレッドのC++（epoll版）に迫る性能を叩き出すようになってます。
今回は Go と PyPy だけの更新ですが、夏までには軽量スレッド最速環境である Haskell の新しい Haskell Platform というディストリビューションが出ると思うので、それを待って全体的に更新したいと思います。
Twisted vs Tornado vs Go で非同期Webサーバー対決
昨日の takada-at の記事で「サーバー側では単純に100ms待ってからレスポンスを返すだけのページを用意しておき、」とあったのですが、今日はそのサーバー側の話をします。
もともとこのサーバーを作った動機は、takada-at が作成中の負荷試験システムがちゃんと並列に負荷をかけられるかどうかを検証するためでした。 すぐにレスポンスを返してしまうと、負荷試験スクリプトがきちんと並列に負荷をかけられなくても PV/sec が出てしまいます。 そこで、 epoll を使って高速に並列接続を扱えるTwistedフレームワークを使って、100msの遅延をしつつ数千PV/secに耐えるWebサーバーを作ってみました。 さらに、同じく epoll を使っている Tornado や Go にも興味があったので、こちらでも同じものを作成し、パフォーマンスを比較してみました。
コード
まずは、コードを見てみましょう。
Twisted Python:
from twisted.internet import epollreactor
epollreactor.install()
from twisted.web import server, resource
from twisted.internet import reactor
class Lazy(resource.Resource):
isLeaf = True
def __init__(self, delay=0.1):
self._delay = delay
def render_GET(self, request):
def after():
request.write('Hello, World!')
request.finish()
reactor.callLater(self._delay, after)
return server.NOT_DONE_YET
if __name__ == '__main__':
import sys
delay = 0.1
try:
delay = float(sys.argv[1]) / 1000
except Exception:
pass
site = server.Site(Lazy(delay))
reactor.listenTCP(8000, site)
reactor.run()
次は、Tornadoです。
from tornado import httpserver, ioloop, web
from time import time
DELAY = 0.1
class MainHandler(web.RequestHandler):
@web.asynchronous
def get(self):
def _hello():
self.write("Hello, World!")
self.finish()
ioloop.IOLoop.instance().add_timeout(time() + DELAY, _hello)
application = web.Application([
(r"/", MainHandler),
])
if __name__ == "__main__":
import sys
try:
DELAY = float(sys.argv[1]) / 1000
except Exception:
pass
http_server = httpserver.HTTPServer(application)
http_server.listen(8001)
ioloop.IOLoop.instance().start()
最後に、Goです。
package main
import (
"flag"
"http"
"io"
"log"
"time"
)
var addr = flag.String("addr", ":9000", "http service address")
var delay = flag.Int64("delay", 100, "response delay[ms]")
func main() {
flag.Int64Var(delay, "d", 100, "response delay[ms]")
flag.Parse()
http.Handle("/", http.HandlerFunc(hello))
err := http.ListenAndServe(*addr, nil)
if err != nil {
log.Exit("ListenAndServe:", err)
}
}
func hello(c *http.Conn, req *http.Request) {
time.Sleep(int64(1000000) * int64(*delay))
io.WriteString(c, "Hello, World!\n")
}
TwistedやTornadoは、ループに後で呼び出す関数を登録していていて明らかにイベントドリブンフレームワークという感じがします。 それに対してGoは Sleep() を使っていて、一見普通のスレッドべースの並列処理に見えます。 しかし、Goはネイティブスレッドではなくgoroutineという軽量なユーザーランドスレッドを利用しており、そのスケジューラは（Linuxの場合）epollを利用しています。通常のスレッドを使うよりも効率的に動作するはずです。
ベンチマーク
それでは、この3つにそれぞれ負荷をかけてみましょう。といっても、100msの遅延だと負荷をかけるのが大変なので、10msの遅延で実行し、ab -c100 -n10000で実験してみます。
Twisted: Requests per second: 2620.31 [#/sec] (mean) Time per request: 38.163 [ms] (mean) Time per request: 0.382 [ms] (mean, across all concurrent requests) Percentage of the requests served within a certain time (ms) 50% 31 66% 32 75% 33 80% 37 90% 38 95% 38 98% 40 99% 44 100% 3082 (longest request) Tornado: Requests per second: 5299.04 [#/sec] (mean) Time per request: 18.871 [ms] (mean) Time per request: 0.189 [ms] (mean, across all concurrent requests) Percentage of the requests served within a certain time (ms) 50% 19 66% 19 75% 19 80% 19 90% 19 95% 19 98% 21 99% 22 100% 33 (longest request) Go: Requests per second: 4712.63 [#/sec] (mean) Time per request: 21.220 [ms] (mean) Time per request: 0.212 [ms] (mean, across all concurrent requests) Percentage of the requests served within a certain time (ms) 50% 19 66% 20 75% 20 80% 21 90% 32 95% 40 98% 42 99% 42 100% 48 (longest request)
TornadoやGoに比べると、Twistedが残念な結果になっています。 これは、Twistedが比較的汎用的で高機能なフレームワークということもありますが、遅延実行する関数をリストに格納していて、実行する関数があるかどうかをリストを全部チェックしているのが大きそうです。（Tornadoはソート済みリストを利用していてます）
Goも、コンパイラ型なのにTornadoに負けてるのが残念ですが、epollから直接イベントドリブンしているTornadoに比べると goroutine という抽象化レイヤを1枚はさんでいるので仕方ないかもしれません。
さらに高速化
まずはTornadoのJITによる高速化に挑戦してみます。PyPy-1.2が一番よさそうですが、セットアップが面倒なのでお手軽なpsycoを使ってみました。もとのソースコードに、次の2行を追加します。
import psyco psyco.full()
結果はこうなりました。
Requests per second: 7503.16 [#/sec] (mean) Time per request: 13.328 [ms] (mean) Time per request: 0.133 [ms] (mean, across all concurrent requests) Percentage of the requests served within a certain time (ms) 50% 13 66% 13 75% 14 80% 14 90% 14 95% 14 98% 15 99% 15 100% 23 (longest request)
5299req/sec => 7503req/sec で、20％以上高速化できました。topで見ている限り、メモリ使用量(RES)も1MB以下です。Tornado+psycoは非常に優秀ですね。
次に、Goでマルチスレッド化を試してみます。goroutineは複数のネイティブスレッドを利用して並列に動作することができます。しかし、現時点ではまだスケジューラがよくないらしく、デフォルトではマルチスレッドを使わないようになっています。環境変数 GOMAXPROCS に並列数を指定して実験してみました。
GOMAXPROCS=6 の場合: Requests per second: 5760.33 [#/sec] (mean) Time per request: 17.360 [ms] (mean) Time per request: 0.174 [ms] (mean, across all concurrent requests) Percentage of the requests served within a certain time (ms) 50% 16 66% 17 75% 17 80% 18 90% 28 95% 33 98% 37 99% 40 100% 53 (longest request)
実験マシンはCore2 Duoで2コアしか載っていない(Hyper Threadingもなし)なのですが、2を指定してもあまり性能が上がらず、そこから1つずつ数字を上げていったところ6までは少しずつ性能が向上していきました。しかも、topを見ている限りCPU使用率は最大の200%には全く届かず120%以下しか利用できていません。 CPUを原因は判りませんが、今回のようなイベントループをヘビーに使う用途にはスケジューラが最適化されておらず、もっとサーバー側でCPUを利用する計算を行う処理をしないとマルチコアを使いきれないのかもしれません。
Goは今回のケースではTornadoに負けてしまいましたが、IO多重化をイベントドリブンよりシンプルに記述でき、コンパイル型言語なので複雑な計算をPythonより圧倒的に高速に計算できそうなので、非常に期待しています。
