CODEWITHSUNDEEP
ruby-on-railsactiverecord
Jake Becker
Jake Becker

Reputation: 21

Log long-running transactions in Rails

I'm getting "Mysql2::Error: Lock wait timeout exceeded" errors in my production Rails app, and I'm looking for help debugging which transaction is locking the tables for an excessively long time. MySQL has a "slow query" log, but not a log of slow transactions, as far as I can tell.

Is there a way to log information about how long transactions take directly from ActiveRecord?

Upvotes: 2

Views: 1406

Answers (1)

Henrik N
Henrik N

Reputation: 16274

My team logs slow transactions like this:

In lib/slow_transaction_logger.rb:

module SlowTransactionLogger
  LOG_IF_SLOWER_THAN_SECONDS = ENV.fetch("LOG_TRANSACTIONS_SLOWER_THAN_SECONDS", "5").to_f

  def transaction(*args)
    start = Time.now
    value = super
    finish = Time.now

    duration = finish - start

    return value if duration <= LOG_IF_SLOWER_THAN_SECONDS

    backtrace = caller.
      select { |path| path.start_with?(Rails.root.to_s) }.
      reject { |row|
        row.include?("/gems/") ||
        row.include?("/app/middleware/") ||
        row.include?("/config/initializers/")
      }

    puts "slow_transaction_logger: duration=#{duration.round(2)} start=#{start.to_s.inspect} finish=#{finish.to_s.inspect} class=#{name} caller=#{backtrace.to_json}"

    value
  end
end

In config/initializers/active_record.rb:

class ActiveRecord::Base
  class << self
    prepend SlowTransactionLogger
  end
end

So by default, it logs transactions slower than 5 seconds, in every environment.

If you set a LOG_TRANSACTIONS_SLOWER_THAN_SECONDS environment variable (e.g. on Heroku), you can tweak that limit.

We log with puts intentionally because it ends up in the logs in Heroku, and we also we see it more easily in dev and tests. But feel free to use Rails.logger if you prefer.

Upvotes: 4

Related Questions