More than 5 years have passed since last update.

ActiveRecord::LockWaitTimeoutが発生したときにtransactionでハマってた

Last updated at 2019-04-12Posted at 2019-04-12

背景

railsでウェブサービスを作っています。ありがたいことにユーザー数も増えてきました。そこで起きたことについてのメモです。

ActiveRecord.transactionを貼っていたことが原因でLockWaitTimeoutが発生していました。

ActiveRecord.transaction do
  users.each do |user|
    user.do_something
    user.profile.do_something
  end
end

users.each do |user|
  ActiveRecord.transaction do
    user.do_something
    user.profile.do_something
  end
end

「transactionを全体に貼るなよ」というのはあると思いますが、お金の関わるところだったので全体で処理が完了するように担保したかったという背景もあり。。

ユーザー数が増えてきたタイミングから ActiveRecord::LockWaitTimeout が発生するようになりました。

まずはログを見ましたが、アクセスが増えてるわけでも重い処理が走っているわけでもなさそうでした。
ということでnginx / puma / mysql の設定を疑いました。

ワーカープロセス数は auto になっていたので自動でコア数に合わせて作成されます

/etc/nginx.conf

worker_processes auto;

pumaのドキュメントより
ワーカー数→CPUコア数 ~ 1.5倍
スレッド数→16
が良いそうです。

.env

RAILS_MAXTHREADS = 16
WEB_CONCURRENCY = CPU_NUM * 1.5 = xx

config/puma.rb

threads_count = ENV.fetch("RAILS_MAX_THREADS") { 5 }
threads threads_count, threads_count
workers ENV.fetch("WEB_CONCURRENCY") { 2 }

.env

RAILS_MAXTHREADS = 16
WEB_CONCURRENCY = CPU_NUM * 1.5 = xx

config/database.yml

pool: <%= ENV['RAILS_MAX_THREADS'] || 5 %>

ユーザーの接続数などが原因かと思っていましたがそんなこともなくLockWaitTimeoutは引き続き発生していました。

ログ見ても特に問題点がなさそうだったので、ダメ元で社内の人に確認すると「運用のとある処理中」にLockWaitTimeoutが発生していることが判明。
ユーザーの動きとは別のものがトリガーで起きていたようです。

該当するソースを読んだらtransactionを貼っていて、修正したら発生しなくなりました。

ActiveRecord::LockWaitTimeout
まわりで調べても設定まわりの話が多くメモ的に残しておこうと思いました。どなたか同じように詰まっている方のお力に慣れれば幸いです。

ソースを読む。

多分データベースのトランザクションを開始してる。