Ruby 1.8.7-pXX v.s. Capistrano 2.5.x

投稿者 akira 2009-07-31 11:41:00 GMT

最近のRubyでCapistranoを実行しようとすると、対象ホストが二つ以上のときにかなりの確率でハングアップしてしまうことに気付いた。しばらくは見て見ぬふりをしていたのだが、仕事に少し関係しそうな気配もあって、調べてみることにした。

1.8.7-p72では問題なかった記憶があり、1.8.7-p174で現象が出ることは確認済み。ということでtagのある1.8.7-p72、1.8.7-p160をかわきりに、ruby_1_8_7におけるversion.hのcommit logを手掛かりに二分探索の雰囲気を出しつつ絞り込みをかけていったところ1.8.7-p135で現象が現れることがわかった。

このパッチレベルでの修正内容はruby-core:20446である。が、これを見ても具体的にどういう影響が出ているのかはわからない。修正内容からするとむしろ状況がよくなってくれそうなものだが…… などと思いつつ、試行錯誤を繰り返した。

まず、Capistranoでの問題はNet::SSHで起こっていることがわかった。Net::SSHではIO.selectを使っいながらソケットから少しずつ読み出すということをしている。これにThreadを組み合わせると現象を起こせる。たとえばこんな感じ:

require "net/ssh"
["localhost","localhost"].map {|h|
  Thread.new{ Net::SSH.start(h, "foo") }
}.each {|t| t.join }

次に、修正内容と見比べつつさらに試行錯誤し、結局はdebug printをいれてスレッドの動きを追いかけた。かなりおおざっぱな読み方しかしていないので間違っているかもしれないが、なんとなくこんな感じの動きのようだった:

  • 読み出し可能になるのを待っているスレッドがある
  • そのスレッドで読み出し可能になる→th_foundに値が入る
  • 次にスケジューリングのためスレッドを順番に見ていくが
  • 運悪く、th_foundなスレッドに到達する前に「次」に実行可能なスレッドが見付かってしまう

現象からいうと運悪くというよりは運良く処理が進むことがあるといったところで、ほとんどの場合、上の再現例の二つのスレッドがゆずり合うような形になっている。

そこで、試みにth_foundしたスレッドにできるだけ処理がまわるよう、スレッドのプライオリティが同じときにも「次」候補のチェックをするように以下のような変更を加えてみた。

--- eval.c	(revision 24335)
+++ eval.c	(working copy)
@@ -11228,7 +11228,7 @@
 	    break;
 	}
 	if ((th->status == THREAD_RUNNABLE || th == th_found) && th->stk_ptr) {
-	    if (!next || next->priority < th->priority) {
+	    if (!next || next->priority <= th->priority) {
                 if (th == th_found) {
                     th_found->status = THREAD_RUNNABLE;
                     th_found->wait_for = 0;

Capistranoでの動きをざっとみたところではこの変更で止まらずに動くようになった。Rubyのテスト(threadのみ)をまわしてみた限りでは影響はなさそう。はてさて。

……という話をIRCでしてみたところmputさんがredmineに登録してくれた(Bug#1848ruby-dev:38971)。あと多分、これは同じ話だと思う。

追記(2009-08-07)

少なくとも上の変更ではまずいと思えるので変更を出しなおしたのがruby-dev:39003。ただ、それでもまずい感じはするよねと思っていたところ、やはり好しくないらしい。

それではということで再現コードを小さくして、debug printで動きを追いかけてみたのがruby-dev:39037になる。th_foundとはちょうどあべこべにスレッドが選択されている…… ような気がしている。

追記(2009-08-10)

ruby-dev:39042にある通りr24442で修正された。

トラックバック

トラックバックリンク:
http://arika.org/diary/trackbacks?article_id=2640