概要
この内容はsql.DBに設定できるコネクションに関する以下の三つのパラメータをどう設定するか、逆に設定しないとどうなるかを説明します。
SetMaxOpenConns()
SetMaxIdleConns()
SetConnMaxLifetime()
既に以下の記事で詳細に説明がされているので合わせて参照していただければと思います。この記事を書くのと、実際に業務で問題に突き当たった際に書いてある内容に非常に助けられました。
Configuring sql.DB for Better Performance
Re: Configuring sql.DB for Better Performance
この記事では自分なりに解釈した各値の設定方法と、設定しないとどのような事が起こるのか、ローカル環境で簡単に検証する方法をまとめています。私自身これを知らないまま開発を進めて痛い目にあったので、今チューニングの必要がなくてもGoでDBをあつかうのであれば、必ずこの三パラメータを抑えてもらえていただければと思います。
結論どうチューニングすれば良いか
以下が前述の二つの記事と、実際のチューニングをしつつ出した結論です。
やりたい事
目的は以下を満たす最良の設定値を見つけ出す事です。
- コネクション数を減らして、コネクションを貼る負荷を軽減したい
- コネクションが増えすぎて、DB側に負荷がかかり過ぎるの抑止したい
- アイドルしたまま使われないコネクションは減らして、コネクションをアイドルしておく負荷を軽減したい
- コネクションのライフタイムを設定して適切に切断する事で負荷軽減および接続したままにしておく事で発生する問題を減らしたい。
最低限のチューニング
- MaxOpenConnsとMaxIdleConnsを同値のまま上下させて、必要な負荷をかけた時に一番パフォーマンスが出るように調整する
- 大きくしすぎると大量のコネクションが発生してDB側の負担となったり、DB側で接続可能なコネクション数をオーバーしたりとエラーになる
- 少なくしすぎるとアプリケーション側で接続待ちの状態になりパフォーマンスが出なくなる。
- ConnMaxLifetimeをMaxOpenConnsと同値(MaxOpenConns * 1s)に設定する
より細かくチューニングする
- MaxIdleConnsを下げる事により、コネクション回数は増えるがアイドルコネクションが減る事により負荷軽減となる。
- Connection数が適度にスパイクしていて、無駄にIdleをしているコネクションが多い場合は下げるとパフォーマンスが出るかもしれない。
- ConnMaxLifetimeは下げる事によりコネクション回数が増えて、上げる事によりコネクション回数が減える。
- ただ、上げることによりコネクション回数が減る代わりに、アイドルのコネクションが必要なくなってもキープし続ける負荷があったり、DB起因でコネクションが中断されたり、フェイルオーバしたりした際に、外部要因で既に切れたコネクションを持ち続けて切断の検知に時間がかかったり、新しいコネクションに切り替えて欲しい際に切り替えがなかなか起こらないというリスクを含んでしまう。
- コネクション回数をどうしても下げたい時に伸ばしてみるという調整方法がベストではと思います。
動作、もし設定しないとどうなるかを理解する
この記事を書くきっかけ。仕組みを理解していなかったためハマったこと
まず、業務でWebアプリケーションを行った際はこの３つのパラメータを全く知らないまま開発を行っていました。開発は順調に進み負荷試験を行った際パフォーマンスが全く出てくれないという問題が起きました。ざっと600rpsで95%タイルで300ms以内というのが目標だったのに100rpsで既にAPIの実行が3sかかっているという始末でした…。
今となってはsql.DBの設定値をしていなかったからと原因が明らかなのですが、当時は何が問題なのか全くわからずまずはプロファイリングをという事でpprofを入れます。これで原因がつかめるかと思いきや以下の二つを見てください。
修正前
修正後
この二つはシンプルにfindでデータを取ってくるAPIで上は何も設定しない、下は必要なさパラメータを設定した状態で300rpsの負荷をかけたサンプルです。今わかった上で見ると、sql.(DB*).connで異常に時間が取られているとわかるのですが、その前提知識がない状態で見るとSysCallに異常な時間が取られている、それは何故なんだというところで止まってしまったのと、実際のケースでは同時に複数のAPIを実行させているので、更に何が問題かわからない状態でした。
結局最終的にAPI毎にコネクションを貼る回数に差異があり、コネクションが多いものが如実に遅いという事に同僚が気づき、原因の根本にたどり着く事ができました。
MaxConnectionとは？設定しないとどうなるか？
最大いくつまでコネクションを貼れるかという設定値です。デフォルト値は無限大で、大量にコネクションが貼られた時にDBに大きな負荷をかけたり、DB側のMaxConnection以上にコネクションが貼られてエラーを巻き起こします。
数値が低いと、それ以上にコネクションを貼りたい時にロック状態になるので、負荷に影響します。
DBとアプリケーション側を見つつ適切な値を設定してあげる必要があります。
MaxIdleConnectionとは？設定しないとどうなるか？
最大いくつまでコネクションをアイドルしておくかという設定値です。
アイドルしたコネクションは再利用されるため、コネクションを貼る負荷が軽減されます。
デフォルトだと全て新規接続されて、コネクションのアイドルが活用されません。
多いとコネクション時にアイドルのものが利用されるのでコネクション回数は減らせますが、アイドル状態にしておくコストとのトレードオフになります。
なおMaxConnection以上には設定しても意味がありません。コネクションがアイドル状態になるため、貼ったコネクション以上にアイドルなコネクションができないためです。
MaxLifetimeの意味、設定しないとどうなるか？
コネクションをどれだけの時間を維持しておくかという数値です。
デフォルトは無限大で、接続に失敗するまでコネクションを利用し続けます。
LifeTimeは下げる事によりコネクション回数が増えて、上げる事によりコネクション回数が減ります。
上げたほうがメリットが高いように見えますが、コネクション回数が減る代わりにアイドルのコネクションが必要なくなってもキープし続ける負荷があったり、DB起因でコネクションが中断されたり、フェイルオーバしたりした際に、外部要因で既に切れたコネクションを持ち続けて切断の検知に時間がかかったり、新しいコネクションに切り替えて欲しい際に切り替えがなかなか起こらないというリスクを含んでしまいます。
コネクションを作成するタイミングが適切に分散されているとしたら、MaxConnectionをMaxLifeTimeで割った秒数に一回接続が走る計算になります。二つが同じ値であれば1秒に一回コネクションが発生します。1sに一回程度の接続であれば、負荷的に問題となり得ないはずなので同じ値に設定しつつ調整していくのいいかと思います。
動作と設定方法について
これらの情報からまずMaxConnectionはDBとアプリ両方の負荷を見つつ、適切な値をみつけると良さそうです
MaxIdleConnectionはデフォルトのままだと、アイドルされず負荷が高いので、MaxConnectionと同値で先にMaxConnectionの最適値を見つけた上で、下げて調整すると良いかなと思います。
あとはLifeTimeについてはコネクションを貼る負荷を見つつ、短い時間で設定できると良さそうという結論に至りました。
それが、先に述べた結論を導き出してます。
（補足１）これらの値の検証をローカルで気軽に試してみる方法
原理はわかるものの、実際に設定を変更してみないとわからないということでローカルで簡単に検証できる環境を構築しています。
上記は本来は今回の件を調べるために作ったものではなく、ISUCONで上位の方が使っていた秘伝のMakefileを自分でも作ってみようという意図のもの作成したものです。ただ、簡単に検証を行えて、pprofも使えて、負荷もかけられるということでやりたい事ができるという事できるので利用しています。負荷をかけるのにはtsenart/vegetaというGoのライブラリを利用しています。業務ではJMeterを使って負荷試験を行ったのですが、こちらはもっと手軽に実行と結果をみる事ができて良い感じです。是非入れて遊んでみていただければと思います。ISUCONにでる方はISUCON対策にもなります。きっと。
負荷試験を行う場合は以下のようにコマンドを実行するのみです。現状はシンプルにセレクトのみのAPIに対し300rpsの負荷を5秒間かけるようにしています。
make st
make stresult
設定の変更は以下の設定ファイルで行えます。Connection以下を変更してください。以下だとデフォルトの状態です。
development:
host : "db"
port : "3306"
user : "root"
password : "pass"
db : "isucon"
logmode : true
Connection:
MaxOpenConnections : 0
MaxIdleConnections : 0
ConnectionMaxLifetimeSeconds : 0
上記の状態でまずは実行してみます。
make st
（中略）
make result
vegeta report vegeta/result/result.bin | slackcat --tee --channel slacktest
slackcat connected to drunkturtle_sandbox as drunkturtle
Requests [total, rate, throughput] 1500, 300.19, 237.60
Duration [total, attack, wait] 5.6313526s, 4.9969148s, 634.4378ms
Latencies [mean, 50, 95, 99, max] 542.32694ms, 607.019818ms, 1.10065431s, 1.274960279s, 1.6715916s
Bytes In [total, mean] 375972, 250.65
Bytes Out [total, mean] 0, 0.00
Success [ratio] 89.20%
Status Codes [code:count] 200:1338 500:162
Error Set:
500 Internal Server Error
slackcat file 1572155552 uploaded to slacktest (0.455s)
全て成功せずに500エラーが発生しているのがわかるかと思います。
試しに以下のように設定を変えて流してみます。
Connection:
MaxOpenConnections : 1000
MaxIdleConnections : 1000
ConnectionMaxLifetimeSeconds : 0
vegeta report vegeta/result/result.bin | slackcat --tee --channel slacktest
slackcat connected to drunkturtle_sandbox as drunkturtle
Requests [total, rate, throughput] 1500, 300.19, 298.69
Duration [total, attack, wait] 5.0218832s, 4.9969079s, 24.9753ms
Latencies [mean, 50, 95, 99, max] 29.171009ms, 18.136358ms, 103.70208ms, 161.08682ms, 299.8524ms
Bytes In [total, mean] 415500, 277.00
Bytes Out [total, mean] 0, 0.00
Success [ratio] 100.00%
Status Codes [code:count] 200:1500
Error Set:
slackcat file 1572155680 uploaded to slacktest (0.353s)
全て200で帰ってくるのが確認できました！
負荷、負荷をかける時間は変更できますし、vegitaを使ってより複雑なテストケースを作ってみると色々試せるのではないかと思います。
（補足２）sql.(DB*).connの挙動、sql.DBのデバッグ
sql.DBのコードリーディングをするとより挙動の理解が深まると思います。
sql.goは3000行ほどあるので全部読み解くのは大変で読みきれていないのですが、DBの接続を行っているconnという関数をみるだけだけでも
なんとなく挙動を抑えられるのではと思います。
一部を抜粋します。日本語で書いてあるコメントが私の解釈です。
// conn returns a newly-opened or cached *driverConn.
func (db *DB) conn(ctx context.Context, strategy connReuseStrategy) (*driverConn, error) {
db.mu.Lock() // sync.Mutex使ってロックを行っている
(略)
// Prefer a free connection, if possible.
numFree := len(db.freeConn)
if strategy == cachedOrNewConn && numFree > 0 {
// MaxIdleConnectionsに関連するアイドルコネクションの制御をしている
// strategyは２パターンでコネクションを必ず新規にするかとアイドルされてものがあれば使うという２ケースある
// 後者の場合かつ、フリーなものがあれば使うという制御をここで流行っている
conn := db.freeConn[0]
copy(db.freeConn, db.freeConn[1:])
db.freeConn = db.freeConn[:numFree-1]
conn.inUse = true
db.mu.Unlock()
(略)
}
// Out of free connections or we were asked not to use one. If we're not
// allowed to open any more connections, make a request and wait.
if db.maxOpen > 0 && db.numOpen >= db.maxOpen {
// Make the connRequest channel. It's buffered so that the
// connectionOpener doesn't block while waiting for the req to be read.
req := make(chan connRequest, 1)
reqKey := db.nextRequestKeyLocked()
db.connRequests[reqKey] = req
db.waitCount++
db.mu.Unlock()
// MaxOpenConnectionsに関連する最大接続数の制御を行っている
// これを超えたもののについてはwait状態になり、それ以上コネクションを作らないように抑制される
(略)
}
// 上記二つの条件をパスしたらコネクションが作成される。なお、デフォルトの状態だとどちらも必ずパスしてしまうので
// コネクションがきたぶんだけ必ず作成されることになるので、問題を引き起こす。
// db.connectorは接続するためのインターフェイスでMySQL,PostgreSQL他DB分の設定がある。ここからは先は各RDBMS固有の処理となる。
db.numOpen++ // optimistically
db.mu.Unlock()
ci, err := db.connector.Connect(ctx)
if err != nil {
db.mu.Lock()
db.numOpen-- // correct for earlier optimism
db.maybeOpenNewConnections()
db.mu.Unlock()
return nil, err
}
db.mu.Lock()
dc := &driverConn{
db: db,
createdAt: nowFunc(),
ci: ci,
inUse: true,
}
db.addDepLocked(dc, dc)
db.mu.Unlock()
return dc, nil
}
また、sql.DBの中身をよくみるとStatsという関数があるのがわかると思います。これはまさにsql.DBで制御している内容をログとして残しているものでより詳細な分析に役立てられそうです。
dbStats := db.DB().Stats()
fmt.Printf("dbStats MaxOpenConnections:%v OpenConnections:%v InUse:%v Idle:%v WaitCount:%v WaitDuration:%v MaxIdleClosed:%v MaxLifetimeClosed:%v \n", dbStats.MaxOpenConnections, dbStats.OpenConnections, dbStats.InUse, dbStats.Idle, dbStats.WaitCount, dbStats.WaitDuration, dbStats.MaxIdleClosed, dbStats.MaxLifetimeClosed)
ログ
dbStats MaxOpenConnections:0 OpenConnections:0 InUse:0 Idle:0 WaitCount:0 WaitDuration:0s MaxIdleClosed:1026 MaxLifetimeClosed:0
（補足３）pprofでこの問題をちゃんと検知する
最初に見たときにはpprofから問題を割り出す事ができなかったのですが、補足２を見たあとだとCPUやMemoryに問題を及ぼすのと合わせて、ロックによって待たされているのではと仮定できそうです。pprofではblockやmutex等のロック状況も見れるのでそれを見てみます。
補足1の設定がデフォルトと、設定を入れたケースで共にpporfのmutexの結果が変わるか見てみます。
修正前
806266447 170 @ 0x473544 0x74bf02 0x74e7a6 0x74e4f1 0x74e703 0x7a59b2 0x7ceec8 0x7bd119 0x819482 0x7ef038 0x7f26bc 0x7f3b86 0x6b23e4 0x81e951 0x6b23e4 0x81ebc5 0x6b23e4 0x81e629 0x6b23e4 0x81ee57 0x6b23e4 0x7f070d 0x7f06c9 0x6b42e6 0x6b56b8 0x6b13a1 0x45dce1
# 0x473543 sync.(*Mutex).Unlock+0x73 /usr/local/go/src/sync/mutex.go:201
# 0x74bf01 database/sql.(*DB).conn+0x2d1 /usr/local/go/src/database/sql/sql.go:1192
# 0x74e7a5 database/sql.(*DB).query+0x65 /usr/local/go/src/database/sql/sql.go:1513
# 0x74e4f0 database/sql.(*DB).QueryContext+0xd0 /usr/local/go/src/database/sql/sql.go:1495
# 0x74e702 database/sql.(*DB).Query+0x82
（略）
修正後
2085648 2 @ 0x473544 0x74c71e 0x74e7a6 0x74e4f1 0x74e703 0x7a59b2 0x7ceec8 0x7bd119 0x819482 0x7ef038 0x7f26bc 0x7f3b86 0x6b23e4 0x81e951 0x6b23e4 0x81ebc5 0x6b23e4 0x81e629 0x6b23e4 0x81ee57 0x6b23e4 0x7f070d 0x7f06c9 0x6b42e6 0x6b56b8 0x6b13a1 0x45dce1
# 0x473543 sync.(*Mutex).Unlock+0x73 /usr/local/go/src/sync/mutex.go:201
# 0x74c71d database/sql.(*DB).conn+0xaed /usr/local/go/src/database/sql/sql.go:1101
# 0x74e7a5 database/sql.(*DB).query+0x65 /usr/local/go/src/database/sql/sql.go:1513
# 0x74e4f0 database/sql.(*DB).QueryContext+0xd0 /usr/local/go/src/database/sql/sql.go:1495
# 0x74e702 database/sql.(*DB).Query+0x82
（略）
ここの結果を見るにロックが大量に発生していた事、修正により対処された事が取れると思います。
今度同様にCPUやMemoryだけをみて結果が掴みづらかったらblockやmutexの結果もみると糸口がつかめそうです。