1_mysql_lock_wait_timeout_problem.MD

Initialize application

gem install rails -v 5.1.2 --no-ri --no-rdoc
rails _5.1.2_ new mysql_lock_wait_timeout_problem
cd mysql_lock_wait_timeout_problem

bundle exec rake db:create
bundle exec rails g model User first_name archived:boolean
bundle exec rails db:migrate

rails generate rspec:install

# change files as listed below

bundle exec rspec spec/lib/users/update_name_spec.rb
F

Failures:

  1) Users::UpdateName should update first name of an archived user
     Failure/Error: users.each { |u| u.update_columns(first_name: 'John') }

     ActiveRecord::StatementInvalid:
       Mysql2::Error: Lock wait timeout exceeded; try restarting transaction: UPDATE `users` SET `users`.`first_name` = 'John' WHERE `users`.`id` = 10
     # ./app/lib/users/update_name.rb:21:in `block in update_all'
     # ./app/lib/users/update_name.rb:21:in `each'
     # ./app/lib/users/update_name.rb:21:in `update_all'
     # ./app/lib/users/update_name.rb:16:in `block (2 levels) in update_batch'
     # ------------------
     # --- Caused by: ---
     # Mysql2::Error:
     #   Lock wait timeout exceeded; try restarting transaction
     #   ./app/lib/users/update_name.rb:21:in `block in update_all'

Start db console while test is hanging and outbut DB status

RAILS_ENV=test bundle exec rails db
mysql> show engine innodb status;


TRANSACTIONS
------------
Trx id counter 4359880
Purge done for trx's n:o < 4359879 undo n:o < 0 state: running but idle
History list length 1034
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 198, OS thread handle 0x700005048000, query id 43397 localhost root init
show engine innodb status
---TRANSACTION 4359879, ACTIVE 13 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 360, 1 row lock(s)
MySQL thread id 200, OS thread handle 0x700004f7c000, query id 43396 localhost root updating
UPDATE `users` SET `users`.`first_name` = 'John' WHERE `users`.`id` = 12
------- TRX HAS BEEN WAITING 13 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 173721 page no 3 n bits 72 index `PRIMARY` of table `mysql_lock_wait_timeout_problem_test`.`users` trx id 4359879 lock_mode X locks rec but not gap waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 7; compact format; info bits 0
 0: len 8; hex 800000000000000c; asc         ;;
 1: len 6; hex 0000004286c2; asc    B  ;;
 2: len 7; hex d6000001510110; asc     Q  ;;
 3: len 4; hex 4a616e65; asc Jane;;
 4: len 1; hex 81; asc  ;;
 5: len 5; hex 99a034ac56; asc   4 V;;
 6: len 5; hex 99a034ac56; asc   4 V;;

------------------
---TRANSACTION 4359874, ACTIVE 13 sec
2 lock struct(s), heap size 360, 1 row lock(s), undo log entries 1
MySQL thread id 199, OS thread handle 0x700004ef4000, query id 43393 localhost root
Trx read view will not see trx with id >= 4359879, sees < 4359879
--------
FILE I/O
--------
I/O thread 0 state: waiting for i/o request (insert buffer thread)
I/O thread 1 state: waiting for i/o request (log thread)
I/O thread 2 state: waiting for i/o request (read thread)
I/O thread 3 state: waiting for i/o request (read thread)
I/O thread 4 state: waiting for i/o request (read thread)
I/O thread 5 state: waiting for i/o request (read thread)
I/O thread 6 state: waiting for i/o request (write thread)
I/O thread 7 state: waiting for i/o request (write thread)
I/O thread 8 state: waiting for i/o request (write thread)
I/O thread 9 state: waiting for i/o request (write thread)
Pending normal aio reads: 0 [0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0] ,
 ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
1320 OS file reads, 89466 OS file writes, 79251 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.38 writes/s, 0.24 fsyncs/s
-------------------------------------

database.yml

# config/database.yml

development:
  adapter: mysql2
  encoding: utf8
  reconnect: false
  database: mysql_lock_wait_timeout_problem_development
  pool: 10
  username: root
  password:
  socket: /tmp/mysql.sock
  local_infile: true

test:
  adapter: mysql2
  encoding: utf8
  reconnect: false
  database: mysql_lock_wait_timeout_problem_test
  pool: 5
  username: root
  password:
  socket: /tmp/mysql.sock

Gemfile

source 'https://rubygems.org'

gem 'rails', '~> 5.1.2'
gem 'mysql2', '0.3.20'

group :development do
  gem 'listen'
end

group :test do
  gem 'rspec', '3.5.0'
  gem 'rspec-rails', '3.5.2'
  gem 'database_cleaner', '1.6.1'
end

rails_helper.rb

# spec/rails_helper.rb

ENV['RAILS_ENV'] ||= 'test'
require File.expand_path('../../config/environment', __FILE__)
require 'spec_helper'
require 'rspec/rails'
ActiveRecord::Migration.maintain_test_schema!

RSpec.configure do |config|
  config.use_transactional_fixtures = false
  config.infer_spec_type_from_file_location!
  config.filter_rails_from_backtrace!

  config.before(:each) do
    DatabaseCleaner.start
  end

  config.after(:each) do |example|
    DatabaseCleaner.clean
  end

end

update_name.rb

# app/lib/users/update_name.rb
class Users::UpdateName
  def call
    User
      .unscoped
      .find_in_batches do |batch|
        update_batch(batch)
      end
  end

  def update_batch(users_batch)
    users_batch
      .each_slice(100)
      .map { |users| Thread.new { update_all(users) } }
      .each(&:join)
  end

  def update_all(users)
    users.each { |u| u.update_columns(first_name: 'John') }
  end
end

update_name_spec.rb

# spec/lib/users/update_name_spec.rb
require 'rails_helper'

describe Users::UpdateName

  it 'should update first name of an archived user' do
    user = User.create(first_name: 'Jane', archived: true)

    Users::UpdateName.new.call

    expect(user.reload.first_name).to eq 'John'
  end

end

user.rb

# app/models/user.rb

class User < ApplicationRecord
  default_scope { where(archived: false) }
end