closure_tree: Trying to add 2 nodes simultaneously to closure_tree table results in a deadlock

When two nodes are added simultaneously to the closure tree table, this results in a deadlock and the query to acquire lock runs infinitely:

 (0.7ms)  SELECT GET_LOCK('b218f48596dc37d16bbcd16d1e18a116c', 0) AS t46e4b4acfd42770bad34d3e2a13a458a
  (0.4ms)  SELECT GET_LOCK('b218f48596dc37d16bbcd16d1e18a116c', 0) AS t9eaf21f51a8c5a1f2e39f6e8c4971b27
  (0.4ms)  SELECT GET_LOCK('b218f48596dc37d16bbcd16d1e18a116c', 0) AS tae827dc66e71e92f4c9f6edecae1cb54
  (0.3ms)  SELECT GET_LOCK('b218f48596dc37d16bbcd16d1e18a116c', 0) AS t7f7d47e378ffde7f311e56fde6613ab5
  (0.3ms)  SELECT GET_LOCK('b218f48596dc37d16bbcd16d1e18a116c', 0) AS ta7af1b261b90cba9e4d7399c96f17e26
  (0.3ms)  SELECT GET_LOCK('b218f48596dc37d16bbcd16d1e18a116c', 0) AS t3ed658e2e0d3008375e7356cc8e1c4a2
  (0.4ms)  SELECT GET_LOCK('b218f48596dc37d16bbcd16d1e18a116c', 0) AS t080acfd6e5536c50c4917ce271671be6
  (0.3ms)  SELECT GET_LOCK('b218f48596dc37d16bbcd16d1e18a116c', 0) AS t850056c6b58f75d8171bdcb69def558a
  (0.3ms)  SELECT GET_LOCK('b218f48596dc37d16bbcd16d1e18a116c', 0) AS t1ece95b52215d7c5e420ea9c0057aa72

You can reproduce the problem easily by using the code below (where List is the closure_tree model):


Thread.new do
  parent = List.find(86)
  new_node = List.new(:name => "test deadlock 1")
  parent.add_child(new_node)
end
Thread.new do
  parent = List.find(82)
  new_node = List.new(:name => "test deadlock 1")
  parent.add_child(new_node)
end

We faced this problem on production, and the infinite locking loop results in mysql being unresponsive, which in turn results in unresponsive app.

closure_tree version: 6.2.0 ruby: 2.3.0 rails: 5.0.0.1

About this issue

  • Original URL
  • State: open
  • Created 8 years ago
  • Reactions: 8
  • Comments: 43 (1 by maintainers)

Most upvoted comments

@mceachen I have started to take a look. I have two PRs open on with_advisory_lock to get the testing infrastructure ready to replicate this issue.

Sorry, its not a deadlock in the traditional sense, its actually worse since a deadlock will be detected and aborted. In this case, the first process has obtained the lock and is proceeding on its way when the second process comes in and attempts to obtain a lock. It fails since writer one already has the a lock (which is the correct behavior IMO). What I am having trouble understanding is why writer 1 hangs until writer 2 gives up attempting to obtain its lock.

If I run something like:

  parent = Tag.create(name: 'lock 1')
  (1..100).each do |i|
        p "adding #{i}"
        new_node = Tag.create(:name => "test deadlock #{i}")
        ActiveRecord::Base.transaction do
             parent = parent.add_child(new_node)
        end
end

on two separate machines upon starting the second both will shortly arrive in a semi-deadlocked situation. The script that I started the call on will then eventually expire and the first writer will continue. I’ve tried moving around the transaction/without it. Below is one potential outcome.

Writer 1 :

D, [2017-02-16T07:31:34.537506 #21545] DEBUG -- :   Tag Exists (0.4ms)  SELECT  1 AS one FROM "tags" INNER JOIN "tag_hierarchies" ON "tags"."id" = "tag_hierarchies"."ancestor_id" WHERE "tag_hierarchies"."descendant_id" = $12 AND "tags"."id" = $2 LIMIT 1  [["descendant_id", 7903], ["id", 7905]]
W, [2017-02-16T07:31:34.537919 #21545]  WARN -- :   ↳ /usr/local/bundle/gems/closure_tree-6.0.0/lib/closure_tree/hierarchy_maintenance.rb:27:in '_ct_validate'

D, [2017-02-16T07:31:34.541672 #21545] DEBUG -- :   SQL (1.6ms)  UPDATE "tags" SET "parent_id" = $1, "updated_at" = $2 WHERE "tags"."id" = $3  [["parent_id", 7903], ["updated_at", "2017-02-16 07:31:34.538876"], ["id", 7905]]
W, [2017-02-16T07:31:34.542309 #21545]  WARN -- :   ↳ /usr/local/bundle/gems/closure_tree-6.0.0/lib/closure_tree/model.rb:138:in 'add_child'

D, [2017-02-16T07:31:34.545266 #21545] DEBUG -- :    (0.5ms)  SELECT pg_try_advisory_lock(1814493058,0) AS t2ea0208ee2526226ecc8d65da8f4c493
W, [2017-02-16T07:31:34.546018 #21545]  WARN -- :   ↳ /usr/local/bundle/gems/with_advisory_lock-3.0.0/lib/with_advisory_lock/postgresql.rb:14:in 'execute_successful?'
D, [2017-02-16T07:31:34.646474 #21545] DEBUG -- :    (0.7ms)  SELECT pg_try_advisory_lock(1814493058,0) AS ta2ef67039c80d539454f14205900baac
W, [2017-02-16T07:31:34.647598 #21545]  WARN -- :   ↳ /usr/local/bundle/gems/with_advisory_lock-3.0.0/lib/with_advisory_lock/postgresql.rb:14:in 
'execute_successful?'

D, [2017-02-16T07:31:34.785180 #21545] DEBUG -- :    (0.8ms)  SELECT pg_try_advisory_lock(1814493058,0) AS tafb0ba91177bd447d53f97cae6f97ae0
W, [2017-02-16T07:31:34.786015 #21545]  WARN -- :   ↳ /usr/local/bundle/gems/with_advisory_lock-3.0.0/lib/with_advisory_lock/postgresql.rb:14:in 'execute_successful?'

D, [2017-02-16T07:31:34.910538 #21545] DEBUG -- :    (0.8ms)  SELECT pg_try_advisory_lock(1814493058,0) AS t878276a11847c5bb14ee22e966d51222
W, [2017-02-16T07:31:34.911517 #21545]  WARN -- :   ↳ /usr/local/bundle/gems/with_advisory_lock-3.0.0/lib/with_advisory_lock/postgresql.rb:14:in 'execute_successful?'

D, [2017-02-16T07:31:35.014669 #21545] DEBUG -- :    (1.2ms)  SELECT pg_try_advisory_lock(1814493058,0) AS t3996341ab230c95a3222cf08044a7593
W, [2017-02-16T07:31:35.015517 #21545]  WARN -- :   ↳ /usr/local/bundle/gems/with_advisory_lock-3.0.0/lib/with_advisory_lock/postgresql.rb:14:in 'execute_successful?'

D, [2017-02-16T07:31:35.098349 #21545] DEBUG -- :    (0.8ms)  SELECT pg_try_advisory_lock(1814493058,0) AS td67fe931e1e97081594bf1d3b7b577ac
W, [2017-02-16T07:31:35.098631 #21545]  WARN -- :   ↳ /usr/local/bundle/gems/with_advisory_lock-3.0.0/lib/with_advisory_lock/postgresql.rb:14:in 'execute_successful?'

D, [2017-02-16T07:31:35.210146 #21545] DEBUG -- :    (0.9ms)  SELECT pg_try_advisory_lock(1814493058,0) AS td2b2a4adf0f2fb2e61565b1a8d58da8b
W, [2017-02-16T07:31:35.210534 #21545]  WARN -- :   ↳ /usr/local/bundle/gems/with_advisory_lock-3.0.0/lib/with_advisory_lock/postgresql.rb:14:in 'execute_successful?'

D, [2017-02-16T07:31:35.351044 #21545] DEBUG -- :    (0.9ms)  SELECT pg_try_advisory_lock(1814493058,0) AS t6ba2e7b92cdaf2d1905f1a6214e7efa2
W, [2017-02-16T07:31:35.351374 #21545]  WARN -- :   ↳ /usr/local/bundle/gems/with_advisory_lock-3.0.0/lib/with_advisory_lock/postgresql.rb:14:in 
'execute_successful?'

D, [2017-02-16T07:31:35.429454 #21545] DEBUG -- :    (0.9ms)  SELECT pg_try_advisory_lock(1814493058,0) AS t8388cb7c01e7341bd1f63e3404fe8e9b
W, [2017-02-16T07:31:35.429904 #21545]  WARN -- :   ↳ /usr/local/bundle/gems/with_advisory_lock-3.0.0/lib/with_advisory_lock/postgresql.rb:14:in 'execute_successful?'

D, [2017-02-16T07:31:35.520427 #21545] DEBUG -- :    (0.9ms)  SELECT pg_try_advisory_lock(1814493058,0) AS tb6c70aa0fe9699434e66857ba96e1c7d
W, [2017-02-16T07:31:35.520766 #21545]  WARN -- :   ↳ /usr/local/bundle/gems/with_advisory_lock-3.0.0/lib/with_advisory_lock/postgresql.rb:14:in 'execute_successful?'

D, [2017-02-16T07:31:35.616061 #21545] DEBUG -- :    (0.9ms)  SELECT pg_try_advisory_lock(1814493058,0) AS taef48c46023f84d4e4c6454fce8dfed7
W, [2017-02-16T07:31:35.616458 #21545]  WARN -- :   ↳ /usr/local/bundle/gems/with_advisory_lock-3.0.0/lib/with_advisory_lock/postgresql.rb:14:in 'execute_successful?'

D, [2017-02-16T07:31:35.756555 #21545] DEBUG -- :    (0.9ms)  SELECT pg_try_advisory_lock(1814493058,0) AS t14f7ff2ec5dae5c9961188d75d2f0ea7
W, [2017-02-16T07:31:35.756914 #21545]  WARN -- :   ↳ /usr/local/bundle/gems/with_advisory_lock-3.0.0/lib/with_advisory_lock/postgresql.rb:14:in 'execute_successful?'

D, [2017-02-16T07:31:35.829528 #21545] DEBUG -- :    (0.7ms)  SELECT pg_try_advisory_lock(1814493058,0) AS t363a59f8e61d4ce5c0fcfc5abf6e8404
W, [2017-02-16T07:31:35.829871 #21545]  WARN -- :   ↳ /usr/local/bundle/gems/with_advisory_lock-3.0.0/lib/with_advisory_lock/postgresql.rb:14:in 'execute_successful?'

D, [2017-02-16T07:31:35.978112 #21545] DEBUG -- :    (0.9ms)  SELECT pg_try_advisory_lock(1814493058,0) AS t57ace053678ffafac925ebec1a163abe
W, [2017-02-16T07:31:35.978513 #21545]  WARN -- :   ↳ /usr/local/bundle/gems/with_advisory_lock-3.0.0/lib/with_advisory_lock/postgresql.rb:14:in 'execute_successful?'

D, [2017-02-16T07:31:36.053677 #21545] DEBUG -- :    (0.7ms)  SELECT pg_try_advisory_lock(1814493058,0) AS t809dd7878f94941becb585a2ee937e3e
W, [2017-02-16T07:31:36.053976 #21545]  WARN -- :   ↳ /usr/local/bundle/gems/with_advisory_lock-3.0.0/lib/with_advisory_lock/postgresql.rb:14:in 'execute_successful?'

Writer 2

D, [2017-02-16T07:31:34.457059 #21548] DEBUG -- : DEBUG: Chewy strategies stack: [2] <- bypass @ deadlock.rb:1
D, [2017-02-16T07:31:34.465650 #21548] DEBUG -- :    (0.5ms)  BEGIN
W, [2017-02-16T07:31:34.465916 #21548]  WARN -- :   ↳ deadlock.rb:3:in `block in <top (required)>'

D, [2017-02-16T07:31:34.488118 #21548] DEBUG -- :   SQL (0.8ms)  INSERT INTO "tags" ("name", "created_at", "updated_at") VALUES ($1, $2, $3) RETURNING "id"  [["name", "lock 1"], ["created_at", "2017-02-16 07:31:34.485771"], ["updated_at", "2017-02-16 07:31:34.485771"]]
W, [2017-02-16T07:31:34.488464 #21548]  WARN -- :   ↳ deadlock.rb:3:in `block in <top (required)>'

D, [2017-02-16T07:31:34.539682 #21548] DEBUG -- :    (0.5ms)  SELECT pg_try_advisory_lock(1814493058,0) AS t9f2a3d3d5ce591e0cbcad87a06e46c26
W, [2017-02-16T07:31:34.539915 #21548]  WARN -- :   ↳ /usr/local/bundle/gems/with_advisory_lock-3.0.0/lib/with_advisory_lock/postgresql.rb:14:in `execute_successful?'

D, [2017-02-16T07:31:34.601380 #21548] DEBUG -- :   SQL (0.7ms)  INSERT INTO "tag_hierarchies" ("ancestor_id", "descendant_id", "generations") VALUES ($1, $2, $3)  [["ancestor_id", 7904], ["descendant_id", 7904], ["generations", 0]]
W, [2017-02-16T07:31:34.601783 #21548]  WARN -- :   ↳ /usr/local/bundle/gems/closure_tree-6.0.0/lib/closure_tree/hierarchy_maintenance.rb:66:in `block in rebuild!'

D, [2017-02-16T07:32:34.608471 #21548] DEBUG -- :    (60004.6ms)  UPDATE "tags"
SET "position" = t.seq + -1
FROM (
  SELECT "id" AS id, row_number() OVER(ORDER BY position) AS seq
  FROM "tags"
  WHERE "parent_id" IS NULL 
) AS t
WHERE "tags"."id" = t.id

W, [2017-02-16T07:32:34.609206 #21548]  WARN -- :   ↳ /usr/local/bundle/gems/closure_tree-6.0.0/lib/closure_tree/numeric_order_support.rb:39:in `reorder_with_parent_id'

D, [2017-02-16T07:32:34.613072 #21548] DEBUG -- :    (1.4ms)  SELECT pg_advisory_unlock(1814493058,0) AS t5a0d17d7a9f5b664b7d1f87c2252d30c
W, [2017-02-16T07:32:34.613436 #21548]  WARN -- :   ↳ /usr/local/bundle/gems/with_advisory_lock-3.0.0/lib/with_advisory_lock/postgresql.rb:14:in `execute_successful?'

D, [2017-02-16T07:32:34.614966 #21548] DEBUG -- :    (0.4ms)  ROLLBACK
W, [2017-02-16T07:32:34.615220 #21548]  WARN -- :   ↳ deadlock.rb:3:in `block in <top (required)>'

D, [2017-02-16T07:32:34.616004 #21548] DEBUG -- : DEBUG: Chewy strategies stack: [2] -> bypass @ deadlock.rb:1
/usr/local/bundle/gems/activerecord-4.2.7.1/lib/active_record/connection_adapters/postgresql_adapter.rb:592:in `async_exec': PG::InFailedSqlTransaction: ERROR:  current transaction is aborted, commands ignored until end of transaction block (ActiveRecord::StatementInvalid)
: SELECT pg_advisory_unlock(1814493058,0) AS t5a0d17d7a9f5b664b7d1f87c2252d30c
	from /usr/local/bundle/gems/activerecord-4.2.7.1/lib/active_record/connection_adapters/postgresql_adapter.rb:592:in `block in exec_no_cache'
	from /usr/local/bundle/gems/activerecord-4.2.7.1/lib/active_record/connection_adapters/abstract_adapter.rb:484:in `block in log'
	from /usr/local/bundle/gems/activesupport-4.2.7.1/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
	from /usr/local/bundle/gems/activerecord-4.2.7.1/lib/active_record/connection_adapters/abstract_adapter.rb:478:in `log'
	from /usr/local/bundle/gems/activerecord-4.2.7.1/lib/active_record/connection_adapters/postgresql_adapter.rb:592:in `exec_no_cache'
	from /usr/local/bundle/gems/activerecord-4.2.7.1/lib/active_record/connection_adapters/postgresql_adapter.rb:584:in `execute_and_clear'
	from /usr/local/bundle/gems/activerecord-4.2.7.1/lib/active_record/connection_adapters/postgresql/database_statements.rb:50:in `select_value'
	from /usr/local/bundle/gems/with_advisory_lock-3.0.0/lib/with_advisory_lock/postgresql.rb:14:in `execute_successful?'
	from /usr/local/bundle/gems/with_advisory_lock-3.0.0/lib/with_advisory_lock/postgresql.rb:9:in `release_lock'
	from /usr/local/bundle/gems/with_advisory_lock-3.0.0/lib/with_advisory_lock/base.rb:81:in `ensure in yield_with_lock'
	from /usr/local/bundle/gems/with_advisory_lock-3.0.0/lib/with_advisory_lock/base.rb:81:in `yield_with_lock'
	from /usr/local/bundle/gems/with_advisory_lock-3.0.0/lib/with_advisory_lock/base.rb:65:in `yield_with_lock_and_timeout'
	from /usr/local/bundle/gems/with_advisory_lock-3.0.0/lib/with_advisory_lock/base.rb:48:in `with_advisory_lock_if_needed'
	from /usr/local/bundle/gems/with_advisory_lock-3.0.0/lib/with_advisory_lock/concern.rb:16:in `with_advisory_lock_result'
	from /usr/local/bundle/gems/with_advisory_lock-3.0.0/lib/with_advisory_lock/concern.rb:10:in `with_advisory_lock'
	from /usr/local/bundle/gems/closure_tree-6.0.0/lib/closure_tree/support.rb:103:in `with_advisory_lock'
	from /usr/local/bundle/gems/closure_tree-6.0.0/lib/closure_tree/hierarchy_maintenance.rb:63:in `rebuild!'
	from /usr/local/bundle/gems/closure_tree-6.0.0/lib/closure_tree/hierarchy_maintenance.rb:39:in `_ct_after_save'
	from /usr/local/bundle/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:432:in `block in make_lambda'
	from /usr/local/bundle/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:228:in `block in halting_and_conditional'
	from /usr/local/bundle/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:506:in `block in call'
	from /usr/local/bundle/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:506:in `each'
	from /usr/local/bundle/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:506:in `call'
	from /usr/local/bundle/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:92:in `__run_callbacks__'
	from /usr/local/bundle/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:778:in `_run_save_callbacks'
	from /usr/local/bundle/gems/activerecord-4.2.7.1/lib/active_record/callbacks.rb:302:in `create_or_update'
	from /usr/local/bundle/gems/activerecord-4.2.7.1/lib/active_record/persistence.rb:120:in `save'
	from /usr/local/bundle/gems/activerecord-4.2.7.1/lib/active_record/validations.rb:37:in `save'
	from /usr/local/bundle/gems/activerecord-4.2.7.1/lib/active_record/attribute_methods/dirty.rb:21:in `save'
	from /usr/local/bundle/gems/activerecord-4.2.7.1/lib/active_record/transactions.rb:286:in `block (2 levels) in save'
	from /usr/local/bundle/gems/activerecord-4.2.7.1/lib/active_record/transactions.rb:351:in `block in with_transaction_returning_status'
	from /usr/local/bundle/gems/activerecord-4.2.7.1/lib/active_record/connection_adapters/abstract/database_statements.rb:213:in `block in transaction'
	from /usr/local/bundle/gems/activerecord-4.2.7.1/lib/active_record/connection_adapters/abstract/transaction.rb:184:in `within_new_transaction'
	from /usr/local/bundle/gems/activerecord-4.2.7.1/lib/active_record/connection_adapters/abstract/database_statements.rb:213:in `transaction'
	from /usr/local/bundle/gems/activerecord-4.2.7.1/lib/active_record/transactions.rb:220:in 'transaction'
	from /usr/local/bundle/gems/activerecord-4.2.7.1/lib/active_record/transactions.rb:348:in 'with_transaction_returning_status'
	from /usr/local/bundle/gems/activerecord-4.2.7.1/lib/active_record/transactions.rb:286:in 'block in save'
	from /usr/local/bundle/gems/activerecord-4.2.7.1/lib/active_record/transactions.rb:301:in 'rollback_active_record_state!'
	from /usr/local/bundle/gems/activerecord-4.2.7.1/lib/active_record/transactions.rb:285:in 'save'
	from /usr/local/bundle/gems/newrelic_rpm-3.17.2.327/lib/new_relic/agent/instrumentation/active_record_helper.rb:26:in 'block in save'
	from /usr/local/bundle/gems/newrelic_rpm-3.17.2.327/lib/new_relic/agent.rb:586:in 'with_database_metric_name'
	from /usr/local/bundle/gems/newrelic_rpm-3.17.2.327/lib/new_relic/agent/instrumentation/active_record_helper.rb:25:in 'save'
	from /usr/local/bundle/gems/activerecord-4.2.7.1/lib/active_record/persistence.rb:34:in 'create'
	from deadlock.rb:3:in `block in <top (required)>'
	from /usr/local/bundle/gems/chewy-0.8.4/lib/chewy/strategy.rb:60:in 'wrap'
	from /usr/local/bundle/gems/chewy-0.8.4/lib/chewy.rb:179:in 'strategy'
	from deadlock.rb:1:in '<top (required)>'
	from /usr/local/bundle/gems/zeus-0.15.3/lib/zeus/load_tracking.rb:50:in 'load'
	from /usr/local/bundle/gems/zeus-0.15.3/lib/zeus/load_tracking.rb:50:in 'load'
	from /usr/local/bundle/gems/railties-4.2.7.1/lib/rails/commands/runner.rb:60:in '<top (required)>'
	from /usr/local/bundle/gems/railties-4.2.7.1/lib/rails/commands/commands_tasks.rb:123:in 'require'
	from /usr/local/bundle/gems/railties-4.2.7.1/lib/rails/commands/commands_tasks.rb:123:in 'require_command!'
	from /usr/local/bundle/gems/railties-4.2.7.1/lib/rails/commands/commands_tasks.rb:90:in 'runner'
	from /usr/local/bundle/gems/railties-4.2.7.1/lib/rails/commands/commands_tasks.rb:39:in 'run_command!'
	from /usr/local/bundle/gems/railties-4.2.7.1/lib/rails/commands.rb:17:in `<top (required)>'
	from bin/rails:9:in `require'
	from bin/rails:9:in `<main>'

I may have found a workaround that works for me – though at present I’m not sure of what other consequences may arise from my solution.

I’d long since upgraded the database to MariaDB 10.x from some older MySQL without apparent incident. Until one day when I needed to reparent something, and then…

Mysql2::Error: Lock wait timeout exceeded; try restarting transaction

At the time, i wrote an awful script that monkey-patched the part of closure_tree that dealt with locking (IIRC), and managed to get my reparenting done.

Now, however, I’m going to need to reparent more often, so I took some time today to do a little more research with a simple test script…

#!/usr/bin/ruby

$LOAD_PATH.unshift '/idw/lib'
Dir.chdir('/idw') do
  require 'rubygems'
  require 'bundler'
  Bundler.require(:default)   # TODO: split this out to just what's needed
  require '/idw/config/environment'
end

require 'pp'

# connect to the right database for the curent environment
IDW::Base.establish_connection(YAML.load(File.read('/idw/config/database.yml'))[ENV['IDW_ENV']])
IDW::Base.connection_pool.with_connection do

  hc = IDW::Hostclass.find_by(name: 'NS_OPMS')
  pp hc.self_and_ancestor_ids

  phc = IDW::Hostclass.find_by(name: 'NS_ORCAWAVE')
  pp phc.self_and_ancestor_ids

  phc.children << hc
  pp hc.self_and_ancestor_ids

end

Which, when run… Failed:

$ ./reparent
D, [2018-03-09T21:57:01.685550 #148] DEBUG -- :    (0.3ms)  SET NAMES utf8,  @@SESSION.sql_mode = CONCAT(CONCAT(@@sql_mode, ',STRICT_ALL_TABLES'), ',NO_AUTO_VALUE_ON_ZERO'),  @@SESSION.sql_auto_is_null = 0, @@SESSION.wait_timeout = 2147483
D, [2018-03-09T21:57:01.739543 #148] DEBUG -- :    (0.2ms)  SET NAMES utf8,  @@SESSION.sql_mode = CONCAT(CONCAT(@@sql_mode, ',STRICT_ALL_TABLES'), ',NO_AUTO_VALUE_ON_ZERO'),  @@SESSION.sql_auto_is_null = 0, @@SESSION.wait_timeout = 2147483
D, [2018-03-09T21:57:01.750891 #148] DEBUG -- :   IDW::Hostclass Load (0.4ms)  SELECT  `hostclasses`.* FROM `hostclasses` WHERE `hostclasses`.`name` = 'NS_OPMS' LIMIT 1
D, [2018-03-09T21:57:01.773695 #148] DEBUG -- :    (0.7ms)  SELECT `hostclasses`.`id` FROM `hostclasses` INNER JOIN `hostclass_hierarchies` ON `hostclasses`.`id` = `hostclass_hierarchies`.`ancestor_id` WHERE `hostclass_hierarchies`.`descendant_id` = 214 ORDER BY `hostclass_hierarchies`.generations asc
[214, 199, 2]
D, [2018-03-09T21:57:01.774403 #148] DEBUG -- :   IDW::Hostclass Load (0.4ms)  SELECT  `hostclasses`.* FROM `hostclasses` WHERE `hostclasses`.`name` = 'NS_ORCAWAVE' LIMIT 1
D, [2018-03-09T21:57:01.776208 #148] DEBUG -- :    (0.6ms)  SELECT `hostclasses`.`id` FROM `hostclasses` INNER JOIN `hostclass_hierarchies` ON `hostclasses`.`id` = `hostclass_hierarchies`.`ancestor_id` WHERE `hostclass_hierarchies`.`descendant_id` = 215 ORDER BY `hostclass_hierarchies`.generations asc
[215, 199, 2]
D, [2018-03-09T21:57:01.776909 #148] DEBUG -- :    (0.3ms)  BEGIN
D, [2018-03-09T21:57:01.781243 #148] DEBUG -- :   IDW::Hostclass Exists (0.5ms)  SELECT  1 AS one FROM `hostclasses` INNER JOIN `hostclass_hierarchies` ON `hostclasses`.`id` = `hostclass_hierarchies`.`ancestor_id` WHERE `hostclass_hierarchies`.`descendant_id` = 215 AND `hostclasses`.`id` = 214 LIMIT 1
D, [2018-03-09T21:57:01.782238 #148] DEBUG -- :   IDW::Hostclass Exists (0.3ms)  SELECT  1 AS one FROM `hostclasses` WHERE `hostclasses`.`name` = 'NS_OPMS' AND (`hostclasses`.`id` != 214) LIMIT 1
D, [2018-03-09T21:57:01.783606 #148] DEBUG -- :   SQL (0.4ms)  UPDATE `hostclasses` SET `parent_id` = 215, `updated_at` = '2018-03-09 21:57:01' WHERE `hostclasses`.`id` = 214
D, [2018-03-09T21:57:01.786316 #148] DEBUG -- :    (0.3ms)  SELECT GET_LOCK('3bd772cb25a662070242f7efd5ca79ef2', 0) AS t5e93ac4ad69f0ed6f2c5c9584d8b188b
D, [2018-03-09T21:57:01.788037 #148] DEBUG -- :    (1.4ms)  DELETE FROM `hostclass_hierarchies`
WHERE descendant_id IN (
  SELECT DISTINCT descendant_id
  FROM (SELECT descendant_id
    FROM `hostclass_hierarchies`
    WHERE ancestor_id = 214
       OR descendant_id = 214
  ) AS x )

D, [2018-03-09T21:57:01.793990 #148] DEBUG -- :    (0.2ms)  BEGIN
D, [2018-03-09T21:57:52.175943 #148] DEBUG -- :   SQL (50381.2ms)  INSERT INTO `hostclass_hierarchies` (`ancestor_id`, `descendant_id`, `generations`) VALUES (214, 214, 0)
D, [2018-03-09T21:57:52.176687 #148] DEBUG -- :    (0.5ms)  ROLLBACK
D, [2018-03-09T21:57:52.177324 #148] DEBUG -- :    (0.4ms)  SELECT RELEASE_LOCK('3bd772cb25a662070242f7efd5ca79ef2') AS t72718680058c1a95838500647177a561
D, [2018-03-09T21:57:52.177853 #148] DEBUG -- :    (0.4ms)  ROLLBACK
/idw/vendor/bundle/ruby/2.4.0/gems/mysql2-0.4.10/lib/mysql2/client.rb:120:in `_query': Mysql2::Error: Lock wait timeout exceeded; try restarting transaction: INSERT INTO `hostclass_hierarchies` (`ancestor_id`, `descendant_id`, `generations`) VALUES (214, 214, 0) (ActiveRecord::StatementInvalid)

…but provided some clues as to what was going on.

  • BEGIN transaction 1
    • UPDATE the node with its new parent
    • SELECT GET_LOCK stuff…
    • DELETE the old hierarchy information
    • BEGIN transaction 2
      • try to INSERT the new hierarchy information, but times out
    • ROLLBACK
    • SELECT RELEASE_LOCK
  • ROLLBACK

The (currently) third solution to https://stackoverflow.com/questions/6000336/how-to-debug-lock-wait-timeout-exceeded-on-mysql mentions that InnoDB’s default isolation level is REPEATABLE_READ, whereas other DBs use READ_COMMITTED.

Setting my database’s default isolation level to READ_COMMITTED…

SET GLOBAL TRANSACTION ISOLATION LEVEL READ COMMITTED;

…did the trick and allowed the reparenting script (and another more complicated script) to work as anticipated. Not sure I’d want to leave this on globally, might be best to set it as tightly around the code as possible (before that first transaction). Maybe something like…

FooModel.transaction(isolation: :read_committed) do
  # the reparenting stuff
end

I’m not confident this solves the other two-thread deadlock issue, as that appears to be happening with non-MySQL/MariaDB databases, also.

@mceachen It appears the issue I am running into is specifically (and I am guessing amitsaxena as well) around the numeric reordering (https://github.com/mceachen/closure_tree/blob/master/lib/closure_tree/hierarchy_maintenance.rb#L76) when calling add_child. Writer 1 will hang on grabbing https://github.com/mceachen/closure_tree/blob/master/lib/closure_tree/hierarchy_maintenance.rb#L63

while writer 2 will attempt to write into: https://github.com/mceachen/closure_tree/blob/master/lib/closure_tree/numeric_order_support.rb#L39

If you call directly children.create() it will avoid this issue, though I would guess any concurrent movement of leafs with numeric ordering enabled could result in this.

If I replace the with_advisory_lock from support.rb with just a model_class.lock(true) the deadlock appears to go away.

I did also note that if you attempt a destroy_all on a large tag set > 10000 (with our without numeric ordering) the destroy will fail with fatal: exception reentered.

Hope this is helpful.