locking.md

Let's examine locking in mysql.

Creating a lock timeout in mysql console:

$ mysql -e 'create database lock_test'
Query OK, 1 row affected (0.00 sec)

$ mysql lock_test -e 'create table lockables (id int primary key auto_increment)'
Query OK, 0 rows affected (0.01 sec)

$ mysql lock_test -e 'insert into lockables values (1)'
Query OK, 1 row affected (0.00 sec)

$ mysql lock_test

mysql> begin;
Query OK, 0 rows affected (0.00 sec)

mysql> select * from lock_test where id = 1 for update;
^Z

$ mysql lock_test

mysql> begin;
Query OK, 0 rows affected (0.00 sec)

mysql> select * from lock_test where id = 1 for update;
ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction

Doing the same in ruby land:

irb> class Lockable < ActiveRecord::Base
   *  establish_connection "mysql2://root@localhost/lock_test"
   * end
=> Lockable(id: integer)
irb> Lockable.transaction do
   *   puts Lockable.lock(true).find(1)
   *   $stdin.readline
   *   puts Lockable.lock(true).find(2)
   * end
   (0.2ms)  BEGIN
  Lockable Load (12.2ms)  SELECT `lockables`.* FROM `lockables` WHERE `lockables`.`id` = 1 LIMIT 1 FOR UPDATE
#<Lockable:0x007fa1d1e49e20>

Now that's waiting for input, in another console:

irb> class Lockable < ActiveRecord::Base
   *  establish_connection "mysql2://root@localhost/lock_test"
   * end
=> Lockable(id: integer)
irb> Lockable.transaction do
   *   puts Lockable.lock(true).find(2)
   *   $stdin.readline
   *   puts Lockable.lock(true).find(1)
   * end
   (0.1ms)  BEGIN
  Lockable Load (0.3ms)  SELECT `lockables`.* FROM `lockables` WHERE `lockables`.`id` = 2 LIMIT 1 FOR UPDATE
#<Lockable:0x007faa00aa1ca0>

Now going back to the first console and hitting enter, then waiting a while:

  Lockable Load (51146.2ms)  SELECT `lockables`.* FROM `lockables` WHERE `lockables`.`id` = 2 LIMIT 1 FOR UPDATE
Mysql2::Error: Lock wait timeout exceeded; try restarting transaction: SELECT  `lockables`.* FROM `lockables`  WHERE `lockables`.`id` = 2 LIMIT 1 FOR UPDATE
   (0.2ms)  ROLLBACK
ActiveRecord::StatementInvalid: Mysql2::Error: Lock wait timeout exceeded; try restarting transaction: SELECT  `lockables`.* FROM `lockables`  WHERE `lockables`.`id` = 2 LIMIT 1 FOR UPDATE
   from /Users/sj26/Projects/.../.bundle/ruby/2.1.0/gems/activerecord-3.2.20/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:245:in `query'
   from /Users/sj26/Projects/.../.bundle/ruby/2.1.0/gems/activerecord-3.2.20/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:245:in `block in execute'
   from /Users/sj26/Projects/.../.bundle/ruby/2.1.0/gems/activerecord-3.2.20/lib/active_record/connection_adapters/abstract_adapter.rb:280:in `block in log'
   from /Users/sj26/Projects/.../.bundle/ruby/2.1.0/gems/activesupport-3.2.20/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
   from /Users/sj26/Projects/.../.bundle/ruby/2.1.0/gems/activerecord-3.2.20/lib/active_record/connection_adapters/abstract_adapter.rb:275:in `log'
   from /Users/sj26/Projects/.../.bundle/ruby/2.1.0/gems/activerecord-3.2.20/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:245:in `execute'
   from /Users/sj26/Projects/.../.bundle/ruby/2.1.0/gems/activerecord-3.2.20/lib/active_record/connection_adapters/mysql2_adapter.rb:213:in `execute'
   from /Users/sj26/Projects/.../.bundle/ruby/2.1.0/gems/activerecord-3.2.20/lib/active_record/connection_adapters/mysql2_adapter.rb:217:in `exec_query'
   from /Users/sj26/Projects/.../.bundle/ruby/2.1.0/gems/activerecord-3.2.20/lib/active_record/connection_adapters/mysql2_adapter.rb:226:in `select'
   from /Users/sj26/Projects/.../.bundle/ruby/2.1.0/gems/activerecord-3.2.20/lib/active_record/connection_adapters/abstract/database_statements.rb:18:in `select_all'
   from /Users/sj26/Projects/.../.bundle/ruby/2.1.0/gems/activerecord-3.2.20/lib/active_record/connection_adapters/abstract/query_cache.rb:63:in `select_all'
... 11 levels...
   from /Users/sj26/Projects/.../.bundle/ruby/2.1.0/gems/activerecord-3.2.20/lib/active_record/relation/finder_methods.rb:122:in `first'
   from /Users/sj26/Projects/.../.bundle/ruby/2.1.0/gems/activerecord-3.2.20/lib/active_record/relation/finder_methods.rb:339:in `find_one'
   from /Users/sj26/Projects/.../.bundle/ruby/2.1.0/gems/activerecord-3.2.20/lib/active_record/relation/finder_methods.rb:315:in `find_with_ids'
   from /Users/sj26/Projects/.../.bundle/ruby/2.1.0/gems/activerecord-3.2.20/lib/active_record/relation/finder_methods.rb:107:in `find'
   from (irb):22:in `block in irb_binding'
   from /Users/sj26/Projects/.../.bundle/ruby/2.1.0/gems/activerecord-3.2.20/lib/active_record/connection_adapters/abstract/database_statements.rb:192:in `transaction'
   from /Users/sj26/Projects/.../.bundle/ruby/2.1.0/gems/activerecord-3.2.20/lib/active_record/transactions.rb:208:in `transaction'
   from (irb):19
   from /Users/sj26/Projects/.../.bundle/ruby/2.1.0/gems/railties-3.2.20/lib/rails/commands/console.rb:47:in `start'
   from /Users/sj26/Projects/.../.bundle/ruby/2.1.0/gems/railties-3.2.20/lib/rails/commands/console.rb:8:in `start'
   from /Users/sj26/Projects/.../.bundle/ruby/2.1.0/gems/railties-3.2.20/lib/rails/commands.rb:41:in `<top (required)>'
   from script/rails:6:in `require'
   from script/rails:6:in `<main>'

50s is the default lock timeout in MySQL, so this makes sense. ActiveRecord yields the error as a StatementInvalid which unfortunately doesn't preserve the intial MySQL error number like DatabaseWrappedException. Instead we'll have to do some regexp matching.