ActiveRecord::DebugErrors
ActiveRecord::DebugErrors is an extension of activerecord to display useful debug logs on errors.
Installation
Add this line to your application's Gemfile:
gem 'activerecord-debug_errors'
And then execute:
$ bundle install
Or install it yourself as:
$ gem install activerecord-debug_errors
Usage
You only have to load the gem:
require 'activerecord-debug_errors'
By loading the gem, you can see useful debug logs on errors as described below.
ActiveRecord::LockWaitTimeout
If you use MySQL and when ActiveRecord::LockWaitTimeout occurs, you can see a log like below:
ActiveRecord::LockWaitTimeout occurred:
------------
TRANSACTIONS
------------
Trx id counter 1511885
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 421781578720592, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421781578719688, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421781578718784, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421781578716976, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421781578717880, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 1511884, ACTIVE 2 sec
1 lock struct(s), heap size 1136, 1 row lock(s)
MySQL thread id 970, OS thread handle 123145454895104, query id 62140 localhost 127.0.0.1 root starting
SHOW ENGINE INNODB STATUS
---TRANSACTION 1511883, ACTIVE 2 sec
3 lock struct(s), heap size 1136, 2 row lock(s)
MySQL thread id 969, OS thread handle 123145455452160, query id 62138 localhost 127.0.0.1 root
-----------
PROCESSLIST
-----------
695 root localhost:60956 information_schema Sleep 3
853 root localhost:60036 Sleep 23
966 root localhost:54726 test Sleep 2
967 root localhost:54731 test Sleep 2
968 root localhost:54732 test Sleep 2
969 root localhost:54734 test Sleep 2
970 root localhost:54735 test Query 0 starting SHOW FULL PROCESSLIST
In the preceding log, you can find that there were two long transactions. The first one was created by thread id 969 (the client localhost:54734), and the second one was created by thread id 970 (the client localhost:54735).
ActiveRecord::Deadlocked
If you use MySQL and when ActiveRecord::Deadlocked occurs, you can see the information of the latest detected deadlock:
ActiveRecord::Deadlocked occurred:
------------------------
LATEST DETECTED DEADLOCK
------------------------
2020-10-26 05:16:54 0x700008fec000
*** (1) TRANSACTION:
TRANSACTION 1511857, ACTIVE 0 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 919, OS thread handle 123145453502464, query id 61760 localhost 127.0.0.1 root statistics
SELECT `users`.* FROM `users` WHERE `users`.`name` = 'bar' 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 1511857 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 ;;
*** (2) TRANSACTION:
TRANSACTION 1511858, ACTIVE 0 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 920, OS thread handle 123145453223936, query id 61761 localhost 127.0.0.1 root statistics
SELECT `users`.* FROM `users` WHERE `users`.`name` = 'foo' 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 1511858 lock_mode X locks rec but not gap
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 ;;
*** (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 1511858 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 ;;
*** WE ROLL BACK TRANSACTION (2)
Note that the user requires the PROCESS priviledge to collect the information.
ActiveRecord::ConnectionTimeoutError
When ActiveRecord::ConnectionTimeoutError occurs, you can see the information of connection owners (threads):
ActiveRecord::ConnectionTimeoutError occured:
connection owners:
Thread #<Thread:0x00007fbda205fa70 sleep_forever> status=sleep priority=0
/path/to/activerecord-debug_errors/spec/activerecord/debug_errors/ext/connection_adapters/connection_pool_spec.rb:32:in `join'
/path/to/activerecord-debug_errors/spec/activerecord/debug_errors/ext/connection_adapters/connection_pool_spec.rb:32:in `each'
/path/to/activerecord-debug_errors/spec/activerecord/debug_errors/ext/connection_adapters/connection_pool_spec.rb:32:in `block (4 levels) in <top (required)>'
/path/to/ruby/gems/2.7.0/gems/rspec-expectations-3.9.3/lib/rspec/matchers/built_in/raise_error.rb:52:in `matches?'
/path/to/ruby/gems/2.7.0/gems/rspec-expectations-3.9.3/lib/rspec/expectations/handler.rb:50:in `block in handle_matcher'
/path/to/ruby/gems/2.7.0/gems/rspec-expectations-3.9.3/lib/rspec/expectations/handler.rb:27:in `with_matcher'
/path/to/ruby/gems/2.7.0/gems/rspec-expectations-3.9.3/lib/rspec/expectations/handler.rb:48:in `handle_matcher'
/path/to/ruby/gems/2.7.0/gems/rspec-expectations-3.9.3/lib/rspec/expectations/expectation_target.rb:65:in `to'
/path/to/ruby/gems/2.7.0/gems/rspec-expectations-3.9.3/lib/rspec/expectations/expectation_target.rb:101:in `to'
/path/to/activerecord-debug_errors/spec/activerecord/debug_errors/ext/connection_adapters/connection_pool_spec.rb:26:in `block (3 levels) in <top (required)>'
-- snip --
/path/to/bin/rspec:23:in `load'
/path/to/bin/rspec:23:in `<main>'
Thread #<Thread:0x00007fbda4908008 /path/to/activerecord-debug_errors/spec/activerecord/debug_errors/ext/connection_adapters/connection_pool_spec.rb:29 dead> status=false priority=0
Thread #<Thread:0x00007fbda4909688 /path/to/activerecord-debug_errors/spec/activerecord/debug_errors/ext/connection_adapters/connection_pool_spec.rb:29 dead> status=false priority=0
Thread #<Thread:0x00007fbda4908170 /path/to/activerecord-debug_errors/spec/activerecord/debug_errors/ext/connection_adapters/connection_pool_spec.rb:29 dead> status=false priority=0
Thread #<Thread:0x00007fbda48fbd58 /path/to/activerecord-debug_errors/spec/activerecord/debug_errors/ext/connection_adapters/connection_pool_spec.rb:29 dead> status=false priority=0
other threads:
Thread #<Thread:0x00007fbda52b3ad0 /path/to/ruby/gems/2.7.0/gems/activerecord-6.0.3.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:334 sleep> status=sleep priority=0
/path/to/ruby/gems/2.7.0/gems/activerecord-6.0.3.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:337:in `sleep'
/path/to/ruby/gems/2.7.0/gems/activerecord-6.0.3.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:337:in `block in spawn_thread'
Thread #<Thread:0x00007fbda5100170 /path/to/activerecord-debug_errors/spec/activerecord/debug_errors/ext/connection_adapters/connection_pool_spec.rb:24 sleep> status=sleep priority=0
/path/to/activerecord-debug_errors/spec/activerecord/debug_errors/ext/connection_adapters/connection_pool_spec.rb:24:in `sleep'
/path/to/activerecord-debug_errors/spec/activerecord/debug_errors/ext/connection_adapters/connection_pool_spec.rb:24:in `block (4 levels) in <top (required)>'
Thread #<Thread:0x00007fbda48fbc40 /path/to/activerecord-debug_errors/spec/activerecord/debug_errors/ext/connection_adapters/connection_pool_spec.rb:29 run> status=run priority=0
/path/to/activerecord-debug_errors/lib/activerecord/debug_errors/ext/connection_adapters/connection_pool.rb:22:in `backtrace'
/path/to/activerecord-debug_errors/lib/activerecord/debug_errors/ext/connection_adapters/connection_pool.rb:22:in `block in dump_threads'
/path/to/activerecord-debug_errors/lib/activerecord/debug_errors/ext/connection_adapters/connection_pool.rb:34:in `each'
/path/to/activerecord-debug_errors/lib/activerecord/debug_errors/ext/connection_adapters/connection_pool.rb:34:in `dump_threads'
/path/to/activerecord-debug_errors/lib/activerecord/debug_errors/ext/connection_adapters/connection_pool.rb:9:in `rescue in acquire_connection'
/path/to/activerecord-debug_errors/lib/activerecord/debug_errors/ext/connection_adapters/connection_pool.rb:6:in `acquire_connection'
/path/to/ruby/gems/2.7.0/gems/activerecord-6.0.3.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:593:in `checkout'
/path/to/activerecord-debug_errors/spec/activerecord/debug_errors/ext/connection_adapters/connection_pool_spec.rb:30:in `block (6 levels) in <top (required)>'
In the preceding log, you can find that there were five connection owners and three other threads. The first owner was the main thread (Thread:0x00007fbda205fa70) and the other owners are dead threads.
Development
After checking out the repo, run bin/setup to install dependencies. Then, run rake spec to run the tests. You can also run bin/console for an interactive prompt that will allow you to experiment.
To install this gem onto your local machine, run bundle exec rake install. To release a new version, update the version number in version.rb, and then run bundle exec rake release, which will create a git tag for the version, push git commits and tags, and push the .gem file to rubygems.org.
Contributing
Bug reports and pull requests are welcome on GitHub at https://github.com/abicky/activerecord-debug_errors.
License
The gem is available as open source under the terms of the MIT License.