ActiveRecord::LockWaitTimeout, ActiveRecord::Deadlocked, ActiveRecord::ConnectionTimeoutError が起きた時に原因調査に役立つ情報を表示する gem を作った

それなりの規模のサービスを運用していると、不可解なエラーに遭遇することはよくあるものです。その中でもデータベース関連のエラーは一見難解な問題に見えるかもしれませんが、原因調査に役立つ情報をさえ出力すればたいていの場合は容易に原因を特定できるものです。というわけで、Rails でよく遭遇するエラーの調査に役立つ情報を出力する gem を作成しました。

activerecord-debug_errors

現在次のエラーをサポートしています。

  • ActiveRecord::LockWaitTimeout (MySQL のみ)
  • ActiveRecord::Deadlocked (MySQL のみ)
  • ActiveRecord::ConnectionTimeoutError

以下、具体的な例を用いてどのような情報が表示されるか説明します。

ActiveRecord::LockWaitTimeout

ActiveRecord::LockWaitTimeout が起きた場合、大きく次の 2 つの可能性が考えられます。

  • 特定のレコードのロックを取ったトランザクションの処理が長時間かかっている
  • 特定のレコードのロックを取ったトランザクションを開始したプロセスが死んでいる

いずれのケースにせよ、長時間かかっているトランザクションと、それを実行しているクライアントの情報があればかなりの手がかりになります。なので、activerecord-debug_errors では ActiveRecord::LockWaitTimeout が起きたら SHOW ENGINE INNODB STATUS の TRANSACTIONS セクションの情報と SHOW FULL PROCESSLIST の結果を表示します。

例えば次のスクリプトを実行してみます。

require 'active_record'
require 'activerecord-debug_errors'

ActiveRecord::Base.establish_connection(
  adapter:  'mysql2',
  host:     ENV['MYSQL_HOST'],
  port:     ENV['MYSQL_PORT'],
  username: ENV['MYSQL_USERNAME'],
  password: ENV['MYSQL_PASSWORD'],
  database: ENV['MYSQL_DATABASE'],
  variables: {
    innodb_lock_wait_timeout: 5,
  },
)

ActiveRecord::Base.logger = Logger.new($stdout).tap do |l|
  l.formatter = ActiveSupport::Logger::SimpleFormatter.new
  l.level = Logger::WARN
end

class User < ActiveRecord::Base; end

unless ActiveRecord::Base.connection.table_exists?('users')
  ActiveRecord::Base.connection.create_table('users') do |t|
    t.string 'name'
    t.index ['name'], name: 'ux_name', unique: true
  end
  User.create!(name: 'foo')
  User.create!(name: 'bar')
end

Array.new(2) do
  Thread.new do
    User.transaction do
      User.lock.find_by!(name: 'foo')
      sleep 7
    end
  end
end.each(&:join)

そうすると次のような出力が得られます。

ActiveRecord::LockWaitTimeout occurred:
------------
TRANSACTIONS
------------
Trx id counter 1511907
Purge done for trx's n:o < 1511588 undo n:o < 0 state: running but idle
History list length 42
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421781578717880, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 1511906, ACTIVE 5 sec
1 lock struct(s), heap size 1136, 1 row lock(s)
MySQL thread id 1016, OS thread handle 123145454059520, query id 62521 localhost 127.0.0.1 root starting
SHOW ENGINE INNODB STATUS
---TRANSACTION 1511905, ACTIVE 5 sec
3 lock struct(s), heap size 1136, 2 row lock(s)
MySQL thread id 1015, OS thread handle 123145453502464, query id 62520 localhost 127.0.0.1 root
-----------
PROCESSLIST
-----------
695     root    localhost:60956 information_schema      Sleep   9
1014    root    localhost:55971 test    Sleep   5
1015    root    localhost:55973 test    Sleep   5
1016    root    localhost:55974 test    Query   0       starting        SHOW FULL PROCESSLIST

上記の結果から、thread id 1015 と thread id 1016 のトランザクションが 5 秒かかっており、前者が localhost:55973、後者が localhost:55974 からのリクエストであることがわかります。この例だとわかりにくいですが、プロセスリストのユーザ情報、クライアントのホスト・ポート情報、SQL 情報から、ロックを保持したままのトランザクションを実行しているアプリケーションを特定できることもあるでしょう。例えば ECS を利用している場合、ECS agent のログをクライアントの IP で検索すればタスクを特定することができます。

ActiveRecord::Deadlocked

MySQL では SHOW ENGINE INNODB STATUS を実行すると LATEST DETECTED DEADLOCK というセクションが表示されるので、このセクションを確認することでデッドロックが起きた原因を調べることができます。なので、activerecord-debug_errors では ActiveRecord::Deadlocked が起きたら LATEST DETECTED DEADLOCK セクションの情報をログに出すようにしています。

例えば次のスクリプトを実行してみます。

require 'active_record'
require 'activerecord-debug_errors'

ActiveRecord::Base.establish_connection(
  adapter:  'mysql2',
  host:     ENV['MYSQL_HOST'],
  port:     ENV['MYSQL_PORT'],
  username: ENV['MYSQL_USERNAME'],
  password: ENV['MYSQL_PASSWORD'],
  database: ENV['MYSQL_DATABASE'],
)

ActiveRecord::Base.logger = Logger.new($stdout).tap do |l|
  l.formatter = ActiveSupport::Logger::SimpleFormatter.new
  l.level = Logger::WARN
end

class User < ActiveRecord::Base; end

unless ActiveRecord::Base.connection.table_exists?('users')
  ActiveRecord::Base.connection.create_table('users') do |t|
    t.string 'name'
    t.index ['name'], name: 'ux_name', unique: true
  end
  User.create!(name: 'foo')
  User.create!(name: 'bar')
end

ths = []
ths << Thread.new do
  User.transaction do
    User.lock.find_by!(name: 'foo')
    sleep 0.1
    User.lock.find_by!(name: 'bar')
  end
end

ths << Thread.new do
  User.transaction do
    User.lock.find_by!(name: 'bar')
    sleep 0.1
    User.lock.find_by!(name: 'foo')
  end
end

ths.each(&:join)

そうすると次のような出力が得られます。

ActiveRecord::Deadlocked occurred:
------------------------
LATEST DETECTED DEADLOCK
------------------------
2020-10-26 06:28:53 0x70000920c000
*** (1) TRANSACTION:
TRANSACTION 1511899, ACTIVE 1 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 4 lock struct(s), heap size 1136, 3 row lock(s)
MySQL thread id 1006, OS thread handle 123145455173632, query id 62434 localhost 127.0.0.1 root statistics
SELECT `users`.* FROM `users` WHERE `users`.`name` = 'foo' LIMIT 1 FOR UPDATE
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 6659 page no 4 n bits 72 index ux_name of table `test`.`users` trx id 1511899 lock_mode X locks rec but not gap waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 3; hex 666f6f; asc foo;;
 1: len 8; hex 8000000000000001; asc         ;;

*** (2) TRANSACTION:
TRANSACTION 1511900, ACTIVE 1 sec starting index read
mysql tables in use 1, locked 1
4 lock struct(s), heap size 1136, 3 row lock(s)
MySQL thread id 1007, OS thread handle 123145455452160, query id 62435 localhost 127.0.0.1 root statistics
SELECT `users`.* FROM `users` WHERE `users`.`name` = 'bar' LIMIT 1 FOR UPDATE
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 6659 page no 4 n bits 72 index ux_name of table `test`.`users` trx id 1511900 lock_mode X locks rec but not gap
Record lock, heap no 2 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 3; hex 666f6f; asc foo;;
 1: len 8; hex 8000000000000001; asc         ;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 6659 page no 4 n bits 72 index ux_name of table `test`.`users` trx id 1511900 lock_mode X locks rec but not gap waiting
Record lock, heap no 3 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 3; hex 626172; asc bar;;
 1: len 8; hex 8000000000000002; asc         ;;

*** WE ROLL BACK TRANSACTION (2)

上記の出力結果から次のようなことがわかります。

  • 1 つ目のトランザクションでは SELECT `users`.* FROM `users` WHERE `users`.`name` = 'foo' LIMIT 1 FOR UPDATE を実行している
  • 1 つ目のトランザクションでは ux_name の name = ‘foo’ のインデックスレコードの排他ロックが取得できるのを待っている
  • 2 つ目のトランザクションでは SELECT `users`.* FROM `users` WHERE `users`.`name` = 'bar' LIMIT 1 FOR UPDATE を実行している
  • 2 つ目のトランザクションでは ux_name の name = ‘foo’ のインデックスレコードの排他ロックを保持している
  • 2 つ目のトランザクションでは ux_name の name = ‘bar’ のインデックスレコードの排他ロックを取得できるのを待っている

LATEST DETECTED DEADLOCK の見方については InnoDB の行レベルロックについて解説してみるが参考になると思います。ただ、Gap Locks の範囲についての説明は間違っているかもしれないので注意してください…。MySQL のコードをいじったりしつつ実験した結果（rec1 <= x < rec2）と結論付けたんですが、ドキュメントの内容的にも「ギャップ」という名前的にも正しくは （rec1 < x < rec2）の気がします。

ActiveRecord::ConnectionTimeoutError

ActiveRecord のコネクションプールはデフォルトサイズが 5 で、一般的な使い方をしていれば 1 スレッドに対して 1 コネクションが割り当てられ、コネクションが足りなくなった場合は終了したスレッドが使っていたコネクションが使い回されるようになっています。よって、この理解が正しければ、DB に接続するスレッドが同時に 5 つを超えて存在しない限り ActiveRecord::ConnectionTimeoutError が起きることはありません。

ところがどういうわけか ActiveRecord::ConnectionTimeoutError に遭遇することもあることでしょう。activerecord-debug_errors ではコネクションを所有しているスレッドの情報を表示することで原因の特定に貢献します。

例えば次のスクリプトを実行してみます。

require 'active_record'
require 'activerecord-debug_errors'

ActiveRecord::Base.establish_connection(
  adapter:  'mysql2',
  host:     ENV['MYSQL_HOST'],
  port:     ENV['MYSQL_PORT'],
  username: ENV['MYSQL_USERNAME'],
  password: ENV['MYSQL_PASSWORD'],
  database: ENV['MYSQL_DATABASE'],
)

ActiveRecord::Base.logger = Logger.new($stdout).tap do |l|
  l.formatter = ActiveSupport::Logger::SimpleFormatter.new
  l.level = Logger::WARN
end

def foo
  ActiveRecord::Base.connection.execute("select 1")
  sleep 1
end

ActiveRecord::Base.connection.execute("select 1")
ths = []
ths << Thread.new(&method(:foo))
ths << Thread.new do
  ActiveRecord::Base.connection.execute("select 1")
  sleep 1
end
ths << Thread.new(&method(:foo))
ths << Thread.new do
  ActiveRecord::Base.connection.execute("select 1")
  sleep 1
end
ths << Thread.new do
  ActiveRecord::Base.connection.execute("select 1")
  sleep 1
end

ths.each(&:join)

すると次のような出力が得られます。

ActiveRecord::ConnectionTimeoutError occured:
  Thread #<Thread:0x00007fe51c05fa88 sleep_forever> status=sleep priority=0
      /tmp/script.rb:40:in `join'
      /tmp/script.rb:40:in `each'
      /tmp/script.rb:40:in `<main>'
  Thread #<Thread:0x00007fe51c1f2788 /tmp/script.rb:18 dead> status=false priority=0
  Thread #<Thread:0x00007fe51c1f2648 /tmp/script.rb:26 dead> status=false priority=0
  Thread #<Thread:0x00007fe51c1f24b8 /tmp/script.rb:18 dead> status=false priority=0
  Thread #<Thread:0x00007fe51c1f2418 /tmp/script.rb:31 dead> status=false priority=0

上記の情報から、次のようなスレッドがコネクションを所有していることがわかります。

  • 40 行目で join を実行しているスレッド（メインスレッド）
  • 18 行目に定義されている foo メソッドを実行していた 2 スレッド
  • 26 行目のブロックを実行していた 1 スレッド
  • 31 行目のブロックを実行していた 1 スレッド

この例ではメインスレッド以外のスレッドは処理を終了しているので ActiveRecord::ConnectionTimeoutError にはならないでほしいものですが、ActiveRecord では明示的にコネクションを解放しない限り、acquire_connection を実行した時にしかコネクションを解放しないのでエラーになっています。

よって、例えば次のようにすれば ActiveRecord::ConnectionTimeoutError は避けられます。

def foo
  ActiveRecord::Base.connection.execute("select 1")
  ActiveRecord::Base.connection_pool.release_connection
  sleep 1
end

ActiveRecord::Base.connection.execute("select 1")
ths = []
ths << Thread.new(&method(:foo))
ths << Thread.new do
  ActiveRecord::Base.connection.execute("select 1")
  ActiveRecord::Base.connection_pool.release_connection
  sleep 1
end
ths << Thread.new(&method(:foo))
ths << Thread.new do
  ActiveRecord::Base.connection.execute("select 1")
  ActiveRecord::Base.connection_pool.release_connection
  sleep 1
end
ths << Thread.new do
  ActiveRecord::Base.connection.execute("select 1")
  ActiveRecord::Base.connection_pool.release_connection
  sleep 1
end

ths.each(&:join)

以上、デバッグが捗りますね！