Rails + MySQL (+ Mongrel?) でDB接続の通信が無い状態が続くとデッドロックする。

(追記) この問題について、原因はRubyの側にあるのではないかと考えています。特定の条件下でTCPSocket#flushを実行すると、スレッドが停止したまま処理が戻ってこなくなります。以下の投稿で、Railsを使わず再現する方法を説明しました。

• http://blade.nagaokaut.ac.jp/cgi-bin/scat.rb/ruby/ruby-list/43356

(追記おわり)

開発サーバが翌日になるとデッドロックする、という現象が続いていて悩みました。

解決方法は、MongrelのFAQに上がっていました。

• http://mongrel.rubyforge.org/faq.html

Q: Mongrel stops working if it’s left alone for a long time.

If you find that Mongrel stops working after a long idle time and you’re using MySQL then you’re hitting a bug in the MySQL driver that doesn’t properly timeout connections. What happens is the MySQL server side of the connection times out and closes, but the MySQL client doesn’t detect this and just sits there.

What you have to do is set:

ActiveRecord::Base.verification_timeout = 14400

Or to any value that is lower than the MySQL server’s interactive_timeout setting. This will make sure that ActiveRecord checks the connection often enough to reset the connection.

• MySQLドライバのバグのせいで、サーバ側がタイムアウトで接続を閉じているのにクライアント側は閉じていないのが原因。
• ActiveRecord::Base.verification_timeout に、 MySQLのinteractive_timeout よりも短い値を設定すると解決する。

ということだそうです。

interactive_timeoutの調べ方は、

# /usr/libexec/mysqld --verbose --help | grep interactive

です。

早速やってみよー。

(追記) 直ってませんでした……。

そもそもinteractive_timeoutではなくwait_timeoutなんじゃないだろうか。マニュアルを見ると、

• http://www.mysql.org/doc/refman/4.1/ja/show-variables.html

• interactive_timeout 対話式接続を終了する前に、サーバがアクティビティを待機する秒数。対話型クライアントは、mysql_real_connect() で CLIENT_INTERACTIVE オプションを使用するクライアントとして定義される。wait_timeout も参照のこと。
• wait_timeout 対話式ではない接続を終了する前に、サーバがアクティビティを待機する秒数。

とあります。

/etc/my.cnf で interactive_timeout=30 に設定してもRailsからの接続は30秒で切れません。一方mysqlコマンドからの接続はきっちり30秒で切れていました。25に減らすと25秒で接続が切れました。

接続がスリープしている時間などは、show processlistコマンドで確認できます。

• http://d.hatena.ne.jp/koseki2/20070202/mysqlprocesslist

wait_timeoutを30に設定すると、Railsからの接続も30秒で切れるようになり、かつ、夜間に発生しているのと同じ無反応状態になるので、wait_timeoutによる接続断が原因のようです。

(追記) 記事タイトルにはデッドロックって書きましたけど、正確にはデッドロックじゃなさそうですね。トレースを見ると、MongrelのスレッドがRails実行のための排他ロックを獲得できず、待ち状態になっているみたいでした。lib/mongrel/rails.rbの以下のあたり。

@guard.synchronize(:EX) {
  Dispatcher.dispatch(cgi, ActionController::CgiRequest::DEFAULT_SESSION_OPTIONS, response.body)
}

(追記) wait_timeoutを短く設定することで無反応状態を再現できる、と思ったんですが、ActiveRecord::Base.verification_timeoutの設定を外したら、再現しなくなりました。。
verification_timeout を設定した状態だと、mysqldを再起動した時も無反応状態になっていました。
mysqlのクエリーログを見てると、verification_timeoutの設定によって、Statisticsコマンドの実行が一定期間行われなくなるみたいでした。

verification_timeout はデフォルト0(毎回接続チェック)みたいだけど、これ増やしたらダメじゃないかなー。高負荷で毎回チェックしたく無い場合に増やす値なんじゃないかという気がする。

# Check for activity after at least +verification_timeout+ seconds.
# Defaults to 0 (always check.)
cattr_accessor :verification_timeout
@@verification_timeout = 0

↓@@verification_timeoutは、下のメソッドの引数に渡される。
/lib/active_record/connection_adapters/abstract_adapter.rb

# Lazily verify this connection, calling +active?+ only if it hasn't
# been called for +timeout+ seconds.
def verify!(timeout)
  now = Time.now.to_i
  if (now - @last_verification) > timeout
    reconnect! unless active?
    @last_verification = now
  end
end

mysql_adapter.rb の active? の実装で@connection.statが呼ばれます。
/lib/active_record/vendor/mysql.rb

def stat()
  command COM_STATISTICS
end

こいつがmysqldにStatisticsコマンドを送っていそう。