ActiveJobでsidekiqを使う場合、connection_poolの値はconcurrency + 1以上にしよう
ActiveRecordのpool = Sidekiqのconcurrency にしていると、アプリの作りによってはエラーが起きるかもしれないよ！という話。
前置き
よく見るのでちょっとうんざりしてきたこのログ。
could not obtain a database connection within 5.000 seconds
sidekiqを使っている人だと1度は見たことがあるのではないかと思う。
この設定でOKなはずだ！という時でも時々発生して、なんだろうこれ〜と思っていたのだが、少し前に原因が判明したので記録する。なお、ActiveRecordとSidekiqのバージョンは以下の通り。
- activerecord (4.2.7.1)
- sidekiq (4.2.5)
なぜ発生するのか？
まず、そもそも「could not obtain〜」が発生する原因だが、ActiveRecordのコネクションプールに空がないからである。
コネクションプールに空きがあるかどうかをどう調べるかだが、connection_pool.rbのacquire_connectionメソッドでそれを行っている。
def acquire_connection
if conn = @available.poll
conn
elsif @connections.size < @size
checkout_new_connection
else
reap
@available.poll(@checkout_timeout)
end
end
このメソッドが何をしているのかというと、
- 使用可能なコネクションを取得しようとする
- それがなく、かつ空きが有る場合は新規にコネクションを作成してそれを使う
- 空きがない場合は再度空くまで待つ
- ここでcheckout_timeout秒待って駄目なら「could not obtain〜」エラーが発生する
つまり、「could not obtain〜」エラーが発生している状態というのはコネクションに空きがなくて待っており、タイムアウトしているということである。
設定の確認
さて、このエラーが出る場合、まずはSidekiqの設定であるconcurrencyとActiveRecordのpoolの値を確認すべきである。なぜなら、Sidekiqはスレッドを使ってジョブを並列処理しており、ActvieRecordを使っている場合各スレッドがコネクションを持つ可能性があるからだ。SidekiqのWikiのConcurrencyを見ても、スレッド数と同じ、もしくは近い値にすると書かれている。
手元のコードではどのような設定になっていたのか？「could not obtain〜」が発生しているということは、concurrency > poolとなっていると推測できる。しかし、実際にはconcurrency = poolであった。この設定だと、1スレッド1コネクションはあるはずなので、「could not obtain〜」は発生しないように思える。
仮説とコードリーディング
とはいえ、実際に発生している。再現条件もよくわかっていないので、仮説を立てて関係しそうなコードを読み、動作を確認することにした。仮説だが、足りているはずのコネクションが足りなくなっているので、何らかの要因によってコネクションが使えなくなってプールが足りなくなった、というものにし、コネクションの確保周辺のコードを読んでいった。
コネクションが1つ使えなくなると concurrency = pool – 1 になるので、並列稼働数が最大になると足りなくなる。その際、プールに空きが出ないままタイムアウトすると「could not obtain〜」が起こる。
このように仮定し、定期的にチェックして解放すればいいんじゃないかと考えてPRを作成したのだが、平行してコードを読んでいるとそれは起こりそうにないことが分かった。
acuire_connectionメソッドの中で、使えなくなったコネクションがある場合、回収するような仕組みになっていたのである。
def acquire_connection
if conn = @available.poll
conn
elsif @connections.size < @size
checkout_new_connection
else
reap
@available.poll(@checkout_timeout)
end
end
8行目で呼び出されているreapメソッドがそれで、コネクションの空きを待つ前に使えなくなったコネクションを解放しているのだ。
解決
どうにも煮詰まったので、1から考え直すことにして、コネクションを貼る箇所でプリントデバッグすることにした。
そうすると、なんとSidekiqの起動前（Sidekiqのロゴが表示される前）にコネクションを貼っている…！
これが原因だった。Railsのinitializerの中でActiveRecordを使っていて、そこでコネクションが貼られていたのであった。
Sidekiqのプロセスがコネクションを1個持ってしまったので、スレッドが使える数が1つ少なくなる。つまり、concurrencyとpoolの数が同じだと1つ足りなくなるのである。
そこで、concurrency = pool – 1になるよう、poolサイズを1大きくして、解決することができた。
おまけ
frequency（秒）という設定を追加すると、設定した時間毎にreapしてくれるReaperがActiveRecordのConnectionPoolにいる。
class Reaper
attr_reader :pool, :frequency
def initialize(pool, frequency)
@pool = pool
@frequency = frequency
end
def run
return unless frequency
Thread.new(frequency, pool) { |t, p|
while true
sleep t
p.reap
end
}
end
end
シンプルな作りで、frequencyを指定するとぐるぐるまわる。指定しないとsleepで止まりっぱなし。
# Creates a new ConnectionPool object. +spec+ is a ConnectionSpecification
# object which describes database connection information (e.g. adapter,
# host name, username, password, etc), as well as the maximum size for
# this ConnectionPool.
#
# The default ConnectionPool maximum size is 5.
def initialize(spec)
super()
@spec = spec
@checkout_timeout = (spec.config[:checkout_timeout] && spec.config[:checkout_timeout].to_f) || 5
@reaper = Reaper.new(self, (spec.config[:reaping_frequency] && spec.config[:reaping_frequency].to_f))
@reaper.run
ConnectionPoolのinitializeで作っている。