Mysql deadlock explanation needed

Question

I received the following deadlock log via "SHOW INNODB STATUS". Can someone care to explain why the transaction was aborted? It seems that Transaction 2 is holding the lock, but is also stuck requesting the same lock (except for the "waiting" part), which leads to a deadlock when Transaction 1 requires it as well.

=====================================                                                                                                                                                                          
091205  6:25:01 INNODB MONITOR OUTPUT                                                                                                                                                                          
=====================================                                                                                                                                                                          
Per second averages calculated from the last 39 seconds                                                                                                                                                        
----------                                                                                                                                                                                                     
SEMAPHORES                                                                                                                                                                                                     
----------                                                                                                                                                                                                     
OS WAIT ARRAY INFO: reservation count 233826, signal count 229982                                                                                                                                              
Mutex spin waits 0, rounds 1569878, OS waits 4740                                                                                                                                                              
RW-shared spins 517345, OS waits 227127; RW-excl spins 4390, OS waits 1945                                                                                                                                     
------------------------                                                                                                                                                                                       
LATEST DETECTED DEADLOCK                                                                                                                                                                                       
------------------------                                                                                                                                                                                       
091205  6:19:35                                                                                                                                                                                                
*** (1) TRANSACTION:                                                                                                                                                                                           
TRANSACTION 0 479286429, ACTIVE 0 sec, process no 17618, OS thread id 2963139472 fetching rows                                                                                                                 
mysql tables in use 1, locked 1                                                                                                                                                                                
LOCK WAIT 176 lock struct(s), heap size 11584                                                                                                                                                                  
MySQL thread id 330396, query id 97467367 64-71-26-218.static.wiline.com 64.71.26.218 autotaggeruser Sorting result                                                                                            
SELECT api_key,completed,compute_units,created,deleted,flags,func_name,group_id,hostname,is_meta,jid,label,language,num_children,parent_ujid,priority,process_id,restartable,status,type,uid,ujid,version,wid FROM jobs WHERE status='new' and is_meta=0 ORDER BY priority asc,jid asc FOR UPDATE                                                                                                                             
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:                                                                                                                                                                   
RECORD LOCKS space id 0 page no 17549 n bits 128 index `PRIMARY` of table `takeyourorder/jobs` trx id 0 479286429 lock_mode X waiting                                                               
Record lock, heap no 61 PHYSICAL RECORD: n_fields 26; compact format; info bits 0                                                                                                                              
0: len 8; hex 800000000000277c; asc       '|;; 1: len 6; hex 00001c915499; asc     T ;; 2: len 7; hex 00000006e21e2a; asc       *;; 3: len 8; hex 8000000000000002; asc         ;; 4: len 8; hex 8000000000000845; asc        E;; 5: SQL NULL; 6: len 8; hex 8000000000002773; asc       's;; 7: len 1; hex 80; asc  ;; 8: len 8; hex 8000000000000002; asc         ;; 9: len 16; hex 636f72656f66746865627261696e2d75; asc coreofthebrain-u;; 10: len 4; hex 80000eb8; asc     ;; 11: len 1; hex 01; asc  ;; 12: len 30; hex 322e362e32202872656c6561736532362d6d61696e742c20417072203139; asc 2.6.2 (release26-maint, Apr 19;...(truncated); 13: len 30; hex 5f5f6d61696e5f5f2e3c6c616d6264613e206174203c737464696e3e3a31; asc __main__.<lambda> at <stdin>:1;; 14: len 5; hex 8000000001; asc      ;; 15: len 0; hex ; asc ;; 16: len 4; hex 80000000; asc     ;; 17: len 4; hex 80000005; asc     ;; 18: len 4; hex 4b19fb58; asc K  X;; 19: len 4; hex 4b19fb77; asc K  w;; 20: len 1; hex 07; asc  ;; 21: len 1; hex 80; asc  ;; 22: len 4; hex 80000000; asc     ;; 23: len 4; hex 80000000; asc     ;; 24: len 1; hex 80; asc  ;; 25: len 4; hex 80001415; asc     ;;                                                                                                            

*** (2) TRANSACTION:
TRANSACTION 0 479286425, ACTIVE 0 sec, process no 17618, OS thread id 2971134864 starting index read, thread declared inside InnoDB 500
mysql tables in use 1, locked 1                                                                                                        
7 lock struct(s), heap size 1024, undo log entries 3                                                                                   
MySQL thread id 330430, query id 97467371 64-71-26-218.static.wiline.com 64.71.26.218 autotaggeruser Updating                          
UPDATE jobs SET status='done' WHERE jid=10099                                                                                          
*** (2) HOLDS THE LOCK(S):                                                                                                             
RECORD LOCKS space id 0 page no 17549 n bits 128 index `PRIMARY` of table `takeyourorder/jobs` trx id 0 479286425 lock_mode X locks rec but not gap
Record lock, heap no 61 PHYSICAL RECORD: n_fields 26; compact format; info bits 0                                                                             
0: len 8; hex 800000000000277c; asc       '|;; 1: len 6; hex 00001c915499; asc     T ;; 2: len 7; hex 00000006e21e2a; asc       *;; 3: len 8; hex 8000000000000002; asc         ;; 4: len 8; hex 8000000000000845; asc        E;; 5: SQL NULL; 6: len 8; hex 8000000000002773; asc       's;; 7: len 1; hex 80; asc  ;; 8: len 8; hex 8000000000000002; asc         ;; 9: len 16; hex 636f72656f66746865627261696e2d75; asc coreofthebrain-u;; 10: len 4; hex 80000eb8; asc     ;; 11: len 1; hex 01; asc  ;; 12: len 30; hex 322e362e32202872656c6561736532362d6d61696e742c20417072203139; asc 2.6.2 (release26-maint, Apr 19;...(truncated); 13: len 30; hex 5f5f6d61696e5f5f2e3c6c616d6264613e206174203c737464696e3e3a31; asc __main__.<lambda> at <stdin>:1;; 14: len 5; hex 8000000001; asc      ;; 15: len 0; hex ; asc ;; 16: len 4; hex 80000000; asc     ;; 17: len 4; hex 80000005; asc     ;; 18: len 4; hex 4b19fb58; asc K  X;; 19: len 4; hex 4b19fb77; asc K  w;; 20: len 1; hex 07; asc  ;; 21: len 1; hex 80; asc  ;; 22: len 4; hex 80000000; asc     ;; 23: len 4; hex 80000000; asc     ;; 24: len 1; hex 80; asc  ;; 25: len 4; hex 80001415; asc     ;;                                                                                                            

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 17548 n bits 144 index `PRIMARY` of table `takeyourorder/jobs` trx id 0 479286425 lock_mode X locks rec but not gap waiting
Record lock, heap no 73 PHYSICAL RECORD: n_fields 26; compact format; info bits 0                                                                                     
0: len 8; hex 8000000000002773; asc       's;; 1: len 6; hex 00001c9151f5; asc     Q ;; 2: len 7; hex 800000003c0110; asc     <  ;; 3: len 8; hex 8000000000000002; asc         ;; 4: len 8; hex 800000000000083d; asc        =;; 5: SQL NULL; 6: SQL NULL; 7: len 1; hex 81; asc  ;; 8: len 8; hex 8000000000000002; asc         ;; 9: len 16; hex 636f72656f66746865627261696e2d75; asc coreofthebrain-u;; 10: len 4; hex 80000eb8; asc     ;; 11: len 1; hex 01; asc  ;; 12: len 30; hex 322e362e32202872656c6561736532362d6d61696e742c20417072203139; asc 2.6.2 (release26-maint, Apr 19;...(truncated); 13: len 30; hex 5f5f6d61696e5f5f2e3c6c616d6264613e206174203c737464696e3e3a31; asc __main__.<lambda> at <stdin>:1;; 14: len 5; hex 8000000001; asc      ;; 15: len 0; hex ; asc ;; 16: len 4; hex 80000000; asc     ;; 17: len 4; hex 80000005; asc     ;; 18: len 4; hex 4b19fb58; asc K  X;; 19: SQL NULL; 20: len 1; hex 02; asc  ;; 21: len 1; hex 80; asc  ;; 22: len 4; hex 80000014; asc     ;; 23: len 4; hex 80000000; asc     ;; 24: len 1; hex 80; asc  ;; 25: SQL NULL;                                                                                                                                                                                          

*** WE ROLL BACK TRANSACTION (1)

Answer 1

The first step is determining what the two queries are:

SELECT api_key, completed, compute_units, created, deleted, flags, func_name, group_id, hostname, is_meta, jid, label, language, num_children, parent_ujid, priority, process_id, restartable, status, type, uid, ujid, version, wid FROM jobs WHERE status='new' and is_meta=0 ORDER BY priority asc,jid asc FOR UPDATE

..and:

UPDATE jobs SET status='done' WHERE jid=10099

The first is a SELECT, the second is an UPDATE. But the key is the FOR UPDATE at the end of the SELECT, which I emphasized in bold.

The FOR UPDATE syntax is for a locking read - you can read the documentation about it here. The MySQL deadlock documentation suggestes using READ COMMITTED if you run into locking issues like these ones.

SHOW INNODB STATUS walk through

Answer 2

I'm not 100% sure but I believe they are not "the same lock".

* (1) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 0 page no 17549 n bits 128 index PRIMARY of table takeyourorder/jobs trx id 0 479286429 lock_mode X waiting Record lock, heap no 61 PHYSICAL RECORD: n_fields 26; compact format; info bits 0

* (2) HOLDS THE LOCK(S): RECORD LOCKS space id 0 page no 17549 n bits 128 index PRIMARY of table takeyourorder/jobs trx id 0 479286425 lock_mode X locks rec but not gap Record lock, heap no 61 PHYSICAL RECORD: n_fields 26; compact format; info bits 0

* (2) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 0 page no 17548 n bits 144 index PRIMARY of table takeyourorder/jobs trx id 0 479286425 lock_mode X locks rec but not gap waiting Record lock, heap no 73 PHYSICAL RECORD: n_fields 26; compact format; info bits 0

Tx(2) holds "heap no 61" record lock and is waiting for "heap no 73" record lock. Tx(1) is waiting for "heap no 61". The log doesn't tell who holds "heap no 73" but maybe it's just a limitation of "SHOW ENGINE INNODB STATUS". You can confirm that similar log will be generated by simple deadlock scenario.