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メソッドでそれを行っている。

connection_pool.rb#L418-L427

このメソッドが何をしているのかというと、

  1. 使用可能なコネクションを取得しようとする
  2. それがなく、かつ空きが有る場合は新規にコネクションを作成してそれを使う
  3. 空きがない場合は再度空くまで待つ
    • ここで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メソッドの中で、使えなくなったコネクションがある場合、回収するような仕組みになっていたのである。

connection_pool.rb#L418-L427

8行目で呼び出されているreapメソッドがそれで、コネクションの空きを待つ前に使えなくなったコネクションを解放しているのだ。

解決

どうにも煮詰まったので、1から考え直すことにして、コネクションを貼る箇所でプリントデバッグすることにした。
そうすると、なんとSidekiqの起動前(Sidekiqのロゴが表示される前)にコネクションを貼っている…!
これが原因だった。Railsのinitializerの中でActiveRecordを使っていて、そこでコネクションが貼られていたのであった。
Sidekiqのプロセスがコネクションを1個持ってしまったので、スレッドが使える数が1つ少なくなる。つまり、concurrencyとpoolの数が同じだと1つ足りなくなるのである。
そこで、concurrency = pool – 1になるよう、poolサイズを1大きくして、解決することができた。

おまけ

frequency(秒)という設定を追加すると、設定した時間毎にreapしてくれるReaperがActiveRecordのConnectionPoolにいる。

connection_pool.rb#L203-L220

シンプルな作りで、frequencyを指定するとぐるぐるまわる。指定しないとsleepで止まりっぱなし。

connection_pool.rb#L227-L240

ConnectionPoolのinitializeで作っている。

References

chimayというConsulと連動したmrubyスクリプトランナーを作っている

img_5003

最近、takaishi/chimay というツールを作っていて結構形になってきたので、一度背景や目的などを整理する。

何これ?

Consul Eventをトリガーとし、渡されたURL(s3, http)からスクリプトをダウンロードしてきて実行するスクリプトランナー、それがchimayである(スクリプトランナーって用語は正しいのだろうか)。

たとえば、以下のようなmrubyスクリプトをS3に置いておく。

標準入力でchimayコマンドにURLを渡すと、URLからスクリプトをダウンロードして実行してくれる。

Consul Event経由で実行する場合は以下のようにする。この場合、「run_script」イベントを監視している全ノードでS3からダウンロードしてスクリプトを実行する処理が走る。もちろん、consul eventコマンドで実行するノードを絞り込むことも可能だ。

fujiwara/stretcher と似ていると思う方もいると思うが、アイデアはstretcherから貰ったもので、インターフェースも極力そろえたいと思っている。違いとしては、stretcherは基本的にデプロイのためのツールだが、chimayはmrubyスクリプトを実行するためのツールという点だろうか。

なぜ作っているのか

端的に書くと、以下のような背景がある。

  • consul eventをトリガーとして、任意のスクリプトを動かしたい
  • スクリプトの実装にはRubyを使いたい
  • スクリプトを更新するコストが結構大きく、これを改善したい

Consulクラスタ上で何か処理を行う場合いくつか方法があって、eventというのはその中の1つ。クラスタの各ノードでイベントの発生を監視し、発生すると決められた処理を実行する。シェルスクリプトを動かしてもいいのだけど、自分の場合は少し複雑なことをやりたかったのでRubyでスクリプトを書いて、それを動かすようにした。

結構いい感じに動いていて、これはいいねということになったのだけど、しばらく使っているとちょっとずつ不便なところとか手を入れたいところがでてくる。普通に修正して各ノードにデプロイすればいいんだけど、ノード数が多いので「この修正量で全ノードにデプロイか…」とつい思ってしまうことがあった。デプロイフローを見直せばいいんだけど、せっかくなので別の方法でアプローチできないかな…ということでchimayを作り始めた。

目的は何?

Chimayを作り始めた目的だが、やはりConsulクラスタ上で実行するスクリプトのデプロイコストを下げるということが大きい。全ノードにAnsibleやChef、Puppetを当てるのは時間がかかる。特に、クラスタ内の任意の1台で何か処理をしたい、という場合だと、全ノードにスクリプトをデプロイするよりはS3からその都度ダウンロードした方が時間がかからなさそうだ。

後は、mruby-cliを使って1つツールを書いてみたかったというのもある。仕事で作った物を汎用化したいという願望があって、うまくうまくできそうなテーマが見つかったわけだ。

進捗どうですか

先週の土曜から始めたのだけど、スクリプトをダウンロードして実行する、というところは割と簡単に書けた。Consul Eventで動くようにするとか、実行するスクリプトに引数を渡すといったところでちょっと手間どった。特に引数は悩ましい。Consul Eventで渡せる値は1つだけで、foo arg1 arg2 のように引数を渡そうと思うとクォートで囲んだりする必要がある。今のところ、URLのクエリで渡す形にしているが、将来的に変更するかもしれない。

書いていて難しかったのは、mrbgemでどういうクラスやメソッドがあるのかを調べる方法がよくわからず、ソースを毎回見に行ってしまったところ。後、テストを動かすとどこかでSegmentationFaultしてしまい、原因がわかっていないのでテストを書けないところだ。テストが書けないのは非常に不便なので早めに原因を取り除きたい…

 

ある程度動くようになったとはいえまだまだ実装中で、テストもないので実際に使えるレベルになるのはもうちょっと先になりそう。

RubyWorldConferenceに参加した(3日目) & KPT

2016年11月3日〜4日に開催されたRubyWorld Conference 2016に参加してきた。その4。といってもこの日は帰るだけ。後はKPT。

https://repl.info/2016/11/09/rubyworldconferenceに参加した2日目/

2016-11-05

観光したかったのだが土曜の夕方の便がとれず、日曜にやることがあったので昼前の便で帰ることにした。松江駅前のバス停にいったらRubyistがたくさんいておもしろかった。

img_4959
米子空港へ向かうバスの中より

KPT

今回のKPTです。

Keep

  • 3泊4日でも基本デイバッグでいける
  • 眼鏡用の洗剤や普段使っている石鹸などを全て持って行った。ストレスなく過ごすことができるのでとてもよい
  • パッカブルなボストンバッグを持って行った。帰りの荷物が増えても対応できるのでよい。
  • 仕事以外はiPhoneだけで十分だった。本も読めるし。前回はiPadあるといいかなー、と思ったけどなくても良さそう。
  • 長財布じゃなくて3つ折り財布を持って行ったがやはり取り扱いやすくてよかった
  • ANAの搭乗、iPhoneのWalletに登録しておけばかざすだけで簡単にできて便利だった
  • 衣類の圧縮袋便利

Problem

  • 3泊ともなるとホテルの寝間着では逆に疲れる
  • コートやシャツが思ったより嵩張った。気温の変化が激しく、調整が難しかった。
  • ホテルのシャワー、水量を増やすと回転して変な方向を向くので使いにくかった
  • 観光できなかったのが残念
  • 充電ケーブル、普段使っているものを持って行ったけど長くて使い勝手が悪い

Try

  • 普段使っている寝間着も持って行く
  • コンパクトにできるアウトドア系のジャケットやダウンで行く
  • 来年はついでに観光したい
  • 充電ケーブルは短い物に変えていく

RubyWorldConferenceに参加した(2日目)

2016年11月3日〜4日に開催されたRubyWorld Conference 2016に参加してきた。その3。イベント自体の様子は少なめです。

http://repl.info/2016/11/07/rubyworldconference_1/

2016-11-04 (2日目)

前日早めに退散したので起床に成功。スポンサーセッションで話すことになっていたので、PCとの接続チェックなどのために早めに向かう必要があった。

こういう場で話すのは久しぶりで、かつ会社としてオフィシャルな立場で話すのは初めてだったので結構緊張した。とはいえ10分だし、会社紹介がメインだったので早口になって時間が余る、ということもなく終了。後から撮っていただいた写真を見たところ、下を向き気味かつ姿勢がちょっと悪いのが気になった。練習不足ですね。

img_4933
くにびきメッセ

 

img_4943
ステッカーなど

2日目のお弁当。なかなか美味しかった。松江らしくシジミが乗っていますね。今回の旅行で1年分くらいシジミ食べた気がする。1日目に引き続きお茶・菓子もあり、Rubyをイメージしたお菓子をいただいた。

img_4941
2日目のお弁当

 

 

img_4945
Rubyをイメージしたお菓子だそう!

ところでこれは松江堀川地ビール館です。非公式イベントで行ったのだけど、とてもよかった。島根のクラフトビールであるびあヘルンを醸造していて、併設しているカウンターやレストランで飲める。何がすごかったって、クラフトビールがピッチャーで出てくる。こんなのはじめてみた…焼き肉とビール飲み放題で、疲れた体によく効きます。その後は一度ホテルに戻って荷物を置いて、散策しつつ見つけた日本酒バーで飲んだりして終了。

img_4948
醸造所併設です

 

img_4951
クラフトビールがピッチャーで出てくるのを初めて見た

 

img_4956
日本酒バーで飲んだ

https://repl.info/2016/11/12/rubyworldconference_3/

RubyWorldConferenceに参加した(1日目)

2016年11月3日〜4日に開催されたRubyWorld Conference 2016に参加してきた。その2。イベント自体の様子は少なめです。

http://repl.info/2016/11/06/rubyworldconference_0/

2016-11-03 (1日目)

さて、メインイベントのRubyWorldConference1日目である。前日うろうろしたが無事に起床し、会場へ向かうことができた。くにびきメッセまでの途中、何かの穴にコケや草が生えていてすごく綺麗でテンションが上がる。スマホしか持ってきていなかったのが悔やまれる。

img_4890
ホテルと会場の間で発見。カメラ持ってきておけば良かった…

ホテルと会場までの間には橋がかかっているのだけど、そこにRWCの宣伝旗がたくさんあった。記念に撮っておいた。会場ではもっと怠惰になろう、という話を聞いたりデプロイに必要な時間が13秒という話を聞いたりしてなかなか熱い感じだった。もっとコンピュータに仕事をさせたいというのは完全に同意で、まだまだ働き過ぎだなあと思う。デプロイ時間をもっと短くしたいというのは時々話していて、10秒とか20秒というのを達成しようとするとアーキテクチャから変えないといけないなあと再度どうやるか考えたり。

RWCとは関係ないのだけど、くにびきメッセの別会場で「世界の書籍展」というのを開催していたので軽く覗いたりもした。豆本と世界最大の鳥類図鑑の展示がおもしろい。特に、絵が描かれていたけど、そこに写真をプリントするとすごいだろうなあ。印画紙でも普通だと売ってないサイズだ。で、ちょっと検索してみるとギネス認定の世界最大の本「Bhutan」、Amazon.comで販売中 というのがあった。これはでかいね。実物を見てみたい。

img_4893
橋に旗が!

 

img_4906
くにびきメッセ、渡り廊下から

お昼はお弁当をお願いしていて、これは1日目のもの。美味しかったです。会場ではお茶と菓子も振る舞われていて、そちらもとても美味しい。休憩時間が結構とられているのがありがたい。1日目の終わりにはRuby Prizeの発表もあったが、尊敬しかなく、自分は何をやってきたんだろうと思ってしまった…こつこつ進むしかないですね。

img_4911
お昼のお弁当

 

img_4912
お茶とお菓子もあるよ

さて、1日目にはレセプションがあったが、最高なので行ったことがない人は行くといいです。結構写真を撮ったけど、だんだん適当になっているのがよくわかる。ちょうどRWC2日目の11/4(金)にカニの水揚げが解禁らしかったが、今回は食べられなかった。次回だな。

img_4914
カニ

お造りはすぐなくなった。このサイズのものは見るのも初めてでインパクトがある。そして撮ったときは気づかなかったけど、写真左下の緑の俵状のものはワサビか。これもすごいな。写真は載せていないけど、ローストポークなんかもあって普通に美味いです。

img_4917
お造り。

 

img_4921
お造りに群がるRubyistの様子です

ウェルカムパーティで存在だけ確認して食べられなかったのが、この松江おでん。なんでも最近売り出し中らしい。後ろの方に写真を載せているけど、日本酒とセットで最高です。KAKEYAと豊の秋が好み。後半になると体が少し冷えてきて、しじみ汁が最高だった。ホテルのバイキングでも用意してあって、呑兵衛にはありがたいことです。

img_4919
松江おでん

 

img_4924
李白

 

img_4925
豊の秋

 

img_4927
KAKEYA

 

img_4928
開春

レセプションの後は公式2次会があった(非公式3次会もあったそうな)が、自分は申し込み忘れていた翌日の早朝に打ち合わせがあるので参加せず、ホテルに戻って寝ることにしたのであった。というわけで1日目終わり。

img_4932
松江の夜

http://repl.info/2016/11/09/rubyworldconferenceに参加した2日目/