[ruby-list:43356] TCPSocket#flushでスレッドが停止する現象について

はじめまして。
小関と申します。

Rails + MySQLを使っていて、長時間DBへのアクセスが無い場合に
Railsアプリケーションが反応しなくなる問題を調べています。


MongrelのFAQでそれらしい現象が報告されているのですが、
http://mongrel.rubyforge.org/faq.html
> Q: Mongrel stops working if it's left alone for a long time.
ここに載っている対策は以下の点で正しくないのではないかと
考えています。

 * ソースを読むと、ActiveRecord::Base.verification_timeout は
接続確認を「行わない」期間を表す値に見える。
 * RailsとMySQL間の接続のタイムアウトは、interactive_timeoutで
はなく、wait_timeoutで設定するのでは。
 * 少なくとも手元の環境では問題が解決しなかった。


いろいろ試した結果、Railsを使わずに、以下の手順で原因と
思われる症状を再現できました。
----------------------------------------------------------------
 1. TCPSocketを、SO_KEEPALIVEソケットオプションをオンで作成。
 2. 別のスレッドを起動する。このスレッドはsleepしているだけでOK。

 3. サーバから接続をcloseする。
 4. クライアントはcloseせず、CLOSE_WAITが消えるまで待つ。
 5. その後2回TCPSocket#flushを実行。

 6. 1回目のflushはBroken pipeの例外が発生する。
 7. 2度目flushの実行中にスレッドが停止したままになる。
----------------------------------------------------------------

上記2.で、別のスレッドを起動しなかった場合は再現しませんでした。
でした。また、4.のCLOSE_WAITが消える前でも、再現しませんでした。

Railsでは、3.がwait_timeoutの切断に相当し、5.の2回のflushが
mysql.rbドライバのCOM_STATISTICS/COM_QUIT送信に相当します。


Rubyのソースにプリント文を入れてどこで止まっているのか確認した
ところ、io.cのio_fflushから呼ばれる、
eval.c rb_thread_fd_writable(fd)内の、
rb_thread_schedule()で停止しているようでした。

http://www.tamacom.com/tour/lang/ruby/S/43.html#L346
http://www.tamacom.com/tour/lang/ruby/S/35.html#L10795

あまりよくわかっていませんが、
curr_thread->wait_for = WAIT_SELECT;
が満たされないので、flushを実行中のスレッドに制御が移らなく
なるのではないかと思います。


これはRuby本体の問題のような気がするのですが、
どうでしょうか？


以下具体的な再現の手順です。

■サーバ (sv.rb) - TCPServerのサンプルほぼそのままです。
---------------------------------------------------------
#! /usr/bin/env ruby

require "socket"

port = ARGV[0]
puts "server[#{$$}]: #{port}"
puts Time.new.to_s

gs = TCPServer.open(port)

while true
  Thread.start(gs.accept) do |s|
    print(s, " is accepted\n")
    while s.gets
      puts $_
    end
    print(s, " is gone\n")
    s.close
  end
end
---------------------------------------------------------

■クライアント (cl.rb)
---------------------------------------------------------
#! /usr/bin/env ruby

require "socket"

def start_another_thread
  @th = Thread.new do
    while true do
      sleep 5
    end
  end
  puts "Thread started: #{@th}"
end

def connect(host, port)
  STDOUT.sync = true
  @sock = TCPSocket.open(host, port)
  @sock.setsockopt Socket::SOL_SOCKET, Socket::SO_KEEPALIVE, true
end

def flush
  begin
    @sock.sync = false
    @sock.write("client[#{$$}]: write " + Time.new.to_s + "\n")
    @sock.sync = true

    puts "--- BEGIN flush"
    @sock.flush
    puts "--- END   flush"
  rescue => e
    puts "rescue: #{e}"
  end
end

Signal.trap(:QUIT) do
  5.times { do_flush }
end


#
# main
#

(host,port,wait) = ARGV
wait = wait.to_i
wait = 150 if wait <= 0

puts "client[#{$$}]: #{host}:#{port} wait:#{wait}sec"
puts Time.new.to_s

if 3 < ARGV.length
  start_another_thread
end

connect(host, port)
flush

while true
  print "--- sleep "
  i = 0
  (wait / 10).times do
    print "#{i += 1}."
    sleep 10
  end
  puts
  5.times { flush }
end

@sock.close
---------------------------------------------------------

■ 再現の手順

0. ターミナルを3つ開く。

1. サーバを10080番ポートで起動。
$ ./sv.rb 10080

2. クライアントを起動。
$ ./cl.rb localhost 10080 7800 1
7800秒後にflushする。末尾の1は別スレッドを起動する指定。

3. netstatのFIN_WAITとrubyを監視。
$ watch -n1 'netstat -nap 2> /dev/null | grep "\(FIN_WAIT\|ruby\)"'

4. 実行中のサーバをC-cで止める。

5. FIN_WAIT2が約1分後に消えるのを確認する。

6. CLOSE_WAITが約2時間後に消えるのを確認する。

7. クライアントが7800秒後に以下を出力して止まる。

--- BEGIN flush
rescue: Broken pipe
--- BEGIN flush

cl.rbの起動オプションで末尾の1を指定しなかった場合は、
別のスレッドが起動せず、5回繰り返しBroken pipeが表示される。

--- BEGIN flush
rescue: Broken pipe
--- BEGIN flush
rescue: Broken pipe
--- BEGIN flush
rescue: Broken pipe
--- BEGIN flush
rescue: Broken pipe
--- BEGIN flush
rescue: Broken pipe


CLOSE_WAITが消えるまでの2時間の待ち時間は、以下の
設定で短縮できる(システム全体の設定が変わるので注意が必要)。

# echo 30 > /proc/sys/net/ipv4/tcp_keepalive_time
# echo 20 > /proc/sys/net/ipv4/tcp_keepalive_intvl

cl.rbの起動オプションは、7800の代わりに150を指定する。
150秒で再現する。

■環境

VMWare上のFedora FC5
# ruby --version
ruby 1.8.6 (2007-03-13 patchlevel 0) [i686-linux]

以上よろしくお願いいたします。

-- 
koseki - http://d.hatena.ne.jp/koseki2/