Mysql2::Error: Deadlock when attempting to lock a job

[gorism]

We've just upgraded from 0.3.3 to 0.4.4, to resolve the race condition problem when running multiple workers. We're now seeing occasional MySQL deadlocks, which are unhandled exceptions and end up killing the worker.

For example:

svc1 Jun  5 12:35:17  Mysql2::Error: Deadlock found when trying to get lock; try restarting transaction: UPDATE `delayed_jobs` SET `locked_at` = '2013-06-05 12:35:16', `locked_by` = 'delayed_job.2 host:svc1 pid:20498' WHERE `delayed_jobs`.`queue` IN ('batch') AND ((run_at <= '2013-06-05 12:35:16' AND (locked_at IS NULL OR locked_at < '2013-06-05 08:35:16') OR locked_by = 'delayed_job.2 host:svc1 pid:20498') AND failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1

It would seem that, at the very least, this should be handled.

In case it matters, we're using delayed_job 3.0.4.

[jamsi]

I get this also with: 4.0.0.beta2

[piotrb]

+1 ..

Seems to happen to us when creating a delayed within another job running, not all the time of course, just very intermittently.

[philister]

+1
delayed_job (3.0.5)
delayed_job_active_record (0.4.4)

[settinghead]

Same here.
delayed_job (3.0.5)
delayed_job_active_record (0.4.4)

[cheneveld]

+1

delayed_job (3.0.5)
activesupport (> 3.0)
delayed_job_active_record (0.4.4)
activerecord (>= 2.1.0, < 4)
delayed_job (> 3.0)

mysql(5.5.27)

[philister]

Can we help anything to solve this? Anyone a patch or hints? We are restarting the workers ever 10 minutes because of this.
Thanks and regards, Ph.

[gorism]

@philister We ended up forking and changing the logic to use a row level lock. I suspect the original implementation went to lengths to avoid using a lock, but in the end I'll accept a performance penalty for more reliability. You can find our fork here: https://github.com/doxo/delayed_job_active_record

Note that we do still get occasional deadlocks which result in restarts, but rare in comparison to what we were getting before. It would be even better if the gem could detect the deadlock and retry, but getting the root cause out of the exception raised by the MySQL adapter is not straightforward, and possibly version dependent. So I opted to live with the occasional deadlocks for now.

[philister]

@gorism Thanks a lot!

[zxiest]

@gorism great fix! Thanks! -- The original dj's workers were dying after deadlock. I'm happy to see my workers alive after some time.

[cainlevy]

edit: see followup at #63 (comment). the new queries may not be a net gain, even without deadlocks.

We were bit by this as well during an upgrade.

I set up a concurrency test on my dev machine using two workers and a self-replicating job. The job simply creates two more of itself, with semi-random priority and run_at values. This setup reliably repros the deadlock within seconds.

The output of show engine innodb status says the contention is between the UPDATE query now used to reserve a job, and the DELETE query used to clean up a finished job. Surprising! Apparently the DELETE query first acquires a lock on the primary index (id) and then on the secondary index (priority, run_at). But the UPDATE query is using the (priority, run_at) index to scan the table, and is trying to grab primary key locks as it goes. Eventually the UPDATE and DELETE queries each grab one of two locks for a given row, try to acquire the other, and 💥. MySQL resolves by killing the UPDATE, which crashes the worker.

The fix I've worked out locally is to replace the index on (priority, run_at) with an index on (priority, run_at, locked_by). This completely stabilizes my concurrency test! My theory is that it allows the UPDATE query's scan to skip over rows held by workers, which takes it out of contention with the DELETE query.

Hope this helps.

🔒🔒

[cheneveld]

+20

Thanks a bunch cainlevy. This did the trick. Great work.

[philister]

Finally this did it for us, too. Thanks @cainlevy (Other solutions didn' t work in our case)

[ngan]

Upgraded from 0.3.3 to 0.4.4 and we're experiencing deadlock issues as well. We're running a total of 10 workers and usually they manage to keep the job queue down to 1000 or so. On mysql 5.1. @cainlevy's solution didn't work for us :-(.

------------------------
LATEST DETECTED DEADLOCK
------------------------
130811  3:19:18
*** (1) TRANSACTION:
TRANSACTION 2607F0BE7C, ACTIVE 0 sec, process no 7937, OS thread id 1364158784 fetching rows
mysql tables in use 1, locked 1
LOCK WAIT 5 lock struct(s), heap size 1248, 21 row lock(s)
MySQL thread id 2166505, query id 64381984645 init
UPDATE `delayed_jobs` SET `locked_at` = '2013-08-11 03:19:18', `locked_by` = 'delayed_job host:app3 pid:26732' WHERE ((run_at <= '2013-08-11 03:19:18' AND (locked_at IS NULL OR locked_at < '2013-08-10 23:19:18') OR locked_by = 'delayed_job host:app3 pid:26732') AND failed_at IS NULL) AND (priority <= '0') ORDER BY priority ASC, run_at ASC LIMIT 1
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 1853 page no 89833 n bits 80 index `PRIMARY` of table `production`.`delayed_jobs` trx id 2607F0BE7C lock_mode X locks rec but not gap waiting
Record lock, heap no 10 PHYSICAL RECORD: n_fields 14; compact format; info bits 32
 0: len 4; hex a1dd92ed; asc     ;;
 1: len 6; hex 002607f0c031; asc  &   1;;
 2: len 7; hex 000000549014ba; asc    T   ;;
 3: len 4; hex 80000000; asc     ;;
 4: len 4; hex 80000000; asc     ;;
 5: len 30; hex 2d2d2d2021727562792f6f626a6563743a44656c617965643a3a50657266; asc --- !ruby/object:Delayed::Perf; (total 1016 bytes);
 6: SQL NULL;
 7: len 8; hex 8000124f11d7316a; asc    O  1j;;
 8: len 8; hex 8000124f11d7316e; asc    O  1n;;
 9: SQL NULL;
 10: len 30; hex 64656c617965645f6a6f6220686f73743a61707030207069643a32333832; asc delayed_job host:app0 pid:2382; (total 31 bytes);
 11: SQL NULL;
 12: len 8; hex 8000124f11d7316a; asc    O  1j;;
 13: len 8; hex 8000124f11d7316a; asc    O  1j;;

*** (2) TRANSACTION:
TRANSACTION 2607F0C031, ACTIVE 0 sec, process no 7937, OS thread id 1363892544 updating or deleting
mysql tables in use 1, locked 1
3 lock struct(s), heap size 1248, 2 row lock(s), undo log entries 1
MySQL thread id 2166501, query id 64381985155 updating
DELETE FROM `delayed_jobs` WHERE `delayed_jobs`.`id` = 568169197
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 1853 page no 89833 n bits 80 index `PRIMARY` of table `production`.`delayed_jobs` trx id 2607F0C031 lock_mode X locks rec but not gap
Record lock, heap no 10 PHYSICAL RECORD: n_fields 14; compact format; info bits 32
 0: len 4; hex a1dd92ed; asc     ;;
 1: len 6; hex 002607f0c031; asc  &   1;;
 2: len 7; hex 000000549014ba; asc    T   ;;
 3: len 4; hex 80000000; asc     ;;
 4: len 4; hex 80000000; asc     ;;
 5: len 30; hex 2d2d2d2021727562792f6f626a6563743a44656c617965643a3a50657266; asc --- !ruby/object:Delayed::Perf; (total 1016 bytes);
 6: SQL NULL;
 7: len 8; hex 8000124f11d7316a; asc    O  1j;;
 8: len 8; hex 8000124f11d7316e; asc    O  1n;;
 9: SQL NULL;
 10: len 30; hex 64656c617965645f6a6f6220686f73743a61707030207069643a32333832; asc delayed_job host:app0 pid:2382; (total 31 bytes);
 11: SQL NULL;
 12: len 8; hex 8000124f11d7316a; asc    O  1j;;
 13: len 8; hex 8000124f11d7316a; asc    O  1j;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 1853 page no 33 n bits 648 index `delayed_jobs_priority` of table `production`.`delayed_jobs` trx id 2607F0C031 lock_mode X locks rec but not gap waiting
Record lock, heap no 406 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 4; hex 80000000; asc     ;;
 1: len 8; hex 8000124f11d7316a; asc    O  1j;;
 2: len 30; hex 64656c617965645f6a6f6220686f73743a61707030207069643a32333832; asc delayed_job host:app0 pid:2382; (total 31 bytes);
 3: len 4; hex a1dd92ed; asc     ;;

*** WE ROLL BACK TRANSACTION (2)

mysql> show indexes from delayed_jobs;
+--------------+------------+-----------------------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+
| Table        | Non_unique | Key_name              | Seq_in_index | Column_name | Collation | Cardinality | Sub_part | Packed | Null | Index_type | Comment |
+--------------+------------+-----------------------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+
| delayed_jobs |          0 | PRIMARY               |            1 | id          | A         |        2873 |     NULL | NULL   |      | BTREE      |         |
| delayed_jobs |          1 | delayed_jobs_locking  |            1 | locked_at   | A         |           1 |     NULL | NULL   | YES  | BTREE      |         |
| delayed_jobs |          1 | delayed_jobs_locking  |            2 | locked_by   | A         |           1 |     NULL | NULL   | YES  | BTREE      |         |
| delayed_jobs |          1 | delayed_jobs_priority |            1 | priority    | A         |           1 |     NULL | NULL   | YES  | BTREE      |         |
| delayed_jobs |          1 | delayed_jobs_priority |            2 | run_at      | A         |        1436 |     NULL | NULL   | YES  | BTREE      |         |
| delayed_jobs |          1 | delayed_jobs_priority |            3 | locked_by   | A         |        1436 |     NULL | NULL   | YES  | BTREE      |         |
+--------------+------------+-----------------------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+
6 rows in set (0.00 sec)

[cainlevy]

What do you get from an explain on a query with the same WHERE and ORDER clauses?

EXPLAIN SELECT * WHERE ((run_at <= '2013-08-11 03:19:18' AND (locked_at IS NULL OR locked_at < '2013-08-10 23:19:18') OR locked_by = 'delayed_job host:app3 pid:26732') AND failed_at IS NULL) AND (priority <= '0') ORDER BY priority ASC, run_at ASC LIMIT 1

[ngan]

mysql> EXPLAIN SELECT * FROM delayed_jobs WHERE ((run_at <= '2013-08-11 03:19:18' AND (locked_at IS NULL OR locked_at < '2013-08-10 23:19:18') OR locked_by = 'delayed_job host:app3 pid:26732') AND failed_at IS NULL) AND (priority <= '0') ORDER BY priority ASC, run_at ASC LIMIT 1;
+----+-------------+--------------+-------+--------------------------------------------+-----------------------+---------+------+------+-------------+
| id | select_type | table        | type  | possible_keys                              | key                   | key_len | ref  | rows | Extra       |
+----+-------------+--------------+-------+--------------------------------------------+-----------------------+---------+------+------+-------------+
|  1 | SIMPLE      | delayed_jobs | range | delayed_jobs_locking,delayed_jobs_priority | delayed_jobs_priority | 5       | NULL |  589 | Using where |
+----+-------------+--------------+-------+--------------------------------------------+-----------------------+---------+------+------+-------------+
1 row in set (0.00 sec)

[cainlevy]

I don't think we have the delayed_jobs_locking index on our table, but I guess it's not being used? Only other thing I can think of is maybe MySQL's 5.1 query planner isn't taking advantage of the updated delayed_jobs_priority index.

Hopefully you can reproduce the deadlock safely with a handful of workers running a self-replicating job. Let us know if you find anything more!

[ngan]

I added delayed_jobs_locking index for other metrics pulling. It would be nice if DJ-AR allowed us to specify the strategy for claiming jobs, because I would use the old strategy and still get new upgraded features.

[romanlehnert]

adding locked_at to the index (as described by @cainlevy) has the side-effekt for me that from 10 workers only a few (2-5) are working at the same time. Maybe this affects the performance on the jobs table?

[t-anjan]

Thanks @cainlevy. Adding locked_at to the index seems to have solved the problem for me as well. I did it yesterday, amidst the chaos of these deadlock errors being thrown all over the place in a queue of 100k jobs. As soon as this change was made, those deadlock issues were gone.

[ValMilkevich]

+1 Thanks @cainlevy, works great.

[ngan]

Is everyone that this is working for on mysql 5.5+?

[michaelglass]

@ngan @cainlevy's fix doesn't help me on 5.5

[t-anjan]

@ngan - I am on MySQL 5.5.31 and @cainlevy's fix DOES help me.

[cainlevy]

MySQL 5.5.x

If my fix isn't working for someone, I'd recommend following the steps I described earlier to set up a repro someplace safe to experiment. It's the only way we're going to learn more.

[michaelglass]

I'll publish my test setup in a moment. In the mean time: could not repro on 5.6.13

[michaelglass]

my experience with this patch: it does stop the deadlock but performance on my DJ doesn't improve after the deadlock is removed.

However, removing mysql optimizations makes performance jump from about 1job/second/worker to about 10 jobs/second/worker. seeing if upgrading to 5.6 will help one way or the other.

[zxiest]

I had originally thought some of the fixes above fixed my deadlock issues but apparently I still got them. I think using multiple processes will cause race conditions with the db so I built a gem that is thread based: a manager thread pulls jobs from the db and distributes them to a threadpool of workers. I would totally welcome contributors to http://github.com/zxiest/delayed_job_active_record_threaded

[csmuc]

Part of the minority as well :)

@albus522 "This issue primarily comes up when running a lot of really fast jobs against a mysql database, at which point why are the jobs being delayed at all."

One of the reasons I use ActiveRecord-backed DJ a lot: It helps me building robust distributed applications. I call remote services with DJs, not to delay them, but to replace the network calls with "INSERT INTO" statements, which are part of the local DB transaction. The DJ then takes care of doing the network call (and only this). I hope you guys don't mind that I plug my blog here, but those who are interested can read more here: http://blog.seiler.cc/post/112879365221/using-a-background-job-queue-to-implement-robust

[whitslar]

Minority here as well. We are using @csmuc 's monkeypatch which got rid of the deadlocks but then our select times got crazy slow (~200k rows, 2-3 seconds, MySQL 5.6.22, AWS RDS db.m1.small).

After monkeying around with indexes we found a pretty weird combination that seems to work well:

add_index :delayed_jobs, [:locked_by, :locked_at, :run_at] #has to be in this order
add_index :delayed_jobs, :run_at

Somehow this causes MySQL to do an index_merge with a sort_union and brings the select times down to a couple ms.

Disclaimer: We haven't used this in production but I'll let you all know how it goes...

[mwalsher]

Same problem here, even with a relatively small number of jobs (~500 recurring hourly - some small, some large), 3 servers, 6 workers each, and only ~2500 rows in the DJ table. Although I even see the deadlocks if only one server is running. These deadlocks seem to cause our DB CPU to hit and maintain ~100% utilization in perpetuity. This is obviously a big problem...

Is there any sort of consensus on which fork or monkey patch solves the problem? @albus522?

@whitslar how have those indexes been working for you over time with @csmuc's monkey patch?

[csmuc]

The other week we tried out the MySQL version a couple of hours in production (by removing my monkey patch) and almost immediately experienced deadlocks.

I also would like to get rid of the monkey patch by having a configuration option. I guess the chances are low to get that merged into this repo, so I'm also interested in moving to a fork as well.

[whitslar]

They've been working great. They've been in production for about 4 weeks now and we have had no issues. No deadlocks and the select times are great. Before the indexes, our production db (db.m3.xlarge, MySQL 5.6.22, ~200k rows, 9 workers) had been running between 70-80% cpu pretty regularly and now it's steady at 5-10%.

[csmuc]

PR to add a configuration option #111

[smikkelsen]

Ok, this is a huge gotcha. I just traced some major DB issues down to this problem here. Long story short, I just found a 47GB mysql-slow query log that completely filled up my hard drive and took down my app. This is one of the many side effects i've been noticing since I added multiple app servers. I only have 3 application servers and 1 worker per server and this is consistently happening. Is there a fix for this in master? or do I need to use a fork?

I'm really not super good with DB tuning, so i'm not sure I follow all of the info posted above, but maybe this can add to the discussion. This is what mysql is flooding my error log with:

[Warning] Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. The statement is unsafe because it uses a LIMIT clause. This is unsafe because the set of rows included cannot be predicted. Statement: UPDATE `delayed_jobs` SET `delayed_jobs`.`locked_at` = '2015-09-16 04:30:59.000000', `delayed_jobs`.`locked_by` = 'delayed_job host:linkthrottle5 pid:808' WHERE ((run_at <= '2015-09-16 04:30:59.585578' AND (locked_at IS NULL OR locked_at < '2015-09-16 00:30:59.585623') OR locked_by = 'delayed_job host:linkthrottle5 pid:808') AND failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1

I think this is a different problem in a way because it is a replication specific problem. But something that should contribute to the decision made here I believe.

[danielristic]

I'm also part of the growing minority of people who are experiencing this issue on real-life production setups. Deadlocks kill delayed jobs processes and we end up having far less workers after spikes of jobs. We're considering monkey-patching, as the different forks do not contain the latest additions to delayed_jobs, or just move to resque.

[jdelStrother]

Another data point - here's what happened when we started monkeypatching to use the reserve_with_scope_using_default_sql method:

[csmuc]

There is an open PR to add a config option: #111

[danielristic]

Wow. I've been using the reserve_with_scope_using_default_sql method on our production server running MySQL 5.5+ for the past 4 days and the processing time has been greatly reduced and no delayed_jobs worker process has been killed since I pushed the change. This PR really needs to be merged.

[klausmeyer]

Good news:
The PR (#111) was merged today and the configuration-option will be part of the next release 😎

[aaronjensen]

Awesome, now you can choose between a slower option and a fundamentally flawed option (see my above comments to see why it is fundamentally flawed). Not sure why I'm still subscribed to this thread... unsubscribing. good luck all.

[whitslar]

Ahh I dunno, the original locking mechanism + the indexes I described above completely fixes the issue for us. And if I were to bet on it, it would fix the root issue for everyone else here, given they were on MySQL >= 5.6 (there were some weird things happening with index merge/sort unions on 5.5, but I haven't tested so I can't confirm, mainly because it only crops it head up under a decent size load) Has anyone else been using the indexes I described? Either way, very happy to have PR #111 merged!

[csmuc]

@whitslar haven't tried in production, but the indexes made the queries actually a bit slower on my dev box (MySQL 5.6.13, 2k records). Maybe I'll spend some time and play around with other indexes

[smikkelsen]

Not sure what i'm doing wrong, but I tried master branch with the default lock method (legacy) and my logs were immediately flooded with deadlock errors:

Mysql2::Error: Deadlock found when trying to get lock; try restarting transaction

I put this in gemfile:
gem 'delayed_job_active_record', git: 'https://github.com/collectiveidea/delayed_job_active_record.git', branch: :master

and this in config/initializers/delayed_job_config.rb
Delayed::Backend::ActiveRecord.configuration.reserve_sql_strategy = :default_sql

Any ideas why this is still a problem / perhaps got worse when I tried the fix?

Thanks

[albus522]

Because that method was rarely better, which is why it isn't the default.

[smikkelsen]

So bottom line delayed jobs will not work with mysql and multiple workers?

[csmuc]

@smikkelsen the SQL must look something like this:

Delayed::Backend::ActiveRecord::Job Load (5.2ms)  SELECT `delayed_jobs`.* FROM `delayed_jobs` WHERE `delayed_jobs`.`queue` IN ('sms') AND ((run_at <= '2016-03-03 23:01:09' AND (locked_at IS NULL OR locked_at < '2016-03-03 19:01:09') OR locked_by = 'www02 pid:2225') AND failed_at IS NULL) ORDER BY priority ASC, run_at ASC, id ASC LIMIT 5

My Rails initializer:

Delayed::Backend::ActiveRecord.configure do |config|
  config.reserve_sql_strategy = :default_sql
end

I successfully use it in production (MySQL 5.6, 8 workers) and ran into deadlocks permanently using the other SQL strategy (which also littered the mysql log files with replication warnings).

[brettwgreen]

Running a ton of small jobs asynchronously is a perfectly reasonable thing to do, as is running multiple workers to offload the actual work. The queueing mechanism should work regardless... period. Shouldn't matter whether there are 5 big slow jobs or 10,000 fast ones.

[albus522]

@brettwgreen It is also reasonable to assume you optimize for your primary use case. No tool will ever work ideally for all situations.

[skuark]

Having a similar issue with the latest version (4.1.3) of delayed_job_active_record gem. In our case, the deadlock occurs occasionally, when new jobs are being inserted and there is a locked job.

I've used the following workaround to fix the issue:

# config/initializers/delayed_job_active_record.rb
# workaround based on https://github.com/collectiveidea/delayed_job_active_record/pull/91
#
module Delayed
  module Backend
    module ActiveRecord
      class Job < ::ActiveRecord::Base
        def save(*)
          retries = 0

          begin
            super
          rescue ::ActiveRecord::Deadlocked => e
            if retries < 100
              logger.info "ActiveRecord::Deadlocked rescued: #{e.message}"
              logger.info 'Retrying...'

              retries += 1
              retry
            else
              raise
            end
          end
        end
      end
    end
  end
end

[alexspark]

I just ran into a version of this issue. we're on mysql 5.7. for me the deadlocks were occurring between DJ worker queries that was searching for updates (optimize sql) and INSERTs from the app to enqueue a job. both queries require a lock on the index, but i concluded there is no deadlock scenario, it's just it just took too dang long to release the lock on the index, even on an nearly empty delayed_jobs table. we have around 12 workers.

What fixed it for us is we ran optimize table delayed_jobs, which i think is sort of like vacuum analyze on postgres. This fixed it, and it makes sense to run this regularly since this table sees constant insertions and deletions. CPU utilization, Read IOPs, deadlock exceptions all stopped after we ran this command. A data point is that we haven't run this command in years and we run 1000's of jobs/day for about 5 years, and the optimize command took around 6 seconds.